Calling os.strerror() in parallel is not thread safe on FreeBSD

[vstinner]

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/874

test_blocking (test.test_concurrent_futures.test_interpreter_pool.InterpreterPoolExecutorTest.test_blocking) ... 

Assertion failed: (count == argsize), function decode_current_locale, file Python/fileutils.c, line 542.
Fatal Python error: Aborted

Current thread 0x00001cbd9c848810 [InterpreterPoolExec] (most recent call first):
  File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/genericpath.py", line 40 in isfile
  File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/site.py", line 983 in <genexpr>
  File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/site.py", line 977 in _venv
  File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/site.py", line 1108 in main
  File "/home/buildbot/buildarea/3.x.opsec-fbsd16/build/Lib/site.py", line 1132 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

Current thread's C stack trace (most recent call first):
  <cannot get C stack on this system>

Extension modules: _testcapi (total: 1)

I 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.

import _testlimitedcapi
import locale
import threading
import time
import os

VERBOSE = True
NTHREAD = 50; LOOPS = 25
LONG_STRING = 1024 * 1024

# FreeBSD 16 locales
#CHANGE_LOCALES = ('C.UTF-8', "fr_FR.ISO8859-1", 'ja_JP.SJIS')
# Fedora 44 locales
CHANGE_LOCALES = ('C.utf8', "fr_FR.iso88591", 'ja_JP.ujis')

STRINGS = (
    b'abc',
    b'x' * LONG_STRING,
    b"blatin1:\xa7\xe9",
    b"b255:\xff",
    bytes(range(1, 256)),
)

unicode_decodelocale = _testlimitedcapi.unicode_decodelocale

def stress():
    for s in STRINGS:
        unicode_decodelocale(s, 'surrogateescape')

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)

def change_locale(event):
    while True:
        for loc in CHANGE_LOCALES:
            if VERBOSE:
                os.write(1, f"set {loc} locale\n".encode())
            locale.setlocale(locale.LC_ALL, loc)
            time.sleep(0.010)
        if event.is_set():
            break

# Test locales
for loc in CHANGE_LOCALES:
    locale.setlocale(locale.LC_ALL, loc)

t1 = time.perf_counter()
event = threading.Event()
change_locale = threading.Thread(target=change_locale, args=(event,), name='change_locale')
change_locale.start()
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()
change_locale.join()
dt = time.perf_counter() - t1
print(f"{dt:.1f} seconds")

gdb traceback:

(gdb) 
#5  0x00000000007acb16 in decode_current_locale (arg=0x20002a05aa0 "blatin1:\247", <incomplete sequence \351>, 
    wstr=0x7fcd6cfefda0, wlen=0x7fcd6cfefd98, errors=_Py_ERROR_SURROGATEESCAPE) at Python/fileutils.c:542
542	            assert(count == argsize);
(gdb) p count
$1 = 9
(gdb) p argsize
$2 = 10
(gdb) p arg
$3 = 0x20002a05aa0 "blatin1:\247", <incomplete sequence \351>

Linked PRs

• gh-158893: Make os.strerror() thread-safe #158927

[vstinner]

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

[vstinner]

Note: I modified the buildbot configuration to log C assertion failures in warnings: commit python/buildmaster-config@61d0c77.

[vstinner]

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

[vstinner]

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)

[vstinner]

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 decode strerror(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

[vstinner]

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!

[vstinner]

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")

[vstinner]

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")

[vstinner]

Ok, I can also reproduce the issue using my first reproducer #158893 (comment) on a Free Threaded build.

[vstinner]

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);