[SOLVED] Sudden VM crash (aborted); short log

[HarryMan]

I had a VM crash a few minutes ago in the following environment:

Devuan Chimaera (debian 11) Host with backported 5.16.0 kernel (Support for USB 3)
Devuan Chimaera guest with standard distro kernel
Vbox 6.1.34 (recently upgraded) on host.
Guest additions might be behind (6.1.32)
Extensions are up to date (6.1.34)

I was tending to something else when I noticed the VM had disappeared. It was left in aborted state.

I saved the log; see attached.

[fth0]

00:00:25.748469 VMMDev: Guest Additions information report: Version 6.1.32 r149290 '6.1.32'

00:05:08.862027 VMMDev: Guest Log: 08:41:54.806457 main     VBoxService 6.1.32 r149290 (verbosity: 0) linux.amd64 (Jan 13 2022 20:10:27) release log
00:05:08.862096 VMMDev: Guest Log: 08:41:54.806489 main     Log opened 2022-04-30T08:41:54.726470000Z
00:05:08.862420 VMMDev: Guest Log: 08:41:54.807008 main     OS Product: Linux
00:05:08.863053 VMMDev: Guest Log: 08:41:54.807610 main     OS Release: 5.16.0-0.bpo.4-amd64
00:05:08.863201 VMMDev: Guest Log: 08:41:54.807801 main     OS Version: #1 SMP PREEMPT Debian 5.16.12-1~bpo11+1 (2022-03-08)
00:05:08.863288 VMMDev: Guest Log: 08:41:54.807886 main     Executable: /opt/VBoxGuestAdditions-6.1.32/sbin/VBoxService
00:05:08.863307 VMMDev: Guest Log: 08:41:54.807889 main     Process ID: 2475
00:05:08.863320 VMMDev: Guest Log: 08:41:54.807893 main     Package type: LINUX_64BITS_GENERIC
00:05:08.866156 VMMDev: Guest Log: 08:41:54.810766 main     6.1.32 r149290 started. Verbose level = 0

00:08:15.695966 VMMDev: Guest Log: 08:45:01.733577 control  Guest control service stopped
00:08:15.771523 VMMDev: Guest Log: 08:45:01.809146 control  Guest control worker returned with rc=VINF_TRY_AGAIN
00:08:15.771752 VMMDev: Guest Log: 08:45:01.809412 main     Session 0 is about to close ...
00:08:15.771777 VMMDev: Guest Log: 08:45:01.809444 main     Stopping all guest processes ...
00:08:15.771794 VMMDev: Guest Log: 08:45:01.809461 main     Closing all guest files ...

00:09:53.584434 VMMDev: Guest Log: 08:46:39.670844 main     VBoxService 6.1.34 r150636 (verbosity: 0) linux.amd64 (Mar 23 2022 00:46:49) release log
00:09:53.584485 VMMDev: Guest Log: 08:46:39.670847 main     Log opened 2022-04-30T08:46:39.670823000Z
00:09:53.584547 VMMDev: Guest Log: 08:46:39.671004 main     OS Product: Linux
00:09:53.584604 VMMDev: Guest Log: 08:46:39.671062 main     OS Release: 5.16.0-0.bpo.4-amd64
00:09:53.584631 VMMDev: Guest Log: 08:46:39.671091 main     OS Version: #1 SMP PREEMPT Debian 5.16.12-1~bpo11+1 (2022-03-08)
00:09:53.584652 VMMDev: Guest Log: 08:46:39.671111 main     Executable: /opt/VBoxGuestAdditions-6.1.34/sbin/VBoxService
00:09:53.584661 VMMDev: Guest Log: 08:46:39.671112 main     Process ID: 5842
00:09:53.584665 VMMDev: Guest Log: 08:46:39.671113 main     Package type: LINUX_64BITS_GENERIC
00:09:53.587455 VMMDev: Guest Log: 08:46:39.673886 main     6.1.34 r150636 started. Verbose level = 0

