bpo-26789: Fix logging.FileHandler._open() at exit by vstinner · Pull Request #23053 · python/cpython (original) (raw)

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service andprivacy statement. We’ll occasionally send you account related emails.

Already on GitHub?Sign in to your account

Conversation11 Commits2 Checks0 Files changed

Conversation

This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.Learn more about bidirectional Unicode characters

[ Show hidden characters]({{ revealButtonHref }})

vstinner

The logging.FileHandler class now keeps a reference to the builtin
open() function to be able to open or reopen the file during Python
finalization.

Fix errors like:

Exception ignored in: (...)
Traceback (most recent call last):
  (...)
  File ".../logging/__init__.py", line 1463, in error
  File ".../logging/__init__.py", line 1577, in _log
  File ".../logging/__init__.py", line 1587, in handle
  File ".../logging/__init__.py", line 1649, in callHandlers
  File ".../logging/__init__.py", line 948, in handle
  File ".../logging/__init__.py", line 1182, in emit
  File ".../logging/__init__.py", line 1171, in _open
NameError: name 'open' is not defined

https://bugs.python.org/issue26789

@vstinner

vsajip

serhiy-storchaka

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

builtin.open is not the only issue. If the encoding is not builtin, it should be imported, but the import machinery does not work at this stage.

Also, caching open creates additional reference loops. And if we use the Python implementation of io.open it can be not working at all.

I think that it would be better to not open file at this stage.

@vsajip

I view this as a bit of a sticking plaster. When shutting down, by definition, some things will get garbage collected/unbound, and some threaded/async code that uses them can fail because some builtin or other disappears. Logging often gets fingered as the culprit, but IMO any code might try to invoke open() during interpreter shutdown and it would fail in the same way. This change just sort of fixes the problem for logging, perhaps, but not IMO in a general way. Perhaps the correct approach for this type of issue might be to say "it's not a bug - if you have threads or async code, it's your responsibility to inform them to shutdown in an orderly way, if you know the interpreter is about to shut down". If it's an uncaught exception that brings the interpreter down, then it doesn't matter that this kind of message is shown - for example you often see "Broken pipe" messages when Ctrl-C-ing a Python process.

I think that it would be better to not open file at this stage.

If by "this stage" you mean interpreter shutdown, how does any code know we're in that stage? The code that does the open() has no context. What about other code in the stdlib that does open()?

@serhiy-storchaka

If by "this stage" you mean interpreter shutdown, how does any code know we're in that stage?

There is no open in builtins. At this point the current code raises a NameError. We have alternative -- continue to raise it or do not (and suppress logging). Or maybe raise different, more specific exception. If this is not the first use of logging and the file was already opened, you can do logging at this stage.

More radical approach: register an exit function and shutdown logging at interpreter shutdown.

@vstinner

More radical approach: register an exit function and shutdown logging at interpreter shutdown.

The logging module registers its logging.shutdown() function in the atexit module. Extract of the unit test of my PR:

            # basicConfig() opens the file, but logging.shutdown() closes
            # it at Python exit. When A.__del__() is called,
            # FileHandler._open() must be called again to re-open the file.
            logging.basicConfig(filename={filename!r})

@vstinner

I consider that the logging module is not the general case. Many applications rely on the logging module for "reliable" logs. I consider that it's important to be able to log as late as possible during the Python shutdown. I'm fine with less important modules failing with "NameError: open".

So far, nobody found a solution to make asyncio finalization more reliable.

So far, nobody found a solution to finalize all Python objects in the "perfect" order. There are so many corner cases.

My PR is a practical solution to a practical issue.

In https://bugs.python.org/issue42208 I made the Python finalization a little bit more reliable and deterministic, but it remains full of corner cases obviously. I modified _io.open() (710e826) to not longer call _bootlocale.getpreferredencoding(False) but a new _Py_GetLocaleEncoding() function to fix bpo-26789, but also implementing _Py_GetLocaleEncoding() is C makes is more consistent with Py_DecodeLocale/Py_EncodeLocale, PyUnicode_DecodeFSDefault/PyUnicode_EncodeFSDefault, etc. For example, using _Py_FORCE_UTF8_LOCALE macro fix the function on VxWorks. And using _Py_FORCE_UTF8_FS_ENCODING macro makes the code less specific to macOS (even if currently only macOS is impacted).

I'm aware that calling open() late during the Python finalization is not reliable, but it seems to work in common cases, which is better than the Python 3.9 state.

@vsajip

My PR is a practical solution to a practical issue.

I agree, and this is why I approved the PR. I said I view it as a sticking plaster - which I think we are all agreed on - and a sticking plaster is a practical solution. I'm OK with merging this, for that reason, even though it isn't a general or perfect solution.

serhiy-storchaka

Comment on lines 4353 to 4355

# Simulate the Python finalization which sets
# modules attributess to None
builtins.open = None

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

open is not set to None. It is removed.

Also some names are removed from the sys module: path, path_hooks, etc.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

open is not set to None. It is removed.

Oh, you're right! The finalize_modules() function (*) is a complex beast. It sets module attributes to None, but sys and builtins are treated differently. The operation which "removes" builtin symbols happens in finalize_restore_builtins():

PyDict_Update(interp->builtins, interp->builtins_copy)

A copy of the builtins dict is created before "open" is added to the builtins dict, on purpose.

(*) I recently renamed finalize_modules(), it was previously called _PyImport_Cleanup even if it's unrelated to import!

@vstinner

The logging.FileHandler class now keeps a reference to the builtin open() function to be able to open or reopen the file during Python finalization.

Fix errors like:

Exception ignored in: (...)
Traceback (most recent call last):
  (...)
  File ".../logging/__init__.py", line 1463, in error
  File ".../logging/__init__.py", line 1577, in _log
  File ".../logging/__init__.py", line 1587, in handle
  File ".../logging/__init__.py", line 1649, in callHandlers
  File ".../logging/__init__.py", line 948, in handle
  File ".../logging/__init__.py", line 1182, in emit
  File ".../logging/__init__.py", line 1171, in _open
NameError: name 'open' is not defined

@vstinner

@vstinner

FYI the test_asyncio failed on the 64-bit Windows job of Azure. I'm not interested to investigate this issue.

@vstinner

I merged my change.

It cannot be backported because I didn't backport https://bugs.python.org/issue42208 (and I don't want to backport these finalization enhancements). Since it's a borderline fix, I prefer to only change the master branch.

adorilson pushed a commit to adorilson/cpython that referenced this pull request

Mar 13, 2021

@vstinner @adorilson

The logging.FileHandler class now keeps a reference to the builtin open() function to be able to open or reopen the file during Python finalization.

Fix errors like:

Exception ignored in: (...)
Traceback (most recent call last):
  (...)
  File ".../logging/__init__.py", line 1463, in error
  File ".../logging/__init__.py", line 1577, in _log
  File ".../logging/__init__.py", line 1587, in handle
  File ".../logging/__init__.py", line 1649, in callHandlers
  File ".../logging/__init__.py", line 948, in handle
  File ".../logging/__init__.py", line 1182, in emit
  File ".../logging/__init__.py", line 1171, in _open
NameError: name 'open' is not defined