Change default time stamp of Vbox.log to absolute (not relative)

[Feline]

Each entry of the release log (VBox.log) appears to have a time stamp. The format of which is hh:mm:ss: but relative to the start of the virtual machine. So an entry starting 00:24:31.123456 is 24 minutes and 31 seconds from when the guest was started. However, most if not all logs from within the guest (examples being the linux kernel log or the windows event log) prefix their entries with the wall clock time. This makes attempting to synchronise entries in both logs, for troubleshooting purposes, quite difficult.

I did find out myself that I could get actual (not relative) time stamps in the release log by using the VBoxManage command but some users that are new to the product may not feel confident in attempting such commands, or indeed know about the command at all.

Perhaps consideration could be given to changing the release log time stamp to show the wall clock time by default ?

[Socratis]

I did find out myself that I could get actual (not relative) time stamps in the release log by using the VBoxManage command

Would you mind sharing the info? Are you referring to the 'debugvm' command with the 'logflags time' option? An exact example would be appreciated. TIA.

[Feline]

The command I used was

VBoxManage debugvm "vm name" logflags --release time

The result was that each entry had the wall clock time followed by the relative time and then the text of the message, for example :

13:38:23.123456 00:01:34.987654 Starting Host clipboard service.

For new users there is the added complication that they may not know the difference between the "debug log" and the "release log" and the logflags settings appear to refer to both types of log.

[Socratis]

Yes, that's what I thought (see my initial question). This has a couple of drawbacks, the biggest ones being that a) it is not permanent and b) the VM has to be running. I thought that you had discovered another way. Thanks anyway.

+1 for the idea in any case.

[Frank Mehnert]

If 'VBoxManage debugvm' is used without the '--release' parameter then the debug logging is changed. Debug logging is not enabled in official builds. I don't think that changing the default time stamp format of release log files makes sense. The current format is very helpful in particular for us (the VBox team) to debug issues reported here. If another format is desired, do it like described in comment:2.

[Feline]

Thank you for your reply frank.

May I ask why the relative format is that much more helpful to the VBox team than having the wall clock time ? I only ask because I've always worked on systems where absolute time stamps were used in logs and was surprised to find a relative value in the VBox log.

Having found the required command to alter the log format, I'm more than happy to use that in the future, should the need arise.

[Frank Mehnert]

It's more helpful because it's easier to read :-) I agree that it's nice to have absolute time stamps in VBox.log if the VBox.log file is used in conjunction with a system log file but this is not the normal case in this bugtracker.

[Feline]

Thank you frank.

Please close ticket when convenient.

[Frank Mehnert]

Thanks for understanding.

[数组越界]

However,I really think it is better to have date and time in release log since we users also need to debug.

[Socratis]

You posted the comment in your duplicate ticket #18474, but I thought it would be better to reply here.

Replying to 数组越界:

The problem is that if I used the following command

VBoxManage debugvm "vm name" logflags --release time

In logs there is only time instead of date and time, since our vms have run a quite long time, I need to find out what happened inside release log when guest restarted.

According to the User Manual, ch. 8.42 VBoxManage debugvm:

VBoxManage debugvm <uuid|vmname> logflags [[--release] | [--debug]] [flags...]

and in the "flags" section, I can see:

time

Prefix each log line with the current UTC wall time.

My understanding is that you want the date as well.


I entered the following command:

VBoxManage startvm <VM>; VBoxManage debugvm <VM> logflags --release time

and although it doesn't start the time logging from the get-go, in my log I see the following:

00:00:00.918239 VirtualBox VM 6.0.97 r129161 darwin.amd64 (Mar 4 2019 14:44:21) ...
00:00:00.918243 Log opened 2019-03-06T07:57:11.964346000Z
...
00:00:01.062177 ******************* End of VT-x features ********************
00:00:01.062192 VMEmt: Halt method global1 (5)
00:00:01.062261 VMEmt: HaltedGlobal1 config: cNsSpinBlockThresholdCfg=2000
00:00:01.062267 Changing the VM state from 'CREATING' to 'CREATED'
00:00:01.067689 Changing the VM state from 'CREATED' to 'POWERING_ON'
00:00:01.067754 Changing the VM state from 'POWERING_ON' to 'RUNNING'
00:00:01.067772 Console: Machine state changed to 'Running'
00:00:01.070337 VMMDev: Guest Log: BIOS: VirtualBox 6.0.97
00:00:01.070472 PCI: Setting up resources and interrupts
00:00:01.070876 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:01.084837 Display::handleDisplayResize: uScreenId=0 ...
00:00:01.084900 GUI: UIFrameBufferPrivate::NotifyChange: ...
00:00:01.085589 VMMDev: Guest Log: CPUID EDX: 0x178bfbbf
00:00:01.085638 PIIX3 ATA: Ctl#0: RESET, DevSel=0 AIOIf=0 ...
00:00:01.085694 PIIX3 ATA: Ctl#0: finished processing RESET
00:00:01.086284 VMMDev: Guest Log: BIOS: ata0-0: ...
00:00:01.086977 PIIX3 ATA: Ctl#0: RESET, DevSel=1 AIOIf=0 ...
00:00:01.087026 PIIX3 ATA: Ctl#0: finished processing RESET
00:00:01.087132 PIIX3 ATA: Ctl#1: RESET, DevSel=0 AIOIf=0 ...
00:00:01.087192 PIIX3 ATA: Ctl#1: finished processing RESET
00:00:01.090711 PIT: mode=2 count=0x48d3 (18643) - 64.00 Hz (ch=0)
00:00:01.106529 Display::handleDisplayResize: uScreenId=0 ...
00:00:01.106579 GUI: UIFrameBufferPrivate::NotifyChange: ...
07:57:12.619070 00:00:01.572977 GUI: UIMachineViewNormal::resendSizeHint...
07:57:12.619126 00:00:01.573031 VMMDev: SetVideoModeHint: ...
07:57:12.619155 00:00:01.573061 GUI: UIMachineView::sltHandleNotifyChange:...
...

So, after the "00:00:01.106579" time mark, the UTC time is prepended to the relative time i the log.

A couple (maybe more) year ago I remember seeing a VBox.log where the UTC time was logged from the first line, I asked, never got an answer, and I never bothered to look how it was done.

Now, you can combine the log start time (the 2nd line in any log) with the time and get something meaningful?

My understanding is that you are proposing this:

...
00:00:01.106579 GUI: UIFrameBufferPrivate::NotifyChange: ...
2019-03-06T07:57:12.619070 00:00:01.572977 GUI: UIMachineViewNormal::resendSizeHint...
2019-03-06T07:57:12.619126 00:00:01.573031 VMMDev: SetVideoModeHint: ...
2019-03-06T07:57:12.619155 00:00:01.573061 GUI: UIMachineView::sltHandleNotifyChange:...
...

Right?

[数组越界]

Yes, I want both date and time.Because it's not easy to calculate the date if it's a long-time running vm,I need to add hours to the base time in 2nd line.