Did you install the VirtualBox Guest Additions 6.1.34 during this VM run, but not reboot the guest OS as requested? Or is the log file damaged (I'm biased because of your other disk I/O related threads )?

I was tending to something else when I noticed the VM had disappeared. It was left in aborted state.

The end of the myvm1.log file doesn't indicate any problems, but it ends prematurely. Did you get an error dialog that you didn't close before copying the file? Or did you mean that you left it "in aborted state" inside the VirtualBox Manager? What does "disappeared" mean here?

[HarryMan]

By "disappeared," I mean it aborted.

There was no error dialog.

Not sure what file you are referring to by "copy." If you mean the log file itself, I checked with lsof that it was not open by one of vbox's programs (yeah, that did occur to me also). When I find a log is cut short, I always run lsof on it just to make sure it is not still held open (maybe due to some file system cache delays, etc.).

But you are right about the guest additions. I must have missed that. They are still 6.1.32.

This has nothing to do with any other problems I reported elsewhere. This is an entirely different VM.

[fth0]

To sum it up, the guest OS inside the VM was running the VirtualBox Guest Additions (GA) 6.1.32 drivers in combination with the GA 6.1.34 services, the VM window disappeared, and the VM was shown in the VirtualBox Manager as aborted. Did you check the log files of the host OS and/or the (user-specific) global VirtualBox log files in ~/.config/VirtualBox? Did you check which VirtualBox processes were still running on the host?

Because of the state of the GA in the VM run, I'm not sure if it makes sense to investigate further, though ...

[HarryMan]

Sorry, once again, for my screw ups with the vbox versions. The guests are running the same versionsin every case; I have double checked this time. One host runs 6.1.32, the other 6.1.34. Each host's guest additions match respectively. In this case, it would be 6.1.32.

I did not realize there are global logs; thank you for that tip. I will be sure to reference them when these issues come up again.

And, just to reiterate, yes the log really was short. I have run into this in some other cases also (I think I posted one other topic here that shows a short log also). It could be that vbox is crashing before it can flush the messages to the log file in these cases.

[HarryMan]

It is happening again, aborted VM with the short log. Here is an update and some new info.

This problem is intermittent.
When the problem occurs, it seems to be reproducible; that is, whatever triggers it seems to set a persistent scenario.
I am running 6.1.34 on both hosts and guests. (I have upgraded all hosts and guests to 6.1.34 since previous posts.)
The 6.1.34 extensions are installed on the hosts.
The VM that is aborting is running GA 6.1.34.
There is another guest running under the same version.
The other guest does not have or need guest additions.
I have tried a different kernel on the host side.
I have rebooted the host with the VM in question with the same results.
I have thoroughly cleaned the file systems on the guest with fsck -f -y /dev/sdb, etc.
There are no apparent disk errors in the host's log files (/var/log/kern shows no errors with *ata*)
The keyboard-video-monitor switch (hereafter "kvms") is ONLY controlled by the host PCs.
No VM on either PC has access to the kvms (i.e., the kvms is not attached to any VMs on any PC).
Only the one VM aborts.

To reproduce the error:
Boot the host.
Start the 2 VMs.
Use the kvms to switch to another machine.
Use the same kvms to switch back to the host with the VM in question.
The GUI shows that the VM has aborted (hence, the short log).

Inspecting the log has not given support any useful information so far.
The attached file may shed some light on this, however.
It looks like there may be some USB subsystem problem.

[HarryMan]

One other observation, which is not quite complete in a sense.

I can definitely make this happen when the VM is in full screen mode. However, I am sure I have seen this happen a few times when it was not in full screen mode.

[fth0]

00:00:07.718765 nspr-6   Failed to open "/dev/vboxdrvu", errno=2, rc=VERR_VM_DRIVER_NOT_INSTALLED

This log message indicates a corrupt VirtualBox installation. I'd suggest to uninstall all VirtualBox packages (the VMs won't be removed), reboot the host, and reinstall Oracle VirtualBox. Please show the output of ls -l /dev/vbox* before the un-installation and after the re-installation.

00:05:26.270052 USBPROXY USBProxyBackendLinux: Device 046d:c52b (sysfs:/sys/devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.1/1-4.1.3//device:/dev/vboxusb/001/009) isn't accessible. giving udev a few seconds to fix this...

This log message indicates that VirtualBox is trying to capture a Logitech Unifying Receiver, which could be related to a wrong USB filter or to the KVM switch.

Regarding the KVM switch, I could envision all sorts of problems. I suppose you're switching several device types (e.g. displays, keyboard, mouse). For an experiment, I'd suggest to attach all but one of those devices to the host instead of to the KVM switch and to try to reproduce the issue. With this strategy, you could discover which of the device types is involved in the problem, or if it's the KVM switch itself.

[HarryMan]

Believe it or not (and you probably won't, I am not even sure if I do myself), but one of the disks of the VM had a file system error, which I was able to fix with fsck. Since then, I am not witnessing the crashes.

This is not to say it is fixed. However -- and this is important -- the errors in the file system were duplicate block links. fsck fixed these by duplicating the blocks so that the files no longer shared them.

So this could be caused by Linux ext4 bugs, or it could be caused by some bug in the vbox virtualization of the disks. At any rate, in all the years I've used Linux and Vbox together, I've never seen these kinds of errors.

I don't want to speak too soon, however. I've gotten bitten by resurgent bugs and problems in the past (not necessarily with virtualbox or Linux file systems, but in general). So let's not call this one solved just yet.

[HarryMan]

As far as those errors from the mouse, those should not have anything to do with this since the mouse is connected via the KVMS, not attached to any particular VM.

Another thing to consider in all of this is that this was only happening to VMs on one host. I've not experienced the same phenomenon on the other host, and that host is far busier than the host in question (the one hosting the VM that was crashing).

Also, I did notice this in the host kernel log (sorry I did not see this earlier):

Code: Select all   Expand viewCollapse view

May 14 02:32:29 testbox1-host kernel: [28463.402117] VirtualBoxVM[7433]: segfault at 7fd0e0f9d0f0 ip 00007fd3771438c4 sp 00007ffc98d0bca8 error 4 in libc-2.31.so[7fd3770c1000+14b000]
May 14 02:32:29 testbox1-host kernel: [28463.402132] Code: 29 4f 10 0f 29 57 20 0f 29 5f 30 48 83 c7 40 48 83 fa 40 77 d0 0f 11 29 0f 11 71 f0 0f 11 79 e0 44 0f 11 41 d0 41 0f 11 23 c3 <0f> 10 26 0f 10 6e 10 0f 10 76 20 0f 10 7e 30 44 0f 10 44 16 f0 4c

This error did occur around the time that the problematic VM crashed.

[HarryMan]

More than a week and no crashes of the VM that had had duplicate block references.

I would say this is solved, as strange as the solution was.