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

@gvanrossum

BPO	20037
Nosy	@gvanrossum, @ncoghlan, @pitrou, @vstinner, @skrah
Files	crash.py iostate_shutdown.patch crash_logging_exc_info.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 2013-12-21.14:53:26.906>
created_at = <Date 2013-12-20.22:19:07.379>
labels = ['type-crash']
title = 'Calling traceback.format_exception() during Pyhon shutdown does crash Python'
updated_at = <Date 2013-12-21.16:57:29.397>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2013-12-21.16:57:29.397>
actor = 'gvanrossum'
assignee = 'none'
closed = True
closed_date = <Date 2013-12-21.14:53:26.906>
closer = 'pitrou'
components = []
creation = <Date 2013-12-20.22:19:07.379>
creator = 'vstinner'
dependencies = []
files = ['33239', '33242', '33243']
hgrepos = []
issue_num = 20037
keywords = ['patch']
message_count = 14.0
messages = ['206707', '206708', '206726', '206727', '206728', '206729', '206730', '206731', '206732', '206733', '206749', '206750', '206751', '206766']
nosy_count = 6.0
nosy_names = ['gvanrossum', 'ncoghlan', 'pitrou', 'vstinner', 'skrah', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue20037'
versions = ['Python 3.4']

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

@antoine

Oh, I think that bpo-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 bpo-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 :-).

Navigation Menu

Repository navigation

Calling traceback.format_exception() during Pyhon shutdown does crash Python #64236

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Calling traceback.format_exception() during Pyhon shutdown does crash Python #64236

Description

Activity

vstinner commented on Dec 20, 2013

vstinner commented on Dec 20, 2013

pitrou commented on Dec 21, 2013

pitrou commented on Dec 21, 2013

pitrou commented on Dec 21, 2013

pitrou commented on Dec 21, 2013

pitrou commented on Dec 21, 2013

pitrou commented on Dec 21, 2013

vstinner commented on Dec 21, 2013

vstinner commented on Dec 21, 2013

python-dev commented on Dec 21, 2013

pitrou commented on Dec 21, 2013

vstinner commented on Dec 21, 2013

gvanrossum commented on Dec 21, 2013

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions