On 5/26/22 8:06 PM, Claudio Fontana wrote: > Hi all, > > I am seeing intermittent failures of make -j check on master. > > I am using gcc 7.5.0, make 4.2.1, meson 0.61.4, ninja-1.10.0 > > I tried these two configurations: > > $ ../configure > > $ ../configure --disable-tcg --enable-kvm > > and the errors seem to appear in both cases, saltuarily, triggering in > different test paths: > > $ make -j > $ make -j check > > 545/581 ERROR:../tests/qtest/qos-test.c:189:subprocess_run_one_test: child > process > (/i386/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/flags-mismatch/subprocess > [100495]) failed unexpectedly ERROR > 545/581 qemu:qtest+qtest-i386 / qtest-i386/qos-test > ERROR 20.74s killed by signal 6 SIGABRT >>>> G_TEST_DBUS_DAEMON=/vm_images/gehc/git/qemu/tests/dbus-vmstate-daemon.sh >>>> QTEST_QEMU_IMG=./qemu-img >>>> QTEST_QEMU_STORAGE_DAEMON_BINARY=./storage-daemon/qemu-storage-daemon >>>> MALLOC_PERTURB_=140 QTEST_QEMU_BINARY=./qemu-system-i386 >>>> /vm_images/gehc/git/qemu/build/tests/qtest/qos-test --tap -k > ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― ✀ > ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― > stderr: > ** > ERROR:../tests/qtest/qos-test.c:189:subprocess_run_one_test: child process > (/i386/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/flags-mismatch/subprocess > [100495]) failed unexpectedly > (test program exited with status code -6) > > > or > > > ▶ 208/218 ERROR:../tests/qtest/qos-test.c:189:subprocess_run_one_test: child > process > (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess > [3995]) failed unexpectedly ERROR > 208/218 qemu:qtest+qtest-x86_64 / qtest-x86_64/qos-test > ERROR 14.19s killed by signal 6 SIGABRT >>>> G_TEST_DBUS_DAEMON=/vm_images/gehc/git/qemu/tests/dbus-vmstate-daemon.sh >>>> QTEST_QEMU_IMG=./qemu-img QTEST_QEMU_BINARY=./qemu-system-x86_64 >>>> MALLOC_PERTURB_=248 >>>> QTEST_QEMU_STORAGE_DAEMON_BINARY=./storage-daemon/qemu-storage-daemon >>>> /vm_images/gehc/git/qemu/build/tests/qtest/qos-test --tap -k > ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― ✀ > ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― > stderr: > ** > ERROR:../tests/qtest/qos-test.c:189:subprocess_run_one_test: child process > (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess > [3995]) failed unexpectedly > > (test program exited with status code -6) > ―――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― > > > > I ran the tests manually a few times directly with: > > $ G_TEST_DBUS_DAEMON=/vm_images/gehc/git/qemu/tests/dbus-vmstate-daemon.sh > QTEST_QEMU_IMG=./qemu-img QTEST_QEMU_BINARY=./qemu-system-x86_64 > MALLOC_PERTURB_=248 > QTEST_QEMU_STORAGE_DAEMON_BINARY=./storage-daemon/qemu-storage-daemon > /vm_images/gehc/git/qemu/build/tests/qtest/qos-test --tap -k > > and I get (saltuarily again): > > # Start of vhost-user tests > # GLib-DEBUG: posix_spawn avoided (workdir specified) (fd close requested) > ok 62 > /x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/migrate > # GLib-DEBUG: posix_spawn avoided (workdir specified) (fd close requested) > # child process > (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess > [15058]) exit status: 1 (error) > # child process > (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess > [15058]) stdout: "" > # child process > (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess > [15058]) stderr: "qemu-system-x86_64: -chardev > socket,id=chr-reconnect,path=/tmp/vhost-test-qvwhvM/reconnect.sock,server=on: > info: QEMU waiting for connection on: > disconnected:unix:/tmp/vhost-test-qvwhvM/reconnect.sock,server=on\nqemu-system-x86_64: > Failed to set msg fds.\nqemu-system-x86_64: vhost VQ 0 ring restore failed: > -22: Invalid argument (22)\nqemu-system-x86_64: Failed to set msg > fds.\nqemu-system-x86_64: vhost VQ 1 ring restore failed: -22: Invalid > argument > (22)\n**\nERROR:../tests/qtest/vhost-user-test.c:810:wait_for_rings_started: > assertion failed (ctpop64(s->rings) == count): (1 == 2)\n" > ** > ERROR:../tests/qtest/qos-test.c:189:subprocess_run_one_test: child process > (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess > [15058]) failed unexpectedly > Bail out! ERROR:../tests/qtest/qos-test.c:189:subprocess_run_one_test: child > process > (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess > [15058]) failed unexpectedly > Aborted (core dumped) > > > gdb -core, bt: > > #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51 > #1 0x00007f193e9abadf in __GI_abort () at abort.c:100 > #2 0x00007f193faf2165 in g_assertion_message (domain=domain@entry=0x0, > file=file@entry=0x560e358c3c16 "../tests/qtest/qos-test.c", > line=line@entry=189, func=func@entry=0x560e358c3d50 <__func__.30035> > "subprocess_run_one_test", > message=message@entry=0x560e35f82400 "child process > (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess > [18063]) failed unexpectedly") at ../glib/gtestutils.c:2913 > #3 0x00007f193faf2b9a in g_test_trap_assertions (domain=0x0, > file=0x560e358c3c16 "../tests/qtest/qos-test.c", line=189, > func=0x560e358c3d50 <__func__.30035> "subprocess_run_one_test", > assertion_flags=<optimized out>, pattern=<optimized out>) > at ../glib/gtestutils.c:3673 > #4 0x00007f193faf1a66 in test_case_run (tc=0x560e35f6ead0) at > ../glib/gtestutils.c:2632 > #5 g_test_run_suite_internal (suite=suite@entry=0x560e35faae00, > path=path@entry=0x0) at ../glib/gtestutils.c:2720 > #6 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35fa9c00, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #7 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35fa9ec0, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #8 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35fa85a0, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #9 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35fa7100, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #10 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35fa7140, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #11 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35fa7160, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #12 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35fa7080, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #13 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35fa7180, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #14 0x00007f193faf197b in g_test_run_suite_internal > (suite=suite@entry=0x560e35f26640, path=path@entry=0x0) at > ../glib/gtestutils.c:2732 > #15 0x00007f193faf1f22 in g_test_run_suite (suite=0x560e35f26640) at > ../glib/gtestutils.c:2807 > #16 0x00007f193faf1f41 in g_test_run () at ../glib/gtestutils.c:2042 > #17 0x0000560e358191e9 in main (argc=<optimized out>, argv=<optimized out>, > envp=<optimized out>) at ../tests/qtest/qos-test.c:338 > > I tried to valgrind a bit the qos-test itself and I got an interesting result > for vhost-user-blk-test/basic. > I guess some memory corruption in a preceding test could make tests that > follow fail?
Forget about his aspect, I think it is a separate problem. valgind of qos-test when run restricted to those specific paths (-p /x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect for example) shows all clear, and still the test fails when run in a while loop after a few attempts: while G_TEST_DBUS_DAEMON=/vm_images/gehc/git/qemu/tests/dbus-vmstate-daemon.sh QTEST_QEMU_IMG=./qemu-img QTEST_QEMU_BINARY=./qemu-system-x86_64 MALLOC_PERTURB_=248 QTEST_QEMU_STORAGE_DAEMON_BINARY=./storage-daemon/qemu-storage-daemon /vm_images/gehc/git/qemu/build/tests/qtest/qos-test --tap -k -p /x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect ; do echo "************************"; done ==23948== Memcheck, a memory error detector ==23948== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al. ==23948== Using Valgrind-3.17.0 and LibVEX; rerun with -h for copyright info ==23948== Command: /vm_images/gehc/git/qemu/build/tests/qtest/qos-test-real --tap -k -p /x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect ==23948== # random seed: R02S1d5bde212d220a83538cd14e01480c4a # starting QEMU: exec ./qemu-system-x86_64 -qtest unix:/tmp/qtest-23948.sock -qtest-log /dev/null -chardev socket,path=/tmp/qtest-23948.qmp,id=char0 -mon chardev=char0,mode=control -display none -machine none -accel qtest # Start of x86_64 tests # Start of pc tests # Start of i440FX-pcihost tests # Start of pci-bus-pc tests # Start of pci-bus tests # Start of virtio-net-pci tests # Start of virtio-net tests # Start of virtio-net-tests tests # Start of vhost-user tests # GLib-DEBUG: posix_spawn avoided (workdir specified) (fd close requested) ok 1 /x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect # Start of reconnect tests # End of reconnect tests # End of vhost-user tests # End of virtio-net-tests tests # End of virtio-net tests # End of virtio-net-pci tests # End of pci-bus tests # End of pci-bus-pc tests # End of i440FX-pcihost tests # End of pc tests # End of x86_64 tests 1..1 ==23948== ==23948== HEAP SUMMARY: ==23948== in use at exit: 140,152 bytes in 1,198 blocks ==23948== total heap usage: 151,072 allocs, 149,874 frees, 7,113,381 bytes allocated ==23948== ==23948== For a detailed leak analysis, rerun with: --leak-check=full ==23948== ==23948== For lists of detected and suppressed errors, rerun with: -s ==23948== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0) ************************ .... # child process (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess [24153]) exit status: 1 (error) # child process (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess [24153]) stdout: "" # child process (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess [24153]) stderr: "qemu-system-x86_64: -chardev socket,id=chr-reconnect,path=/tmp/vhost-test-aK70bN/reconnect.sock,server=on: info: QEMU waiting for connection on: disconnected:unix:/tmp/vhost-test-aK70bN/reconnect.sock,server=on\nqemu-system-x86_64: Failed to set msg fds.\nqemu-system-x86_64: vhost VQ 0 ring restore failed: -22: Invalid argument (22)\nqemu-system-x86_64: Failed to set msg fds.\nqemu-system-x86_64: vhost VQ 1 ring restore failed: -22: Invalid argument (22)\n**\nERROR:../tests/qtest/vhost-user-test.c:810:wait_for_rings_started: assertion failed (ctpop64(s->rings) == count): (1 == 2)\n" ** ERROR:../tests/qtest/qos-test.c:189:subprocess_run_one_test: child process (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess [24153]) failed unexpectedly Bail out! ERROR:../tests/qtest/qos-test.c:189:subprocess_run_one_test: child process (/x86_64/pc/i440FX-pcihost/pci-bus-pc/pci-bus/virtio-net-pci/virtio-net/virtio-net-tests/vhost-user/reconnect/subprocess [24153]) failed unexpectedly ==24147== ==24147== Process terminating with default action of signal 6 (SIGABRT): dumping core > > Here: > > # starting vhost-user backend: exec ./storage-daemon/qemu-storage-daemon > --blockdev driver=file,node-name=disk0,filename=qtest.OkpNv2 --export > type=vhost-user-blk,id=disk0,addr.type=fd,addr.str=3,node-name=disk0,writable=on,num-queues=1 > > # starting QEMU: exec ./qemu-system-x86_64 -qtest unix:/tmp/qtest-23786.sock > -qtest-log /dev/null -chardev socket,path=/tmp/qtest-23786.qmp,id=char0 -mon > chardev=char0,mode=control -display none -M pc -device > vhost-user-blk-pci,id=drv0,chardev=char1,addr=4.0 -object > memory-backend-memfd,id=mem,size=256M,share=on -M memory-backend=mem -m 256M > -chardev socket,id=char1,path=/tmp/qtest-23786-sock.RAqTFy -accel qtest > ==23786== Use of uninitialised value of size 8 > ==23786== at 0x5EFEE01: _itoa_word (_itoa.c:180) > ==23786== by 0x5F02740: vfprintf (vfprintf.c:1642) > ==23786== by 0x5FBA8FE: __vsprintf_chk (vsprintf_chk.c:83) > ==23786== by 0x5FBA829: __sprintf_chk (sprintf_chk.c:31) > ==23786== by 0x140A25: sprintf (stdio2.h:33) > ==23786== by 0x140A25: qtest_memwrite (libqtest.c:1067) > ==23786== by 0x13642F: virtio_blk_request (vhost-user-blk-test.c:90) > ==23786== by 0x13714D: test_invalid_discard_write_zeroes > (vhost-user-blk-test.c:123) > ==23786== by 0x1380CB: test_basic (vhost-user-blk-test.c:357) > ==23786== by 0x1380CB: basic (vhost-user-blk-test.c:452) > ==23786== by 0x121837: run_one_test (qos-test.c:182) > ==23786== by 0x4EBAA65: test_case_run (gtestutils.c:2632) > ==23786== by 0x4EBAA65: g_test_run_suite_internal (gtestutils.c:2720) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== Uninitialised value was created by a stack allocation > ==23786== at 0x1370B0: test_invalid_discard_write_zeroes > (vhost-user-blk-test.c:102) > ==23786== > ==23786== Conditional jump or move depends on uninitialised value(s) > ==23786== at 0x5EFEE08: _itoa_word (_itoa.c:180) > ==23786== by 0x5F02740: vfprintf (vfprintf.c:1642) > ==23786== by 0x5FBA8FE: __vsprintf_chk (vsprintf_chk.c:83) > ==23786== by 0x5FBA829: __sprintf_chk (sprintf_chk.c:31) > ==23786== by 0x140A25: sprintf (stdio2.h:33) > ==23786== by 0x140A25: qtest_memwrite (libqtest.c:1067) > ==23786== by 0x13642F: virtio_blk_request (vhost-user-blk-test.c:90) > ==23786== by 0x13714D: test_invalid_discard_write_zeroes > (vhost-user-blk-test.c:123) > ==23786== by 0x1380CB: test_basic (vhost-user-blk-test.c:357) > ==23786== by 0x1380CB: basic (vhost-user-blk-test.c:452) > ==23786== by 0x121837: run_one_test (qos-test.c:182) > ==23786== by 0x4EBAA65: test_case_run (gtestutils.c:2632) > ==23786== by 0x4EBAA65: g_test_run_suite_internal (gtestutils.c:2720) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== Uninitialised value was created by a stack allocation > ==23786== at 0x1370B0: test_invalid_discard_write_zeroes > (vhost-user-blk-test.c:102) > ==23786== > ==23786== Conditional jump or move depends on uninitialised value(s) > ==23786== at 0x5F027F8: vfprintf (vfprintf.c:1642) > ==23786== by 0x5FBA8FE: __vsprintf_chk (vsprintf_chk.c:83) > ==23786== by 0x5FBA829: __sprintf_chk (sprintf_chk.c:31) > ==23786== by 0x140A25: sprintf (stdio2.h:33) > ==23786== by 0x140A25: qtest_memwrite (libqtest.c:1067) > ==23786== by 0x13642F: virtio_blk_request (vhost-user-blk-test.c:90) > ==23786== by 0x13714D: test_invalid_discard_write_zeroes > (vhost-user-blk-test.c:123) > ==23786== by 0x1380CB: test_basic (vhost-user-blk-test.c:357) > ==23786== by 0x1380CB: basic (vhost-user-blk-test.c:452) > ==23786== by 0x121837: run_one_test (qos-test.c:182) > ==23786== by 0x4EBAA65: test_case_run (gtestutils.c:2632) > ==23786== by 0x4EBAA65: g_test_run_suite_internal (gtestutils.c:2720) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== Uninitialised value was created by a stack allocation > ==23786== at 0x1370B0: test_invalid_discard_write_zeroes > (vhost-user-blk-test.c:102) > ==23786== > ==23786== Conditional jump or move depends on uninitialised value(s) > ==23786== at 0x5F0324C: vfprintf (vfprintf.c:1642) > ==23786== by 0x5FBA8FE: __vsprintf_chk (vsprintf_chk.c:83) > ==23786== by 0x5FBA829: __sprintf_chk (sprintf_chk.c:31) > ==23786== by 0x140A25: sprintf (stdio2.h:33) > ==23786== by 0x140A25: qtest_memwrite (libqtest.c:1067) > ==23786== by 0x13642F: virtio_blk_request (vhost-user-blk-test.c:90) > ==23786== by 0x13714D: test_invalid_discard_write_zeroes > (vhost-user-blk-test.c:123) > ==23786== by 0x1380CB: test_basic (vhost-user-blk-test.c:357) > ==23786== by 0x1380CB: basic (vhost-user-blk-test.c:452) > ==23786== by 0x121837: run_one_test (qos-test.c:182) > ==23786== by 0x4EBAA65: test_case_run (gtestutils.c:2632) > ==23786== by 0x4EBAA65: g_test_run_suite_internal (gtestutils.c:2720) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== by 0x4EBA97A: g_test_run_suite_internal (gtestutils.c:2732) > ==23786== Uninitialised value was created by a stack allocation > ==23786== at 0x1370B0: test_invalid_discard_write_zeroes > (vhost-user-blk-test.c:102) > ==23786== > > > Ciao, > > Claudio >
