Bug 259234

Summary: emulators/virtualbox-ose proliferation of ~/⋯-VirtualBoxVM-⋯.log files
Product: Ports & Packages Reporter: Graham Perrin <grahamperrin>
Component: Individual Port(s)Assignee: Virtualbox Team (Nobody) <vbox>
Status: Closed FIXED    
Severity: Affects Many People CC: madpilot, newton.ja.terry
Priority: --- Flags: bugzilla: maintainer-feedback? (vbox)
Version: Latest   
Hardware: Any   
OS: Any   

Description Graham Perrin freebsd_committer freebsd_triage 2021-10-17 18:49:11 UTC
<https://forums.freebsd.org/threads/82478/>

> VirtualBox creates small logs in the working directory

Confirmed, at least for ~

% ls ~/*.log | grep -i virtualbox
/home/grahamperrin/2021-10-10-18-14-31.079-VirtualBoxVM-74616.log
/home/grahamperrin/2021-10-11-17-31-03.009-VirtualBoxVM-40559.log
/home/grahamperrin/2021-10-11-17-31-18.067-VirtualBoxVM-40561.log
/home/grahamperrin/2021-10-11-17-37-25.039-VirtualBoxVM-40574.log
/home/grahamperrin/2021-10-11-17-57-23.022-VirtualBoxVM-40639.log
/home/grahamperrin/2021-10-11-17-58-35.045-VirtualBoxVM-40641.log
/home/grahamperrin/2021-10-11-19-13-43.029-VirtualBoxVM-40777.log
/home/grahamperrin/2021-10-11-19-26-03.006-VirtualBoxVM-40802.log
/home/grahamperrin/2021-10-11-19-27-00.004-VirtualBoxVM-40804.log
/home/grahamperrin/2021-10-11-19-53-00.033-VirtualBoxVM-40845.log
/home/grahamperrin/2021-10-11-20-02-48.025-VirtualBoxVM-40871.log
/home/grahamperrin/2021-10-11-20-09-06.046-VirtualBoxVM-40878.log
/home/grahamperrin/2021-10-11-20-10-34.012-VirtualBoxVM-40884.log
/home/grahamperrin/2021-10-12-05-50-48.024-VirtualBoxVM-85072.log
/home/grahamperrin/2021-10-13-05-26-17.090-VirtualBoxVM-4675.log
/home/grahamperrin/2021-10-13-05-33-42.007-VirtualBoxVM-4684.log
/home/grahamperrin/2021-10-16-00-04-21.092-VirtualBoxVM-50520.log
/home/grahamperrin/2021-10-16-00-12-02.013-VirtualBoxVM-50607.log
/home/grahamperrin/2021-10-16-01-54-55.083-VirtualBoxVM-51135.log
/home/grahamperrin/2021-10-16-04-20-32.007-VirtualBoxVM-51385.log
/home/grahamperrin/2021-10-16-04-31-46.059-VirtualBoxVM-51428.log
/home/grahamperrin/2021-10-16-05-43-43.011-VirtualBoxVM-4849.log
/home/grahamperrin/2021-10-16-06-37-46.015-VirtualBoxVM-5531.log
/home/grahamperrin/2021-10-16-07-31-12.017-VirtualBoxVM-5565.log
/home/grahamperrin/2021-10-16-08-01-42.011-VirtualBoxVM-5598.log
/home/grahamperrin/2021-10-16-08-10-28.064-VirtualBoxVM-5603.log
/home/grahamperrin/2021-10-16-14-28-31.068-VirtualBoxVM-6622.log
/home/grahamperrin/2021-10-16-16-30-11.037-VirtualBoxVM-6843.log
/home/grahamperrin/2021-10-16-16-39-49.076-VirtualBoxVM-6864.log
/home/grahamperrin/2021-10-16-17-01-36.092-VirtualBoxVM-6927.log
/home/grahamperrin/2021-10-16-18-34-25.048-VirtualBoxVM-7224.log
/home/grahamperrin/2021-10-16-20-50-30.046-VirtualBoxVM-7542.log
/home/grahamperrin/2021-10-17-02-38-28.084-VirtualBoxVM-8440.log
/home/grahamperrin/2021-10-17-03-12-01.077-VirtualBoxVM-8531.log
/home/grahamperrin/2021-10-17-03-20-26.098-VirtualBoxVM-8541.log
/home/grahamperrin/2021-10-17-04-21-47.032-VirtualBoxVM-50441.log
/home/grahamperrin/2021-10-17-04-28-22.030-VirtualBoxVM-50458.log
/home/grahamperrin/2021-10-17-04-51-46.094-VirtualBoxVM-50513.log
/home/grahamperrin/2021-10-17-09-38-29.080-VirtualBoxVM-3030.log
/home/grahamperrin/2021-10-17-09-44-30.016-VirtualBoxVM-3073.log
/home/grahamperrin/2021-10-17-12-11-30.021-VirtualBoxVM-2821.log
/home/grahamperrin/2021-10-17-12-59-15.001-VirtualBoxVM-2926.log
/home/grahamperrin/2021-10-17-15-51-17.000-VirtualBoxVM-3290.log
/home/grahamperrin/2021-10-17-16-17-05.018-VirtualBoxVM-3328.log
/home/grahamperrin/2021-10-17-16-29-22.013-VirtualBoxVM-3369.log
/home/grahamperrin/2021-10-17-16-47-30.028-VirtualBoxVM-3397.log
/home/grahamperrin/2021-10-17-17-53-28.066-VirtualBoxVM-3595.log
/home/grahamperrin/2021-10-17-18-00-07.084-VirtualBoxVM-3618.log
/home/grahamperrin/2021-10-17-18-36-19.056-VirtualBoxVM-3671.log
% pkg info -x virtualbox
virtualbox-ose-6.1.26_3
virtualbox-ose-kmod-6.1.26
% uname -aKU
FreeBSD mowa219-gjp4-8570p-freebsd 14.0-CURRENT FreeBSD 14.0-CURRENT #112 main-n249988-2c614481fd5: Sun Oct 10 21:42:16 BST 2021     root@mowa219-gjp4-8570p-freebsd:/usr/obj/usr/src/amd64.amd64/sys/GENERIC-NODEBUG  amd64 1400036 1400036
% freebsd-version -kru
14.0-CURRENT
14.0-CURRENT
14.0-CURRENT
%
Comment 1 Graham Perrin freebsd_committer freebsd_triage 2021-10-21 05:56:03 UTC
From opening post <https://forums.freebsd.org/posts/537276>: 

> … from virtualbox-ose-6.1.22_1 to virtualbox-ose-6.1.26_3. …

If it helps to understand the bug, as it is now: 

* I vaguely recall occasional manual removal of .log files from ~ with 
  _lesser_ versions of VirtualBox. 

There were, in the past, so few that I paid almost zero attention. I did wonder whether they were visible debris, from guest sessions that were abnormally killed. (So little attention, I never thought to browse my home directory _during_ a run of a guest, to tell whether a .log was normally visible during a run.)

----

As things are now: 

% pkg info -x virtualbox
virtualbox-ose-6.1.26_3
virtualbox-ose-kmod-6.1.26
% 

I see a log file appear immediately after starting, for example, a saved session. 

During the run: 

% date ; cat 2021-10-21-05-50-55.003-VirtualBoxVM-56324.log
Thu 21 Oct 2021 06:55:39 BST
Log created: 2021-10-21T05:50:55.038476000Z
Process ID:  56324 (0xdc04)
Parent PID:  56320 (0xdc00)
Executable:  /usr/local/lib/virtualbox/VirtualBoxVM
Arg[0]: /usr/local/lib/virtualbox/VirtualBoxVM
Arg[1]: --comment
Arg[2]: Windows
Arg[3]: --startvm
Arg[4]: 6bec4796-c6ff-4ebc-8c20-3e56093e1eca
Arg[5]: --no-startvm-errormsgbox
%
Comment 2 Graham Perrin freebsd_committer freebsd_triage 2021-10-21 06:43:38 UTC
(In reply to Graham Perrin from comment #1)

> … During the run: …

After graceful closure and save of the guest, followed by a graceful quit of the Oracle VM VirtualBox application: the same. 

(The file persists, nothing appended.)
Comment 3 Guido Falsi freebsd_committer freebsd_triage 2021-10-21 07:50:46 UTC
This is a known issue since 6.1.x got in the tree. It was deemed not important enough to not update the port to 6.1.

They are left behind every time a virtual machine is started. Someone (can't remember who) observed they used to be created in the past too, but usually automatically removed if everything went fine with the launched VM.

One thing that could help with this is dig out in the source code where these files are being created.

When debugging such issues a lot of time needs to be spent on finding the involved part of the source code [1], especially when the involved people do not know the structure of the code by hearth. So if you have time to spend on this digging the source code would help more than describing the external behaviour of the software, which is already known.

Also understanding the original purpose of these log files could help.


[1] this is also the reason why good backtraces are so important when any bug arises in any mildly complex software
Comment 4 Graham Perrin freebsd_committer freebsd_triage 2021-10-21 21:39:08 UTC
Thanks, I'll do what I can (and draw attention in FreeBSD Forums).
Comment 5 Newton Terry 2021-10-23 16:38:22 UTC
(In reply to Guido Falsi from comment #3)
> One thing that could help with this is dig out in the source code where these
> files are being created.
It looks like the involved parts of the source code are to find in 
https://www.virtualbox.org/browser/vbox/trunk/src/VBox/Runtime/VBox/log-vbox.cpp

"Create the default logging instance."
https://www.virtualbox.org/browser/vbox/trunk/src/VBox/Runtime/VBox/log-vbox.cpp#L496

"Write a log header."
https://www.virtualbox.org/browser/vbox/trunk/src/VBox/Runtime/VBox/log-vbox.cpp#L519

I'm not sure how to proceed from here to find the purpose of their creation and the cause of the log files not being removed, assuming they are automatically removed.


Apropos, the creation of those log files can be suppressed by setting VirtualBox env variable "VBOX_LOG_DEST" to "nofile".

References: 
https://www.virtualbox.org/browser/vbox/trunk/src/VBox/Runtime/VBox/log-vbox.cpp#L38
https://www.virtualbox.org/wiki/VBoxLogging
Comment 6 Guido Falsi freebsd_committer freebsd_triage 2021-10-23 20:27:08 UTC
(In reply to Newton Terry from comment #5)

Thanks for your findings.

So this is the default logging mechanism doing its work. If configured to log a lot of information would be logged to these files.

As far as I know these files have always been created by virtualbox but usually got deleted, maybe right away, depending on..."Something".

But I cannot see any code to remove these files in `src/VBox/Runtime/common/log/log.cpp` or `src/VBox/Runtime/VBox/log-vbox.cpp`. 

So at present I'm asking myself how these got deleted in version 5.2.x.

A quick look at the old distfile or the change history of these files is not helpful unluckily.
Comment 7 Guido Falsi freebsd_committer freebsd_triage 2022-02-09 10:08:55 UTC
To the OP, is this still an issue?

Looks like the latest update (6.1.32) fixed this.

Can you confirm?
Comment 8 Guido Falsi freebsd_committer freebsd_triage 2022-03-05 15:57:34 UTC
My testing shows the issue has been fixed after upgrade to 6.1.32
Comment 9 Graham Perrin freebsd_committer freebsd_triage 2022-04-04 16:26:15 UTC
(In reply to Guido Falsi from comment #7)

My apologies for the late response. 

I removed the    setenv VBOX_LOG_DEST nofile    workaround from my 
                 ~/.cshrc
then used Oracle VM VirtualBox Manager to start two guests. After gracefully shutting down one of the guests then quitting Oracle VM VirtualBox Manager: 

* no unexpected .log file in my home directory. 

Thank you!

----

% ls ~/*.log | grep -i virtualbox
ls: No match.
% ls ~/*.log 
ls: No match.
% pkg info -x virtualbox
virtualbox-ose-6.1.32_2
virtualbox-ose-kmod-6.1.32_1
% pkg -vv | grep -e url -e enabled
    url             : "pkg+http://pkg0.pkt.freebsd.org/FreeBSD:14:amd64/latest",
    enabled         : yes,
    url             : "https://alpha.pkgbase.live/current/FreeBSD:14:amd64/latest",
    enabled         : no,
    url             : "file:///usr/local/poudriere/data/packages/main-default",
    enabled         : yes,
% uname -aKU
FreeBSD mowa219-gjp4-8570p-freebsd 14.0-CURRENT FreeBSD 14.0-CURRENT #8 main-n254268-50e244964e9-dirty: Mon Apr  4 09:29:49 BST 2022     root@mowa219-gjp4-8570p-freebsd:/usr/obj/usr/src/amd64.amd64/sys/GENERIC-NODEBUG amd64 1400056 1400056
%