Using logging or warnings during Python finalization does crash Python

[vstinner]

BPO	42208
Nosy	@vstinner, @corona10, @miss-islington
PRs	bpo-42208: Pass tstate to _PyGC_CollectNoFail() #23038 bpo-42208: Move _PyImport_Cleanup() to pylifecycle.c #23040 bpo-42208: Fix test_gdb for gc_collect_main() name #23041 bpo-42208: GitHub Action: Add gdb to posix dependencies #23043 bpo-42208: Call GC collect earlier in PyInterpreterState_Clear() #23044 [3.9] bpo-42208: GitHub Action: Add gdb to posix dependencies (GH-23043) #23047 [3.8] bpo-42208: GitHub Action: Add gdb to posix dependencies (GH-23043) #23049 bpo-42208: Add _Py_GetLocaleEncoding() #23050 bpo-42208: Add _locale._get_locale_encoding() #23052
Files	logging.patch crash.py

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2020-10-31.00:33:13.309>
created_at = <Date 2020-10-30.14:57:17.900>
labels = ['interpreter-core', '3.10']
title = 'Using logging or warnings during Python finalization does crash Python'
updated_at = <Date 2020-10-31.00:33:13.309>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2020-10-31.00:33:13.309>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2020-10-31.00:33:13.309>
closer = 'vstinner'
components = ['Interpreter Core']
creation = <Date 2020-10-30.14:57:17.900>
creator = 'vstinner'
dependencies = []
files = ['49553', '49554']
hgrepos = []
issue_num = 42208
keywords = ['patch']
message_count = 11.0
messages = ['379974', '379978', '379987', '379996', '379997', '380001', '380005', '380015', '380017', '380019', '380020']
nosy_count = 3.0
nosy_names = ['vstinner', 'corona10', 'miss-islington']
pr_nums = ['23038', '23040', '23041', '23043', '23044', '23047', '23049', '23050', '23052']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue42208'
versions = ['Python 3.10']

[vstinner]

If you apply attached logging.patch, Python crash using attached crash.py:

$ echo|./python -i crash.py
>>>
>>> 
python: Python/_warnings.c:872: setup_context: Assertion `globals != NULL' failed.
Abandon (core dumped)

Attached logging.patch is a fix for bpo-26789: logging.FileHandler keeps a reference to the builtin open() function.

Attached crash.py does 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.

--

The logging module does automatically close files at exit using:

   atexit.register(shutdown)

But crash.py, a new file is opened by a logging handler after logging.shutdown() is called. Maybe another problem is that the logging module does not clear logger handlers, or prevent handlers to log more message, after shutdown() is called.

[vstinner]

New changeset 8b34148 by Victor Stinner in branch 'master':
bpo-42208: Pass tstate to _PyGC_CollectNoFail() (GH-23038)
8b34148

[vstinner]

New changeset dff1ad5 by Victor Stinner in branch 'master':
bpo-42208: Move _PyImport_Cleanup() to pylifecycle.c (GH-23040)
dff1ad5

[vstinner]

New changeset b9ee4af by Victor Stinner in branch 'master':
bpo-42208: Fix test_gdb for gc_collect_main() name (GH-23041)
b9ee4af

[vstinner]

bpo-42208: Pass tstate to _PyGC_CollectNoFail() (GH-23038)
8b34148

This change renames collect() to gc_collect_main(). It broke test_gdb on buildbots, whereas test_gdb passed on Travis CI on my PR 23038. Also, test_gdb is skipped on the Ubuntu job of GitHub Action since gdb is not installed. I created python/core-workflow#383 to add gdb to Ubuntu dependencies. My PR 23043 adds gdb dependency.

[vstinner]

New changeset eba5bf2 by Victor Stinner in branch 'master':
bpo-42208: Call GC collect earlier in PyInterpreterState_Clear() (GH-23044)
eba5bf2

[vstinner]

New changeset 09c6120 by Miss Skeleton (bot) in branch '3.9':
bpo-42208: GitHub Action: Add gdb to posix dependencies (GH-23043) (GH-23047)
09c6120

[vstinner]

This change renames collect() to gc_collect_main(). It broke test_gdb on buildbots, whereas test_gdb passed on Travis CI on my PR 23038. Also, test_gdb is skipped on the Ubuntu job of GitHub Action since gdb is not installed. I created python/core-workflow#383 to add gdb to Ubuntu dependencies. My PR 23043 adds gdb dependency.

Fixed by:

commit 6e03c0a (upstream/master, master)
Author: Victor Stinner <vstinner@python.org>
Date: Fri Oct 30 22:52:30 2020 +0100

GitHub Action: Add gdb to posix dependencies (GH-23043)

Sort also dependencies and remove duplicates (liblzma-dev).

[vstinner]

New changeset 710e826 by Victor Stinner in branch 'master':
bpo-42208: Add _Py_GetLocaleEncoding() (GH-23050)
710e826

[vstinner]

New changeset b62bdf7 by Victor Stinner in branch 'master':
bpo-42208: Add _locale._get_locale_encoding() (GH-23052)
b62bdf7

[vstinner]

I fixed all issues which prevented to fix bpo-26789, I close thie issue.