Bug 964177

That's a code bug - it should report the offset relative to UTC at all times.

NB the value from the event is intended to be able to be passed directly into the XML in the <clock adjustment=NNN> value which is secounds-relative-to-UTC.

Changing the bug title since it is a code bug, not a docs one.

It's not libvirt bug.

The "offset" value libvirt returns is from qemu event "RTC_CHANGE":

<...>
RTC_CHANGE
----------

Emitted when the guest changes the RTC time.

Data:

- "offset": delta against the host UTC in seconds (json-number)

Example:

{ "event": "RTC_CHANGE",
    "data": { "offset": 78 },
    "timestamp": { "seconds": 1267020223, "microseconds": 435656 } }
</...>

Though the documentation says the offset is delta against the "host UTC" in
seconds. It actually returns the delta against the specified date if one uses
the -rtc options like "--rtc base=2013-05-29T07:08:14", which is produced
by the following libvirt XML:

  <clock offset='variable' adjustment='10962' basis='utc'/>

I got correct "offset" when using the "-rtc" as "-rtc=utc".

Testing:

1) Start the guest with the XML above, which produces qemu command
    line like:

/usr/bin/qemu-kvm -name f18 -S -M pc-1.2 -enable-kvm -m 1024 -smp 1,sockets=1,cores=1,threads=1 -uuid 89a743a9-1da9-43b2-0bfe-01a8f3d94d8e -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/f18.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc  base=2013-05-29T08:32:02 -no-shutdown -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x6 -drive file=/var/lib/libvirt/images/f18.img,if=none,id=drive-scsi0-0-0-0,format=raw -device scsi-hd,bus=scsi0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0-0-0-0,id=scsi0-0-0-0,bootindex=1 -drive if=none,id=drive-ide0-1-0,readonly=on,format=raw -device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -netdev tap,fd=26,id=hostnet0,vhost=on,vhostfd=27 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:14:99:98,bus=pci.0,addr=0x3 -chardev pty,id=charserial0 -device isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0 -vnc 127.0.0.1:0 -vga cirrus -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5

2) Current host date in seconds since the epoch

% date -u +%s
1369812761

2) Calculate the date in seconds since epoch time of the specified time

% date -u +%s --date="2013-05-29T08:32:0"
1369816322

3) Minitor the qemu events

% python examples/domain-events/events-python/event-test.py

4) Change the hardware clock in guest (5 hours past the host date)

%  hwclock --set --date="29 May 2013 12:20 UTC"
%  hwclock -s

5) Get the date in seconds since epoch time of guest

% date -u +%s
1369830010


7) Check the offset got by event-test.py

myDomainEventRTCChangeCallback: Domain f18(3) 13613


% bc
bc 1.06.95
Copyright 1991-1994, 1997, 1998, 2000, 2004, 2006 Free Software Foundation, Inc.
This is free software with ABSOLUTELY NO WARRANTY.
For details type `warranty'.
1369830010 - 1369812761
17249
17249/60/60
4
1369830010 - 1369816322
13688
13688/60/60
3

Above means the offset is 3 hours past the specified date. What we expect is
4 hours past the host UTC date.

(In reply to Osier Yang from comment #6)
> It's not libvirt bug.
> 
> The "offset" value libvirt returns is from qemu event "RTC_CHANGE":
> 

As Comment #6 said, it's either a doc bug or code bug of qemu. Move to qemu.

(In reply to Osier Yang from comment #6)
> It's not libvirt bug.
> 
> The "offset" value libvirt returns is from qemu event "RTC_CHANGE":
> 
> <...>
> RTC_CHANGE
> ----------
> 
> Emitted when the guest changes the RTC time.
> 
> Data:
> 
> - "offset": delta against the host UTC in seconds (json-number)
> 
> Example:
> 
> { "event": "RTC_CHANGE",
>     "data": { "offset": 78 },
>     "timestamp": { "seconds": 1267020223, "microseconds": 435656 } }
> </...>
> 
> Though the documentation says the offset is delta against the "host UTC" in
> seconds. It actually returns the delta against the specified date if one uses
> the -rtc options like "--rtc base=2013-05-29T07:08:14", which is produced
> by the following libvirt XML:
> 
>   <clock offset='variable' adjustment='10962' basis='utc'/>
> 
> I got correct "offset" when using the "-rtc" as "-rtc=utc".
> 
> Testing:
> 
> 1) Start the guest with the XML above, which produces qemu command
>     line like:
> 
> /usr/bin/qemu-kvm -name f18 -S -M pc-1.2 -enable-kvm -m 1024 -smp
> 1,sockets=1,cores=1,threads=1 -uuid 89a743a9-1da9-43b2-0bfe-01a8f3d94d8e
> -no-user-config -nodefaults -chardev
> socket,id=charmonitor,path=/var/lib/libvirt/qemu/f18.monitor,server,nowait
> -mon chardev=charmonitor,id=monitor,mode=control -rtc 
> base=2013-05-29T08:32:02 -no-shutdown -device
> piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device
> virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x6 -drive
> file=/var/lib/libvirt/images/f18.img,if=none,id=drive-scsi0-0-0-0,format=raw
> -device
> scsi-hd,bus=scsi0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0-0-0-0,
> id=scsi0-0-0-0,bootindex=1 -drive
> if=none,id=drive-ide0-1-0,readonly=on,format=raw -device
> ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -netdev
> tap,fd=26,id=hostnet0,vhost=on,vhostfd=27 -device
> virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:14:99:98,bus=pci.0,
> addr=0x3 -chardev pty,id=charserial0 -device
> isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0 -vnc
> 127.0.0.1:0 -vga cirrus -device
> virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5
> 
> 2) Current host date in seconds since the epoch
> 
> % date -u +%s
> 1369812761
> 
> 2) Calculate the date in seconds since epoch time of the specified time
> 
> % date -u +%s --date="2013-05-29T08:32:0"
> 1369816322
> 
> 3) Minitor the qemu events
> 
> % python examples/domain-events/events-python/event-test.py
> 
> 4) Change the hardware clock in guest (5 hours past the host date)
> 
> %  hwclock --set --date="29 May 2013 12:20 UTC"
> %  hwclock -s
> 
> 5) Get the date in seconds since epoch time of guest
> 
> % date -u +%s
> 1369830010
> 
> 
> 7) Check the offset got by event-test.py
> 
> myDomainEventRTCChangeCallback: Domain f18(3) 13613
> 
> 
> % bc
> bc 1.06.95
> Copyright 1991-1994, 1997, 1998, 2000, 2004, 2006 Free Software Foundation,
> Inc.
> This is free software with ABSOLUTELY NO WARRANTY.
> For details type `warranty'.
> 1369830010 - 1369812761
> 17249
> 17249/60/60
> 4
> 1369830010 - 1369816322
> 13688
> 13688/60/60
> 3
> 
> Above means the offset is 3 hours past the specified date. What we expect is
> 4 hours past the host UTC date.

The offset is just the delta relative to the RTC clock itself at that moment. So from item 7 of comment above:

13613/60/60
3.7813888888

So the guest advanced its clock by 13613 seconds.

I don't think it is safe to change the interface at this point, it is 3 years old now. There is a risk of breaking other QEMU users.
It is simple to calculate delta to UTC:

1) when starting the guest: 
a = record start time (host clock). b = record value passed to -rtc base.
2) when guest changes rtc:
  c = record host clock.
  d = record delta from RTC_CHANGE_EVENT event.

e = time value guest wrote into RTC = b + (c - a) + d 

Then you can convert to UTC easily (just the difference between e and host clock).

(In reply to Osier Yang from comment #6)
> It's not libvirt bug.

Yes it is.
 
> The "offset" value libvirt returns is from qemu event "RTC_CHANGE":

You are just describing the broken implementation here. The libvirt event semantics are that it should provide the offset from UTC. This implies libvirt must convert the value it gets from QEMU.

What's the status on this bug?  It looks like this mail is relevant:
http://post-office.corp.redhat.com/archives/rhvirt-patches/2013-June/msg00059.html

Michal Skrivanek pointed out that it should be documented as it currently works, so leaving open for a doc fix.

(In reply to Dave Allan from comment #20)
> Michal Skrivanek pointed out that it should be documented as it currently
> works, so leaving open for a doc fix.

Documented where?

Michal would like to see this documented in http://libvirt.org/html/libvirt-libvirt.html#virConnectDomainEventRTCChangeCallback, I suppose.

I, on the other hand, would like to see the implementation fixed. If we are afraid that something out there depends on the long-broken logic of VIR_DOMAIN_EVENT_ID_RTC_CHANGE, let us have another event (say VIR_DOMAIN_EVENT_ID_RTC_CHANGE2) which reports "the new RTC offset from UTC, measured in seconds" as reported by the current documentation.

Okay, since "base date + qemu uptime" == "current date", then you're saying that the offset returned really is just "the change relative to the old clock", correct? (that's what I read in your documentation change as well)

Based on that, I'm not sure why the conversation was muddied up with math that included the qemu start time and uptime.

*HOWEVER*, I just ran through a test similar to what Osier did in Comment 6 on both qemu 1.6.2 (Fedora 20) and on RHEL6, and in both cases, when I specify:

    <clock offset='variable' basis='utc'/>

I get a qemu commandline with "-rtc base=....", but when I watch the events coming from qemu as I use hwclock to move the RTC up and down by anything from a few seconds to an hour, I see that the event *is* reporting the new offset relative to UTC, *NOT* the change relative to the old RTC.

Has this behavior been knowingly/accidentally changed in qemu since this Bug was created? Can you see a problem with that test that would invalidate the results?

Created attachment 897541 [details]
script to add $1 seconds to the current date and set the RTC clock to that date

I'm starting to figure out the math, and why the upstream patch is broken and unworkable.

I've written a short script, addsecs, to aid in testing. It is called like this:

   addsecs 10      - adds 10 seconds to the current RTC date and sets the RTC
   addsecs -10     - substracts 10 seconds from current RTC date and sets RTC

On a guest with the following <clock> element in libvirt:

  <clock offset='variable' adjustment='3600' basis='utc'/>

which resulted in the following qemu commandline option:

  -rtc base=2014-05-20T10:53:59

I ran some tests with this on RHEL6.5 while watching the value sent by qemu and found the following:

  addsec 10  - offset in qemu event is "10" (give or take a couple seconds)
  addsec 10  - offset in qemu event is "20"
  addsec 10  - offset in qemu event is "30"
  addsec 30  - offset in qemu event is "60"
  addsec -60 - offset is 0

So according to this, all that needs to be done is add the *original* adjustment to the newly received offset - that will both be saved as the new adjustment, and sent to the event handler.

Note that the "new adjustment" *MUST NOT* be used for future computation of the next new adjustment. So, is it possible to derive the original offset from the information we currently have stored? We have this:

basedate = host UTC (or localtime) + adjustment at domain start time
adjustment - cumulative of all adjustments since domain started.
time() - current host UTC at time of event

If we knew the exact uptime (as Marcelo suggested), we could do

  adjustment0 = (basedate + uptime) - time()

(since basedate is the original time() + adjustment0). However, that information hasn't been saved anywhere in the domain status, nor has the raw time() at start (without adjust0 added in).

adjust0 *is* available in the inactive config of the domain, but of course that doesn't exist for transient domains. In a word: Bah.

What I think needs to be done: add a private adjustment0 attribute to clock that gets a copy of adjustment at domain start. Whenever an RTCChange event is received, add adjustment0 + offsetFromQEMU and 1) set that as adjustment in the domain status as well as 2) pass that value on to the event handler.

In the meantime, it appears that saving basedate is pointless. Since is is both private and unused by any other code in libvirt, I think it should be immediately removed to eliminate clutter.

(NB: all of these discussions have been about behavior for

  <clock offset='variable' basis='utc'/>

In the case of

    <clock offset='variable' basis='localtime'/>

the adjustment in the config is relative to localtime rather than utc, but qemu will simply be reporting the new offset from the original offset. Since the event has no provision for specifying utc vs. localtime, that means in this case we will need to add the difference between utc and localtime before passing on to the event handler. For example, if localtime is 1 hour ahead of utc, and you start with:

    <clock offset='variable' basis='localtime' adjustment='50'/>

adjust0 should be saved as 50 + 3600, *not* just 50. If the guest then adjusts its clock forward by 10 seconds, the new offset from UTC should be 3600 + 50 + 10 = 3660, *not* 60.

Hmm - in the case of basis='localtime', I think that the "adjustment" saved in the status shouldn't be  the offset that is reported in the event. Rather it should be the new adjustment relative to localtime. So in the example above, when the guest adds 10 seconds to its RTC, the event should report "3660" (new offset of time relative to UTC), but the domain status should have adjustment changed to "60" (offset of time relative to localtime). This way if the domain is migrated, the status can be used as config. when starting on the new host.

Patches sent to upstream list for review:

https://www.redhat.com/archives/libvir-list/2014-May/msg00738.html

These revert the original patch that had been applied last year, and fix operation not just for basis='utc', but also for basis='localtime' (which, coincidentally was broken for migration too, and is fixed by the same patch).

I think qemu has a bug.  Laine's proposed patches would have libvirt track all RTC change events from qemu, to keep a running sum.  But if we miss an event, such as due to a libvirtd restart, we've lost an accurate state.  I think the only sane thing is for qemu to have a QMP interface that can be polled to ask what qemu's current offset is.  Any time we receive the RTC change event (which tells us only how much the current offset was adjusted), we then followup with the query to learn the new offset.  We can't change the RTC change event semantics, but we CAN make qemu smarter about giving us the right information in the format we need, and in a way that works even with lost events.

4 patches have been pushed upstream, with a 4th required to make DST processing work properly:

commit 1cddaea7aeca441b733c31990a3f139dd2d346f6
Author: Laine Stump <laine>
Date:   Sat May 24 08:21:26 2014 -0600

    util: new function virTimeLocalOffsetFromUTC
    
commit b8efa6f2e301bf8918429818c88654a1ee4643a1
Author: Laine Stump <laine>
Date:   Tue May 20 14:43:33 2014 +0300

    Revert "qemu: Report the offset from host UTC for RTC_CHANGE event"
    
    This reverts commit e31b5cf393857a6ca78d148c19393e28dfb39de1.
 
commit b62d67da3e106d8081877499f143996fd50e2918
Author: Laine Stump <laine>
Date:   Wed May 21 12:54:34 2014 +0300

    qemu: fix RTC_CHANGE event for <clock offset='variable' basis='utc'/>
    
commit cde8ca2dfda6b69eebb70695e5a42b0cc6bd2c38
Author: Laine Stump <laine>
Date:   Wed May 21 17:20:50 2014 +0300

    qemu: fix <clock offset='variable' basis='localtime'/>
    

The pending patch is here:

  https://www.redhat.com/archives/libvir-list/2014-May/msg00900.html

with a discussion of why it is needed here:

  https://www.redhat.com/archives/libvir-list/2014-May/msg00898.html

While backporting these patches, I've run across Bug 1046192, filed against RHEL7 which says that <clock offset='variable' basis='localtime'/> didn't work. This was fixed in RHEL7, but hasn't been fixed in RHEL6, which specifically disallows basis='localtime'.

Can I assume that this means we shouldn't backport this patch (which I forgot to list above)?

commit cde8ca2dfda6b69eebb70695e5a42b0cc6bd2c38
Author: Laine Stump <laine>
Date:   Wed May 21 17:20:50 2014 +0300

    qemu: fix <clock offset='variable' basis='localtime'/>
    
    For a clock element as above, libvirt simply converts current system
    time with localtime_r(), then starts qemu with a time string that
    doesn't contain any timezone information. So, from qemu's point of
    view, the -rtc string it gets for:
    
       <clock offset='variable' basis='utc' adjustment='10800'/>
    
    is identical to the -rtc string it gets for:
    
       <clock offset='variable' basis='localtime' adjustment='0'/>
    
    (assuming the host is in a timezone that is 10800 seconds ahead of
    UTC, as is the case on the machine where this message is being
    written).

"localtime" is evil. Everybody should use "utc" everywhere.

Jokes aside - I do not use basis='localtime', and do not care if it is buggy.

Okay, that means that the only thing needed to be backported to RHEL6 to satisfy this BZ is this patch:

commit b62d67da3e106d8081877499f143996fd50e2918
Author: Laine Stump <laine>
Date:   Wed May 21 12:54:34 2014 +0300

    qemu: fix RTC_CHANGE event for <clock offset='variable' basis='utc'/>

The 1st patch listed in Comment 35 is a new internal function only needed for basis='localtime'the 2nd is reverting a patch that was only upstream, and the 4th is again only needed for basis='localtime'.

Note, however, that if this BZ is cloned to RHEL7, *all* the patches here will need to be backported.

For future reference in case this needs to be backported to some libvirt earlier than 1.2.5 - fixing this bug requires the 4 patches listed in Comment 35, plus the following patch:

commit 26d43113a3326c90ec52548a16111fd8ab237bae
Author: Laine Stump <laine>
Date:   Tue May 27 16:35:57 2014 +0300

    util: fix virTimeLocalOffsetFromUTC DST processing

Additionally, the patches listed in Bug 1046192 (fixed upstream in 1.2.2) will be needed (and should be applied *before* any of the patches listed in this BZ)

This fix can be verified:

For basis='utc', the previous libvirt-1.1.1-29.el7 will return the offset
between guest time and the RTC clock value passed by '-rtc base='. But in
the latest libvirt-1.2.7-1.el7:

1. configure basis='utc', and start guest
# virsh dumpxml r6 | grep clock
  <clock offset='variable' adjustment='0' basis='utc'/>

# virsh start r6
Domain r6 started

2. run event-test.py in another terminal
# python event-test.py

3. change RTC time in guest
# ./addsec 100
Old: 1408353617 Mon 18 Aug 2014 05:20:17 PM EDT
New: 1408353717 Mon Aug 18 05:21:57 EDT 2014

4. check event-test.py output
myDomainEventRTCChangeCallback: Domain r6(26) 99

5. check the config
# virsh dumpxml r6 | grep clock
  <clock offset='variable' adjustment='99' basis='utc'/>

The virConnectDomainEventRTCChangeCallback return 99 which is
guest RTC clock increased (inaccurate, but acceptable).


For basis='localtime':
1. configure basis='localtime', start guest, and record UTC time
# virsh dumpxml r6 | grep clock
  <clock offset='variable' adjustment='0' basis='localtime'/>
# virsh start r6;date -u +%s
Domain r6 started

1408351723

2. compute the localtime and UTC in host
# ps -ef | grep base=
qemu      5698     1  0 16:48 ?        00:00:00 /usr/libexec/qemu-kvm -name r6 -S -machine pc-i440fx-rhel7.0.0,accel=kvm,usb=off -m 1024 -realtime mlock=off -smp 4,sockets=4,cores=1,threads=1 -uuid 5d8bcdb9-f61a-4031-b4ac-817b873d356e -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/r6.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=2014-08-18T16:48:43 -no-shutdown -boot strict=on -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x8 -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x5 -drive file=/var/lib/libvirt/images/xuzhang-20140113-raw.img,if=none,id=drive-virtio-disk0,format=raw,cache=none -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x6,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 -chardev pty,id=charserial0 -device isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0 -vnc 127.0.0.1:0 -vga qxl -global qxl-vga.ram_size=67108864 -global qxl-vga.vram_size=67108864 -device intel-hda,id=sound0,bus=pci.0,addr=0x4 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x7 -msg timestamp=on
root      5711 13056  0 16:48 pts/4    00:00:00 grep --color=auto base=

# date -u +%s --date='2014-08-18T16:48:43'
1408380523

# echo 1408380523 - 1408351723 | bc
28800

This is the the gap between localtime and UTC.

# virsh dumpxml r6 | grep clock
  <clock offset='variable' adjustment='28800' basis='utc'/>

And it is recorded in config xml.

3. run event-test.py in another terminal
# python event-test.py

4. check virConnectDomainEventRTCChangeCallback returns
in guest:
# ./addsec 0
Old: 1408380630 Mon 18 Aug 2014 12:50:30 PM EDT
New: 1408380630 Mon Aug 18 12:50:30 EDT 2014

event-test.py gets:
myDomainEventRTCChangeCallback: Domain r6(25) 28799

The value is inaccurate, but acceptable.

So I will set the status to VERIFIED.

Sorry this bug still depend on bug 1110429, which is not verified.

libvirt should also need to take care of it.

Hi Laine,

This bug depands on qemu bug 1110429, which adds "rtc-time" link to "/machine/rtc".

But I didn't figure out how libvirtd uses it:
I used qemu-kvm-rhev-2.1.0-3.el7.x86_64 to start a guest, and restart libvirtd,
but no qom-get for rtc-timer.

My question is if I could verified this bug without 'rtc-time' support?

Thanks,
Jincheng Miao

My opinion is that this BZ is fixed regardless of whether libvirt uses the qom "rtc-time" value. This bug is only about how the offset sent in libvirt's  VIR_DOMAIN_EVENT_ID_RTC_CHANGE event was incorrect, and that has been fixed. The dependency on Bug 1110429 was caused by the way that bug was created (it was cloned from another bug which was cloned from this bug). So this BZ can be marked as VERIFIED.

That said, libvirt still needs to separately track adding in support for qemu's new "rtc-time" querying, so I've created a new BZ cloned from Bug 1110429 to track that - Bug 1139766, and I've removed the dependency of this BZ on 1110429 (and 1110419, which was a RHEL6 BZ that was closed as DEFERRED).

According to comment 47 from Laine, this bug is no longer depands on qemu bug
1110429 which adds "rtc-time".

And based on my comment 44, the offset of virConnectDomainEventRTCChangeCallback
is already fixed in libvirt-1.2.7-1.el7. So I'll change the status to VERIFIED.

Finally, thanks for Laine's help.

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-0323.html

Hi Laine,

I found if I set clock offset to utc instead of variable, libvirt will not set the "adjustment" attribute in live xml when receive a 'rtc-change' event.

Do you think this is a problem?

Steps:
# virsh dumpxml rhel7.4|grep clock
  <clock offset='utc'>
  </clock>

# virsh start rhel7.4

# virsh event rhel7.4 --all --loop

Log in guest, adjust hwclock, +3600s:
# ./addsec 3600

Libvirt receive a rtc-change:
event 'rtc-change' for domain rhel7.4: 3599

# virsh dumpxml rhel7.4|grep clock
  <clock offset='utc'>
  </clock>

Thank you.
Fangge Jin

It's been seceral years since I thought about this code (I've done my best to *forget* it, because it was a nightmare to figure out), so it would take me a long time to get my brain into context to give a reasonable answer.. It's possible someone on libvir-list could give you an immediate answer.