classification
Title: ValueError warning in test_urllib due to io.IOBase destructor
Type: behavior Stage: resolved
Components: IO Versions: Python 3.9, Python 3.8
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: miss-islington, serhiy.storchaka, vstinner, xtreak
Priority: normal Keywords: patch

Created on 2019-05-14 17:55 by xtreak, last changed 2019-06-12 02:42 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 13317 closed xtreak, 2019-05-14 18:04
PR 13955 closed vstinner, 2019-06-11 01:05
PR 13996 merged vstinner, 2019-06-12 01:42
PR 13998 merged miss-islington, 2019-06-12 02:07
Messages (8)
msg342492 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2019-05-14 17:55
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.
msg342708 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2019-05-17 11:12
I think this is a bug in BasicIO. close() should be idempotent. Calling it on the closed file should have no effect.
msg342709 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2019-05-17 11:35
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.
msg342710 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2019-05-17 11:36
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] https://github.com/python/cpython/blob/be6dbfb43b89989ccc83fbc4c5234f50f44c47ad/Lib/test/test_urllib.py#L61
[2] https://github.com/python/cpython/blob/be6dbfb43b89989ccc83fbc4c5234f50f44c47ad/Lib/test/test_urllib.py#L67
[3] https://github.com/python/cpython/blob/be6dbfb43b89989ccc83fbc4c5234f50f44c47ad/Lib/http/client.py#L919
[4] https://github.com/python/cpython/blob/be6dbfb43b89989ccc83fbc4c5234f50f44c47ad/Lib/urllib/request.py#L2145
msg345164 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-11 01:08
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.
msg345167 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-11 01:12
I proposed PR 13955: a fix in 2 lines.
msg345297 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-12 02:07
New changeset eb976e47e261760330c1bed224019b073b05e994 by Victor Stinner in branch 'master':
bpo-36918: Fix "Exception ignored in" in test_urllib (GH-13996)
https://github.com/python/cpython/commit/eb976e47e261760330c1bed224019b073b05e994
msg345299 - (view) Author: miss-islington (miss-islington) Date: 2019-06-12 02:26
New changeset 9d37ae0bee25692572c201378cd0692df22fa2ac by Miss Islington (bot) in branch '3.8':
bpo-36918: Fix "Exception ignored in" in test_urllib (GH-13996)
https://github.com/python/cpython/commit/9d37ae0bee25692572c201378cd0692df22fa2ac
History
Date User Action Args
2019-06-12 02:42:40vstinnersetstatus: open -> closed
stage: patch review -> resolved
resolution: fixed
versions: + Python 3.9
2019-06-12 02:26:07miss-islingtonsetnosy: + miss-islington
messages: + msg345299
2019-06-12 02:07:50miss-islingtonsetpull_requests: + pull_request13861
2019-06-12 02:07:42vstinnersetmessages: + msg345297
2019-06-12 01:42:10vstinnersetpull_requests: + pull_request13859
2019-06-11 01:12:13vstinnersetmessages: + msg345167
2019-06-11 01:08:50vstinnersetmessages: + msg345164
2019-06-11 01:05:00vstinnersetpull_requests: + pull_request13823
2019-06-11 00:59:29vstinnersetpull_requests: - pull_request13428
2019-05-22 22:12:53vstinnersetpull_requests: + pull_request13428
2019-05-17 11:36:30xtreaksetmessages: + msg342710
2019-05-17 11:35:29serhiy.storchakasetmessages: + msg342709
2019-05-17 11:12:29serhiy.storchakasetnosy: + serhiy.storchaka
messages: + msg342708
components: + IO, - Tests
2019-05-14 18:04:14xtreaksetkeywords: + patch
stage: patch review
pull_requests: + pull_request13236
2019-05-14 17:55:07xtreakcreate