Description of problem: Windows 7 guest reports incorrect time after a VM restart. Version-Release number of selected component (if applicable): RHEV-M: 3.2.6 RHEV-H: 6.5 (20140118.1.3.2.el6_5) vdsm-4.10.2-30.1.el6ev.x86_64 libvirt-0.10.2-29.el6_5.9.x86_64 How reproducible: This problem is reproducible every following the steps below. Steps to Reproduce: 1. Create a new Windows 7 VM with Time Zone - (GMT-05:00) US Eastern Standard Time 2. Start the VM 3. Verify the time on the Window and correct if neccesary. 4. Shutdown or Poweroff the VM. 5. Start the VM and verify the time. Actual results: The time on the Windows 7 VM is not set to correct time. Expected results: The time on the VM should correct based on the timezone. Additional info:
Testing on: 3.2.6 ================== Installed a Windows 7 VM. Time Zone - (GMT-05:00) US Eastern Standard Time Created a template. Created a pool. 1. Windows 7 VM deployed using a template from a pool. Windows time 3:51pm - // Should be 4:51pm EST utc_diff = -18000 Windows VM timezone EST vdsm.log: --------- 'timeOffset': '-18000', qemu.log: --------- -rtc base=2014-10-01T15:49:11,driftfix=slew 2. Corrected the time: Windows time 4:51pm utc_diff = 3521 3. Shutdown and Restart the system Windows time 9:54pm - // GMT -5 utc_diff = 3521 vdsm.log: ---------- 'timeOffset': '3521' qemu.log: ----------- -rtc base=2014-10-01T21:53:36,driftfix=slew 4. Corrected the time: Windows time 4:55pm utc_diff = -18005 5. Shutdown and Restart the system Windows time 3:59pm - // Should be 4:59 EST utc_diff = -18005 vdsm.log: ---------- 'timeOffset': '-18005' qemu.log: ------------ -rtc base=2014-10-01T15:58:16,driftfix=slew 6. Changed the time Windows time 5:03pm utc_diff = 3597 7. Shutdown and Restart the system Windows time 10:06pm utc_diff = 3597 vdsm.log: ----------- 'timeOffset': '3597' qemu.log: --------- -rtc base=2014-10-01T22:05:17,driftfix=slew
Correction on the RHEV-H libvirt revision. Should be libvirt-0.10.2-29.el6_5.7.x86_64.
I see two problems here, please correct me, Bimal, if I am wrong. 1) The display time of Windows VM is always off by 1 Hour (18000-14400=3600) after initial creation of VM in a pool from template. 2) 5 hours diff time on VM from the requested time zone after hard reboot. Looking through the outputs provided, seems like all the stack behaves properly and the value in the database is propagated correctly from the database to qemu. Which points to a question, how the database is updated by engine. What is the logic of updating utc_diff field?
1) The display time of Windows VM is always off by 1 Hour (18000-14400=3600) after initial creation of VM in a pool from template. >> This is correct. 2) 5 hours diff time on VM from the requested time zone after hard reboot. >> The 5 hour diff was only seen in 3.2.6 release. >> On 3.4.x the time, it was off by 1 hour. Didn't observe the 5 hour diff.
So, in 3.4, I see that timeOffset of a VM saved ok when VM is shut down. But then, when it is started, it is updated again to the "initial run" offset value. Looking through the code and the database values, seems to me that the logic is wrong. utc_diff is the one that is constantly updated. While time_zone is never changing. While the code says - use time_zone to calculate the offset. Please se below: from RunVmCommandBase.java ~~~ /** * Asynchronous event, send by vds on running vm success. Vm decided successfully run when it's status turn to Up. * If there are vdss, not succeeded to run vm - treat them as suspicious. */ public void runningSucceded() { ... Backend.getInstance() .getResourceManager() .RunVdsCommand(VDSCommandType.UpdateVmDynamicData, new UpdateVmDynamicDataVDSCommandParameters(getCurrentVdsId(), getVm().getDynamicData())); <<-- [1] ~~~ [1] here we update vm dynamic data from Vm Dynamic State which, I can't say when updated - from database or anyhow by the host? I believe by database only, so it reads the time_zone value from it. Next, let's check businessentities/VM.java to see how we get the offset: ~~~ /** * Tracking value of VM's UTC offset. Useful for long running VMs when there * can be significant drift over initial value computed from timeZone. * Note that this value is no longer being used when * starting VMs (The timeZone field is used to calculate that offset) and is kept * in sync with value reported by VDSM only for debugging purposes. * {@see VmInfoBuilderBase#buildVmTimeZone()} */ public Integer getUtcDiff() { return this.vmDynamic.getUtcDiff(); } ~~~ And now, here is what is happening in the database: ~~~ [mku] right after shutdown and adjust time: engine_20141003202157=> select vm_name, time_zone , utc_diff from vms where vm_name ilike '%vm-1'; vm_name | time_zone | utc_diff ---------+--------------------------+---------- vm-1 | US Eastern Standard Time | -14402 (1 row) [mku] right after starting the vm -> value of utc_diff is taken from time_zone: engine_20141003202157=> select vm_name, time_zone , utc_diff from vms where vm_name ilike '%vm-1'; vm_name | time_zone | utc_diff ---------+--------------------------+---------- vm-1 | US Eastern Standard Time | -18000 ~~~ Bottom line - todo: We need to decide which of the two fields is going to be used all the time and which would represent the initial run. If indeed utc_diff is in vm_dynamic (compared to time_zone, which is in static), why it is not used all the time??
(In reply to Bimal Chollera from comment #9) > >> The 5 hour diff was only seen in 3.2.6 release. > >> On 3.4.x the time, it was off by 1 hour. Didn't observe the 5 hour diff. yes, that's the part which was fixed in 3.3; the TZ offset (as set in the UI in Edit VM dialog, System subtab) is now always used to initialize the hw clock of the VM
(In reply to Marina from comment #10) > So, in 3.4, I see that timeOffset of a VM saved ok when VM is shut down. > But then, when it is started, it is updated again to the "initial run" > offset value. yes. note it's the TZ in System tab (it's split in two now, the one in System is for every VM start, the one in Initial Run is for cloud-init/sysprep purposes) > Looking through the code and the database values, seems to me that the logic > is wrong. utc_diff is the one that is constantly updated. While time_zone is > never changing. While the code says - use time_zone to calculate the offset. ^^ exactly, so the utc_diff is not being actively used for anything anymore. It just still gets the updates from the guest and is updated in the db…but it gets overwritten on next VM run Note it may be that in some places the comments are nto updated appropriately, even though the second code snippet says it correctly > Please se below: > > > from RunVmCommandBase.java > ~~~ > /** > * Asynchronous event, send by vds on running vm success. Vm decided > successfully run when it's status turn to Up. > * If there are vdss, not succeeded to run vm - treat them as suspicious. > */ > public void runningSucceded() { > ... > Backend.getInstance() > .getResourceManager() > .RunVdsCommand(VDSCommandType.UpdateVmDynamicData, > new > UpdateVmDynamicDataVDSCommandParameters(getCurrentVdsId(), > getVm().getDynamicData())); <<-- [1] > ~~~ > [1] here we update vm dynamic data from Vm Dynamic State which, I can't say > when updated - from database or anyhow by the host? I believe by database > only, so it reads the time_zone value from it. > > Next, let's check businessentities/VM.java to see how we get the offset: > ~~~ > /** > * Tracking value of VM's UTC offset. Useful for long running VMs when > there > * can be significant drift over initial value computed from timeZone. > * Note that this value is no longer being used when > * starting VMs (The timeZone field is used to calculate that offset) > and is kept > * in sync with value reported by VDSM only for debugging purposes. > * {@see VmInfoBuilderBase#buildVmTimeZone()} > */ > public Integer getUtcDiff() { > return this.vmDynamic.getUtcDiff(); > } > ~~~ > > And now, here is what is happening in the database: > ~~~ > [mku] right after shutdown and adjust time: > engine_20141003202157=> select vm_name, time_zone , utc_diff from vms where > vm_name ilike '%vm-1'; > vm_name | time_zone | utc_diff > ---------+--------------------------+---------- > vm-1 | US Eastern Standard Time | -14402 > (1 row) > > [mku] right after starting the vm -> value of utc_diff is taken from > time_zone: > engine_20141003202157=> select vm_name, time_zone , utc_diff from vms where > vm_name ilike '%vm-1'; > vm_name | time_zone | utc_diff > ---------+--------------------------+---------- > vm-1 | US Eastern Standard Time | -18000 yes so it gets reset to UTC-5 on each run. That is what's configured. The -14402 means that during the VM run the hw clock was adjusted to UTC-4 (and drifted by 2 seconds, which is not significant) probably because of a different setting in the guest OS > Bottom line - todo: > We need to decide which of the two fields is going to be used all the time > and which would represent the initial run. If indeed utc_diff is in > vm_dynamic (compared to time_zone, which is in static), why it is not used > all the time?? we stopped considering the dynamic updates in ~3.3. Originally it was there to preserve the drift, but that meant we had more issues…as VMs on next run were being started with intentionally skewed times. So we replaced that with this "fixed" correction to the desired TZ offset. The downside is that the TZ selected in UI *must* match the configuration of guest OS. Reporting/alerting on the discrepancy is part of RFE bug 869296 which is being implemented right now So, for the particular case I suggest checking the guest TZ configuration wrt what's set in the UI. The UI setting has no other significance so feel free to change it to anything what results in the desired offset
It seems there was incorrect mapping of exactly this timezone (US Eastern Standard Time) that disregarded the DST. Fix post upstream.
Verified: rhevm-3.5.0-0.19.beta.el6ev.noarch libvirt-0.10.2-46.el6_6.1.x86_64 sanlock-2.8-1.el6.x86_64 qemu-kvm-rhev-0.12.1.2-2.448.el6.x86_64 vdsm-4.16.7.3-1.el6ev.x86_64 also, verified engine utc_diff is correct: engine=# select vm_name, time_zone, utc_diff from vms; vm_name | time_zone | utc_diff ---------+--------------------------+---------- VM1 | Etc/GMT | 0 win7 | US Eastern Standard Time | -18000 VM2 | Etc/GMT | 0 (3 rows)
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHSA-2015-0158.html