classification
Title: logging: Trying to log during Python finalization with NameError: name 'open' is not defined
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.10
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Charles Bouchard-Légaré, JanVok, Peer Sommerlund, Sandeep, methane, r.david.murray, serhiy.storchaka, smurfix, veky, vinay.sajip, vstinner, yselivanov
Priority: normal Keywords: patch

Created on 2016-04-17 15:12 by smurfix, last changed 2020-11-02 22:32 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
error.py JanVok, 2017-02-21 13:28 Program showing the error
Pull Requests
URL Status Linked Edit
PR 23053 merged vstinner, 2020-10-31 00:30
Messages (22)
msg263612 - (view) Author: Matthias Urlichs (smurfix) * Date: 2016-04-17 15:12
… or, if you do, ignore errors.

This is during program shutdown. Unfortunately, I am unable to create a trivial example which exhibits the order of destruction necessary to trigger this problem.

Traceback (most recent call last):
  File "/usr/lib/python3.5/asyncio/tasks.py", line 93, in __del__
  File "/usr/lib/python3.5/asyncio/base_events.py", line 1160, in call_exception_handler
  File "/usr/lib/python3.5/logging/__init__.py", line 1308, in error
  File "/usr/lib/python3.5/logging/__init__.py", line 1415, in _log
  File "/usr/lib/python3.5/logging/__init__.py", line 1425, in handle
  File "/usr/lib/python3.5/logging/__init__.py", line 1487, in callHandlers
  File "/usr/lib/python3.5/logging/__init__.py", line 855, in handle
  File "/usr/lib/python3.5/logging/__init__.py", line 1047, in emit
  File "/usr/lib/python3.5/logging/__init__.py", line 1037, in _open
NameError: name 'open' is not defined
msg288299 - (view) Author: Jan Vorwerk (JanVok) Date: 2017-02-21 13:28
Indeed, the error message is quite... surprising and misleading.
To reproduce, please run the attached (admittedly wrong) program that I could simplify a lot.

It seems to occur when a exception is raised at the wrong time...
I hope this helps nail down (at least) one use case.

'pip install aiohttp' is required

Best regards
msg288302 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-02-21 14:39
> Please do not log during shutdown

These logs are supposed to help you to find bugs in your application. Sadly, it's hard to log errors during Python shutdown because Pyhon is destroying its world: many basic functions are broken during shutdown.

We already fixed many errors, but not that one.

IMHO it's worth it to repair the logging module to be able to log during shutdown.

The logging module should be be enhanced to handle more nicely such error during Python finalization.
msg288316 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-02-21 19:34
> The logging module should be be enhanced to handle more nicely such error during Python finalization.

How does a particular piece of logging package code know it's being called during Python finalization? This sort of problem (exceptions caused by disappearing builtins, for example) isn't confined to logging, surely?
msg288317 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-02-21 19:36
Calling logging.shutdown() when you know you're about to exit should eliminate some of the issues.
msg288320 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2017-02-21 20:56
If I understand correctly, the logging during shutdown coming out of asyncio helps debug errors in asyncio programs, and this logging can't happen before shutdown starts (so the application calling logging.shutdown would just hide the errors, I think).

Yes, the general problem affects more than just logging, and when it is reasonable to do so we try to fix (or at least cleanly report) these shutdown issues in stdlib code.  Whether it is reasonable to do so in this case I don't know.
msg288321 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-02-21 21:10
> How does a particular piece of logging package code know it's being called during Python finalization?

sys.is_finalizing()
msg288329 - (view) Author: Inada Naoki (methane) * (Python committer) Date: 2017-02-22 04:38
I'm -1 on suppress log silently.
While error message is bit surprising,

Traceback (most recent call last):
  File "/usr/lib/python3.5/asyncio/tasks.py", line 93, in __del__
  File "/usr/lib/python3.5/asyncio/base_events.py", line 1160, in call_exception_handler
...
  File "/usr/lib/python3.5/logging/__init__.py", line 1037, in _open
NameError: name 'open' is not defined

This traceback is very meaningful.
You can read tasks.py:93, and find there are pending task remains.

Implementing fallback mechanism make potential risk to miss such very
important traceback.
msg288342 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-02-22 07:53
> sys.is_finalizing()

Good to know. Is the "sys" binding guaranteed to be around even when other builtins like "open" aren't available? In order to handle things "nicely" during shutdown, what guarantees can logging code rely on in terms of what's available? I'm assuming handling things nicely doesn't mean just swallowing any exceptions raised.
msg288346 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-02-22 09:30
There are no guaranties. But in recent Python versions the order of finalising is more predicable. It is hard to reproduce a case when some builtins or sys member is not available (with some exceptions).

