Repository navigation
Calling os.strerror() in parallel is not thread safe on FreeBSD #158893
Description
Activity
On FreeBSD 16, the stress test triggers a SIGSEGV: mbstowcs_l() calls a NULL pointer.
gdb traceback:
Program terminated with signal SIGSEGV, Segmentation fault.
Address not mapped to object.
#0 0x0000000000000000 in ?? ()
[Current thread is 1 (LWP 109042)]
(gdb) where
#0 0x0000000000000000 in ?? ()
#1 0x0000000824b01dfe in mbstowcs_l (locale=<optimized out>, pwcs=<optimized out>, s=<optimized out>, n=<optimized out>)
at /home/pkgbuild/worktrees/main/lib/libc/locale/mbstowcs.c:49
#2 mbstowcs (
pwcs=0x8f4040190 L"\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xfdfdfdfd\xfdfdfdfd\xfdfdfdfd\xc455c73f\004\xc451c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc44fc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc44dc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc44bc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc449c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc447c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc445c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc443c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc441c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc43fc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc43dc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc43bc73f\x1b4a304a\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd"..., s=<optimized out>, n=7) at /home/pkgbuild/worktrees/main/lib/libc/locale/mbstowcs.c:54
#3 0x000000000087c685 in _Py_mbstowcs (
dest=0x8f4040190 L"\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xcdcdcdcd\xfdfdfdfd\xfdfdfdfd\xfdfdfdfd\xc455c73f\004\xc451c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc44fc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc44dc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc44bc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc449c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc447c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc445c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc443c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc441c73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc43fc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc43dc73f\x1b4a304a", '\xdddddddd' <repeats 14 times>, "\xc43bc73f\x1b4a304a\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd\xdddddddd"..., src=0x82aa52fe0 "b255:\377", n=7) at Python/fileutils.c:180
#4 0x000000000087a001 in decode_current_locale (arg=0x82aa52fe0 "b255:\377", wstr=0x90de25ce8, wlen=0x90de25ce0,
errors=_Py_ERROR_SURROGATEESCAPE) at Python/fileutils.c:539
#5 0x0000000000879a45 in decode_locale_impl (arg=0x82aa52fe0 "b255:\377", wstr=0x90de25ce8, wlen=0x90de25ce0,
current_locale=1, errors=_Py_ERROR_SURROGATEESCAPE) at Python/fileutils.c:629
#6 0x00000000008798ff in _Py_DecodeLocale (arg=0x82aa52fe0 "b255:\377", wstr=0x90de25ce8, wlen=0x90de25ce0,
current_locale=1, errors=_Py_ERROR_SURROGATEESCAPE) at Python/fileutils.c:703
#7 0x00000000006a2c60 in unicode_decode_locale (str=0x82aa52fe0 "b255:\377", len=6, errors=_Py_ERROR_SURROGATEESCAPE,
current_locale=1) at Objects/unicodeobject.c:3988
#8 0x00000000006a2dfe in PyUnicode_DecodeLocale (str=0x82aa52fe0 "b255:\377", errors=0x82a70f7e8 "surrogateescape")
at Objects/unicodeobject.c:4031
#9 0x000000086847eb9a in unicode_decodelocale (self=<module at remote 0x82a339930>,
args=(b'b255:\xff', 'surrogateescape')) at ./Modules/_testlimitedcapi/unicode.c:1032
Note: I modified the buildbot configuration to log C assertion failures in warnings: commit python/buildmaster-config@61d0c77.
AMD64 FreeBSD16 3.x: https://buildbot.python.org/#/builders/1857/builds/877
Assertion failed: (count == argsize) in test_concurrent_initialization_subinterpreter() of test_datetime:
======================================================================
FAIL: test_concurrent_initialization_subinterpreter (test.datetimetester.ExtensionModuleTests_Fast.test_concurrent_initialization_subinterpreter)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/test/datetimetester.py", line 7585, in test_concurrent_initialization_subinterpreter
rc, out, err = script_helper.assert_python_ok("-c", script)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^
File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/test/support/script_helper.py", line 182, in assert_python_ok
return _assert_python(True, *args, **env_vars)
File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/test/support/script_helper.py", line 167, in _assert_python
res.fail(cmd_line)
~~~~~~~~^^^^^^^^^^
File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/test/support/script_helper.py", line 80, in fail
raise AssertionError(f"Process return code is {exitcode}\n"
...<10 lines>...
f"---")
AssertionError: Process return code is -6 (SIGABRT)
command line: ['/home/buildbot/buildarea/3.x.opsec-fbsd16/build/python', '-X', 'faulthandler', '-I', '-c', "if True:\n from concurrent.futures import InterpreterPoolExecutor\n\n def func():\n import _datetime\n print('a', end='')\n\n with InterpreterPoolExecutor() as executor:\n for _ in range(8):\n executor.submit(func)\n "]
stdout:
---
---
stderr:
---
Assertion failed: (count == argsize), function decode_current_locale, file Python/fileutils.c, line 542.
Fatal Python error: Aborted
Current thread 0x00001cf53c442810 [InterpreterPoolExec] (most recent call first):
File "<frozen importlib._bootstrap_external>", line 155 in _path_stat
File "<frozen importlib._bootstrap_external>", line 161 in _path_is_mode_type
File "<frozen importlib._bootstrap_external>", line 169 in _path_isfile
File "<frozen importlib._bootstrap_external>", line 1386 in find_spec
File "<frozen importlib._bootstrap_external>", line 1251 in _get_spec
File "<frozen importlib._bootstrap_external>", line 1277 in find_spec
File "<frozen importlib._bootstrap>", line 1216 in _find_spec
File "<frozen importlib._bootstrap>", line 1292 in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 1344 in _find_and_load
Current thread's C stack trace (most recent call first):
<cannot get C stack on this system>
---
----------------------------------------------------------------------
Ran 1166 tests in 6.680s
FAILED (failures=1, skipped=33)
Warning -- files was modified by test_datetime
Warning -- Before: []
Warning -- After: ['python.core']
test test_datetime failed
AMD64 FreeBSD16 3.x: https://buildbot.python.org/#/builders/1857/builds/878
Assertion failed: (count == argsize) in test_endian_table_init_subinterpreters() of test_struct
0:06:30 load avg: 4.67 mem: 3.9 GiB [211/558/1] test_struct worker non-zero exit code (Exit code -6 (SIGABRT))
test_1530559 (test.test_struct.StructTest.test_1530559) ... ok
test_705836 (test.test_struct.StructTest.test_705836) ... ok
test_Struct_reinitialization (test.test_struct.StructTest.test_Struct_reinitialization) ... ok
...
test_count_overflow (test.test_struct.StructTest.test_count_overflow) ... ok
test_custom_struct_init (test.test_struct.StructTest.test_custom_struct_init) ... ok
test_custom_struct_new (test.test_struct.StructTest.test_custom_struct_new) ... ok
test_custom_struct_new_and_init (test.test_struct.StructTest.test_custom_struct_new_and_init) ... ok
test_endian_table_init_subinterpreters (test.test_struct.StructTest.test_endian_table_init_subinterpreters) ...
Assertion failed: (count == argsize), function decode_current_locale, file Python/fileutils.c, line 542.
Fatal Python error: Aborted
Current thread 0x0000282aff446810 [InterpreterPoolExec] (most recent call first):
Current thread's C stack trace (most recent call first):
<cannot get C stack on this system>
Extension modules: _testcapi, _testinternalcapi (total: 2)
I used gdb to check when decode_current_locale() is called by a sub-interpreter.
vstinner@freebsd16$ cat sub.py
import _testcapi
import os
code = 'import os; os.write(1, b".")'
print("HERE"); os.uname()
_testcapi.run_in_subinterp(code)
vstinner@freebsd16$ gdb -args ./python sub.py
(gdb) b os_uname
(gdb) run
Breakpoint 1, os_uname (module=<module at remote 0x804333df0>, _unused_ignored=0x0) at ./Modules/clinic/posixmodule.c.h:3609
3609 return os_uname_impl(module);
(gdb) b decode_current_locale
Breakpoint 2 at 0x879f0a: file Python/fileutils.c, line 510.
First breakpoint is <built-in function readlines> in <frozen getpath>:
- Py_fopen() calls PyErr_SetFromErrnoWithFilenameObject(PyExc_OSError, path)
- PyErr_SetFromErrnoWithFilenameObject(PyExc_OSError, path) calls
PyUnicode_DecodeLocale(s, "surrogateescape")to decodestrerror(i) PyUnicode_DecodeLocale()calls `decode_current_locale()
(gdb) c
Continuing.
Breakpoint 2, decode_current_locale (arg=0x800d62ca0 "No such file or directory", wstr=0x7fffffff2e48, wlen=0x7fffffff2e40, errors=_Py_ERROR_SURROGATEESCAPE) at Python/fileutils.c:510
510 assert(arg != NULL);
(gdb) py-bt
Traceback (most recent call first):
<built-in function readlines>
File "<frozen getpath>", line 356, in <module>
<built-in method run_in_subinterp of module object at remote 0x8043397f0>
File "/home/vstinner/python/main/sub.py", line 5, in <module>
_testcapi.run_in_subinterp(code)
(gdb) where
#0 decode_current_locale (arg=0x800d62ca0 "No such file or directory", wstr=0x7fffffff2e48, wlen=0x7fffffff2e40, errors=_Py_ERROR_SURROGATEESCAPE) at Python/fileutils.c:510
#1 0x0000000000879a45 in decode_locale_impl (arg=0x800d62ca0 "No such file or directory", wstr=0x7fffffff2e48, wlen=0x7fffffff2e40, current_locale=1, errors=_Py_ERROR_SURROGATEESCAPE)
at Python/fileutils.c:629
#2 0x00000000008798ff in _Py_DecodeLocale (arg=0x800d62ca0 "No such file or directory", wstr=0x7fffffff2e48, wlen=0x7fffffff2e40, current_locale=1, errors=_Py_ERROR_SURROGATEESCAPE)
at Python/fileutils.c:703
#3 0x00000000006a2c60 in unicode_decode_locale (str=0x800d62ca0 "No such file or directory", len=25, errors=_Py_ERROR_SURROGATEESCAPE, current_locale=1) at Objects/unicodeobject.c:3988
#4 0x00000000006a2dfe in PyUnicode_DecodeLocale (str=0x800d62ca0 "No such file or directory", errors=0x2816b0 "surrogateescape") at Objects/unicodeobject.c:4031
#5 0x00000000007b3ca9 in PyErr_SetFromErrnoWithFilenameObjects (exc=<type at remote 0x95af20>, filenameObject='/home/vstinner/python/pyvenv.cfg', filenameObject2=0x0)
at Python/errors.c:846
#6 0x00000000007b3c31 in PyErr_SetFromErrnoWithFilenameObject (exc=<type at remote 0x95af20>, filenameObject='/home/vstinner/python/pyvenv.cfg') at Python/errors.c:824
#7 0x000000000087ad9f in Py_fopen (path='/home/vstinner/python/pyvenv.cfg', mode=0x260fd5 "rb") at Python/fileutils.c:1971
#8 0x000000000094ec96 in getpath_readlines_impl (module=0x0, pathobj='/home/vstinner/python/pyvenv.cfg') at ./Modules/getpath.c:390
#9 0x000000000094e2c1 in getpath_readlines (module=0x0, arg='/home/vstinner/python/pyvenv.cfg') at ./Modules/clinic/getpath.c.h:346
#10 0x00000000006031c6 in cfunction_vectorcall_O (func=<built-in function readlines>, args=0x7fffffff3208, nargsf=9223372036854775809, kwnames=0x0) at Objects/methodobject.c:535
Later, _path_stat() of importlib._bootstrap_external calls os.stat(). The syscall fails, and again, PyErr_SetFromErrnoWithFilenameObject() calls PyUnicode_DecodeLocale() to decode strerror().
Breakpoint 2, decode_current_locale (arg=0x800d62ca0 "No such file or directory", wstr=0x7ffffffeccb8, wlen=0x7ffffffeccb0, errors=_Py_ERROR_SURROGATEESCAPE) at Python/fileutils.c:510
510 assert(arg != NULL);
(gdb) py-bt
Traceback (most recent call first):
<built-in method stat of module object at remote 0x8062f3df0>
File "<frozen importlib._bootstrap_external>", line 155, in _path_stat
File "<frozen zipimport>", line 73, in __init__
File "<frozen importlib._bootstrap_external>", line 1212, in _path_hooks
File "<frozen importlib._bootstrap_external>", line 1236, in _path_importer_cache
File "<frozen importlib._bootstrap_external>", line 1249, in _get_spec
File "<frozen importlib._bootstrap_external>", line 1277, in find_spec
File "<frozen importlib._bootstrap>", line 1216, in _find_spec
File "<frozen importlib._bootstrap>", line 1292, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 1344, in _find_and_load
<built-in method __import__ of module object at remote 0x8062f03d0>
<built-in method run_in_subinterp of module object at remote 0x8043397f0>
File "/home/vstinner/python/main/sub.py", line 5, in <module>
_testcapi.run_in_subinterp(code)
(gdb) where
#0 decode_current_locale (arg=0x800d62ca0 "No such file or directory", wstr=0x7ffffffeccb8, wlen=0x7ffffffeccb0, errors=_Py_ERROR_SURROGATEESCAPE) at Python/fileutils.c:510
#1 0x0000000000879a45 in decode_locale_impl (arg=0x800d62ca0 "No such file or directory", wstr=0x7ffffffeccb8, wlen=0x7ffffffeccb0, current_locale=1, errors=_Py_ERROR_SURROGATEESCAPE)
at Python/fileutils.c:629
#2 0x00000000008798ff in _Py_DecodeLocale (arg=0x800d62ca0 "No such file or directory", wstr=0x7ffffffeccb8, wlen=0x7ffffffeccb0, current_locale=1, errors=_Py_ERROR_SURROGATEESCAPE)
at Python/fileutils.c:703
#3 0x00000000006a2c60 in unicode_decode_locale (str=0x800d62ca0 "No such file or directory", len=25, errors=_Py_ERROR_SURROGATEESCAPE, current_locale=1) at Objects/unicodeobject.c:3988
#4 0x00000000006a2dfe in PyUnicode_DecodeLocale (str=0x800d62ca0 "No such file or directory", errors=0x2816b0 "surrogateescape") at Objects/unicodeobject.c:4031
#5 0x00000000007b3ca9 in PyErr_SetFromErrnoWithFilenameObjects (exc=<type at remote 0x95af20>, filenameObject='/usr/local/lib/python316t.zip', filenameObject2=0x0)
at Python/errors.c:846
#6 0x00000000007b3c31 in PyErr_SetFromErrnoWithFilenameObject (exc=<type at remote 0x95af20>, filenameObject='/usr/local/lib/python316t.zip') at Python/errors.c:824
#7 0x00000000008a0dfd in posix_path_object_error (path='/usr/local/lib/python316t.zip') at ./Modules/posixmodule.c:1909
#8 0x00000000008a0dd5 in path_object_error (path='/usr/local/lib/python316t.zip') at ./Modules/posixmodule.c:1919
#9 0x00000000008a08d9 in path_error (path=0x7ffffffecfb8) at ./Modules/posixmodule.c:1937
#10 0x00000000008a06e0 in posix_do_stat (module=<module at remote 0x8062f3df0>, function_name=0x28e886 "stat", path=0x7ffffffecfb8, dir_fd=-100, follow_symlinks=1)
at ./Modules/posixmodule.c:2952
#11 0x00000000008a0134 in os_stat_impl (module=<module at remote 0x8062f3df0>, path=0x7ffffffecfb8, dir_fd=-100, follow_symlinks=1) at ./Modules/posixmodule.c:3300
#12 0x00000000008957e9 in os_stat (module=<module at remote 0x8062f3df0>, args=0x7ffffffed1d8, nargs=1, kwnames=0x0) at ./Modules/clinic/posixmodule.c.h:107
Aha! I wrote a reliable reproducer for FreeBSD 16: call os.strerror() on a loop in many threads.
import _testlimitedcapi
import threading
import time
import os
import locale
import sys
VERBOSE = True
VERBOSE = False
NTHREAD = 25; LOOPS = 25
LOCALE = 'C.UTF-8'
unicode_decodelocale = _testlimitedcapi.unicode_decodelocale
expected = {i: os.strerror(i) for i in range(1, 96+1)}
def stress():
for i in range(1, 96+1):
res = os.strerror(i)
if res != expected[i]:
print(f"ERROR! os.strerror({i}) returned {res!r}, expected {expected[i]!r}")
sys.exit(1)
def worker(i):
sched_yield = os.sched_yield
for loop in range(LOOPS):
if VERBOSE:
os.write(1, f"worker {i} loop {loop}\n".encode())
stress()
sched_yield()
#time.sleep(1e-3)
print(f"Set locale to {LOCALE}")
locale.setlocale(locale.LC_ALL, LOCALE)
t1 = time.perf_counter()
event = threading.Event()
threads = [threading.Thread(target=worker, args=(i,), name=f'worker{i}')
for i in range(NTHREAD)]
for thread in threads:
thread.start()
for thread in threads:
thread.join()
event.set()
dt = time.perf_counter() - t1
print(f"{dt:.1f} seconds")Example of output:
Set locale to C.UTF-8
ERROR! os.strerror(1) returned 'Connection reset by peer', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'RPC prog. not avail', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'RPC version wrong', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Protocol wrong type for ', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Resource temporarily una', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Attribute not found', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'File too large', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Connection refused', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Operation now in progres', expected 'Operation not permitted'
ERROR! os.strerror(1) returned "Can't send after socket ", expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Device busy', expected 'Operation not permitted'
ERROR! os.strerror(54) returned 'Operation not permitted', expected 'Connection reset by peer'
ERROR! os.strerror(1) returned 'Inappropriate ioctl for ', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Function not implemented', expected 'Operation not permitted'
ERROR! os.strerror(34) returned 'Result too larger', expected 'Result too large'
ERROR! os.strerror(1) returned 'Destination address requ', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Too many processes', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'No such process', expected 'Operation not permitted'
ERROR! os.strerror(3) returned 'Socket is alread', expected 'No such process'
ERROR! os.strerror(79) returned 'Operation not permitted', expected 'Inappropriate file type or format'
ERROR! os.strerror(47) returned 'Operation not permitted', expected 'Address family not supported by protocol family'
ERROR! os.strerror(1) returned 'Destination address requ', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Illegal byte sequence', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Protocol family not supp', expected 'Operation not permitted'
0.0 seconds
The reproducer runs just fine on Linux and FreeBSD 15. So the problem is that the C strerror() function is no longer thread safe on FreeBSD 16.
The assertion failure in decode_current_locale() is just a side effect. mbstowcs() is called twice on the same pointer, the second call returns a different length. That's normal if the string pointed by the pointer changes meanwhile!
I updated my os.strerror() stress test.
Problem: now, for an unknown reason, I can no longer reproduce the bug on FreeBSD 16!?
import locale
import os
import sys
import threading
import time
VERBOSE = True
VERBOSE = False
#NTHREAD = 25; LOOPS = 100
NTHREAD = 5; LOOPS = 100
LOCALE = None
#LOCALE = 'C.UTF-8'
expected = {i: os.strerror(i) for i in range(1, 96+1)}
def stress():
ncall = 0
for i in range(1, 96+1):
try:
res = os.strerror(i)
except ValueError as exc:
print(f"ERROR! os.strerror({i}) failed with {exc}")
sys.exit(1)
if res != expected[i]:
print(f"ERROR! os.strerror({i}) returned {res!r}, expected {expected[i]!r}")
sys.exit(1)
ncall += 1
return ncall
def worker(i, calls, stop_event):
sched_yield = os.sched_yield
while not stop_event.is_set():
if VERBOSE:
os.write(1, f"worker {i} loop {loop}\n".encode())
calls[i] += stress()
sched_yield()
#time.sleep(1e-3)
if LOCALE:
print(f"Set locale to {LOCALE}")
locale.setlocale(locale.LC_ALL, LOCALE)
else:
loc = locale.setlocale(locale.LC_CTYPE, None)
print(f"Test LC_CTYPE locale {loc}")
calls = [0] * NTHREAD
print(f"Run {NTHREAD} threads running {LOOPS} loops")
t1 = time.perf_counter()
stop_event = threading.Event()
threads = [threading.Thread(target=worker, args=(i, calls, stop_event), name=f'worker{i}')
for i in range(NTHREAD)]
print(f"Start {NTHREAD} threads.....", flush=True)
for thread in threads:
thread.start()
print("Run threads for 5 seconds......", flush=True)
time.sleep(5)
stop_event.set()
for thread in threads:
thread.join()
dt = time.perf_counter() - t1
total = sum(calls)
print(f"os.strerror() called {total:,} times in {dt:.1f} seconds")
for i, ncall in enumerate(calls):
print(f"- Thread {i}: {ncall:,} calls")Aha, I wrote a script which always reproduces the issue on FreeBSD 15 and FreeBSD 16, but not on Linux.
The script calls os.strerror() in a loop in 5 sub-interpreters and each sub-interpreter has its own GIL.
os.strerror() calls strerror() which is not thread safe, but it works if all threads are guarded by the unique global GIL. With this script, since each interpreter has its own GIL, calling strerror() returns the same pointer but changes the string pointed by the pointer!
import locale
import os
import _interpreters
import sys
import threading
import time
import _testcapi
NTHREAD = 5
code = """
import os
LOOPS = 5_000
ERRORS = tuple(range(1, 96 + 1))
sched_yield = os.sched_yield
expected = {i: os.strerror(i) for i in ERRORS}
def stress():
ncall = 0
for errno in ERRORS:
try:
res = os.strerror(errno)
except ValueError as exc:
print(f"ERROR! os.strerror({errno}) failed with {exc}")
sys.exit(1)
if res != expected[errno]:
print(f"ERROR! os.strerror({errno}) returned {res!r}, expected {expected[errno]!r}")
sys.exit(1)
ncall += 1
return ncall
def worker():
ncall = 0
for _ in range(LOOPS):
ncall += stress()
sched_yield()
return ncall
ncall = worker()
print("OK", ncall, "calls")
"""
def run_code(code):
interp_id = _interpreters.create(reqrefs=True)
excinfo = _interpreters.exec(interp_id, code, restrict=True)
if excinfo is not None:
raise Exception(repr(excinfo))
_interpreters.destroy(interp_id, restrict=True)
loc = locale.setlocale(locale.LC_CTYPE, None)
print(f"Test LC_CTYPE locale {loc}")
print(f"Run {NTHREAD} threads")
t1 = time.perf_counter()
threads = [threading.Thread(target=run_code, args=(code,), name=f'worker{i}')
for i in range(NTHREAD)]
print(f"Start {NTHREAD} threads.....", flush=True)
for thread in threads:
thread.start()
for thread in threads:
thread.join()
dt = time.perf_counter() - t1
print(f"Ran {NTHREAD} threads in {dt:.1f} seconds")Ok, I can also reproduce the issue using my first reproducer #158893 (comment) on a Free Threaded build.
Debug patch to have a more reliable check to detect if decode_current_locale() input string is mutated during the call.
Details
diff --git a/Python/fileutils.c b/Python/fileutils.c
index 8ed88047b35..b4b19659c91 100644
--- a/Python/fileutils.c
+++ b/Python/fileutils.c
@@ -516,6 +516,13 @@ decode_current_locale(const char* arg, wchar_t **wstr, size_t *wlen,
return _Py_CODEC_UNSUPPORTED_ERROR_HANDLER;
}
+size_t duplen = strlen(arg);
+char *dup = malloc(duplen + 1);
+if (dup == NULL) {
+ return -1;
+}
+memcpy(dup, arg, duplen + 1);
+
#ifdef HAVE_BROKEN_MBSTOWCS
/* Some platforms have a broken implementation of
* mbstowcs which does not count the characters that
@@ -535,9 +542,26 @@ decode_current_locale(const char* arg, wchar_t **wstr, size_t *wlen,
return _Py_CODEC_MEMORY_ERROR;
}
+sched_yield();
+
// +1 to write also the trailing NUL character
size_t count = _Py_mbstowcs(res, arg, argsize + 1);
if (count != DECODE_ERROR) {
+
+ int fatal = 0;
+ if (memcmp(dup, arg, duplen + 1) != 0) {
+ printf("BUG! decode_current_locale() arg mutated! \"%s\" (%zu) != \"%s\" (%zu)\n", dup, strlen(dup), arg, strlen(arg));
+ fatal = 1;
+ }
+ if (count != argsize) {
+ printf("BUG! count %zd != argsize %zd\n", count, argsize);
+ fatal = 1;
+ }
+ if (fatal) {
+ abort();
+ }
+ free(dup);
+
// Success
assert(count == argsize);
*wstr = res;
@@ -569,6 +593,13 @@ decode_current_locale(const char* arg, wchar_t **wstr, size_t *wlen,
mbstate_t mbs;
memset(&mbs, 0, sizeof mbs);
while (argsize) {
+sched_yield();
+
+ if (memcmp(dup, arg, duplen + 1) != 0) {
+ printf("BUG! decode_current_locale() arg mutated! \"%s\" (%zu) != \"%s\" (%zu)\n", dup, strlen(dup), arg, strlen(arg));
+ abort();
+ }
+
size_t converted = _Py_mbrtowc(out, (char*)in, argsize, &mbs);
if (converted == 0) {
/* Reached end of string; null char stored. */
@@ -596,6 +627,7 @@ decode_current_locale(const char* arg, wchar_t **wstr, size_t *wlen,
argsize -= converted;
out++;
}
+ free(dup);
if (wlen != NULL) {
*wlen = out - res;
assert(res[*wlen] == 0);On Python 3.15 with Free Threading, calling os.strerror() in parallel can return the wrong error message or truncate the error message. Example of output:
vstinner@freebsd$ ./python ../main/repro.py
Set locale to C.UTF-8
ERROR! os.strerror(1) returned 'Too many levels of remot', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Operation not supported', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'State not recoverable', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Connection reset by peer', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Previous owner died', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Too many links', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Illegal byte sequence', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Operation now in progres', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Attribute not found', expected 'Operation not permitted'
ERROR! os.strerror(52) returned 'Operation not permitted', expected 'Network dropped connection on reset'
ERROR! os.strerror(1) returned 'File exists', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Permission denied', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Protocol error', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Protocol not supported', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Interrupted system call', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Address already in use', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Argument list too long', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Protocol family not supp', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Link has been severed', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Operation already in progr', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Programming error', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Protocol wrong type for ', expected 'Operation not permitted'
ERROR! os.strerror(1) returned 'Operation canceled', expected 'Operation not permitted'
ERROR! os.strerror(25) returned 'Operation not permitted', expected 'Inappropriate ioctl for device'
0.0 seconds
Too many levels of remotis truncatedos.strerror(1)returnedOperation not supported, expectedOperation not permitted: well, we got the wrong error message.
The change #158927 should fix the issue. I will backport the fix to 3.14 and 3.15 branches once the 3.15 branch will be unblocked (next week).
AMD64 FreeBSD Refleaks still fails -- in fact it looks like it started failing when this fix was merged.
AMD64 FreeBSD Refleaks still fails -- in fact it looks like it started failing when this fix was merged.
My change adds even more assertions, so maybe the new assertions discovered a new bug.
Two tests failed: test_concurrent_futures.test_interpreter_pool and test_datetime. I already saw these tests failing on FreeBSD 15 and FreeBSD 16, and my fix was supposed to fix these exact tests.
The Refleaks buildbot is running FreeBSD 14. Maybe something is different on FreeBSD 14?
I cannot reproduce these failures on FreeBSD 15.
FAIL: test_concurrent_initialization_subinterpreter (test.datetimetester.ExtensionModuleTests_Fast.test_concurrent_initialization_subinterpreter)
(...)
Assertion failed: (strlen(arg) == arglen), function _Py_DecodeLocale, file Python/fileutils.c, line 733.
Fatal Python error: Aborted
Current thread 0x000000942da25810 [InterpreterPoolExec] (most recent call first):
File "<frozen importlib._bootstrap_external>", line 155 in _path_stat
File "<frozen importlib._bootstrap_external>", line 161 in _path_is_mode_type
File "<frozen importlib._bootstrap_external>", line 169 in _path_isfile
File "<frozen importlib._bootstrap_external>", line 1386 in find_spec
File "<frozen importlib._bootstrap_external>", line 1251 in _get_spec
File "<frozen importlib._bootstrap_external>", line 1277 in find_spec
File "<frozen importlib._bootstrap>", line 1216 in _find_spec
File "<frozen importlib._bootstrap>", line 1292 in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 1344 in _find_and_load
File "/home/buildbot/buildarea/3.x.opsec-fbsd14.refleak/build/Lib/functools.py", line 18 in <module>
File "<frozen importlib._bootstrap>", line 543 in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 754 in exec_module
File "<frozen importlib._bootstrap>", line 909 in _load_unlocked
File "<frozen importlib._bootstrap>", line 1303 in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 1344 in _find_and_load
File "/home/buildbot/buildarea/3.x.opsec-fbsd14.refleak/build/Lib/pickle.py", line 29 in <module>
File "<frozen importlib._bootstrap>", line 543 in _call_with_frames_removed
File "<frozen importlib._bootstrap_external>", line 754 in exec_module
File "<frozen importlib._bootstrap>", line 909 in _load_unlocked
File "<frozen importlib._bootstrap>", line 1303 in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 1344 in _find_and_load
and
test_map_timeout_from_callable (test.test_concurrent_futures.test_interpreter_pool.InterpreterPoolExecutorTest.test_map_timeout_from_callable) ...
Assertion failed: (strlen(arg) == arglen), function _Py_DecodeLocale, file Python/fileutils.c, line 733.
Fatal Python error: Aborted
Current thread 0x000039b534c25810 [InterpreterPoolExec] (most recent call first):
Current thread's C stack trace (most recent call first):
<cannot get C stack on this system>
Extension modules: _testcapi (total: 1)
and
FAIL: test_concurrent_initialization_subinterpreter (test.datetimetester.ExtensionModuleTests_Fast.test_concurrent_initialization_subinterpreter)
(...)
Assertion failed: (count == argsize), function decode_current_locale, file Python/fileutils.c, line 547.
Fatal Python error: Aborted
Current thread 0x00003e35ae025810 [InterpreterPoolExec] (most recent call first):
File "<frozen getpath>", line 356 in <module>
Oh ok, the explanation is event simpler: I only fixed os.strerror(), but strerror() is called in other places. I wrote #158982 to fix all calling sites.
Recently, I made a large refactoring of locale encoding C functions (PR #158680): commit d19febb. I added an assertion to decode_current_locale() to check that the second _Py_mbstowcs() call returns the same size than the the first _Py_mbstowcs() call.
But this assertion failed on the "AMD64 FreeBSD16 3.x" buildbot while running
test_concurrent_futures.test_interpreter_pool: https://buildbot.python.org/#/builders/1857/builds/874I wrote a stress test to try to reproduce the issue. I reproduced the issue on Linux (Fedora 44).
This stress test is special: it changes the LC_CTYPE locale every 10 ms. I don't think that it's a realistic scenario, but it might explain the assertion failure seen on FreeBSD 16.
gdb traceback:
Linked PRs