ValueError warning in test_urllib due to io.IOBase destructor

[tirkarthi]

BPO	36918
Nosy	@vstinner, @serhiy-storchaka, @miss-islington, @tirkarthi
PRs	bpo-36918: Don't close the object which is again closed by destructor #13317 bpo-36918, test_urllib: Silence FakeHTTPConnection destructor errors #13955 bpo-36918: Fix "Exception ignored in" in test_urllib #13996 [3.8] bpo-36918: Fix "Exception ignored in" in test_urllib (GH-13996) #13998

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2019-06-12.02:42:40.104>
created_at = <Date 2019-05-14.17:55:07.967>
labels = ['type-bug', '3.8', '3.9', 'expert-IO']
title = 'ValueError warning in test_urllib due to io.IOBase destructor'
updated_at = <Date 2019-06-12.02:42:40.100>
user = 'https://github.com/tirkarthi'

bugs.python.org fields:

activity = <Date 2019-06-12.02:42:40.100>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-06-12.02:42:40.104>
closer = 'vstinner'
components = ['IO']
creation = <Date 2019-05-14.17:55:07.967>
creator = 'xtreak'
dependencies = []
files = []
hgrepos = []
issue_num = 36918
keywords = ['patch']
message_count = 8.0
messages = ['342492', '342708', '342709', '342710', '345164', '345167', '345297', '345299']
nosy_count = 4.0
nosy_names = ['vstinner', 'serhiy.storchaka', 'miss-islington', 'xtreak']
pr_nums = ['13317', '13955', '13996', '13998']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue36918'
versions = ['Python 3.8', 'Python 3.9']

[tirkarthi]

Issue for https://bugs.python.org/issue18748#msg340059.

comment :

Is there someone interested to debug remaining "Exception ignored:" logs in test_urllib?

test_invalid_redirect (test.test_urllib.urlopen_HttpTests) ...
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f24be0>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
ok

test_read_bogus (test.test_urllib.urlopen_HttpTests) ...
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f24cd0>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
ok

test_redirect_limit_independent (test.test_urllib.urlopen_HttpTests) ...
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f24cd0>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f24c30>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f24460>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f24a50>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f247d0>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52ea95f0>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52ea99b0>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f2f820>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f2fbe0>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <http.client.HTTPResponse object at 0x7fca52f2fd70>
Traceback (most recent call last):
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 402, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 415, in flush
    self.fp.flush()
ValueError: I/O operation on closed file.
ok

It's unclear to be if it's a bug in http.client, a bug in the test... or something else.

[serhiy-storchaka]

I think this is a bug in BasicIO. close() should be idempotent. Calling it on the closed file should have no effect.

[serhiy-storchaka]

No, BasicIO.close() is correct.

This is a bug in the garbage collector: the underlying file is closed before closing HTTPResponse. The HTTPResponse instance has a reference to the file object, the file object does not have a reference to the HTTPResponse instance, therefore the HTTPResponse instance should be destroyed first.

[tirkarthi]

My analysis was that close was called on fakesocket which is internally closed when it's counter resets to zero and the destructor was trying to flush on a closed object during destructor call.

Comment from https://bugs.python.org/issue18748#msg341106

The ValueError warnings in test_urllib noted in msg340059 feels like an issue with the test where FakeSocket calls close by itself once it's internal io_refs counter is 0 and during destructor again close is called on an already closed object causing the ValueError.

• The test uses fakehttp() creating FakeSocket starting with io_refs as 1 [1]
• During the test in urlopen, sock.makefile() (io_refs += 1) is called increasing the io_refs to be 2.
• HTTPConnection.close calls sock.close (fakesocket.close) [3] calling io_refs -= 1 and to fakesocket.io_ref to be 1.
• This test uses raises status 302 with http_error_302 which calls self.redirect_internal where self.close is again called causing fp.io_refs == 0 and subsequently calling io.BytesIO.close(self) to close the object. [4]
• During the end of the test destructor is called on the above closed fakesocket object and trying to flush on a closed object causes the ValueError warnings .

Maybe a check could be added during flush to make sure the object is not closed by testing for self.closed but I am not sure if closed attribute is guaranteed to be present. Removing the manual call to close in fakesocket could help since the destructor should be taking care of it and I could see no test failures or warnings removing the close as io_refs gets to 0.

[1]

cpython/Lib/test/test_urllib.py

Line 61 in be6dbfb

io_refs = 1

[2]

cpython/Lib/test/test_urllib.py

Line 67 in be6dbfb

self.io_refs += 1

[3]

cpython/Lib/http/client.py

Line 919 in be6dbfb

sock.close() # close it manually... there may be other refs

[4]

cpython/Lib/urllib/request.py

Line 2145 in be6dbfb

fp.close()

[vstinner]

Well, maybe Python GC can be enhanced. In the meanwhile, I would like to make these warnings quiet since they are very annoying when I have to analyze buildbot warnings. Moreover, this issues blocks my bpo-37069.

Maybe open a separated issue to propose to enhance the GC, if you have an idea how to change it.

[vstinner]

I proposed PR 13955: a fix in 2 lines.

[vstinner]

New changeset eb976e4 by Victor Stinner in branch 'master':
bpo-36918: Fix "Exception ignored in" in test_urllib (GH-13996)
eb976e4

[miss-islington]

New changeset 9d37ae0 by Miss Islington (bot) in branch '3.8':
bpo-36918: Fix "Exception ignored in" in test_urllib (GH-13996)
9d37ae0