classification
Title: Calling traceback.format_exception() during Pyhon shutdown does crash Python
Type: crash Stage: resolved
Components: Versions: Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: gvanrossum, haypo, ncoghlan, pitrou, python-dev, skrah
Priority: normal Keywords: patch

Created on 2013-12-20 22:19 by haypo, last changed 2013-12-21 16:57 by gvanrossum. This issue is now closed.

Files
File name Uploaded Description Edit
crash.py haypo, 2013-12-20 22:19
iostate_shutdown.patch pitrou, 2013-12-21 13:19 review
crash_logging_exc_info.py haypo, 2013-12-21 13:51
Messages (14)
msg206707 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2013-12-20 22:19
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
msg206708 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2013-12-20 22:22
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
msg206726 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-12-21 12:01
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).
msg206727 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-12-21 12:04
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
msg206728 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-12-21 12:05
Ah, that was before the latest changes. Scratch that.
msg206729 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-12-21 12:13
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.
msg206730 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-12-21 12:19
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.
msg206731 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-12-21 13:19
Here is a patch with tests.
msg206732 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2013-12-21 13:51
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).
msg206733 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2013-12-21 13:52
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.
msg206749 - (view) Author: Roundup Robot (python-dev) Date: 2013-12-21 14:52
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
msg206750 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-12-21 14:53
Applied Victor's comments and committed the fix.
msg206751 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2013-12-21 14:54
> Applied Victor's comments

Thanks!
msg206766 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2013-12-21 16:57
Thanks for the quick fix guys! Sorry for the duplicate bug (probably a race condition :-).
History
Date User Action Args
2013-12-21 16:57:29gvanrossumsetmessages: + msg206766
2013-12-21 14:54:57hayposetmessages: + msg206751
2013-12-21 14:53:26pitrousetstatus: open -> closed
resolution: fixed
messages: + msg206750

stage: patch review -> resolved
2013-12-21 14:52:35python-devsetnosy: + python-dev
messages: + msg206749
2013-12-21 13:52:10hayposetmessages: + msg206733
2013-12-21 13:51:01hayposetfiles: + crash_logging_exc_info.py

messages: + msg206732
2013-12-21 13:19:13pitrousetfiles: + iostate_shutdown.patch
messages: + msg206731

keywords: + patch
type: crash
stage: patch review
2013-12-21 12:19:53pitrousetmessages: + msg206730
2013-12-21 12:13:33pitrousetmessages: + msg206729
2013-12-21 12:05:25pitrousetmessages: + msg206728
2013-12-21 12:04:45pitrousetmessages: + msg206727
2013-12-21 12:01:25pitrousetnosy: + gvanrossum, ncoghlan, pitrou
messages: + msg206726
2013-12-21 11:57:55pitroulinkissue20038 superseder
2013-12-21 11:22:16skrahsetnosy: + skrah
2013-12-20 22:22:02hayposetmessages: + msg206708
2013-12-20 22:19:07haypocreate