| msg362807 - (view) |
Author: Evgeny Boytsov (boytsovea) |
Date: 2020-02-27 15:25 |
| Hello everybody! We are using Python 3.7 running at CentOS 7 x64. Python is used as a library to create dynamic extensions for our app server. Some time ago we began to experience crashes in decimal module in some heavy-multithreaded scenarios. After some testing and debugging I was able to reproduce it without our own code using only pybind11 library to simplify embedding (in real app we are using boost.python). I've built python 3.8 with clang 7 and address sanitizer enabled and got error "use-after-free" with some additional data. Please find attached C++ source file, python module and ASAN output. Is it really a bug (most probably - data race) or there is something wrong with such embedding scenario? |
|
|
| msg362812 - (view) |
Author: Stefan Krah (skrah) *  |
Date: 2020-02-27 15:57 |
| Before I look at the example code: Can you also reproduce this with Python 3.6? The threading code in _decimal was changed to a ContextVar in 3.7. There's a high chance though that the problem is in the c++ module. |
|
|
| msg362820 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-02-27 17:23 |
| I've briefly looked at the zip archive. Without going much into the C++ module as a whole, this should not be done: gil_unlocker.UnlockGILAndSleep() self.val = decimal.Decimal(1) / decimal.Decimal(7) gil_unlocker.UnlockGILAndSleep() If you want C++ threads with a released GIL, you should use libmpdec directly and not the Python module. |
|
|
| msg362825 - (view) |
Author: Evgeny Boytsov (boytsovea) |
Date: 2020-02-27 17:41 |
| Please note, that UnlockGILandSleep takes GIL back before returning. In a real production code there is a database query. In this example I emulate them with random sleep. So I don't see any problems here. |
|
|
| msg362834 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-02-27 20:07 |
| I built your example with 3.6: git clone https://github.com/pybind/pybind11 wget https://bugs.python.org/file48923/decimal_crash.zip unzip decimal_crash.zip git checkout v3.6.7 ./configure --with-pydebug make g++ -std=c++11 -pthread -Wno-unused-result -Wsign-compare -g -Og -Wall -Wextra -Wno-unused-result -Wno-unused-parameter -Wno-missing-field-initializers -I. -I./Include -I./pybind11/include -c main.cpp g++ -pthread -Xlinker -export-dynamic -o main main.o libpython3.6dm.a -lpthread -ldl -lutil -lm cp python python3 PATH=.:$PATH ./main And I literally get this error (not always, it may take 10 runs or so): $ ./main Fatal Python error: Python memory allocator called without holding the GIL Thread 0x00007f1e73fff700 (most recent call first): Thread 0x00007f1e7b836700 (most recent call first): Thread 0x00007f1e7a834700 (most recent call first): Thread 0x00007f1e7b035700 (most recent call first): Thread 0x00007f1e7d039700 (most recent call first): Thread 0x00007f1e7c838700 (most recent call first): Current thread 0x00007f1e7c037700 (most recent call first): Thread 0x00007f1e7e84f740 (most recent call first): Aborted (core dumped) So no, I don't think the GIL handling is correct. |
|
|
| msg362865 - (view) |
Author: Evgeny Boytsov (boytsovea) |
Date: 2020-02-28 04:12 |
| Thank you for feedback. I will try to reproduce the issue with 3.6. By the way, haven't you used gdb with python pretty-printers enabled to examine the state of the program? I've got the same error message, then I breaked the execution in debugger and tried to examine the callstack of threads, that stucked in UnlockGILandSleep. The reason for it is clear: then the debugger tries to build a callstack, some of pretty printers try to execute some python code to give a better representation of interpreter objects. The code is executed at the top of the stack of the examined thread. Since this thread explicitly released the GIL before going to sleep, these functions hit the assert about calling the memory allocator without holdng the GIL. Disabling pretty-printers makes these error messages to disappear. |
|
|
| msg362869 - (view) |
Author: Evgeny Boytsov (boytsovea) |
Date: 2020-02-28 06:35 |
| I'am unable to reproduce neither my or your issues with python 3.6. The program runs infinitely as it meant to be. Can you please give me C++ traceback from the core dump, which was created when you ran my program? |
|
|
| msg362875 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-02-28 11:49 |
| This is 3.6.7, compiled --with-pydebug: $ ./main Aborted (core dumped) (gdb) bt #0 0x00007f9974077428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54 #1 0x00007f997407902a in __GI_abort () at abort.c:89 #2 0x000000000056e2d1 in Py_FatalError (msg=msg@entry=0x62ccf8 "Python memory allocator called without holding the GIL") at Python/pylifecycle.c:1462 #3 0x00000000004c0cec in _PyMem_DebugCheckGIL () at Objects/obmalloc.c:1963 #4 0x00000000004c0d27 in _PyMem_DebugMalloc (ctx=0x8f7220 <_PyMem_Debug+96>, nbytes=75) at Objects/obmalloc.c:1971 #5 0x00000000004c204e in PyObject_Malloc (size=) at Objects/obmalloc.c:479 #6 0x00000000004ec12f in PyUnicode_New (size=10, maxchar=) at Objects/unicodeobject.c:1281 #7 0x00000000005162f4 in _PyUnicodeWriter_PrepareInternal (writer=writer@entry=0x7f9971ca4cf0, length=length@entry=10, maxchar=, maxchar@entry=127) at Objects/unicodeobject.c:13565 #8 0x000000000051af20 in PyUnicode_DecodeUTF8Stateful (s=0x61d15b "crash_test", size=10, errors=errors@entry=0x0, consumed=consumed@entry=0x0) at Objects/unicodeobject.c:5067 #9 0x000000000051c6b0 in PyUnicode_FromString (u=) at Objects/unicodeobject.c:2077 #10 0x0000000000563c1c in PyImport_ImportModule (name=) at Python/import.c:1266 #11 0x00000000004531dd in pybind11::module::import (name=0x61d15b "crash_test") at ./pybind11/include/pybind11/pybind11.h:849 #12 0x0000000000446434 in ThreadFunc () at main.cpp:30 #13 0x000000000046a1b1 in std::_Bind_simple<void (*())()>::_M_invoke<>(std::_Index_tuple<>) (this=0x10c28d8) at /usr/include/c++/5/functional:1531 #14 0x000000000046a10a in std::_Bind_simple<void (*())()>::operator()() (this=0x10c28d8) at /usr/include/c++/5/functional:1520 #15 0x000000000046a09a in std::thread::_Impl<std::_Bind_simple<void (*())()> >::_M_run() (this=0x10c28c0) at /usr/include/c++/5/thread:115 #16 0x00007f99749e3c80 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6 #17 0x00007f99750bb6ba in start_thread (arg=0x7f9971ca5700) at pthread_create.c:333 #18 0x00007f997414941d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109 |
|
|
| msg362876 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-02-28 11:57 |
| Note that my pybind11 is from GitHub master, it can also be a pybind11 issue. It is interesting that you cannot reproduce your original issue with 3.6, so I'm reopening this issue. I think we need a reproducer without pybind11 though, could you tweak Programs/_testembed.c (from the CPython sources) to run the crash script? |
|
|
| msg362877 - (view) |
Author: Evgeny Boytsov (boytsovea) |
Date: 2020-02-28 12:35 |
| Your callstack is very strange. At line 30 of main.cpp GIL is obviously locked: // importing module in this tread gstate = PyGILState_Ensure(); py::module crash_test = py::module::import( "crash_test" ); <-- import PyGILState_Release( gstate ); I suppose that there is something wrong with your setup. Maybe - wrong working directory for the main executable, which doesn't contain crash_test.py Also I've tried to revert this patch https://github.com/python/cpython/pull/5278 for 3.7. It makes problem to disappear, 1 hour of stable work under ASAN. So I suppose it is the source of the bug. I will try to tweak _testembed.c. |
|
|
| msg362878 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-02-28 13:19 |
| Regarding *my* issue, it could be anything, e.g. a missing call to PyEval_InitThreads() in 3.6: "Changed in version 3.7: This function is now called by Py_Initialize(), so you don’t have to call it yourself anymore." This is why we need to eliminate pybind11 so we can see what is actually going on. |
|
|
| msg362880 - (view) |
Author: Evgeny Boytsov (boytsovea) |
Date: 2020-02-28 14:20 |
| I rewrote my example without pybind and eliminated C++ module (I realized that time.sleep() also releases the GIL, so we achieve the same effect). Still the same results: with python 3.7.3 app crashes with attached ASAN output, with python 3.7.3 without https://github.com/python/cpython/pull/5278 works just fine. To run main.cpp you should add directory with crash_test.py to PYTHONPATH. |
|
|
| msg362882 - (view) |
Author: Evgeny Boytsov (boytsovea) |
Date: 2020-02-28 14:52 |
| Also I understood the source of your crash with my initial example. Since you haven't used CMake to configure project, pybind didn't setup required macroses to enable threading support. So no issues in pybind. |
|
|
| msg362885 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-02-28 16:11 |
| > With python 3.7.3 without https://github.com/python/cpython/pull/5278 works just fine. Thanks, I'm now getting the same results as you. Looking at the smaller test case, I also agree that it should work (as it did in 3.6). |
|
|
| msg363192 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-03-02 17:05 |
| I think the PR fixes the issue but I have to run longer tests still. Threads created by PyGILState_Ensure() could have a duplicate tstate->id, which confused the ContextVar caching machinery. |
|
|
| msg363208 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-03-02 20:22 |
| New changeset b3b9ade4a3d3fe00d933bcd8fc5c5c755d1024f9 by Stefan Krah in branch 'master': bpo-39776: Lock ++interp->tstate_next_unique_id. (GH-18746) (#18746) https://github.com/python/cpython/commit/b3b9ade4a3d3fe00d933bcd8fc5c5c755d1024f9 |
|
|
| msg363239 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-03-03 08:19 |
| New changeset 5a92f42d8723ee865be80f028d402204649da15d by Stefan Krah in branch '3.8': bpo-39776: Lock ++interp->tstate_next_unique_id. (GH-18746) (#18746) (#18752) https://github.com/python/cpython/commit/5a92f42d8723ee865be80f028d402204649da15d |
|
|
| msg363240 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-03-03 08:20 |
| New changeset 852aee69f49c654a03ad1f64d90a78ba8848e2c6 by Stefan Krah in branch '3.7': bpo-39776: Lock ++interp->tstate_next_unique_id (GH-18746) https://github.com/python/cpython/commit/852aee69f49c654a03ad1f64d90a78ba8848e2c6 |
|
|
| msg363248 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-03-03 09:19 |
| Since many duplicate tstate ids are generated in the test case before the crash happens, I guess a set of tstates with the same id silently uses the cached context of the "winner" tstate. This can lead to incorrect results without noticing. |
|
|
| msg363266 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-03-03 15:21 |
| Also _pydecimal was affected. This is a modified version of Evgeny's test case: from _pydecimal import * from time import sleep from random import randint import sys sys.setswitchinterval(0.0000001) def usleep(x): sleep(x/1000000.0) class Test: def __init__(self, threadno): self.threadno = threadno def GetCallback(self): usleep(randint(0, 9)); setcontext(Context(Emax=self.threadno)) usleep(randint(0, 9)) c = getcontext() try: if c.Emax != self.threadno: raise RuntimeError("GetCallback: another thread changed this thread's context") except AttributeError: raise RuntimeError("GetCallback: type(c)==%s and c.Emax disappeared" % type(c)) usleep(randint(0, 9)) return self.Callback def Callback(self): c = getcontext() try: c.Emax = self.threadno except AttributeError: raise RuntimeError("Callback: type(c)==%s and c.Emax disappeared" % type(c)) def DoTest(threadno): return Test(threadno).GetCallback() It produces one of the exceptions or a segfault. You may have to build in release mode to get the race. |
|
|
| msg363267 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-03-03 15:23 |
| Setting to release blocker, but please move to deferred again if a release is almost finished. |
|
|
| msg363270 - (view) |
Author: Ned Deily (ned.deily) * |
Date: 2020-03-03 16:07 |
| Thanks for the heads-up and the fix, Stefan. The fix for 3.7.x was merged before the 3.7.7rc1 cutoff (by a few hours!) and the next 3.8.x release cutoff is planned for April and 3.9.0a5 is later in March, so, if you are not planning to merge any other changes for this issue, we can set the issue status to "closed" now. |
|
|
| msg363274 - (view) |
Author: Stefan Krah (skrah) * |
Date: 2020-03-03 16:21 |
| Thanks Ned, closing then. Evgeny, please reopen if you see it again (I ran the tests for about 20 min, way above the usual reproduction time of 1 min). Thanks for the very instructive test case! |
|
|
| msg363338 - (view) |
Author: Evgeny Boytsov (boytsovea) |
Date: 2020-03-04 08:36 |
| I checked both my test example and real production code with your patch. I'm unable to reproduce the bug, so I think it is fixed now. Thank you! |
|
|
| msg363406 - (view) |
Author: Yury Selivanov (yselivanov) * |
Date: 2020-03-05 00:42 |
| Thank you so much, Stefan, for looking into this. Really appreciate the help. |
|
|