GeezerVison is showing github.com — test_syslog: test_syslog_threaded() crashs randomly on ARM64 macOS 3.x · Issue #98178 · python/cpython
test_syslog: test_syslog_threaded() crashs randomly on ARM64 macOS 3.x #98178Descriptiontest_syslog crashed 4 times in the last 2 days, each time in the test_syslog_threaded() function, on the "ARM64 macOS 3.x" buildbot:
Example of crash:
Fatal Python error: Segmentation fault
Thread 0x000000017bbcf000 (most recent call first):
File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/test/test_syslog.py", line 67 in logger
File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/threading.py", line 986 in run
File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/threading.py", line 1049 in _bootstrap_inner
File "/Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build/Lib/threading.pymake: *** [buildbottest] Segmentation fault: 11
This crash is on the syslog.syslog() call in a thread. Code:
@threading_helper.requires_working_threading()
def test_syslog_threaded(self):
start = threading.Event()
stop = False
def opener():
start.wait(10)
i = 1
while not stop:
syslog.openlog(f'python-test-{i}') # new string object
i += 1
def logger():
start.wait(10)
while not stop:
syslog.syslog('test message from python test_syslog') # <=== HERE: line 67
orig_si = sys.getswitchinterval()
support.setswitchinterval(1e-9)
try:
threads = [threading.Thread(target=opener)]
threads += [threading.Thread(target=logger) for k in range(10)]
with threading_helper.start_threads(threads):
start.set()
time.sleep(0.1)
stop = True
finally:
sys.setswitchinterval(orig_si)Activityvstinner commented on Oct 11, 2022
on the "ARM64 macOS 3.x" buildbot
It's running macOS 11.6 / ARM64 (Aarch64): Apple M1 CPU.
test.pythoninfo:
build.NDEBUG: build assertions (macro not defined)
build.Py_DEBUG: Yes (sys.gettotalrefcount() present)
datetime.datetime.now: 2022-10-11 04:29:08.870490
os.environ[MACOSX_DEPLOYMENT_TARGET]: 11.6
os.environ[TMPDIR]: /var/folders/39/qz2m3x352hd7djhs80p6vf7c0000gp/T/
os.getcwd: /Users/buildbot/buildarea/3.x.pablogsal-macos-m1.macos-with-brew/build
platform.architecture: 64bit
platform.platform: macOS-11.6-arm64-arm-64bit
platform.python_implementation: CPython
sys.version: 3.12.0a0 (heads/main:b399115ef1, Oct 11 2022, 04:28:51) [Clang 13.0.0 (clang-1300.0.29.3)]
sysconfig[HOST_GNU_TYPE]: aarch64-apple-darwin20.6.0
vstinner commented on Oct 11, 2022 vstinner commented on Oct 11, 2022 The crash started to occur at build 2780 which was triggered by b399115 : no idea if it's related to this change. vstinner commented on Oct 11, 2022 It's unclear to me if the 3.11 branch is affected on this buildbot worker (ARM64 macOS). There was a single build on the 3.11 branch in the last 2 days (since the crash started to occur on the main branch): https://buildbot.python.org/all/#/builders/1030 I don't see any crash on the 3.11 branch for one month. davfsa commented on Oct 11, 2022 Fidget-Spinner commented on Oct 11, 2022 ambv commented on Oct 11, 2022 I'm unable to reproduce neither with pydebug nor with an opt build, neither with -F nor with re-starting -m test thousands of times. Now I'm thinking this has to be an interdependence between different tests. The obvious candidates are test_thread* but I'm somehow thinking this will be test_logging, test_asyncio, or test_concurrent_futures. Trying with all those to find the culprit right now... no dice yet. ambv commented on Oct 11, 2022 Doesn't seem to be multiprocessing (although one of those runs is deadlocked):
1:00:09 load avg: 26.97 [358] test_syslog passed -- running: test_multiprocessing_spawn (32.1 sec), test_multiprocessing_spawn (51 min 18 sec), test_multiprocessing_spawn (1 min 4 sec), test_multiprocessing_spawn (1 min 11 sec), test_multiprocessing_spawn (30.3 sec) ronaldoussoren commented on Oct 11, 2022 A crash log from the buildbot would be nice, that should contain a stack trace of the crash.
BTW. cae7d1d recently added more syslog tests. That commit also has some refcounting fixes in _testcapimodule.c, which look sane to me. ambv commented on Oct 11, 2022 Also doesn't look like it's concurrent.futures related...
1:19:15 load avg: 10.72 [378] test_syslog passed -- running: test_concurrent_futures (1 min 5 sec), test_concurrent_futures (41.6 sec)
I'm in the process of getting the crash log from the box for you, Ronald. Reacted by Ronald Oussoren ned-deily commented on Oct 11, 2022 Do we know for sure that the libc syslog on macOS is thread-safe? There seems to be some discussion in the past about this on the webs. ronaldoussoren commented on Oct 11, 2022
Do we know for sure that the libc syslog on macOS is thread-safe? There seems to be some discussion in the past about this on the webs.
Indeed. This issue mentions ASL handles cannot be used concurrently on two threads and the syslog implementation uses a single global ASL handle. The most recent code dump from Apple uses a lock to create the ASL handle, but doesn't guard usage of said handle.
This may well be an OS bug.
Which begs the question: Is this something we want to work around by introducing a lock on our end, even if that isn't a 100% fix because this wouldn't guard syslog() calls from C code. If not, disabling the multi-threading test in test_syslog would likely avoid the crash by not calling syslog concurrently on our end.
Sigh... ambv commented on Oct 11, 2022 @ronaldoussoren unfortunately it seems that buildbot python.exe crashes don't produce any output in our buildbot's ~/Library/Logs/DiagnosticReports. @pablogsal checked that manually producing a C binary with a bus error and running it does put a file in this folder. Somehow not when we're running automated builds. Since he's out on vacation, we'll continue the hunt after he's back. I was unable to reproduce today on macOS 12.6. The buildbot runs 11.6, maybe that's the differentiating factor. ronaldoussoren commented on Oct 11, 2022 BTW. I haven't been able to reproduce the issue on my end, but haven't tried tested on macOS 11 yet (the version used on the buildbot). vstinner commented on Oct 13, 2022 Well, for me it's quite clear the macOS syslog implementation is not thread-safe, and so using a lock (like the GIL) in Python is the right solution to make the code correct.
* thread #7, stop reason = EXC_BAD_ACCESS (code=1, address=0xffffffffffffffff)
* frame #0: 0x00000001a14a4190 libsystem_asl.dylib`_asl_msg_index + 60
frame #1: 0x00000001a14a5588 libsystem_asl.dylib`asl_msg_lookup + 76
frame #2: 0x00000001a14a549c libsystem_asl.dylib`_asl_evaluate_send + 772
frame #3: 0x00000001a14b7880 libsystem_asl.dylib`_vsyslog + 196
frame #4: 0x00000001a14a900c libsystem_asl.dylib`syslog$DARWIN_EXTSN + 44
The source code can be found in Apple syslog source code:
But frame locall variables are not included in the trace, and I don't know how to get the C line numbre from the trace (_asl_msg_index + 60). I don't have access to macOS.
_asl_evaluate_send() uses a lock, but later, not at the beginning of the function which calls asl_msg_lookup().
I cannot find anything like a mutex or a lock in asl_msg.c.
2019, Someone else hitting a similar syslog() crash on macOS with threads: rigetti/rpcq#92 (comment)
man 3 asl on my macbook says: The state information in a client handle is not protected by locking or thread synchronization mechanisms, except for one special case where NULL is used as a client handle. That special case is described below. (...)
asl manual page: https://developer.apple.com/library/archive/documentation/System/Conceptual/ManPages_iPhoneOS/man3/asl.3.html
When logging from multiple threads, each thread must open a separate client handle using asl_open.
vstinner commented on Oct 13, 2022 The Python syslog.syslog() function calls openlog() once, and then store the result. So all threads use the same log "handle".
/* only one instance, only one syslog, so globals should be ok */
static PyObject *S_ident_o = NULL; /* identifier, held by openlog() */
static char S_log_open = 0;
The syslog C API doesn't accept any "log handle": it's stored somewhere by the C library between openlog() and syslog() calls.
The unit test is a stress test for multi-threading: it calls Python syslog.openlog() and syslog.syslog() functions in a loop from many threads in parallel. Since the GIL is released, magic happens :-)
threads = [threading.Thread(target=opener)]
threads += [threading.Thread(target=logger) for k in range(10)]
with threading_helper.start_threads(threads):
start.set()
time.sleep(0.1)
stop = TrueIt seems like these threads only work for 0.1 second. If you want to make the crash more likely, replace sleep(0.1) with sleep(30).
Maybe sometimes, if openlog() and syslog() are called at the same time from two threads, there is a race condition in syslog() and there is a crash.
It's a little bit weird that openlog() and syslog() don't have any kind of locking since the API is somehow "state less": no "state" is passed to syslog(). The internal asl handle is stored internally by openlog(). ronaldoussoren commented on Oct 13, 2022 Looking at the code I linked to earlier the problem is a race condition between calls to openlog and syslog inside libc.
- openlog releases the ASL handle (if any) and creates a new one, this path is guarded by a lock
- syslog uses the ASL handle without locking and hence might grab the handle in a call to an ASL API just before it is reset after which things go boom when ASL tries to use the handle.
What I don't understand at all is why someone took the effort of adding a mutex to guard changing the handle in openlog, but didn't add a similar guard when using the handle later on. In normal code your very unlikely to hit this race condition because applications generally only call openlog once, but still. vstinner commented on Oct 13, 2022 My PR #98238 got merged, so I close the issue.
If someone wants to fix/enhance macOS, I suggest you opening a bug report on the macOS side instead ;-) ambv commented on Oct 13, 2022
It seems like these threads only work for 0.1 second. If you want to make the crash more likely, replace sleep(0.1) with sleep(30).
I tried that on macOS 12.6 and couldn't reproduce with -F -j6 when running for over an hour:
1:17:52 load avg: 61.52 [868] test_syslog passed (30.8 sec)
I even tried to set the sleep to 0.1 * randint(1, 100) and -j20 to force more concurrent syslog/openlog calls but that didn't reproduce either when running for an hour:
1:34:06 load avg: 150.95 [14513] test_syslog passed
Next I'll try my old Intel laptop with macOS 10.15. ronaldoussoren commented on Oct 13, 2022 vstinner commented on Oct 13, 2022 In that case, the Python syslog module should hold or not the GIL depending on the macOS version.
On macOS, the Python select module checks at runtime if poll() is broken or not, to workaround another macOS issue:
/*
* On some systems poll() sets errno on invalid file descriptors. We test
* for this at runtime because this bug may be fixed or introduced between
* OS releases.
*/
static int select_have_broken_poll(void) { ... }
MetadataMetadataDevelopmentNo branches or pull requestsIssue actions
|