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

Created on 2019-05-14 17:55 by xtreak, last changed 2019-05-22 22:12 by vstinner.

Pull Requests
URL Status Linked Edit
PR 13317 open xtreak, 2019-05-14 18:04
PR 13512 open vstinner, 2019-05-22 22:12
Messages (4)
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
History
Date User Action Args
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