Hi, has anyone ever run "make check" from nbd against nbdkit with a python plugin? I usually get segfaults during such a run, and sometimes various other errors happen before the segfault, suggesting that some memory corruption is underway. AFAICS a pure python plugin should not be able to cause memory corruption.

Examples of nbdkit logs for running "make check" or subsets of it from nbd against nbdkit: nbdkit -n -f python script=ssd-ftl-wearleveling.py disksize=52428800 nbdkit: python[6]: error: ssd-ftl-wearleveling.py: callback failed: close nbdkit: python[7]: error: invalid flush request: expecting offset and length == 0 nbdkit: python[7]: error: write reply: Connection reset by peer Segmentation fault nbdkit -n -f python script=ssd-ftl-wearleveling.py disksize=52428800 Fatal Python error: GC object already tracked Segmentation fault nbdkit -n -f python script=ssd-ftl-wearleveling.py disksize=52428800 Segmentation fault nbdkit -n -f python script=ssd-ftl-wearleveling.py disksize=52428800 nbdkit: python[1]: error: invalid flush request: expecting offset and length == 0 nbdkit: python[1]: error: write reply: Broken pipe nbdkit: python[3]: error: client sent NBD_OPT_ABORT to abort the connection nbdkit: python[6]: error: ssd-ftl-wearleveling.py: callback failed: close Traceback (most recent call last): File "ssd-ftl-wearleveling.py", line 221, in close pickle.dump(lbahist, f) File "/usr/lib/python2.7/pickle.py", line 1370, in dump Segmentation fault (core dumped) My close function just dumps the disk image and write access history with python pickle. It does not have any return statement, and because of that I seriously doubt that said close function can fail. I'm now trying to replicate this with example.py. Will report back. Regards, Carl-Daniel _______________________________________________ Libguestfs mailing list Libguestfs(a)redhat.com https://www.redhat.com/mailman/listinfo/libguestfs

On 26.09.2016 14:29, Richard W.M. Jones wrote: > On Mon, Sep 26, 2016 at 02:18:02PM +0200, Carl-Daniel Hailfinger wrote: >> Hi, >> >> has anyone ever run "make check" from nbd against nbdkit with a python >> plugin? I usually get segfaults during such a run, and sometimes various >> other errors happen before the segfault, suggesting that some memory >> corruption is underway. >> AFAICS a pure python plugin should not be able to cause memory corruption. > Correct, a python plugin should not cause memory corruption, > and nbdkit shouldn't segfault ever. > > Did you get a stack trace from C (not from Python)? The core files were useless, but I ran nbdkit in gdb and got something... (gdb) run -n -f /software/nbdkit/plugins/python/.libs/nbdkit-python-plugin.so script=/software/nbdkit/plugins/python/ssd-ftl-wearleveling.py disksize=52428800 Starting program: /software/nbdkit/src/nbdkit -n -f /software/nbdkit/plugins/python/.libs/nbdkit-python-plugin.so script=/software/nbdkit/plugins/python/ssd-ftl-wearleveling.py disksize=52428800 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". Breakpoint 1, py_config (key=0x7fffffffe2e0 "script", value=0x7fffffffe2e7 "/software/nbdkit/plugins/python/ssd-ftl-wearleveling.py") at python.c:107 107 { (gdb) info shared >From To Syms Read Shared Object Library 0x00007ffff7ddaae0 0x00007ffff7df5490 Yes /lib64/ld-linux-x86-64.so.2 0x00007ffff7bd6ed0 0x00007ffff7bd79ce Yes /lib/x86_64-linux-gnu/libdl.so.2 0x00007ffff79bd9f0 0x00007ffff79ca471 Yes /lib/x86_64-linux-gnu/libpthread.so.0 0x00007ffff7612520 0x00007ffff7757183 Yes /lib/x86_64-linux-gnu/libc.so.6 0x00007ffff73f0000 0x00007ffff73f13e7 Yes /software/nbdkit/plugins/python/.libs/nbdkit-python-plugin.so 0x00007ffff6ed70c0 0x00007ffff7065782 Yes (*) /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 0x00007ffff6c73e00 0x00007ffff6c83bf8 Yes /lib/x86_64-linux-gnu/libz.so.1 0x00007ffff6a6ff10 0x00007ffff6a70804 Yes /lib/x86_64-linux-gnu/libutil.so.1 0x00007ffff676e610 0x00007ffff67dd056 Yes /lib/x86_64-linux-gnu/libm.so.6 (*): Shared library is missing debugging information. (gdb) c Continuing. [New Thread 0x7ffff62eb700 (LWP 24498)] [Thread 0x7ffff62eb700 (LWP 24498) exited] [New Thread 0x7ffff62eb700 (LWP 24516)] [Thread 0x7ffff62eb700 (LWP 24516) exited] [New Thread 0x7ffff62eb700 (LWP 24519)] [Thread 0x7ffff62eb700 (LWP 24519) exited] [New Thread 0x7ffff62eb700 (LWP 24536)] [Thread 0x7ffff62eb700 (LWP 24536) exited] [New Thread 0x7ffff62eb700 (LWP 24549)] [Thread 0x7ffff62eb700 (LWP 24549) exited] [New Thread 0x7ffff62eb700 (LWP 24561)] [New Thread 0x7ffff4c26700 (LWP 24580)] nbdkit: python[6]: error: ssd-ftl-wearleveling.py: callback failed: close [Thread 0x7ffff62eb700 (LWP 24561) exited] nbdkit: python[7]: error: invalid flush request: expecting offset and length == 0 nbdkit: python[7]: error: write reply: Connection reset by peer Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x7ffff4c26700 (LWP 24580)] 0x00007ffff7015306 in PyEval_EvalFrameEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 (gdb) bt #0 0x00007ffff7015306 in PyEval_EvalFrameEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #1 0x00007ffff7018059 in PyEval_EvalFrameEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #2 0x00007ffff7018059 in PyEval_EvalFrameEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #3 0x00007ffff701954d in PyEval_EvalCodeEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #4 0x00007ffff7017dd8 in PyEval_EvalFrameEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #5 0x00007ffff701954d in PyEval_EvalCodeEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #6 0x00007ffff704e6d0 in ?? () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #7 0x00007ffff6fbad43 in PyObject_Call () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #8 0x00007ffff7033577 in PyEval_CallObjectWithKeywords () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0 #9 0x00007ffff73f0af0 in py_close (handle=0x625338) at python.c:234 #10 0x0000000000405803 in plugin_close (conn=conn@entry=0x7fffe8000910) at plugins.c:377 #11 0x00000000004037ec in free_connection (conn=0x7fffe8000910) at connections.c:147 #12 0x0000000000404476 in _handle_single_connection (sockout=<optimized out>, sockin=<optimized out>) at connections.c:99 #13 handle_single_connection (sockin=<optimized out>, sockout=<optimized out>) at connections.c:109 #14 0x0000000000405e73 in start_thread (datav=0x7fffffffdd40) at sockets.c:220 #15 0x00007ffff79c0184 in start_thread (arg=0x7ffff4c26700) at pthread_create.c:312 #16 0x00007ffff76ed37d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