The order of clearing (see PyImport_Cleanup() in Python/import.c):

1. Clear builtins._ and selected sys members (in particular this breaks import). Restore standard IO streams.

2. Clear sys.modules and all modules that don't have external references.

3. Restore builtins to its initial state (in particular builtins.open no longer available).

4. Clear the content of still alive modules except sys and builtins.

5. Clear sys.

6. Clear builtins.
msg291230 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-04-06 15:09
In the OP, the error is caused by `open` being unavailable, which is a builtin. According to what Serhiy says, this error would be after step 6 in his list, so `sys` wouldn't be available either, and nor perhaps would any other builtins.

As some termination issues are asyncio-related (e.g. this one, "coroutine was never awaited"), it would make more sense for this kind of error handling to happen there - there's more contextual information available than there is in logging, so the error message displayed would be more useful because it could use the additional context available.
msg361129 - (view) Author: Sandeep (Sandeep) * Date: 2020-01-31 20:05
I did import aiohttp and called function sys.is_finalizing() just before 
logging.basicConfig but still the same error.

Has  logging.basicConfig worked in past ? If yes what  additional package I need to add

Thanks
msg379966 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-30 14:24
I marked bpo-39513 and bpo-42203 as duplicates of this issue.

I changed the title to reflect that the root issue is that logging during Python finalization can fail with NameError: name 'open' is not defined.
msg379968 - (view) Author: Vedran Čačić (veky) * Date: 2020-10-30 14:26
> In the OP, the error is caused by `open` being unavailable, which is a builtin. According to what Serhiy says, this error would be after step 6

I think you read the post above incorrectly. The phase 3 is the one where open is removed, since it's not a "native" builtin, but imported from io.
msg379971 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-30 14:32
I hacked logging.FileHandler to keep a reference to the builtin open() function. I got new problems.

In my test, I got a crash because of an unclosed file. It happens after PyInterpreterState_Clear(), in finalize_interp_clear():

    /* Last explicit GC collection */
    _PyGC_CollectNoFail();

setup_context() of Python/_warings.c does crash because tstate->interp->sysdict is NULL at this point.

Moreover, _io.TextIOWrapper.__init__() fails to import the locale module (to call locale.getpreferredencoding(), since the encoding is None) and picks the "ascii" encoding.

Moreover, even if I work around all these issues, _warnings.showwarnings() logs "lost sys.stderr" into stderr because, again, tstate->interp->sysdict is NULL at this point (and so sys.stderr no longer exists).

It looks like a bug in finalize_interp_clear() which triggers a garbage collection, whereas Python is no longer usable.
msg379975 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-30 14:57
> It looks like a bug in finalize_interp_clear() which triggers a garbage collection, whereas Python is no longer usable.

I created bpo-42208 "Using logging or warnings during Python finalization does crash Python".
msg379982 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2020-10-30 16:38
I am not sure that its all the same issue. There may be several different issues:

* Issue39513. Logging fails with confusing traceback when called late at shutdown. I think that if logging cannot work at this stage it should either do nothing or emit a warning.

* Issue26789. asyncio creates reference loops which caused to executing code late at shutdown, and that code uses logging which always fail. It would be better to avoid creating reference loops, and if it is impossible, break the earlier.

* Issue42203. And there may be different issue in asyncio tests. Tests should clean up after them and do not leave the code be executed later. It may be the same as issue26789, but tests can make additional efforts to clean up.
msg379986 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-30 17:01
> Issue26789. asyncio creates reference loops which caused to executing code late at shutdown, and that code uses logging which always fail.

Well, I suggest to attempt fixing logging.

The reference cycle in asyncio.Task.set_exception() is *by design*. It's really trick to fix it. Since the creation of asyncio, nobody managed to find a solution to fix it. Once I propose to create an asyncio task forcing a GC collection every minute, but it was never implemented.

If you have a clever idea to fix Task.set_exception() design, please open a separated issue.
msg380021 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-31 00:35
Note: Attached error.py no longer works with a recent aiohttp version.
msg380023 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-10-31 00:36
Attached PR 23053 fix the root issue of the infamous "NameError: name 'open' is not defined" error in the logging module.
msg380253 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-11-02 22:17
New changeset 45df61fd2d58e8db33179f3b5d00e53fe6a7e592 by Victor Stinner in branch 'master':
bpo-26789: Fix logging.FileHandler._open() at exit (GH-23053)
https://github.com/python/cpython/commit/45df61fd2d58e8db33179f3b5d00e53fe6a7e592
msg380254 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-11-02 22:32
I fixed the issue in the master and I will not backport the change to stable branches on purpose. Thanks for the review Vinay!

--

I pushed a change in Python 3.10 which reduces the risk of "NameError: name 'open' is not defined" when logging really late during the Python finalization.

It's a workaround on fragile finalization code. Please don't rely on it! You should release resources explicitly at exit. Don't rely on implicit __del__() finalizers.

I chose to enhance the logging module anyway since the initial issue was that asyncio failed to log a message at exit, a message which is supposed to help developer to fix their code. It's a convenient tool to ease debugging. But, again, it would be really bad idea to rely on it to ensure that logging still works after logging.shutdown() has been called!

About asyncio, for development, you can try to frequently call gc.collect() using call_later() or something, to get issues like "never-retrieved exceptions":
https://docs.python.org/dev/library/asyncio-dev.html

I chose to restrict this issue to the very specific case of NameError when calling logging.FileHandler.emit() late during the Python finalization.

If someone wants to enhance another function, please open a new issue.

I will not backport my change since the Python finalization is really fragile and my logging fix rely on many enhancements made in the master that will not be backported to Python 3.9 and older on purpose. Changes on the finalization are also fragile and can introduce new subtile bugs. It happened multiple times. But overall, step by step, the Python finalization becomes more and more reliable ;-)

For curious people, here are my notes on the Python finalization:
https://pythondev.readthedocs.io/finalization.html

--

About the logging, honestly, I'm not sure that it's a good idea that FileHandler.emit() reopens the file after logging.shutdown() has been called (this function calls FileHandler.close() which closes the file).

But if someone disagrees, please open a separated issue ;-) This one is now closed.
History
Date User Action Args
2020-11-02 22:32:14vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg380254

stage: patch review -> resolved
2020-11-02 22:17:49vstinnersetmessages: + msg380253
2020-10-31 00:36:58vstinnersetmessages: + msg380023
2020-10-31 00:35:50vstinnersetmessages: + msg380021
2020-10-31 00:30:54vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request21972
2020-10-30 17:01:05vstinnersetmessages: + msg379986
2020-10-30 16:38:08serhiy.storchakasetmessages: + msg379982
2020-10-30 14:57:54vstinnersetmessages: + msg379975
2020-10-30 14:32:19vstinnersetmessages: + msg379971
2020-10-30 14:26:10vekysetnosy: + veky
messages: + msg379968
2020-10-30 14:24:35vstinnersettitle: asyncio: Please do not log during shutdown -> logging: Trying to log during Python finalization with NameError: name 'open' is not defined
nosy: + vstinner

messages: + msg379966

versions: + Python 3.10, - Python 3.5
components: + Library (Lib), - asyncio
2020-10-30 14:23:33vstinnerlinkissue39513 superseder
2020-10-30 14:23:31vstinnerlinkissue42203 superseder
2020-02-01 12:15:00vstinnersetnosy: - vstinner

title: Please do not log during shutdown -> asyncio: Please do not log during shutdown
2020-01-31 20:05:31Sandeepsetnosy: + Sandeep
messages: + msg361129
2019-03-19 04:15:12Peer Sommerlundsetnosy: + Peer Sommerlund
2017-04-06 15:09:10vinay.sajipsetmessages: + msg291230
2017-04-05 14:26:26Charles Bouchard-Légarésetnosy: + Charles Bouchard-Légaré
2017-02-22 09:30:18serhiy.storchakasetmessages: + msg288346
2017-02-22 07:53:45vinay.sajipsetmessages: + msg288342
2017-02-22 04:38:54methanesetnosy: + methane
messages: + msg288329
2017-02-21 22:29:58gvanrossumsetnosy: - gvanrossum
2017-02-21 21:10:31serhiy.storchakasetnosy: + serhiy.storchaka
messages: + msg288321
2017-02-21 20:56:26r.david.murraysetnosy: + r.david.murray
messages: + msg288320
2017-02-21 19:36:22vinay.sajipsetmessages: + msg288317
2017-02-21 19:34:10vinay.sajipsetmessages: + msg288316
2017-02-21 14:39:20vstinnersetmessages: + msg288302
2017-02-21 13:28:29JanVoksetfiles: + error.py
nosy: + JanVok
messages: + msg288299

2016-04-17 17:00:27serhiy.storchakasetnosy: + vinay.sajip
2016-04-17 15:12:07smurfixcreate