[Libguestfs] nbdkit 1.1.15 -- test-python failure

[Richard W.M. Jones]

On Wed, Sep 27, 2017 at 11:54:48PM +0200, Hilko Bengen wrote:
> Hi,
> 
> when I tested building nbdkit 1.1.15 in a current Debian chroot, I ran
> into the following test failure. A repeated build went fine through the
> tests and so far I have not been able to reproduce it with the previous
> version.
> 
> The failing build was done using a clean Debian/sid, amd64 chroot
> spawned by sbuild.
> nbdkit: debug: /<<PKGBUILDDIR>>/plugins/python/.libs/nbdkit-python-plugin.so: unload
> Exception AttributeError: "'module' object has no attribute 'close'" in 'garbage collection' ignored
> Fatal Python error: unexpected exception during garbage collection
> nbdkit terminated by signal 6
> FAIL test-python (exit status: 1)

I've not seen this particular problem, but I did see another segfault
during plugin unload which you can (rarely) reproduce like this:

  make && while make check TESTS=test-socket-activation >& /tmp/log ; do echo -n . ; done

It can take many iterations to see the crash.  When the tests exit,
examine both /tmp/log and tests/test-suite.log.

The stack trace from the crash is:

Thread 2 (Thread 0x7f67a975d800 (LWP 22742)):
#0  0x00007f67a9579250 in _dl_sort_fini () from /lib64/ld-linux-x86-64.so.2
#1  0x00007f67a9579402 in _dl_fini () from /lib64/ld-linux-x86-64.so.2
#2  0x00007f67a8817c68 in __run_exit_handlers () from /lib64/libc.so.6
#3  0x00007f67a8817cba in exit () from /lib64/libc.so.6
#4  0x00000000004046ac in main (argc=<optimized out>, argv=<optimized out>)
    at main.c:506

Thread 1 (Thread 0x7f67a099b700 (LWP 22745)):
#0  0x00007f67a8870fc6 in strlen () from /lib64/libc.so.6
#1  0x00007f67a884f465 in fputs () from /lib64/libc.so.6
#2  0x0000000000406715 in prologue (type=0x409928 "debug") at errors.c:54
#3  0x000000000040685d in nbdkit_debug (fs=fs at entry=0x40ace6 "close")
    at errors.c:91
#4  0x00000000004077d9 in plugin_close (conn=conn at entry=0x7f679c000910)
    at plugins.c:386
#5  0x0000000000404de3 in free_connection (conn=0x7f679c000910)
    at connections.c:228
#6  0x00000000004059fd in _handle_single_connection (sockout=<optimized out>, 
    sockin=<optimized out>) at connections.c:179
#7  handle_single_connection (sockin=<optimized out>, sockout=<optimized out>)
    at connections.c:189
#8  0x0000000000408023 in start_thread (datav=0x7fff1a4fbbe0) at sockets.c:262
#9  0x00007f67a8bb536d in start_thread () from /lib64/libpthread.so.0
#10 0x00007f67a88edbbf in clone () from /lib64/libc.so.6

It seems to indicate some kind of race condition between the plugin
being unloaded from memory while plugin_close is being called.
However I wasn't able to determine exactly what is happening.  I'll
take another look in a minute.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
libguestfs lets you edit virtual machines.  Supports shell scripting,
bindings from many languages.  http://libguestfs.org