bpo-18748: io.IOBase destructor now logs close() errors in dev mode

[vstinner]

The development mode (-X dev) now logs exceptions in io.IOBase
destructor if close() fails. These exceptions are silent by default.

https://bugs.python.org/issue18748

[vstinner]

That's a shy fix for https://bugs.python.org/issue18748#msg339979 : only log I/O error on close() in development mode (-X dev). Maybe we should even stop to silence these errors by default?

[pitrou]

Have you tried running e.g. the test suite with -Xdev and see how many of those errors pop up?

[vstinner]

Example with bug.py from https://bugs.python.org/issue18748#msg339979.

Without the change.

$ ./python bug.py 
libgcc_s.so.1 must be installed for pthread_cancel to work
Aborted (core dumped)

... Python silently ignores the EBADF error on close(3) causing weird bug which calls abort() and creates a coredump :-( Or sometimes, you are lucky and nothing happens. Example with -X dev (but without my change):

$ ./python -X dev bug.py 
bug.py:28: ResourceWarning: unclosed file <_io.TextIOWrapper name='a.txt' mode='w+' encoding='UTF-8'>
  main()
ResourceWarning: Enable tracemalloc to get the object allocation traceback

ResourceWarning isn't the real bug here, it's more ore less fine to rely on Python to automatically close files usually.

With the change.

$ ./python -X dev bug.py 
bug.py:28: ResourceWarning: unclosed file <_io.TextIOWrapper name='a.txt' mode='w+' encoding='UTF-8'>
  main()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Exception ignored in: <_io.TextIOWrapper name='a.txt' mode='w+' encoding='UTF-8'>
OSError: [Errno 9] Bad file descriptor

The interesting part is the new exception which contains the filename a.txt, useful to identify the bug, and the exception: OSError: [Errno 9] Bad file descriptor.

[vstinner]

Have you tried running e.g. the test suite with -Xdev and see how many of those errors pop up?

Good idea. Not yet, will do.

[vstinner]

So what is your preference? Continue to silence I/O errors on close() by default (when called from the destructor)? Or always log these errors?

In my experience, EBADF can cause a lot damage and are hard to detect when Python makes them slient.

But here, the code contains the comment:

        /* Silencing I/O errors is bad, but printing spurious tracebacks is
           equally as bad, and potentially more frequent (because of
           shutdown issues). */

So I proposed the compromise of reusing -X dev...

[pitrou]

I think these should be silenced by default.

[serhiy-storchaka]

I think there is a bug in the io streams code that causes EBADF. Logging it in debug mode will help us to fix it.

Perhaps there are other places where an error is silenced intentionally because otherwise it would confuse users by spurious tracebacks. It would worth to enabling logging in debug mode in all such cases.

[vstinner]

It would worth to enabling logging in debug mode in all such cases.

Do you mean to enable these logs by default in debug build, ./configure --with-pydebug and "#ifdef Py_DEBUG"? I agree.

[vstinner]

Have you tried running e.g. the test suite with -Xdev and see how many of those errors pop up?

Hopefully, only test_io and test_urllib log such errors. In fact that most of Python code base is sane :-)

I pushed a fix to silence most destructor errors in test_io, but not all of them. I didn't touch test_urllib.

Some tests of CBufferedRWPairTest log "Exception ignored in: ..." but I'm not sure that it's a bug in the test or in io.BufferedRWPair. buffered_close() which doesn't call parent IOBase.close() method, wheareas _io_FileIO_close_impl() does call it. I'm always lost in the code base of the io module, so I can be wrong ;-)

[vstinner]

I'm not sure how to fix test_urllib yet. Maybe it should be fixed in a separated change.

[vstinner]

Hum, fixing tests is non-trivial. Rather than pushing half baken fix for test_io and no fix for test_urllib, I modified my PR to make the minimum change: start to log exceptions. Instead, I will create a separated PR to fix test_io and another to fix test_urllib.

[vstinner]

Oh, I reverted too many fixes from test_io. This PR needs a minimum fix for test_io to not break the CI :-)

[vstinner]

Have you tried running e.g. the test suite with -Xdev and see how many of those errors pop up?

I also checked our buildbot configuration: such "ignore exception" is logged in the "warnings" of a buildbot, and a build becomes orange in that case.

https://github.com/python/buildmaster-config/blob/fd08bbf525d55b10c2eba7916534eb20e06a4232/master/custom/steps.py#L25-L27

        # PyErr_WriteUnraisable() exception: usually, error in
        # garbage collector or destructor
        r"Exception ignored in:",

[vstinner]

Maybe the fact that close() exceptions are ignored silently in io.IOBase constructor should be better documented, but I'm not sure where it should be documented. If someone has an idea, please go ahead and write a pull request :-)