VBoxHeadless log file created in working directory since on 6.1.28

Discussions related to using VirtualBox on Linux hosts.
Post Reply
challengeursli
Posts: 20
Joined: 21. Oct 2021, 14:52

VBoxHeadless log file created in working directory since on 6.1.28

Post by challengeursli »

Since we upgraded our Ubuntu servers to VirtualBox 6.1.28, one of them is showing a weird behavior.

Every time our Mono/C# application calls a startvm command like this:

Code: Select all

VBoxManage startvm "W7_1" --type headless
a log file named like this is created:

Code: Select all

2021-11-26-09-35-27.016-VBoxHeadless-24090.log
Contents:

Code: Select all

Log created: 2021-11-26T09:26:34.547685000Z
Process ID:  31153 (0x79b1)
Parent PID:  6893 (0x1aed)
Executable:  /usr/lib/virtualbox/VBoxHeadless
Arg[0]: /usr/lib/virtualbox/VBoxHeadless
Arg[1]: --comment
Arg[2]: W7_1
Arg[3]: --startvm
Arg[4]: 5ffa184c-1cfe-4ce7-8918-71756a39ad6b
Arg[5]: --vrde
Arg[6]: config
I cannot reproduce it manually, it only happens when called from the Mono application.

The directory is filling up with thousands of these files, and we want to avoid that.

I saw a very old post which seems related here:
https://www.virtualbox.org/ticket/1956

Is there some switch to disable this?
klaus
Oracle Corporation
Posts: 1115
Joined: 10. May 2007, 14:57

Re: VBoxHeadless log file created in working directory since on 6.1.28

Post by klaus »

Those log files are debug log files, and as the name says should be created only for debug builds. Happens usually because developers made a mistake, somehow triggering debug logging.

In your case the cause is unclear, since there are no messages besides the log header. This means it's a different case than the ticket you found (there it was forgotten unconditional debug logging). Your case appears to be conditional logging (which still writes out the header, but nothing else because the default debug log settings are "log nothing").

It can be hard to track down the cause (especially for others who do not see this happen), because in your case it appears to be dependent on the "circumstance" of starting the VM. Suspect it's some environment variable which triggers it, so you might get some clues by comparing the environments in both contexts. You can either do that by instrumenting your code and comparing it against the environment variables in a usual shell shown by the "env" command. Or you can get the environment of a running process with

Code: Select all

cat /proc/[pid]/environ
. Note that this consists of NUL separated strings (NUL is invisible in usual terminals, and there are no newlines which would make it much easier to read). And the pid can be taken either from the name of the log file (the number after the last -) or from the content of the log file. Which tells me that your example isn't consistent (the log filename can't be for the file with the content).

Alternatively you could try enabling all debug logging, and see if you get some hints about the cause this way. This needs setting environment variable VBOX_LOG to "all=~0" (the variable should not contain "", but you may need "" to avoid shell expansion). For this it can be handy that

Code: Select all

VBoxManage startvm
has an option to pass environment variable, and you'll need -E VBOX_LOG="all=~0". Use "" at your discretion, as mentioned before. With all logging enabled you should get some text, which hopefully gives a clue about which part of the code is producing it.
challengeursli
Posts: 20
Joined: 21. Oct 2021, 14:52

Re: VBoxHeadless log file created in working directory since on 6.1.28

Post by challengeursli »

Thanks Klaus for the extensive tips.

It is correct that I pasted the contents of a file that didn't match the given file name, acutally the PIDs do match, of course.

I have checked the environment variables for the vboxheadless processes.
They looked like this:

Code: Select all

MAIL=/var/mail/xxx
USER=jbxs2c
LANGUAGE=en_US:enSHLVL=2
HOME=/home/xxx
DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
LOGNAME=xxx
_=/usr/bin/VBoxManage
XDG_SESSION_ID=c3
PATH=/usr/bin:/bin:/usr/sbin:/sbin
INVOCATION_ID=a7907ec0de284288a52fdfe982f2cce0
XDG_RUNTIME_DIR=/run/user/1000
LANG=en_US.UTF-8
SHELL=/bin/bash
PWD=/home/xxx
LOG=/home/xxx/somelog
VBOX_XPCOM_HOME=/usr/lib/virtualbox
I can see some variables here coming from the script that starts the very first VM.
To rule out that this is causing the issue, I stopped all VMs, waited for VBoxSVC to terminate, and then started a VM manually once, which led to more "default" environment variables.
Still the logs are being created.

