VBoxManage hangs after some parallel operations

[georgesovetov]

This sometimes happens when I run some commands in parallel.

Processes:

(ins)george@gsovetov:~/Development/***$ ps -AlF | grep --color -i vbox 
1 S root      1321     2  0  60 -20 -     0 -          0   4 Jan30 ?        00:00:00 [iprt-VBoxWQueue]
1 S root      1341     2  0  80   0 -     0 -          0   7 Jan30 ?        00:00:00 [iprt-VBoxTscThr]
0 S george    7401 32042  0  80   0 -  3196 -        992   1 19:53 pts/4    00:00:00 grep --color -i vbox
0 S george   15921 23446  0  80   0 - 596033 -     919504  6 17:22 ?        00:00:59 /usr/lib/virtualbox/VBoxHeadless --comment ***-001 --startvm e03278fd-e235-594b-8ad9-*** --vrde config
0 S george   16040 23446  0  80   0 - 595039 -     913772  1 17:22 ?        00:01:29 /usr/lib/virtualbox/VBoxHeadless --comment ***-002 --startvm a2221747-de55-5022-b579-*** --vrde config
0 S george   23441     1  0  80   0 - 47323 SyS_po 37212  10 Jan30 ?        07:07:13 /usr/lib/virtualbox/VBoxXPCOMIPCD
0 S george   23446     1  1  80   0 - 512180 core_s 1102356 2 Jan30 ?       11:12:08 /usr/lib/virtualbox/VBoxSVC --auto-shutdown
0 S george   25549     1  0  80   0 - 98202 -      16452  11 18:11 tty2     00:00:00 /usr/lib/virtualbox/VBoxManage controlvm ***-001 nic3 intnet 4c8cf59c-40eb-11e9-a5eb-e8de2706accd 10.254.254.0/28 flat
0 S george   25593     1  0  80   0 - 98202 -      16392   1 18:11 tty2     00:00:20 /usr/lib/virtualbox/VBoxManage createmedium disk --filename /home/george/***-004.vmdk --diffparent /home/george/***-template.vmdk
0 S george   25697     1  0  80   0 - 98202 -      16668   3 18:11 tty2     00:00:00 /usr/lib/virtualbox/VBoxManage list vms

Three last commands are hanging.

There are always four threads, one of which is hanging in poll. Typical backtrace of hanging command (with lots of "??" unfortunately):

pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225

Thread 4 (Thread 0x7ff0dc331700 (LWP 25603)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
#1  0x00007ff0e76d327e in RTSemEventWait () from /usr/lib/virtualbox/VBoxRT.so
...

Thread 3 (Thread 0x7ff0ddc49700 (LWP 25602)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007ff0e729ccfb in VBoxNsprPR_WaitCondVar () from /usr/lib/virtualbox/VBoxXPCOM.so
#2  0x00007ff0e729cf3b in VBoxNsprPR_Wait () from /usr/lib/virtualbox/VBoxXPCOM.so
...

Thread 2 (Thread 0x7ff0ddcca700 (LWP 25601)):
#0  0x00007ff0e69856ad in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007ff0e729a134 in ?? () from /usr/lib/virtualbox/VBoxXPCOM.so
#2  0x00007ff0e729bb8f in VBoxNsprPR_Poll () from /usr/lib/virtualbox/VBoxXPCOM.so
...

Thread 1 (Thread 0x7ff0e8037680 (LWP 25593)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
#1  0x00007ff0e729c881 in ?? () from /usr/lib/virtualbox/VBoxXPCOM.so
#2  0x00007ff0e729cc9e in VBoxNsprPR_WaitCondVar () from /usr/lib/virtualbox/VBoxXPCOM.so
#3  0x00007ff0e729cf3b in VBoxNsprPR_Wait () from /usr/lib/virtualbox/VBoxXPCOM.so
...
#11 0x0000000000000000 in ?? ()

I have Windows and Linux guests but it seems it doesn't matter what the guests are.

[georgesovetov]

strace -f -o VboxManage.strace.txt /usr/lib/virtualbox/VBoxManage list vms

[georgesovetov]

gdb --pid 25593 -ex 'thread apply all bt' --batch > 25593.bt.txt

[georgesovetov]

From the user perspective, it looks like this:

(ins)george@gsovetov:~/Development/func_tests$ VBoxManage list vms
"win10-old" {25217df2-1323-4675-b588-1cad844b588a}
"trusty" {49086e3f-dbec-4450-bdb2-a4f329df7ef3}
"win10-new" {9c4de5de-056d-497f-a7e6-c570425656b5}
"win10-0-template" {85f9b4fc-b2d4-4c99-a9d5-383dc3719b1a}
"win10-0-template-20180921" {6ebdf3ec-d886-4c8a-9ef8-a5175eead935}
"dummy-0-dummy" {ea2aced2-ad59-59cd-b133-a66beb111873}
"dummy-0-list-a" {b7a9e8b2-7d31-52e1-9458-551f6b320ea7}

^{That's where it hangs.}

There is another thing to mention. For simplicity, I place all VMs into a single folder and all their logs go into a single subfolder named Logs. I thought they could clash somehow only when I was filling out the bug report form and could't find there log files from running VMs. Two of five log files were empty, other three ended with entries related to poweroff.

One of two running machines was unresponsive, the other could be accessed via SSH.

Here are netstat output, recv queue size of unresponsive VM is 2:

(ins)george@gsovetov:~/Development/***$ sudo netstat -ltpn | grep -i vbox
tcp        0      0 0.0.0.0:20010           0.0.0.0:*               LISTEN      15921/VBoxHeadless
tcp        0      0 0.0.0.0:20011           0.0.0.0:*               LISTEN      15921/VBoxHeadless
tcp        2      0 0.0.0.0:20012           0.0.0.0:*               LISTEN      15921/VBoxHeadless
tcp        0      0 0.0.0.0:20020           0.0.0.0:*               LISTEN      16040/VBoxHeadless
tcp        0      0 0.0.0.0:20021           0.0.0.0:*               LISTEN      16040/VBoxHeadless
tcp        0      0 0.0.0.0:20022           0.0.0.0:*               LISTEN      16040/VBoxHeadless
tcp6       0      0 :::20010                :::*                    LISTEN      15921/VBoxHeadless
tcp6       0      0 :::20020                :::*                    LISTEN      16040/VBoxHeadless