>> Examples of nbdkit logs for running "make check" or subsets of it from >> nbd against nbdkit: >> >> nbdkit -n -f python script=ssd-ftl-wearleveling.py disksize=52428800 >> nbdkit: python[6]: error: ssd-ftl-wearleveling.py: callback failed: close >> nbdkit: python[7]: error: invalid flush request: expecting offset and >> length == 0 >> nbdkit: python[7]: error: write reply: Connection reset by peer >> Segmentation fault >> >> nbdkit -n -f python script=ssd-ftl-wearleveling.py disksize=52428800 >> Fatal Python error: GC object already tracked >> Segmentation fault >> >> nbdkit -n -f python script=ssd-ftl-wearleveling.py disksize=52428800 >> Segmentation fault >> >> nbdkit -n -f python script=ssd-ftl-wearleveling.py disksize=52428800 >> nbdkit: python[1]: error: invalid flush request: expecting offset and >> length == 0 >> nbdkit: python[1]: error: write reply: Broken pipe >> nbdkit: python[3]: error: client sent NBD_OPT_ABORT to abort the connection >> nbdkit: python[6]: error: ssd-ftl-wearleveling.py: callback failed: close >> Traceback (most recent call last): >> File "ssd-ftl-wearleveling.py", line 221, in close >> pickle.dump(lbahist, f) >> File "/usr/lib/python2.7/pickle.py", line 1370, in dump >> Segmentation fault (core dumped) >> >> My close function just dumps the disk image and write access history >> with python pickle. It does not have any return statement, and because >> of that I seriously doubt that said close function can fail. >> >> I'm now trying to replicate this with example.py. Will report back.

On 26.09.2016 20:40, Carl-Daniel Hailfinger wrote: > On 26.09.2016 19:20, Carl-Daniel Hailfinger wrote: >> On 26.09.2016 14:29, Richard W.M. Jones wrote: >>> On Mon, Sep 26, 2016 at 02:18:02PM +0200, Carl-Daniel Hailfinger wrote: >>>> Hi, >>>> >>>> has anyone ever run "make check" from nbd against nbdkit with a python >>>> plugin? I usually get segfaults during such a run, and sometimes various >>>> other errors happen before the segfault, suggesting that some memory >>>> corruption is underway. >>>> AFAICS a pure python plugin should not be able to cause memory corruption. >>> Correct, a python plugin should not cause memory corruption, >>> and nbdkit shouldn't segfault ever. >>> >>> Did you get a stack trace from C (not from Python)? >> The core files were useless, but I ran nbdkit in gdb and got something... > And another one... my close function pickles all python objects which > were accessed in the plugin. Maybe that's what exposes the memory > corruption on close. > [...] > Will try instrumenting the close function next. The results are in. I dumped the reference counters for various python objects inside py_close and often the reference counters are off-by-one or off-by-two in the crashing case. AFAICS the python API says that once you have threads, you have to do the GIL dance: https://docs.python.org/2/c-api/init.html#thread-state-and-the-global-int... . All the crashes I saw can be explained by unsynchronized accesses to python objects. I found the bug. plugin_lock_request() is used to lock client requests only, but it does _not_ lock any other calls into the plugin. Due to that, the following calls are neither locked against each other nor are they locked against client requests: plugin_register (const char *_filename, plugin_cleanup (void) plugin_config (const char *key, const char *value) plugin_config_complete (void) plugin_open (struct connection *conn, int readonly) plugin_close (struct connection *conn) plugin_get_size (struct connection *conn) plugin_can_write (struct connection *conn) plugin_can_flush (struct connection *conn) plugin_is_rotational (struct connection *conn) plugin_can_trim (struct connection *conn) That means dumping the plugin-internal data on connection close is not locked against the requests within that connection, and any garbage collection triggered by the last request may still be running while plugin_close runs. Boom. In general, when working with python any call into python should be wrapped like this: PyGILState_STATE gstate; gstate = PyGILState_Ensure(); /* Perform Python actions here. */ result = CallSomeFunction(); /* evaluate result or handle exception */ /* Release the thread. No Python API allowed beyond this point. */ PyGILState_Release(gstate); That would even allow us to run everything in parallel. I have now added a call to plugin_lock_request() within plugin_close() and will check if it still explodes. That's obviously less than what the python developers recommend, but it may at least reduce the likelihood of the crashes.