test_syslog: test_syslog_threaded() crashs randomly on ARM64 macOS 3.x

[vstinner]

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:

• Today: https://buildbot.python.org/all/#/builders/725/builds/2786
• 2 days ago: https://buildbot.python.org/all/#/builders/725/builds/2780

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)

[vstinner]

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]

cc @pablogsal @ambv @ned-deily @ronaldoussoren

[vstinner]

The crash started to occur at build 2780 which was triggered by b399115 : no idea if it's related to this change.

[vstinner]

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]

Something else that might be useful to note is that both crashes you linked to were running test_multiprocessing_spawn at 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?

[Fidget-Spinner]

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.

[ambv]

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]

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]

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]

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.

[ned-deily]

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]

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]

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