… 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

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

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.

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?

Calling logging.shutdown() when you know you're about to exit should eliminate some of the issues.

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.

How does a particular piece of logging package code know it's being called during Python finalization?

sys.is_finalizing()

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.

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.

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.

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.

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

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.

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.

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.

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".

I am not sure that its all the same issue. There may be several different issues:

• bpo-39513. 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.

• bpo-26789. 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.

• bpo-42203. 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 bpo-26789, but tests can make additional efforts to clean up.

bpo-26789. 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.

Note: Attached error.py no longer works with a recent aiohttp version.

Attached PR 23053 fix the root issue of the infamous "NameError: name 'open' is not defined" error in the logging module.

New changeset 45df61f by Victor Stinner in branch 'master':
bpo-26789: Fix logging.FileHandler._open() at exit (GH-23053)
45df61f

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.