Skip to content
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 and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

bpo-26789: Fix logging.FileHandler._open() at exit #23053

Merged
merged 2 commits into from Nov 2, 2020

Conversation

vstinner
Copy link
Member

@vstinner vstinner commented Oct 31, 2020

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
Copy link
Member Author

vstinner commented Oct 31, 2020

cc @vsajip @serhiy-storchaka

I fixed https://bugs.python.org/issue42208 which now makes possible to simply fix https://bugs.python.org/issue26789 with this simple change.

vsajip
vsajip approved these changes Oct 31, 2020
Copy link
Member

@serhiy-storchaka serhiy-storchaka left a comment

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
Copy link
Member

vsajip commented Oct 31, 2020

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
Copy link
Member

serhiy-storchaka commented Nov 1, 2020

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
Copy link
Member Author

vstinner commented Nov 1, 2020

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
Copy link
Member Author

vstinner commented Nov 1, 2020

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
Copy link
Member

vsajip commented Nov 2, 2020

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.

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

@serhiy-storchaka serhiy-storchaka Nov 2, 2020

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.

Copy link
Member Author

@vstinner vstinner Nov 2, 2020

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 added 2 commits Nov 2, 2020
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
Copy link
Member Author

vstinner commented Nov 2, 2020

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

@vstinner vstinner merged commit 45df61f into python:master Nov 2, 2020
3 of 4 checks passed
@vstinner vstinner deleted the logging_shutdown branch Nov 2, 2020
@vstinner
Copy link
Member Author

vstinner commented Nov 2, 2020

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
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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

5 participants