iSCSI timeout causes bad VBoxHeadless behaviour

[Jakob Østergaard Hegelund]

I have an iSCSI server which some times takes a little too long to respond to iSCSI requests.

Most of the time, VB pauses the affected VMs. However, sometimes instead of pause VB will power-off the VM but not complete the power-off. I wonder why it decides to power-off rather than pause - is this a bug or intended? In case it is intended, there still is a bug:

What happens is that I have a VBoxHeadless process running, but the VM state is set to "powered off". Since I cannot power it off using VBoxManage (cannot power-off a powered-off VM), there is no VB interface to properly power off the VM. I shouldn't need one either - if the state is powered-off, the VBoxHeadless process should not be there at all.

The only "solution" I have is to kill the VBoxHeadless process. This can't be right.

Host details; IBM HS22 blade with 8 (HT) cores and 32G memory running Solaris 10 update 9 and VirtualBox 4.0.2.

The VB log from the time this happens says:

306:50:47.638 iSCSI: login to target iqn.1986-03.com.sun:02:33f117f0-be5b-6a82-ab92-fa9aa4bd65ea failed
306:50:47.638 I/O cache: Error while writing entry at offset 38037016064 (4096 bytes) to medium "ahci-0-0" (rc=VERR_BROKEN_PIPE)
306:50:47.638 VM: Raising runtime error 'BLKCACHE_IOERR' (fFlags=0x6)
306:50:47.638 I/O cache: Error while writing entry at offset 37954772480 (12288 bytes) to medium "ahci-0-0" (rc=VERR_BROKEN_PIPE)
306:50:47.638 Changing the VM state from 'RUNNING' to 'SUSPENDING'.
306:50:47.639 I/O cache: Error while writing entry at offset 18555645440 (4096 bytes) to medium "ahci-0-0" (rc=VERR_BROKEN_PIPE)
306:50:47.639 I/O cache: Error while writing entry at offset 18555633152 (4096 bytes) to medium "ahci-0-0" (rc=VERR_BROKEN_PIPE)
306:50:47.639 I/O cache: Error while writing entry at offset 38037044736 (49152 bytes) to medium "ahci-0-0" (rc=VERR_BROKEN_PIPE)
306:50:47.639 I/O cache: Error while writing entry at offset 38077488640 (8192 bytes) to medium "ahci-0-0" (rc=VERR_BROKEN_PIPE)
306:50:47.639 I/O cache: Error while writing entry at offset 38037020160 (24576 bytes) to medium "ahci-0-0" (rc=VERR_BROKEN_PIPE)
306:50:47.639 I/O cache: Error while writing entry at offset 18555698688 (20480 bytes) to medium "ahci-0-0" (rc=VERR_NET_CONNECTION_REFUSED)
328:19:30.594 VirtualBoxClient: detected unresponsive VBoxSVC (rc=NS_ERROR_CALL_FAILED)
328:19:30.594 VBoxHeadless: VBoxSVC became unavailable, exiting.
328:19:30.594 Console::powerDown(): A request to power off the VM has been issued (mMachineState=Running, InUninit=1)
328:19:30.594 VRDP: TCP server closed.
328:20:00.604 VirtualBoxClient: detected working VBoxSVC (rc=NS_OK)

The VM no longer appears under "VBoxManage list runningvms".

However, a "ps" will still show a VBoxHeadless process for this VM.

A VBoxManage to inquire for state says:

$ VBoxManage showvminfo ...|grep tate
State:           powered off (since 2011-01-24T14:03:54.000000000)

It seems to me that the poweroff stops half way through. If only it could go all the way, the Solaris SMF would discover this and restart my VM.