Opened 17 months ago
Closed 17 months ago
#443 closed defect (fixed)
clock gets desynced
| Reported by: | joanna | Owned by: | marmarek |
|---|---|---|---|
| Priority: | major | Milestone: | Release 1 |
| Component: | core | Keywords: | |
| Cc: | marmarek |
Description
It seems like the qvm-sync-clock (most likely run by a cron job) has desynced my time. After resume the time was correct, but a few moments later it got set incorrectly to roughly the time when the machine was suspended a few hours back.
It seems like the ntpdate in the netvm must have failed (e.g. due to networking problem), but the qvm-sync-clock script must have missed that, and used the incorrect time from the netvm anyway.
Here's a snippet of my messages log from Dom0:
Feb 9 09:27:25 dom0 kernel: [229015.168850] PM: resume of devices complete after 699.879 msecs Feb 9 09:27:25 dom0 kernel: [229015.169306] Restarting tasks ... done. Feb 9 09:27:25 dom0 kernel: [229015.174246] video LNXVIDEO:00: Restoring backlight state Feb 9 09:27:25 dom0 kernel: [229015.180839] usb 2-1.1: USB disconnect, address 9 Feb 9 09:27:25 dom0 pulseaudio[3582]: ratelimit.c: 252 events suppressed Feb 9 09:27:28 dom0 kernel: [229017.403431] pciback 0000:00:19.0: get owner: 8 Feb 9 09:27:28 dom0 kernel: [229017.403952] pciback 0000:00:19.0: get owner: 8 Feb 9 09:27:28 dom0 kernel: [229017.457967] pciback 0000:00:19.0: get owner: 8 Feb 9 09:27:28 dom0 kernel: [229017.458436] pciback 0000:00:19.0: get owner: 8 Feb 9 01:16:23 dom0 pulseaudio[3582]: ratelimit.c: 256 events suppressed Feb 9 09:36:55 dom0 kernel: [229586.631896] usb 1-1.6: USB disconnect, address 6
Note how the time was correct, and then suddenly changed to 01:16:23. Later it was reverted back to the correct value after I manually run qvm-sync-clock...
Interestingly I made an experiment: 1) I disabled networking, and 2) run ntpdate restart in the netvm, and 3) checked the $?, thinking it might be 0, and so explaining this problem. But it was correctly set to 1, so this doesn't explain how qvm-sync-clock might got a wrong time from netvm...
Change History (8)
comment:1 Changed 17 months ago by marmarek
comment:2 Changed 17 months ago by joanna
qrexec logs from netvm:
Feb 9 00:15:44 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7187 Feb 9 00:15:44 netvm qrexec_agent[398]: executed user:date -u pid 7275 Feb 9 00:15:44 netvm qrexec_agent[398]: eintr Feb 9 00:15:44 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7275 Feb 9 01:15:18 netvm qrexec_agent[398]: executed root:service NetworkManager stop; for if in `ls /sys/class/net|grep -v "lo\|vif"`; do ip l s $if down; done; modprobe -r uhci_hcd ehci_hcd pid 7297 Feb 9 01:15:19 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7297 Feb 9 01:15:24 netvm qrexec_agent[398]: executed user:nm-online -x pid 7333 Feb 9 01:15:25 netvm qrexec_agent[398]: executed root:modprobe ehci_hcd; modprobe uhci_hcd; [ -x /bin/systemctl ] && systemctl start NetworkManager.service || service qubes_core_netvm start pid 7353 Feb 9 01:15:25 netvm qrexec_agent[398]: eintr Feb 9 01:15:25 netvm qrexec_agent[398]: send exit code for client_id 8 pid 7353 Feb 9 01:15:25 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7333 Feb 9 01:15:25 netvm qrexec_agent[398]: executed root:/etc/init.d/ntpdate restart pid 7368 Feb 9 01:15:33 netvm qrexec_agent[398]: executed root:service NetworkManager stop; for if in `ls /sys/class/net|grep -v "lo\|vif"`; do ip l s $if down; done; modprobe -r uhci_hcd ehci_hcd pid 7401 Feb 9 01:15:33 netvm qrexec_agent[398]: send exit code for client_id 8 pid 7401 Feb 9 01:15:39 netvm qrexec_agent[398]: executed user:nm-online -x pid 7430 Feb 9 01:15:40 netvm qrexec_agent[398]: executed root:modprobe ehci_hcd; modprobe uhci_hcd; [ -x /bin/systemctl ] && systemctl start NetworkManager.service || service qubes_core_netvm start pid 7450 Feb 9 01:15:40 netvm qrexec_agent[398]: send exit code for client_id 9 pid 7450 Feb 9 01:15:40 netvm qrexec_agent[398]: send exit code for client_id 8 pid 7430 Feb 9 01:15:40 netvm qrexec_agent[398]: executed root:/etc/init.d/ntpdate restart pid 7468 Feb 9 01:15:40 netvm qrexec_agent[398]: eintr Feb 9 01:15:40 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7368 Feb 9 01:15:40 netvm qrexec_agent[398]: executed user:date -u pid 7482 Feb 9 01:15:40 netvm qrexec_agent[398]: eintr Feb 9 01:15:40 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7482 Feb 9 01:15:58 netvm qrexec_agent[398]: eintr Feb 9 01:15:58 netvm qrexec_agent[398]: send exit code for client_id 8 pid 7468 Feb 9 01:23:48 netvm qrexec_agent[398]: executed user:nm-online -x pid 7555 Feb 9 01:23:48 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7555 Feb 9 01:23:48 netvm qrexec_agent[398]: executed root:/etc/init.d/ntpdate restart pid 7567 Feb 9 09:35:39 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7567 Feb 9 09:35:39 netvm qrexec_agent[398]: executed user:date -u pid 7597 Feb 9 09:35:39 netvm qrexec_agent[398]: eintr Feb 9 09:35:39 netvm qrexec_agent[398]: send exit code for client_id 7 pid 7597 Feb 9 10:38:58 netvm qrexec_agent[398]: executed (nowait) user:gnome-terminal pid 7778
comment:3 Changed 17 months ago by joanna
And from some other AppVM:
Feb 9 01:15:22 work qrexec_agent[499]: executed (nowait) root:date -s "Thu Feb 9 01:28:16 CET 2012" pid 5545 Feb 9 01:28:16 work qrexec_agent[499]: eintr Feb 9 01:28:30 work qrexec_agent[499]: executed (nowait) root:date -s "Thu Feb 9 09:27:26 CET 2012" pid 5554 Feb 9 09:27:26 work qrexec_agent[499]: eintr Feb 9 09:27:27 work qrexec_agent[499]: executed (nowait) root:date -u -s "Thu Feb 9 00:15:40 UTC 2012 Feb 9 09:27:27 work qrexec_agent[499]: " pid 5563 Feb 9 01:15:40 work qrexec_agent[499]: eintr Feb 9 01:23:52 work qrexec_agent[499]: executed (nowait) root:date -u -s "Thu Feb 9 08:35:39 UTC 2012 Feb 9 01:23:52 work qrexec_agent[499]: " pid 5583 Feb 9 09:35:39 work qrexec_agent[499]: eintr Feb 9 09:39:22 work qrexec_agent[499]: executed (nowait) user:gnome-terminal pid 5595 Feb 9 10:42:20 work qrexec_agent[499]: executed (nowait) user:gnome-terminal pid 5765 Feb 9 10:42:20 work qrexec_agent[499]: eintr
comment:4 Changed 17 months ago by marmarek
Looks like the first /etc/init.d/ntpdate restart did not synced the time. Tested manually and it also sets correct exit code (!= 0 if failed). But the other thing is interesting:
qvm-sync-clock calls in netvm (in order):
- nm-online -x (to wait for the network)
- /etc/init.d/ntpdate restart (to sync time)
Here I see that NetworkManager? is started by pm-scripts AFTER calling nm-online -x (which exists immediately when no NetworkManager? is running). So the order of pm-scripts need to be fixed.
comment:5 Changed 17 months ago by marmarek
BTW have you some messages about time sync in /var/log/pm-suspend.log (dom0)?
comment:6 Changed 17 months ago by joanna
pm-susped.log:
Initial commandline parameters: --quirk-dpms-suspend
--quirk-dpms-on
--quirk-vbestate-restore
--quirk-vbemode-restore
--quirk-vga-mode3
--quirk-vbe-post
Thu Feb 9 01:28:24 CET 2012: Running hooks for suspend.
/usr/lib64/pm-utils/sleep.d/00auto-quirk suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/00logging suspend suspend: Linux dom0 2.6.38.3-10.xenlinux.qubes.x86_64 #1 SMP Sat Dec 24 18:09:56 EST 2011 x86_64 x86_64 x86_64 GNU/Linux
Module Size Used by
usbhid 48251 0
hid 88836 1 usbhid
xt_tcpudp 3772 7
xt_physdev 1827 28
bridge 90456 2
stp 2291 1 bridge
llc 6008 2 bridge,stp
af_packet 23787 0
iptable_nat 5839 0
nf_nat 23604 1 iptable_nat
nf_conntrack_ipv4 10128 3 iptable_nat,nf_nat
nf_conntrack 86772 3 iptable_nat,nf_nat,nf_conntrack_ipv4
nf_defrag_ipv4 1761 1 nf_conntrack_ipv4
iptable_filter 1938 1
ip_tables 21605 2 iptable_nat,iptable_filter
x_tables 26769 5 xt_tcpudp,xt_physdev,iptable_nat,iptable_filter,ip_tables
sha256_generic 10351 0
dm_snapshot 33663 4
binfmt_misc 8370 1
dm_mirror 15828 0
dm_region_hash 13123 1 dm_mirror
dm_log 10726 2 dm_mirror,dm_region_hash
blktap 125515 0 [permanent]
netbk 41641 0 [permanent]
gntdev 8325 78
evtchn 5882 70
blkbk 26381 0 [permanent]
blkback_pagemap 2862 1 blkbk
snd_hda_codec_realtek 352799 1
snd_hda_intel 28786 5
snd_hda_codec 106767 2 snd_hda_codec_realtek,snd_hda_intel
snd_hwdep 7474 1 snd_hda_codec
snd_seq 64803 0
snd_seq_device 7578 1 snd_seq
pcspkr 2182 0
snd_pcm 103509 3 snd_hda_intel,snd_hda_codec
btusb 17481 0
bluetooth 110684 1 btusb
uvcvideo 67698 0
videodev 77490 1 uvcvideo
v4l2_compat_ioctl32 7335 1 videodev
sg 31705 0
qcserial 4700 0
usb_wwan 14023 1 qcserial
usbserial 41181 2 qcserial,usb_wwan
snd_timer 26285 2 snd_seq,snd_pcm
sony_laptop 35275 0
joydev 12165 0
iTCO_wdt 12668 0
snd 80657 17 snd_hda_codec_realtek,snd_hda_intel,snd_hda_codec,snd_hwdep,snd_seq,snd_seq_device,snd_pcm,snd_timer
iTCO_vendor_support 3110 1 iTCO_wdt
sdhci_pci 10165 0
sdhci 23685 1 sdhci_pci
mmc_core 94899 1 sdhci
i2c_i801 10840 0
rfkill 21079 2 bluetooth,sony_laptop
intel_ips 13084 0
battery 12413 0
ac 4089 0
wmi 11148 0
thermal 14639 0
soundcore 8212 1 snd
snd_page_alloc 9100 2 snd_hda_intel,snd_pcm
tpm_infineon 8827 0
processor 34247 0
fpu 2638 4
aesni_intel 46320 12
cryptd 11340 5 aesni_intel
aes_x86_64 8064 1 aesni_intel
aes_generic 27727 2 aesni_intel,aes_x86_64
xts 2903 4
gf128mul 8399 1 xts
dm_crypt 18824 1
ext4 399882 1
jbd2 90056 1 ext4
crc16 1739 1 ext4
uas 9779 0
usb_storage 52735 0
raid0 8913 1
sr_mod 15340 0
sd_mod 38418 2
cdrom 42564 1 sr_mod
ahci 22146 4
libahci 24983 1 ahci
libata 223474 2 ahci,libahci
scsi_mod 224115 6 sg,uas,usb_storage,sr_mod,sd_mod,libata
ehci_hcd 60797 0
usbcore 209562 10 usbhid,btusb,uvcvideo,qcserial,usb_wwan,usbserial,uas,usb_storage,ehci_hcd
tpm_tis 11938 1
tpm 17299 2 tpm_infineon,tpm_tis
tpm_bios 6260 1 tpm
i915 537703 2
drm_kms_helper 37272 1 i915
drm 232588 3 i915,drm_kms_helper
intel_agp 12418 1 i915
i2c_algo_bit 6408 1 i915
button 6658 1 i915
intel_gtt 18872 3 i915,intel_agp
agpgart 39754 3 drm,intel_agp,intel_gtt
i2c_core 31494 6 videodev,i2c_i801,i915,drm_kms_helper,drm,i2c_algo_bit
video 15058 1 i915
thermal_sys 18262 3 thermal,processor,video
hwmon 2688 1 thermal_sys
pciback 48941 0
xenbus_be 4125 4 blktap,netbk,blkbk,pciback
total used free shared buffers cached
Mem: 1674288 1600964 73324 0 15492 903452
-/+ buffers/cache: 682020 992268
Swap: 4161532 98368 4063164
success.
/usr/lib64/pm-utils/sleep.d/00powersave suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/00sony-vaio-audio suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/01grub suspend suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/01qubes-suspend-netvm suspend suspend: (null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
Redirecting to /bin/systemctl stop NetworkManager.service
success.
/usr/lib64/pm-utils/sleep.d/01qubes-sync-vms-clock suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/02qubes-pause-vms suspend suspend:
Pausing VM: 'netvm'...
Pausing VM: 'firewallvm'...
Pausing VM: 'work-pub'...
Pausing VM: 'work'...
Pausing VM: 'bank'...
Pausing VM: 'personal'...
Pausing VM: 'vault'...
Pausing VM: 'qubes'...
success.
/usr/lib64/pm-utils/sleep.d/49bluetooth suspend suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/55NetworkManager suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/56atd suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/56dhclient suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/75modules suspend suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/90clock suspend suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/94cpufreq suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/95led suspend suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/95packagekit suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/98smart-kernel-video suspend suspend: success.
/usr/lib64/pm-utils/sleep.d/99hd-apm-restore.hook suspend suspend: saving level 255 for device sdb
saving level 255 for device sda
success.
/usr/lib64/pm-utils/sleep.d/99sony-vaio-audio suspend suspend: Thu Feb 9 01:28:26 CET 2012
Simple mixer control 'Master',0
Capabilities: pvolume pvolume-joined pswitch pswitch-joined penum
Playback channels: Mono
Limits: Playback 0 - 64
Mono: Playback 0 [0%] [-64.00dB] [on]
success.
/usr/lib64/pm-utils/sleep.d/99video suspend suspend: error: "kernel.acpi_video_flags" is an unknown key
success.
Thu Feb 9 01:28:26 CET 2012: performing suspend
Thu Feb 9 09:27:25 CET 2012: Awake.
Thu Feb 9 09:27:25 CET 2012: Running hooks for resume
/usr/lib64/pm-utils/sleep.d/99video resume suspend: success.
/usr/lib64/pm-utils/sleep.d/99sony-vaio-audio resume suspend: Thu Feb 9 09:27:25 CET 2012
Simple mixer control 'Master',0
Capabilities: pvolume pvolume-joined pswitch pswitch-joined penum
Playback channels: Mono
Limits: Playback 0 - 64
Mono: Playback 0 [0%] [-64.00dB] [on]
success.
/usr/lib64/pm-utils/sleep.d/99hd-apm-restore.hook resume suspend: restoring level 255 for device sdb
/dev/sdb:
setting Advanced Power Management level to disabled
APM_level = off
restoring level 255 for device sda
/dev/sda:
setting Advanced Power Management level to disabled
APM_level = off
success.
/usr/lib64/pm-utils/sleep.d/98smart-kernel-video resume suspend: success.
/usr/lib64/pm-utils/sleep.d/95packagekit resume suspend: method return sender=:1.1261 -> dest=:1.1296 reply_serial=2
success.
/usr/lib64/pm-utils/sleep.d/95led resume suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/94cpufreq resume suspend: success.
/usr/lib64/pm-utils/sleep.d/90clock resume suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/75modules resume suspend: success.
/usr/lib64/pm-utils/sleep.d/56dhclient resume suspend: success.
/usr/lib64/pm-utils/sleep.d/56atd resume suspend: success.
/usr/lib64/pm-utils/sleep.d/55NetworkManager resume suspend: success.
/usr/lib64/pm-utils/sleep.d/49bluetooth resume suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/02qubes-pause-vms resume suspend:
UnPausing VM: 'netvm'...
UnPausing VM: 'firewallvm'...
UnPausing VM: 'work-pub'...
UnPausing VM: 'work'...
UnPausing VM: 'bank'...
UnPausing VM: 'personal'...
UnPausing VM: 'vault'...
UnPausing VM: 'qubes'...
success.
/usr/lib64/pm-utils/sleep.d/01qubes-sync-vms-clock resume suspend:
Syncing VMs clock to: Thu Feb 9 09:27:26 CET 2012
Running command on VM: 'firewallvm'...
Running command on VM: 'work-pub'...
Running command on VM: 'work'...
Running command on VM: 'bank'...
Running command on VM: 'personal'...
Running command on VM: 'vault'...
Running command on VM: 'qubes'...
success.
/usr/lib64/pm-utils/sleep.d/01qubes-suspend-netvm resume suspend: (null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
(null) is an invalid domain identifier (rc=-6)
success.
/usr/lib64/pm-utils/sleep.d/01grub resume suspend: not applicable.
/usr/lib64/pm-utils/sleep.d/00sony-vaio-audio resume suspend: Simple mixer control 'Master',0
Capabilities: pvolume pvolume-joined pswitch pswitch-joined penum
Playback channels: Mono
Limits: Playback 0 - 64
Mono: Playback 64 [100%] [0.00dB] [on]
success.
/usr/lib64/pm-utils/sleep.d/00powersave resume suspend: success.
/usr/lib64/pm-utils/sleep.d/00logging resume suspend: success.
/usr/lib64/pm-utils/sleep.d/00auto-quirk resume suspend: succes[ OK ]
Thu Feb 9 00:15:40 UTC 2012
ed.
Restarting ntpdate (via systemctl): [FAILED]
Job failed. See system logs and 'systemctl status' for details.
Time sync failed, aborting!
comment:7 Changed 17 months ago by marmarek
- Owner changed from joanna to marmarek
- Status changed from new to accepted
comment:8 Changed 17 months ago by marmarek
- Resolution set to fixed
- Status changed from accepted to closed
Note: See
TracTickets for help on using
tickets.
Can you post also qrexec log (now in /var/log/messages) from netvm and some other VM?