GeezerVison is showing github.com — Crash when concurrently writing with `print` and concurrently modifying `sys.stdout` · Issue #130163 · python/cpython
Crash when concurrently writing with print and concurrently modifying sys.stdout #130163DescriptionCrash report
What happened?
Playing with the code from #130148, I stumbled on a segfault in a free-threaded debug build with the following (seems to trigger faster/more consistently when pasted in the REPL):
from contextlib import redirect_stdout
from io import StringIO
from threading import Thread
import time
def test_redirect():
text = StringIO()
with redirect_stdout(text):
print("hello1", file=text)
time.sleep(0.1)
print("hello2", file=text)
print(text.getvalue())
assert text.getvalue() == "hello1\nhello2\n"
for x in range(100):
Thread(target=test_redirect, args=()).start()I didn't have time to check whether JIT, debug or no-gil are strictly necessary for this to crash. JIT is not needed for this to crash.
Cause
The problem is that in the print() implementation, _PySys_GetAttr returns a borrowed reference.
|
if (file == Py_None) { |
|
PyThreadState *tstate = _PyThreadState_GET(); |
|
file = _PySys_GetAttr(tstate, &_Py_ID(stdout)); |
So if sys.stdout changes concurrently with the print(), the program may crash because file will point to a deallocated Python object.
This affects the GIL-enabled build as well. See this reproducer: https://gist.github.com/colesbury/c48f50e95d5d68e24814a56e2664e587
Suggested fix
Introduce a _PySys_GetAttrRef that returns a new reference instead of a borrowed reference. Use that instead.
We should audit all the uses of _PySys_GetAttr and PySys_GetObject. I expect most of them will need to be replaced with functions that return new references, but it doesn't all have to be in a single PR.
CPython versions tested on:
CPython main branch
Operating systems tested on:
Linux
Output from running 'python -VV' on the command line:
Python 3.14.0a5+ experimental free-threading build (heads/main:359c7dde3bb, Feb 15 2025, 17:54:11) [GCC 11.4.0]
Linked PRs
Activitychanged the title [-]Segfault in a freethreaded JIT build from using `contextlib.redirect_stdout` in threads[/-] [+]Segfault in a freethreaded build from using `contextlib.redirect_stdout` in threads[/+] on Feb 15, 2025picnixz commented on Feb 15, 2025 The issue could be with StringIO() or sys.stdout/sys.stderr or with context managers in general. I don't know where to start to investigate this =/ tomasr8 commented on Feb 15, 2025 Here's the backtrace:
#0 PyObject_GetAttr (v=v@entry=0x2002c0f00d0, name=0x555555b83358 <_PyRuntime+110680>) at Objects/object.c:1288
#1 0x0000555555688162 in PyFile_WriteObject (v=v@entry=0x555555b836e0 <_PyRuntime+111584>, f=f@entry=0x2002c0f00d0, flags=flags@entry=1) at Objects/fileobject.c:113
#2 0x0000555555688279 in PyFile_WriteString (s=s@entry=0x5555558efa49 "\n", f=f@entry=0x2002c0f00d0) at Objects/fileobject.c:149
#3 0x000055555579c917 in builtin_print_impl (module=module@entry=0x2000025c5d0, args=args@entry=0x7fffd4bffb78, args_length=args_length@entry=1, sep=0x0, sep@entry=0x555555b410a0 <_Py_NoneStruct>, end=0x0, end@entry=0x555555b410a0 <_Py_NoneStruct>, file=0x2002c0f00d0, file@entry=0x555555b410a0 <_Py_NoneStruct>, flush=0) at Python/bltinmodule.c:2222
#4 0x000055555579ca97 in builtin_print (module=0x2000025c5d0, args=args@entry=0x7fffd4bffb78, nargs=nargs@entry=1, kwnames=kwnames@entry=0x0) at Python/clinic/bltinmodule.c.h:985
#5 0x00005555556c245b in cfunction_vectorcall_FASTCALL_KEYWORDS (func=0x2000025d670, args=0x7fffd4bffb78, nargsf=<optimized out>, kwnames=0x0) at Objects/methodobject.c:452
#6 0x0000555555667519 in _PyObject_VectorcallTstate (tstate=0x555555cb4900, callable=callable@entry=0x2000025d670, args=args@entry=0x7fffd4bffb78, nargsf=9223372036854775809, kwnames=kwnames@entry=0x0) at ./Include/internal/pycore_call.h:167
#7 0x00005555556675f5 in PyObject_Vectorcall (callable=callable@entry=0x2000025d670, args=args@entry=0x7fffd4bffb78, nargsf=<optimized out>, kwnames=kwnames@entry=0x0) at Objects/call.c:327
#8 0x00005555557abdd3 in _PyEval_EvalFrameDefault (tstate=<optimized out>, frame=0x7ffff7e3d1b0, throwflag=<optimized out>) at Python/generated_cases.c.h:1371
#9 0x00005555557d0ca5 in _PyEval_EvalFrame (tstate=tstate@entry=0x555555cb4900, frame=frame@entry=0x7ffff7e3d020, throwflag=throwflag@entry=0) at ./Include/internal/pycore_ceval.h:116
#10 0x00005555557d0e76 in _PyEval_Vector (tstate=0x555555cb4900, func=0x2000068dc90, locals=locals@entry=0x0, args=0x7fffd4bffd48, argcount=<optimized out>, kwnames=0x0) at Python/ceval.c:1745
#11 0x0000555555667192 in _PyFunction_Vectorcall (func=<optimized out>, stack=<optimized out>, nargsf=<optimized out>, kwnames=<optimized out>) at Objects/call.c:413
#12 0x000055555566a435 in _PyObject_VectorcallTstate (tstate=tstate@entry=0x555555cb4900, callable=callable@entry=0x2000068dc90, args=args@entry=0x7fffd4bffd48, nargsf=nargsf@entry=1, kwnames=kwnames@entry=0x0) at ./Include/internal/pycore_call.h:167
#13 0x000055555566a69a in method_vectorcall (method=<optimized out>, args=0x555555b87c98 <_PyRuntime+129432>, nargsf=0, kwnames=0x0) at Objects/classobject.c:72
#14 0x0000555555668e22 in _PyVectorcall_Call (tstate=tstate@entry=0x555555cb4900, func=0x55555566a4bd <method_vectorcall>, callable=callable@entry=0x200006b8170, tuple=tuple@entry=0x555555b87c70 <_PyRuntime+129392>, kwargs=kwargs@entry=0x0) at Objects/call.c:273
#15 0x0000555555669151 in _PyObject_Call (tstate=0x555555cb4900, callable=0x200006b8170, args=0x555555b87c70 <_PyRuntime+129392>, kwargs=0x0) at Objects/call.c:348
#16 0x000055555566918d in PyObject_Call (callable=<optimized out>, args=<optimized out>, kwargs=<optimized out>) at Objects/call.c:373
#17 0x00005555558cf626 in thread_run (boot_raw=boot_raw@entry=0x555555cb48b0) at ./Modules/_threadmodule.c:354
#18 0x000055555585b7f3 in pythread_wrapper (arg=<optimized out>) at Python/thread_pthread.h:242
#19 0x00007ffff7c9caa4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
#20 0x00007ffff7d29c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78
The immediate cause seems to be related to the printing itself, but I didn't dig into it too much devdanzin commented on Feb 15, 2025
The issue could be with StringIO() or sys.stdout/sys.stderr or with context managers in general.
Substituting StringIO with the following stops crashing, would it point to it being the culprit?
class FakeStringIO:
def write(self, value):
pass
def getvalue(self):
return "hello1\nhello2\n"
def flush(self):
passpicnixz commented on Feb 15, 2025 I suspect it has something to do with the PyFile_* interface. tomasr8 commented on Feb 15, 2025 Might be something to do with redirect_stdout, I'm getting a segfault even with this simplified reproducer:
from contextlib import redirect_stdout
from io import StringIO
from threading import Thread
import time
def test_redirect():
text = StringIO()
with redirect_stdout(text):
time.sleep(0.1)
print(text.getvalue())
for x in range(100):
Thread(target=test_redirect, args=()).start()edit:
Both crashes seem to be caused by Py_TYPE returning NULL. Here's the backtrace for this repro:
#0 _Py_Dealloc (op=op@entry=0x2009c1000d0) at Objects/object.c:2994
#1 0x00005555556c8407 in _Py_DecRefSharedDebug (o=o@entry=0x2009c1000d0, filename=filename@entry=0x5555558e4237 "./Include/refcount.h", lineno=lineno@entry=502) at Objects/object.c:418
#2 0x00005555556c2569 in Py_DECREF (filename=filename@entry=0x5555558e4237 "./Include/refcount.h", lineno=lineno@entry=502, op=0x2009c1000d0) at ./Include/refcount.h:347
#3 0x00005555556c28bb in Py_XDECREF (op=<optimized out>) at ./Include/refcount.h:502
#4 0x00005555556c2ff1 in meth_dealloc (self=0x2009e0e0160) at Objects/methodobject.c:172
#5 0x00005555556c82fe in _Py_Dealloc (op=0x2009e0e0160) at Objects/object.c:3014
#6 0x00005555556c83d7 in _Py_MergeZeroLocalRefcount (op=op@entry=0x2009e0e0160) at Objects/object.c:436
#7 0x000055555568767f in Py_DECREF (filename=filename@entry=0x5555558eb2c2 "Objects/fileobject.c", lineno=lineno@entry=127, op=op@entry=0x2009e0e0160) at ./Include/refcount.h:343
#8 0x00005555556881c1 in PyFile_WriteObject (v=v@entry=0x555555b836e0 <_PyRuntime+111584>, f=f@entry=0x2009c1000d0, flags=flags@entry=1) at Objects/fileobject.c:127
#9 0x0000555555688279 in PyFile_WriteString (s=s@entry=0x5555558efa49 "\n", f=f@entry=0x2009c1000d0) at Objects/fileobject.c:149
#10 0x000055555579c917 in builtin_print_impl (module=module@entry=0x2000025c5d0, args=args@entry=0x7fff5f3ffb78, args_length=args_length@entry=1, sep=0x0, sep@entry=0x555555b410a0 <_Py_NoneStruct>, end=0x0, end@entry=0x555555b410a0 <_Py_NoneStruct>, file=0x2009c1000d0, file@entry=0x555555b410a0 <_Py_NoneStruct>, flush=0) at Python/bltinmodule.c:2222
#11 0x000055555579ca97 in builtin_print (module=0x2000025c5d0, args=args@entry=0x7fff5f3ffb78, nargs=nargs@entry=1, kwnames=kwnames@entry=0x0) at Python/clinic/bltinmodule.c.h:985
#12 0x00005555556c245b in cfunction_vectorcall_FASTCALL_KEYWORDS (func=0x2000025d670, args=0x7fff5f3ffb78, nargsf=<optimized out>, kwnames=0x0) at Objects/methodobject.c:452
#13 0x0000555555667519 in _PyObject_VectorcallTstate (tstate=0x555555daaa30, callable=callable@entry=0x2000025d670, args=args@entry=0x7fff5f3ffb78, nargsf=9223372036854775809, kwnames=kwnames@entry=0x0) at ./Include/internal/pycore_call.h:167
#14 0x00005555556675f5 in PyObject_Vectorcall (callable=callable@entry=0x2000025d670, args=args@entry=0x7fff5f3ffb78, nargsf=<optimized out>, kwnames=kwnames@entry=0x0) at Objects/call.c:327
#15 0x00005555557abdd3 in _PyEval_EvalFrameDefault (tstate=<optimized out>, frame=0x7ffff75641b0, throwflag=<optimized out>) at Python/generated_cases.c.h:1371
#16 0x00005555557d0ca5 in _PyEval_EvalFrame (tstate=tstate@entry=0x555555daaa30, frame=frame@entry=0x7ffff7564020, throwflag=throwflag@entry=0) at ./Include/internal/pycore_ceval.h:116
#17 0x00005555557d0e76 in _PyEval_Vector (tstate=0x555555daaa30, func=0x2000068dc90, locals=locals@entry=0x0, args=0x7fff5f3ffd48, argcount=<optimized out>, kwnames=0x0) at Python/ceval.c:1745
#18 0x0000555555667192 in _PyFunction_Vectorcall (func=<optimized out>, stack=<optimized out>, nargsf=<optimized out>, kwnames=<optimized out>) at Objects/call.c:413
#19 0x000055555566a435 in _PyObject_VectorcallTstate (tstate=tstate@entry=0x555555daaa30, callable=callable@entry=0x2000068dc90, args=args@entry=0x7fff5f3ffd48, nargsf=nargsf@entry=1, kwnames=kwnames@entry=0x0) at ./Include/internal/pycore_call.h:167
#20 0x000055555566a69a in method_vectorcall (method=<optimized out>, args=0x555555b87c98 <_PyRuntime+129432>, nargsf=0, kwnames=0x0) at Objects/classobject.c:72
#21 0x0000555555668e22 in _PyVectorcall_Call (tstate=tstate@entry=0x555555daaa30, func=0x55555566a4bd <method_vectorcall>, callable=callable@entry=0x200006babd0, tuple=tuple@entry=0x555555b87c70 <_PyRuntime+129392>, kwargs=kwargs@entry=0x0) at Objects/call.c:273
#22 0x0000555555669151 in _PyObject_Call (tstate=0x555555daaa30, callable=0x200006babd0, args=0x555555b87c70 <_PyRuntime+129392>, kwargs=0x0) at Objects/call.c:348
#23 0x000055555566918d in PyObject_Call (callable=<optimized out>, args=<optimized out>, kwargs=<optimized out>) at Objects/call.c:373
#24 0x00005555558cf626 in thread_run (boot_raw=boot_raw@entry=0x555555daa9e0) at ./Modules/_threadmodule.c:354
#25 0x000055555585b7f3 in pythread_wrapper (arg=<optimized out>) at Python/thread_pthread.h:242
#26 0x00007ffff7c9caa4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
#27 0x00007ffff7d29c3c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78
picnixz commented on Feb 15, 2025
Might be something to do with redirect_stdout, I'm getting a segfault even with this simplified reproducer:
Have you tried removing the usage to StringIO()? because it appears that we crash in Py_DECREF of a file object. sergey-miryanov commented on Feb 16, 2025 Yes, it is caused by redirect_stdout.
- At some point, print from T1 and T2 uses StringIO, which is owned by T1.
PyObject_GetAttr (
|
writer = PyObject_GetAttr(f, &_Py_ID(write)); |
) increments shared ref_cnt (by T2) and local ref_cnt (by T1).Py_DECREF (
) from T2 decrements shared ref_cnt and got 0 and do _Py_DeallocPy_DECREF from T1 decrements local ref_cnt, got 0 and go to _Py_MergeZeroLocalRefcount, see that shared ref_cnt is 0 and go to fast path and do _Py_Dealloc.- This is double free and so segfault.
The easiest way to fix this is probably to protect PyFile_WriteObject with a critical section. However, this might slightly affect the performance of single-threaded apps.
The best solution might be to update the documentation and point out this potential issue with redirect_*. devdanzin commented on Feb 16, 2025
Have you tried removing the usage to StringIO()?
Using open("/dev/null", "w") instead of StringIO still segfaults.
Yes, it is caused by redirect_stdout.
But any program that does redirect_stdout does will also segfault:
from threading import Thread
import sys
import time
def test_redirect():
text = open("/dev/null", "w")
old_stdout = sys.stdout
sys.stdout = text
print("hello1")
time.sleep(0.3)
print("hello2")
sys.stdout = old_stdout
for x in range(200):
Thread(target=test_redirect, args=()).start()
The easiest way to fix this is probably to protect PyFile_WriteObject with a critical section. However, this might slightly affect the performance of single-threaded apps.
Would making the presence of the critical section dependent on whether the build is freethreaded (and/or the GIL is disabled) avoid the performance impact for gilfull builds? Or would it be a bad idea to have this conditional difference in behavior?
The best solution might be to update the documentation and point out this potential issue with redirect_*.
ISTM that fixing the segfault is necessary, even if a note is added to docs, because users may hit the segfault without using redirect_*. sergey-miryanov commented on Feb 17, 2025
Oh, I wouldn't know how. Feel free to take it forward.
Thanks, I will try. sergey-miryanov commented on Feb 23, 2025 I've looked at how _PySys_GetAttr is used. I can reproduce the segfault error in some places where it's used. I've written tests for these places.
@colesbury @ZeroIntensity, @serhiy-storchaka please take a look.
Here's a copy from my PR:
|
Repro |
Tests |
Raised exception |
_pickle.c/whichmodule |
No |
No |
Don't keep |
_threadmodule.c/thread_excepthook |
No |
No |
Keep |
faulthandler.c/faulthandler_get_fileno |
Yes |
Yes |
Don't keep |
bltinmodule.c/builtin_print_impl |
Yes |
Yes |
Don't keep |
bltinmodule.c/builtin_input_impl |
Yes |
Yes |
Don't keep |
errors.c/write_unraisable_exc |
No |
No |
Keep |
errors.c/format_unraisable_v |
Yes |
Yes |
Keep |
_warnings.c/show_warning |
Yes |
Yes |
Don't keep |
intrinsics.c/print_expr |
No |
No |
Don't keep |
pylifecycle.c/flush_std_files |
Yes/No |
Yes/No |
Don't keep |
pythonrun.c/_PyRun_InteractiveLoopObject |
No |
No |
Don't keep |
pythonrun.c/pyrun_one_parse_ast |
No |
No |
Don't keep |
pythonrun.c/_Py_HandleSystemExitAndKeyboardInterrupt |
No |
No |
Don't keep |
pythonrun.c/_PyErr_PrintEx |
Yes |
Yes |
Don't keep |
pythonrun.c/PyErr_Display |
No |
No |
Don't keep |
pythonrun.c/flush_io_stream |
No |
No |
Don't keep |
sysmodule.c/sys_displayhook |
Maybe |
No |
Don't keep |
sysmodule.c/get_warnoptions |
No |
No |
Don't keep |
sysmodule.c/PySys_ResetWarnOptions |
No |
No |
Don't keep |
sysmodule.c/PySys_HasWarnOptions |
No |
No |
Don't keep |
sysmodule.c/_PySys_AddXOptionWithError |
No |
No |
Don't keep |
sysmodule.c/PySys_SetArgvEx |
No |
No |
Don't keep |
sysmodule.c/sys_write |
No |
No |
Don't keep |
sysmodule.c/sys_format |
No |
No |
Don't keep |
traceback.c/_Py_FindSourceFile |
No |
No |
Don't keep |
|
|
|
|
- I can get a "segfault" error when I use
sys_displayhook, but not where it's used.
- For
sys_write, sys_format - I have checked all the places where they called, and most of the locations are safe. However, a few places use %s specifier, in such places it is very tricky to get segfault.
get_warnoptions, PySys_ResetWarnOptions, _PySys_AddXOptionWithError - are deprecated, but it is a very tricky to get segfault too.flush_io_stream, PyErr_Display, pyrun_one_parse_ast, print_expr, write_unraisable_exc, thread_excepthook - very tight - They use a borrowed reference right after getting. It might be possible to reproduce it under heavy contention, but I wasn't able to do so._PyRun_InteractiveLoopObject only checks presence of ps1 and ps2.flush_std_files used from _Py_Finalize and from fatal_error. For _Py_Finalize I can repro, for fatal_error - no.whichmodule, _Py_FindSourceFile iterate borrowed reference, but I wasn't able to reproduce segfault.- Keep or not before raised exception - in the most places
_PySys_GetAttr called without an exception set.
Also, can you point me out what to do next? I can replace _PySys_GetAttr with _PySys_GetAttrRef, but in the most places it is interleave with @serhiy-storchaka PRs. I'm not sure what the correct way to deal with this situation is. Reacted by devdanzin and Tomas R. serhiy-storchaka commented on Feb 25, 2025 #130503 is an adaptation of #111035 or #129736 that does not introduce new public API and does not change the current behavior (except fixing crashes, mainly). It will make minimal difference with #111035 or #129736, whatever will be accepted for future Python version.
I added also tests for print(), input() and sys.displayhook() (they are relatively simple). Reproducers for other crashes are harder, so I do not think that this is worth hassle.
Thank you for your tests, @sergey-miryanov, but sorry, I have not used them. They are high quality, but too large and expensive. It is not worth to keep them forever after fixing this issue. sergey-miryanov commented on Feb 25, 2025 @serhiy-storchaka I simplified it a bit yesterday, not sure if you saw the latest changes. Maybe it will be useful, but it is all up to you. Anyway, it was very interesting. vstinner commented on Feb 27, 2025 I cannot reproduce the crash using #130163 (comment) reproducer. Can we close the issue? serhiy-storchaka commented on Feb 27, 2025 It has already been fixed.
MetadataMetadataDevelopmentNo branches or pull requestsIssue actions
|