René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"Possible race condition between `threading.local()` and GIL acquisition on Linux","articleBody":"# Bug report\r\n\r\nTSAN reports a race condition from a Python program that both uses `threading.local()` and also a native extension that attempts to acquire the GIL in a separate, native thread.\r\n\r\nTo reproduce, build both the Python interpreter and the native module with TSAN. An example native module is like this, but note that all that matters is that it spawns a native thread that attempts to acquire the GIL:\r\n\r\n**thread_haver.cc:**\r\n```c++\r\n#define PY_SSIZE_T_CLEAN\r\n#include \u003cPython.h\u003e\r\n#include \u003cpthread.h\u003e\r\n#include \u003cstdint.h\u003e\r\n#include \u003cstdio.h\u003e\r\n#include \u003cstdlib.h\u003e\r\n\r\nextern \"C\" {\r\n\r\nstatic pthread_t t;\r\n\r\nstatic void* DoWork(void* arg) {\r\n  printf(\"Thread trying to acquire GIL\\n\");\r\n  fflush(stdout);\r\n  PyGILState_STATE py_threadstate = PyGILState_Ensure();   // Race here!!\r\n  printf(\"Thread called with arg %p\\n\", arg);\r\n  PyGILState_Release(py_threadstate);\r\n  printf(\"Thread has released GIL\\n\");\r\n  return arg;\r\n}\r\n\r\nstatic PyObject* SomeNumber(PyObject* module, PyObject* object) {\r\n  if (pthread_create(\u0026t, nullptr, DoWork, nullptr) != 0) {\r\n    fprintf(stderr, \"pthread_create failed\\n\");\r\n    abort();\r\n  }\r\n  return PyLong_FromLong(reinterpret_cast\u003cuintptr_t\u003e(object));\r\n}\r\n\r\nstatic PyObject* AnotherNumber(PyObject* module, PyObject* object) {\r\n  if (pthread_join(t, nullptr) != 0) {\r\n    fprintf(stderr, \"pthread_join failed\\n\");\r\n    abort();\r\n  }\r\n  return PyLong_FromLong(reinterpret_cast\u003cuintptr_t\u003e(object));\r\n}\r\n\r\n}  // extern \"C\"\r\n\r\nstatic PyMethodDef thbmod_methods[] = {\r\n    {\"some_number\", SomeNumber, METH_O, \"Makes a number.\"},\r\n    {\"another_number\", AnotherNumber, METH_O, \"Makes a number.\"},\r\n    {nullptr, nullptr, 0, nullptr}        /* Sentinel */\r\n};\r\n\r\nstatic struct PyModuleDef thbmod = {\r\n    PyModuleDef_HEAD_INIT,\r\n    \"thread_haver\",   /* name of module */\r\n    nullptr,          /* module documentation, may be NULL */\r\n    1024,             /* size of per-interpreter state of the module,\r\n                         or -1 if the module keeps state in global variables. */\r\n    thbmod_methods,\r\n};\r\n\r\nPyMODINIT_FUNC PyInit_thread_haver() {\r\n  return PyModule_Create(\u0026thbmod);\r\n}\r\n```\r\n\r\nCompile this into a shared object and using TSAN with, say, `${CC} -fPIC -shared -O2 -fsanitize=thread -o thread_haver.so thread_haver.cc`.\r\n\r\nNow the data race happens if we create and destroy a `threading.local()` object in Python:\r\n\r\n**demo.py:**\r\n```py\r\nimport threading\r\nimport thread_haver\r\n\r\nprint(\"Number: {}\".format(thread_haver.some_number(thread_haver)))  # starts a thread\r\nfor _ in range(10000):\r\n  _ = threading.local()   # race here (?)\r\nprint(\"Number: {}\".format(thread_haver.another_number(threading)))  # joins the thread\r\n\r\n```\r\n\r\nConcretely, here is the TSAN output, for Python 3.9:\r\n\r\n```\r\nThread trying to acquire GIL\r\nNumber: 135325830047024\r\n==================\r\nWARNING: ThreadSanitizer: data race (pid=[...])\r\n  Read of size 8 at 0x7b4400019f98 by main thread:\r\n    #0 local_clear [...]/Modules/_threadmodule.c:819:25 (python+0xcbc14e)\r\n    #1 local_dealloc [...]/Modules/_threadmodule.c:838:5 (python+0xcbbd1d)\r\n    #2 _Py_DECREF [...]/Include/object.h:447:9 (python+0x104efaa)\r\n    #3 _Py_XDECREF [...]/Include/object.h:514:9 (python+0x104efaa)\r\n    #4 insertdict [...]/Objects/dictobject.c:1123:5 (python+0x104efaa)\r\n\r\n  Previous write of size 8 at 0x7b4400019f98 by thread T1:\r\n    #0 malloc [...]/tsan/rtl/tsan_interceptors_posix.cpp:683:5 (python+0xbd28f1)\r\n    #1 _PyMem_RawMalloc [...]/Objects/obmalloc.c:116:11 (python+0x1083956)\r\n\r\n  Location is heap block of size 264 at 0x7b4400019f00 allocated by thread T1:\r\n    #0 malloc [...]/tsan/rtl/tsan_interceptors_posix.cpp:683:5 (python+0xbd28f1)\r\n    #1 _PyMem_RawMalloc [...]/Objects/obmalloc.c:116:11 (python+0x1083956)\r\n\r\n  Thread T1 (tid=3039745, running) created by main thread at:\r\n    #0 pthread_create [...]/tsan/rtl/tsan_interceptors_posix.cpp:1038:3 (python+0xbd4679)\r\n    #1 SomeNumber(_object*, _object*) thread_haver.cc:23:7 (thread_haver.so+0xb58)\r\n    #2 cfunction_vectorcall_O [...]/Objects/methodobject.c:516:24 (python+0x107cb3d)\r\n\r\n\r\nSUMMARY: ThreadSanitizer: data race [...]/Modules/_threadmodule.c:819:25 in local_clear\r\n==================\r\nThread called with arg (nil)\r\nThread has released GIL\r\nNumber: 135325829912464\r\nThreadSanitizer: reported 1 warnings\r\n```\r\n\r\nUnfortunately, the backtrace does not go into the details of `PyGILState_Ensure()`, but the race seems to be on `tstate-\u003edict` in https://github.com/python/cpython/blob/5ef90eebfd90147c7e774cd5335ad4fe69a7227c/Modules/_threadmodule.c#L819 from the `threading.local()` deallocation function, and on the `tstate` struct being allocated by `malloc` (by the GIL acquisition?).\r\n\r\n# Your environment\r\n\r\n- CPython versions tested on: 3.9 and 3.10\r\n- Operating system and architecture: Linux (Debian-derived)\r\n\r\nI suspect that there may be some TLS access that both the `threading.local()` deallocation function and the GIL acquisition perform and that may not be sufficiently synchronised. It could also be a bug in TSAN that it does not track TLS access correctly.\r\n\r\n\u003c!-- gh-linked-prs --\u003e\r\n### Linked PRs\r\n* gh-100922\r\n* gh-100937\n* gh-100938\n* gh-100939\n* gh-100953\n\u003c!-- /gh-linked-prs --\u003e\r\n","author":{"url":"https://github.com/tkoeppe","@type":"Person","name":"tkoeppe"},"datePublished":"2023-01-09T17:22:45.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":8},"url":"https://github.com/100892/cpython/issues/100892"}