I then further investigated the log files and noticed that they are solely being created for Windows 7 VMs (both 32 and 64 bit). We also run Windows 10, Linux and other VMs on this server, but no log files for these.

So I assume it must be something specific in these VMs (in their configuration/vbox file?) triggering the logging.
I checked the vbox file for ExtraDataItem containing Dbg or Debug, but couldn't find anything.

Do you have an idea what's going on and why it may only be happening for W7 VMs?
klaus
Oracle Corporation
Posts: 1115
Joined: 10. May 2007, 14:57

Re: VBoxHeadless log file created in working directory since on 6.1.28

Post by klaus »

In this case I would hope that turning on all debug logging (which in a release build shouldn't produce anything) when starting one of your Windows 7 VMs should give a hint.

The command line would be

Code: Select all

VBoxManage startvm -E VBOX_LOG="all=~0" win7
Of course use the appropriate VM name instead of "win7".

If this produces more than the debug log file header this would hopefully give me enough hints what is causing the whole issue.
challengeursli
Posts: 20
Joined: 21. Oct 2021, 14:52

Re: VBoxHeadless log file created in working directory since on 6.1.28

Post by challengeursli »

The nice thing is that I found that the log is also created if I start the VM manually.
I had troubles reproducing this before because I wasn't starting Windows 7 VMs, and as I wrote the issue happens only for W7.

So now I do:

Code: Select all

vboxmanage startvm -E VBOX_LOG="all=~0"  "W7 Analyzer New 30" --type headless
which produces the following log:

Code: Select all

Log created: 2021-12-06T09:10:26.242613000Z
Process ID:  13554 (0x34f2)
Parent PID:  13532 (0x34dc)
Executable:  /usr/lib/virtualbox/VBoxHeadless
Arg[0]: /usr/lib/virtualbox/VBoxHeadless
Arg[1]: --comment
Arg[2]: W7 Analyzer New 30
Arg[3]: --startvm
Arg[4]: c577dd42-ca2f-40cc-8788-fcc29affadd1
Arg[5]: --vrde
Arg[6]: config
Audio: Initializing OSS driver
OSS: No devices found, audio is not available
OSS: No devices found, audio is not available
challengeursli
Posts: 20
Joined: 21. Oct 2021, 14:52

Re: VBoxHeadless log file created in working directory since on 6.1.28

Post by challengeursli »

The issue seems to be related to the OSS audio driver.
For some reason, the Windows 7 machines have "OSS Audio driver" set, while e.g. on W10, I see "Pulse Audio".
If I change the audio driver to "Pulse Audio" for the W7 machine, the log file is not created anymore.

I have also tried installing the following packages on the Ubuntu host:
  • oss-core
    oss4-gtk
But the log is still created, error remains:

Code: Select all

Audio: Initializing OSS driver
OSS: No devices found, audio is not available
It would be nice to be able to fix this without having to change the config on all W7 VMs and take new snapshots. Do you have an idea how?
klaus
Oracle Corporation
Posts: 1115
Joined: 10. May 2007, 14:57

Re: VBoxHeadless log file created in working directory since on 6.1.28

Post by klaus »

Thanks, that helped... the OSS audio code had debug logging enabled unconditionally, causing this mess. Probably an unintentional change during development which shouldn't have been ever committed to the repository. Fixed in the source code, and the next release (and also the next test build, any build with revision 148672 and higher) will not show this behavior.

I suspect that you don't need any audio for your VMs, especially not OSS. For headless VMs it can make sense to have audio enabled, but it would use a different audio backend anyway if you connect over RDP/VNC/...
challengeursli
Posts: 20
Joined: 21. Oct 2021, 14:52

Re: VBoxHeadless log file created in working directory since on 6.1.28

Post by challengeursli »

Thanks klaus, I'll apply a temporary fix then and wait for the next release.
Post Reply