Re: make -j check failing on master, interesting valgrind errors on qos-test vhost-user-blk-test/basic

[Claudio Fontana]

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
>