Issue 20037: Calling traceback.format_exception() during Pyhon shutdown does crash Python

Attached crash.py script does crash Python.

Python traceback on the crash:

(gdb) py-bt
Traceback (most recent call first):
  File "/home/haypo/prog/python/default/Lib/tokenize.py", line 431, in open
    text = TextIOWrapper(buffer, encoding, line_buffering=True)
  File "/home/haypo/prog/python/default/Lib/linecache.py", line 126, in updatecache
    with tokenize.open(fullname) as fp:
  File "/home/haypo/prog/python/default/Lib/linecache.py", line 41, in getlines
    return updatecache(filename, module_globals)
  File "/home/haypo/prog/python/default/Lib/linecache.py", line 15, in getline
    lines = getlines(filename, module_globals)
  File "/home/haypo/prog/python/default/Lib/traceback.py", line 65, in _extract_tb_or_stack_iter
    line = linecache.getline(filename, lineno, f.f_globals)
  File "/home/haypo/prog/python/default/Lib/traceback.py", line 18, in _format_list_iter
    for filename, lineno, name, line in extracted_list:
  File "/home/haypo/prog/python/default/Lib/traceback.py", line 153, in _format_exception_iter
    yield from _format_list_iter(_extract_tb_iter(tb, limit=limit))
  File "/home/haypo/prog/python/default/Lib/traceback.py", line 181, in format_exception
    return list(_format_exception_iter(etype, value, tb, limit, chain))
  File "/home/haypo/prog/python/default/Lib/asyncio/futures.py", line 178, in __del__
    exc.__traceback__)
  Garbage-collecting

End of the C traceback:

#46 0x00000000005aa742 in PyEval_CallObjectWithKeywords (func=<method at remote 0x7ffff19e79f8>, arg=(), kw=0x0) at Python/ceval.c:4107
#47 0x00000000004ee268 in slot_tp_finalize (
    self=<Future(_state='FINISHED', _exception=ValueError(), _loop=<_UnixSelectorEventLoop(_selector=<EpollSelector(_epoll=<select.epoll at remote 0x7ffff0dd3a18>, _fd_to_key={9: <SelectorKey at remote 0x7fffeefaa0e0>}, _map=<_SelectorMapping(_selector=<...>) at remote 0x7ffff18eae90>) at remote 0x7ffff18ea1f8>, _running=False, _signal_handlers={}, _default_executor=None, _ssock=<socket at remote 0x7fffef7e6e68>, _internal_fds=1, _scheduled=[], _ready=<collecti---Type <return> to continue, or q <return> to quit---
ons.deque at remote 0x7ffff18c56e0>, _csock=<socket at remote 0x7fffeefb5958>) at remote 0x7ffff18ea190>, _log_traceback=True, _callbacks=[]) at remote 0x7ffff18ea0c0>) at Objects/typeobject.c:5954
#48 0x000000000043b530 in finalize_garbage (collectable=0x7fffffffdc90, old=0x8eea20 <generations+64>) at Modules/gcmodule.c:793
#49 0x000000000043bce5 in collect (generation=2, n_collected=0x0, n_uncollectable=0x0, nofail=1) at Modules/gcmodule.c:1009
#50 0x000000000043cff4 in _PyGC_CollectNoFail () at Modules/gcmodule.c:1625
#51 0x00000000005cd873 in PyImport_Cleanup () at Python/import.c:383
#52 0x000000000041e898 in Py_Finalize () at Python/pythonrun.c:622
#53 0x000000000043a65c in Py_Main (argc=2, argv=0x970020) at Modules/main.c:800
#54 0x000000000041aad9 in main (argc=2, argv=0x7fffffffe0b8) at ./Modules/python.c:69

Begin of the C traceback:

#0  0x00000000004bf70a in PyModule_GetState (m=0x0) at Objects/moduleobject.c:292
#1  0x00000000006373b6 in textiowrapper_init (self=0x7ffff1073790, args=(<_io.BufferedReader at remote 0x7fffefa094b8>, 'utf-8'), 
    kwds={'line_buffering': True}) at ./Modules/_io/textio.c:855
#2  0x00000000004daf26 in type_call (type=0x94d700 <PyTextIOWrapper_Type>, args=(<_io.BufferedReader at remote 0x7fffefa094b8>, 'utf-8'), 
    kwds={'line_buffering': True}) at Objects/typeobject.c:759

Yes, the current idiom for calling PyModule_GetState in extension modules isn't safe (because it assumes nothing ever errors out, which can be wrong in the shutdown phase).

Speaking of which, Victor, your script works here:

$ ./python futcrash.py 
Future/Task exception was never retrieved:
Traceback (most recent call last):
  File "futcrash.py", line 4, in <module>
    raise ValueError()
ValueError

Ah, that was before the latest changes. Scratch that.

See issue18710 for an API proposal which may help in some cases.

Also, see https://mail.python.org/pipermail/python-dev/2013-August/127862.html for an involved discussion of issues with the current "module state" scheme.

Note that the module state is only used when no explicit encoding is given to TextIOWrapper(), so the following patch fixes this particular issue:

$ hg di
diff --git a/Modules/_io/textio.c b/Modules/_io/textio.c
--- a/Modules/_io/textio.c
+++ b/Modules/_io/textio.c
@@ -852,7 +852,7 @@ textiowrapper_init(textio *self, PyObjec
     char *errors = NULL;
     char *newline = NULL;
     int line_buffering = 0, write_through = 0;
-    _PyIO_State *state = IO_STATE;
+    _PyIO_State *state = NULL;
 
     PyObject *res;
     int r;
@@ -891,6 +891,7 @@ textiowrapper_init(textio *self, PyObjec
     if (encoding == NULL) {
         /* Try os.device_encoding(fileno) */
         PyObject *fileno;
+        state = IO_STATE;
         fileno = _PyObject_CallMethodId(buffer, &PyId_fileno, NULL);
         /* Ignore only AttributeError and UnsupportedOperation */
         if (fileno == NULL) {


However, since doing I/O at shutdown is not a particularly uncommon operation, we should still fix the general case to at least raise a proper exception.

Here is a patch with tests.

Oh, I think that #19421 was also a duplicate of this issue. Updated example from this issue: attached script crash_logging_exc_info.py.

Output:
---
$ ./python crash_logging_exc_info.py
Erreur de segmentation (core dumped)
---

Output with iostate_shutdown.patch applied:
---
$ ./python ~/crash_logging_exc_info.py 
CRITICAL:root:error
Traceback (most recent call last):
  File "/home/haypo/crash_logging_exc_info.py", line 7, in __del__
    raise ValueError()
ValueError
---

@Antoine: You should also add a test based on crash_logging_exc_info.py in test_logging, to test the whole feature (display a traceback during Python shutdown).

iostate_shutdown.patch: "_PyIO_State *state = IO_STATE;" looks weird to me. The macro should be take parenthesis: "_PyIO_State *state = IO_STATE();". When I read IO_STATE, it looks like a global variable, whereas it does call a real function.

New changeset 9158f201f6d0 by Antoine Pitrou in branch 'default':
Issue #20037: Avoid crashes when doing text I/O late at interpreter shutdown.
http://hg.python.org/cpython/rev/9158f201f6d0

Applied Victor's comments and committed the fix.

> Applied Victor's comments

Thanks!

Thanks for the quick fix guys! Sorry for the duplicate bug (probably a race condition :-).

stage: patch review -> resolved

messages: + msg206732

keywords: + patch
type: crash
stage: patch review