Repository navigation
test_syslog: test_syslog_threaded() crashs randomly on ARM64 macOS 3.x #98178
Description
Activity
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.0It'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.
Something else that might be useful to note is that both crashes you linked to were running
test_multiprocessing_spawnat the same time as the crash occurred.https://buildbot.python.org/all/#/builders/725/builds/2780/steps/5/logs/stdio (line 297)
0:01:56 load avg: 3.14 [106/434/1] test_syslog crashed (Exit code -11) -- running: test_multiprocessing_spawn (1 min 37 sec), test_asyncio (33.1 sec), test_concurrent_futures (1 min 28 sec)https://buildbot.python.org/all/#/builders/725/builds/2786/steps/5/logs/stdio (line 627)
0:05:50 load avg: 2.50 [389/434/1] test_syslog crashed (Exit code -11) -- running: test_multiprocessing_spawn (1 min 14 sec)Which doesnt seem to be the case for other non-crashing builds (ie https://buildbot.python.org/all/#/builders/725/builds/2785/steps/5/logs/stdio)
Could these be related?
b399115 is not the first crash. See https://buildbot.python.org/all/#/builders/725.
First crash in recent times was 2 days ago https://buildbot.python.org/all/#/builders/725/builds/2780 during testing of commit d876528.
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.
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)
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.
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 OussorenDo we know for sure that the libc
syslogon macOS is thread-safe? There seems to be some discussion in the past about this on the webs.Do we know for sure that the libc
syslogon 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...
@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.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).
10 remaining items
- added a commit that references this issue
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 + 44The source code can be found in Apple syslog source code:
- https://opensource.apple.com/source/syslog/syslog-349.1.1/libsystem_asl.tproj/src/asl.c.auto.html : _asl_evaluate_send()
- https://opensource.apple.com/source/syslog/syslog-349.1.1/libsystem_asl.tproj/src/asl_msg.c.auto.html : asl_msg_lookup(), _asl_msg_index()
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.
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 = True
It seems like these threads only work for 0.1 second. If you want to make the crash more likely, replace
sleep(0.1)withsleep(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
aslhandle is stored internally by openlog().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.
It seems like these threads only work for 0.1 second. If you want to make the crash more likely, replace
sleep(0.1)withsleep(30).I tried that on macOS 12.6 and couldn't reproduce with
-F -j6when 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.
It looks like the issue is fixed in macOS 12, the latest sources are on GitHub instead of opensource.apple.com and manage the ASL handle more sanely: https://github.com/apple-oss-distributions/syslog/blob/syslog-392.100.2/libsystem_asl.tproj/src/syslog.c
In this version the ASL handle used in syslog() is a new reference instead of a borrowed reference (to use Python terminology). That explains why we couldn't reproduce the issue on macOS 12 systems.
Reacted by Łukasz LangaIn 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) { ... }- added 2 commits that reference this issue
on Oct 14, 2022
test_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:
This crash is on the
syslog.syslog()call in a thread. Code: