Possible deadlock at shutdown while recursively acquiring head lock

[Zac-HD]

HypothesisWorks/hypothesis#3585 is reproducible on Python 3.10.10 but not 3.10.9, and so we suspect that #100922 may have introduced a (rare?) deadlock while fixing the data race in #100892.

The downstream bug report on Hypothesis includes a reliable (but not minimal reproducer) on OSX - though it's unclear whether this might be an artifact of different patch versions of CPython on the various machines which have checked so far.

Linked PRs

• GH-102126: fix deadlock at shutdown when clearing thread states #102222
• [3.11] GH-102126: fix deadlock at shutdown when clearing thread state… #102234
• [3.10] GH-102126: fix deadlock at shutdown when clearing thread state… #102235
• [3.9] GH-102126: fix deadlock at shutdown when clearing thread states (GH-102222) #102236

[handrews]

I'm the downstream bug reporter, and I have verified on my M1 Pro Mac OS 12.6.2 laptop that:

• 3.10.9, 3.11.1, 3.12.0a5, and 3.12-dev do not have the problem
• 3.10.10, 3.11.2 do have the problem

I have not had time to find a more minimal reproduction.

[sergei-maertens]

I've created a smaller reproducible example here: https://github.com/sergei-maertens/threading-deadlock

The advantage is that it's possible to reproduce on a linux/docker context and there's no actual application code involved except for two libraries that happen to trigger this when combined (coverage + hypothesis).

@CharString remarked that the hypothesis bug report requires two calls to the st.recursive function and we only have one, however it is possible that we end up having two because there's one call at import time and then another in a different thread due to the way coverage works

I looked into the coverage code a bit yesterday and they do some funky stuff to eventually pass it to exec (see https://github.com/nedbat/coveragepy/blob/master/coverage/execfile.py#L211) which would probably account for the additional thread? I'm not very familiar with these lower level concepts though.

[carljm]

I was able to repro this issue on my Mac using Docker and the instructions at https://github.com/sergei-maertens/threading-deadlock

I also attempted to repro using the same repro.py and requirements.txt, but on an Amazon EC2 bare-metal Ubuntu Linux, building CPython myself (aiming to confirm bisection to the specific commit) but was unable to repro in that environment on any CPython commit (I tried 3.10 latest and main branch). The repro steps I tried:

> cd ~/cpython
> ./configure
> make -j
> cd ~/threading-deadlock
> ~/cpython/python -m venv venv
> ./venv/bin/pip install -r requirements.txt
> COVERAGE_DEBUG=process,pid ./venv/bin/coverage run repro.py
47548.f44a: cwd is now '/home/carljm/threading-deadlock'
47548.f44a: New process: executable: '/home/carljm/threading-deadlock/venv/bin/python'
47548.f44a: New process: cmd: ['./venv/bin/coverage', 'run', 'repro.py']
47548.f44a: New process: pid: 47548, parent pid: 22454
irrelevant
47548.f44a: atexit: pid: 47548, instance: <coverage.control.Coverage object at 0x7fc178b4a540>

[karolyi]

Hey,

I've run into the same problem and went to #python on liberachat where I got some help. I have a django project that uses django-haystack, and the same phenomenon occurs. Because of this bug, my entire CI and production system started acting weird because of the hanging processes.

Upon debugging the hanging process with gdb with the python extension enabled, I've got the following debug log:

source /usr/local/src/Python-3.10.10/python-gdb.py

(gdb) thread apply all backtrace

Thread 1 (LWP 101784 of process 2863):
#0  0x0000000800b085ba in _umtx_op () from /lib/libc.so.7
#1  0x0000000800a8ab26 in sem_clockwait_np () from /lib/libc.so.7
#2  0x00000000004ff984 in PyThread_acquire_lock_timed (lock=0x80121a000, microseconds=<optimized out>, intr_flag=intr_flag@entry=0) at Python/thread_pthread.h:486
#3  0x00000000004ffbac in PyThread_acquire_lock (lock=<optimized out>, waitflag=waitflag@entry=1) at Python/thread_pthread.h:752
#4  0x000000000054f175 in local_clear (self=self@entry=0x810b31f60) at ./Modules/_threadmodule.c:861
#5  0x000000000054f266 in local_dealloc (self=0x810b31f60) at ./Modules/_threadmodule.c:893
#6  0x00000000004701f3 in subtype_dealloc (self=<ClientIndex at remote 0x810b31f60>) at Objects/typeobject.c:1460
#7  0x000000000044caad in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#8  _Py_XDECREF (op=<optimized out>) at ./Include/object.h:567
#9  free_keys_object (keys=0x810b21330) at Objects/dictobject.c:628
#10 0x000000000044d430 in dictkeys_decref (dk=0x810b21330) at Objects/dictobject.c:337
#11 dict_dealloc (mp=0x810b68fc0) at Objects/dictobject.c:2076
#12 0x000000000044d375 in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#13 _Py_XDECREF (op=<optimized out>) at ./Include/object.h:567
#14 dict_dealloc (mp=0x810b5ce40) at Objects/dictobject.c:2068
#15 0x0000000000470321 in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#16 subtype_dealloc (self=<UnifiedIndex(_indexes={<ModelBase(__module__='myproject.booking.models', __doc__='Recipient of an `Order`.', autocomplete_fields={'first_name': 'given-name', 'last_name': 'family-name', 'salutation': 'honorific-title', 'title': 'honorific-suffix', 'company': 'organization', 'street_and_nr': 'address-line1', 'address_ext': 'address-line2', 'postal_code': 'postal-code', 'place': 'address-level2', 'state': 'address-level1', 'country': 'country', 'phone': 'tel', 'fax': 'fax', 'email': 'email', 'birth_date': 'bday'}, placeholder_fields={'first_name': <__proxy__(_proxy____args=('John',), _proxy____kw={}) at remote 0x80cd54220>, 'last_name': <__proxy__(_proxy____args=('Doe',), _proxy____kw={}) at remote 0x80cd542b0>, 'company': <__proxy__(_proxy____args=('Example company',), _proxy____kw={}) at remote 0x80cd54340>, 'street_and_nr': <__proxy__(_proxy____args=('Example street 1',), _proxy____kw={}) at remote 0x80cd543d0>, 'address_ext': <__proxy__(_proxy____args=('Apartment, suite, unit, building, floor',), _proxy__...(truncated)) at Objects/typeobject.c:1438
#17 0x000000000044d375 in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#18 _Py_XDECREF (op=<optimized out>) at ./Include/object.h:567
#19 dict_dealloc (mp=0x810b690c0) at Objects/dictobject.c:2068
#20 0x0000000000470321 in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#21 subtype_dealloc (self=<MyProjectSearchEngine(using='default', options={'ENGINE': 'myproject.base.haystack.MyProjectSearchEngine', 'PATH': '/home/project/build/backend/xapian_index/default', 'myproject-lockfile': '/home/project/build/backend/xapian_index/default.lockfile'}, queries=[], _index=<UnifiedIndex(_indexes={<ModelBase(__module__='myproject.booking.models', __doc__='Recipient of an `Order`.', autocomplete_fields={'first_name': 'given-name', 'last_name': 'family-name', 'salutation': 'honorific-title', 'title': 'honorific-suffix', 'company': 'organization', 'street_and_nr': 'address-line1', 'address_ext': 'address-line2', 'postal_code': 'postal-code', 'place': 'address-level2', 'state': 'address-level1', 'country': 'country', 'phone': 'tel', 'fax': 'fax', 'email': 'email', 'birth_date': 'bday'}, placeholder_fields={'first_name': <__proxy__(_proxy____args=('John',), _proxy____kw={}) at remote 0x80cd54220>, 'last_name': <__proxy__(_proxy____args=('Doe',), _p...(truncated)) at Objects/typeobject.c:1438
#22 0x000000000044caad in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#23 _Py_XDECREF (op=<optimized out>) at ./Include/object.h:567
#24 free_keys_object (keys=0x810b40240) at Objects/dictobject.c:628
#25 0x000000000044d430 in dictkeys_decref (dk=0x810b40240) at Objects/dictobject.c:337
#26 dict_dealloc (mp=0x810b69480) at Objects/dictobject.c:2076
#27 0x000000000044caad in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#28 _Py_XDECREF (op=<optimized out>) at ./Include/object.h:567
#29 free_keys_object (keys=0x810a7f3c0) at Objects/dictobject.c:628
#30 0x000000000044d430 in dictkeys_decref (dk=0x810a7f3c0) at Objects/dictobject.c:337
#31 dict_dealloc (mp=0x808cea580) at Objects/dictobject.c:2076
#32 0x000000000044d5d0 in _Py_DECREF (op={'connections': {'default': <MyProjectSearchEngine(using='default', options={'ENGINE': 'myproject.base.haystack.MyProjectSearchEngine', 'PATH': '/home/project/build/backend/xapian_index/default', 'myproject-lockfile': '/home/project/build/backend/xapian_index/default.lockfile'}, queries=[], _index=<UnifiedIndex(_indexes={<ModelBase(__module__='myproject.booking.models', __doc__='Recipient of an `Order`.', autocomplete_fields={'first_name': 'given-name', 'last_name': 'family-name', 'salutation': 'honorific-title', 'title': 'honorific-suffix', 'company': 'organization', 'street_and_nr': 'address-line1', 'address_ext': 'address-line2', 'postal_code': 'postal-code', 'place': 'address-level2', 'state': 'address-level1', 'country': 'country', 'phone': 'tel', 'fax': 'fax', 'email': 'email', 'birth_date': 'bday'}, placeholder_fields={'first_name': <__proxy__(_proxy____args=('John',), _proxy____kw={}) at remote 0x80cd54220>, 'last_name': <__proxy__...(truncated)) at ./Include/object.h:500
#33 delitem_common (mp=mp@entry=0x808925f40, hash=hash@entry=2156362729, ix=<optimized out>, old_value={'connections': {'default': <MyProjectSearchEngine(using='default', options={'ENGINE': 'myproject.base.haystack.MyProjectSearchEngine', 'PATH': '/home/project/build/backend/xapian_index/default', 'myproject-lockfile': '/home/project/build/backend/xapian_index/default.lockfile'}, queries=[], _index=<UnifiedIndex(_indexes={<ModelBase(__module__='myproject.booking.models', __doc__='Recipient of an `Order`.', autocomplete_fields={'first_name': 'given-name', 'last_name': 'family-name', 'salutation': 'honorific-title', 'title': 'honorific-suffix', 'company': 'organization', 'street_and_nr': 'address-line1', 'address_ext': 'address-line2', 'postal_code': 'postal-code', 'place': 'address-level2', 'state': 'address-level1', 'country': 'country', 'phone': 'tel', 'fax': 'fax', 'email': 'email', 'birth_date': 'bday'}, placeholder_fields={'first_name': <__proxy__(_proxy____args=('John',), _proxy____kw={}) at remote 0x80cd54220>, 'last_name': <__proxy__...(truncated)) at Objects/dictobject.c:1667
#34 0x0000000000450bc8 in _PyDict_DelItem_KnownHash (op={}, key=<weakref.ReferenceType at remote 0x808cf26b0>, hash=2156362729) at Objects/dictobject.c:1719
#35 0x000000000054ee45 in _localdummy_destroyed (localweakref=<optimized out>, dummyweakref=<weakref.ReferenceType at remote 0x808cf26b0>) at ./Modules/_threadmodule.c:1057
#36 0x0000000000591459 in cfunction_vectorcall_O (func=<built-in method _localdummy_destroyed of weakref.ReferenceType object at remote 0x808cf18f0>, args=0x7fffffffd3c8, nargsf=<optimized out>, kwnames=<optimized out>) at Objects/methodobject.c:516
#37 0x00000000004aef59 in _PyObject_VectorcallTstate (nargsf=9223372036854775809, kwnames=0x0, args=0x7fffffffd3c8, callable=<built-in method _localdummy_destroyed of weakref.ReferenceType object at remote 0x808cf18f0>, tstate=0x801249280) at ./Include/cpython/abstract.h:114
#38 PyObject_CallOneArg (arg=<optimized out>, func=<built-in method _localdummy_destroyed of weakref.ReferenceType object at remote 0x808cf18f0>) at ./Include/cpython/abstract.h:184
#39 handle_callback (ref=<optimized out>, callback=<built-in method _localdummy_destroyed of weakref.ReferenceType object at remote 0x808cf18f0>) at Objects/weakrefobject.c:952
#40 0x00000000004b25b3 in PyObject_ClearWeakRefs (object=object@entry=<_thread._localdummy at remote 0x80877be90>) at Objects/weakrefobject.c:998
#41 0x000000000054ea76 in localdummy_dealloc (self=0x80877be90) at ./Modules/_threadmodule.c:676
#42 0x000000000044caad in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#43 _Py_XDECREF (op=<optimized out>) at ./Include/object.h:567
#44 free_keys_object (keys=0x80ef0f180) at Objects/dictobject.c:628
#45 0x000000000044d430 in dictkeys_decref (dk=0x80ef0f180) at Objects/dictobject.c:337
#46 dict_dealloc (mp=0x802cb48c0) at Objects/dictobject.c:2076
#47 0x00000000004f0365 in _Py_DECREF (op=<optimized out>) at ./Include/object.h:500
#48 PyThreadState_Clear (tstate=tstate@entry=0x801249280) at Python/pystate.c:848
#49 0x00000000004f0420 in interpreter_clear (interp=0x80124e7c0, tstate=0x801249280) at Python/pystate.c:298
#50 0x00000000004f079c in _PyInterpreterState_Clear (tstate=<optimized out>) at Python/pystate.c:361
#51 0x00000000004ea9a0 in finalize_interp_clear (tstate=tstate@entry=0x801249280) at Python/pylifecycle.c:1665
#52 0x00000000004eb655 in Py_FinalizeEx () at Python/pylifecycle.c:1843
#53 0x00000000004eed4a in Py_FinalizeEx () at Python/pylifecycle.c:1708
#54 Py_Exit (sts=1) at Python/pylifecycle.c:2858
#55 0x00000000004f3575 in handle_system_exit () at Python/pythonrun.c:775
#56 _PyErr_PrintEx (tstate=0x801249280, set_sys_last_vars=set_sys_last_vars@entry=1) at Python/pythonrun.c:785
#57 0x00000000004f3b16 in PyErr_PrintEx (set_sys_last_vars=1) at Python/pythonrun.c:880
#58 PyErr_Print () at Python/pythonrun.c:886
#59 _PyRun_SimpleFileObject (fp=fp@entry=0x800bbb6c0, filename=filename@entry='/home/project/build/backend/manage.py', closeit=closeit@entry=1, flags=flags@entry=0x7fffffffd718) at Python/pythonrun.c:462
#60 0x00000000004f3d95 in _PyRun_AnyFileObject (fp=0x800bbb6c0, filename=filename@entry='/home/project/build/backend/manage.py', closeit=closeit@entry=1, flags=flags@entry=0x7fffffffd718) at Python/pythonrun.c:90
#61 0x000000000042644b in pymain_run_file_obj (skip_source_first_line=0, filename='/home/project/build/backend/manage.py', program_name='python') at Modules/main.c:353
#62 pymain_run_file (config=0x80124eb70) at Modules/main.c:372
#63 pymain_run_python (exitcode=0x7fffffffd714) at Modules/main.c:587
#64 Py_RunMain () at Modules/main.c:666
#65 0x00000000004269e3 in pymain_main (args=0x7fffffffd850) at Modules/main.c:696
#66 Py_BytesMain (argc=argc@entry=9, argv=argv@entry=0x7fffffffd910) at Modules/main.c:720
#67 0x000000000041c065 in main (argc=argc@entry=9, argv=argv@entry=0x7fffffffd910) at ./Programs/python.c:15
#68 0x00000000004253e0 in _start (ap=<optimized out>, cleanup=<optimized out>) at /usr/src/lib/csu/amd64/crt1_c.c:75

Hope this can help somebody.

[karolyi]

@sergei-maertens I can reproduce the bug with your test on my CI, FreeBSD jail with python3.10.10, and not with python3.10.9. Python is clearly the culprit.

Haven't tried on my Linux box, but probably it would result in the same phenomenon.

[karolyi]

Compiling python from the main branch gives a python that doesn't have this issue.

I tried to revert to 762745a in there to see if the repo state there results in a Python 3.12.0a4+ (tags/v3.12.0a4-4-g762745a124:762745a124) that hangs, but it doesn't.

[carljm]

@karolyi if you try compiling Python from a different commit, say the same commit that was released as 3.10.10, can you repro the issue?

[karolyi]

@carljm the tag v3.10.10 refers a commit in the 3.10 branch, and the entire 3.10 branch is broken now in terms of this bug as of the referred merge.

Reverting the referred (cherry-picked) commit in the 3.10 branch fixed the issue, so the culprit is indeed 762745a, however checking out to the main branch version at this commit results in a working 3.12.

Hence, git bisect isn't helping here.

Something is in there in the main branch that fixes this issue. Probably architectural changes that are way harder for me to figure out.

[carljm]

The reason I ask is because on Ubuntu Linux, as mentioned above, I couldn't reproduce the issue even on 3.10 branch, when compiling Python myself. So are you saying that when compiling Python yourself, you are able to repro the issue from 3.10 branch, but not from main? I didn't see that clearly mentioned above. (When you say you reproed with 3.10.10 and not 3.10.9, it's not clear where those Pythons came from.)