search

QubesOS / qubes-issues

The Qubes OS Project issue tracker
https://www.qubes-os.org/doc/issue-tracking/
534 stars 47 forks source link

Dom0 clock is ~5 minutes late #5646

Closed sjvudp closed 1 year ago

sjvudp commented 4 years ago

Qubes OS version R4.0.3

Affected component(s) or functionality System time

Brief summary Qubes OS is the only system that sets the clock OFF; other systems set the clock correctly. Typically the time displayed is like 5 minutes past the correct time. I can be seen when opening https://www.time.gov/

To Reproduce It happens automatically. The log looks like this:

...
2020-02-12 22:17:19 - sdwdate - INFO - remote 1: bqs3dobnazs7h4u4.onion
2020-02-12 22:17:19 - sdwdate - INFO - * comment: ExtremeLeaks  2014    Investigative Journalism    https://www.extremeleaks.org    Norway
2020-02-12 22:17:19 - sdwdate - INFO - * remote_unixtime: 1581546052
2020-02-12 22:17:19 - sdwdate - INFO - * consensus/valid-after: 2020-02-12 21:00:00
2020-02-12 22:17:19 - sdwdate - INFO - * remote_time          : 2020-02-12 22:20:52
2020-02-12 22:17:19 - sdwdate - INFO - * consensus/valid-until: 2020-02-13 00:00:00
2020-02-12 22:17:19 - sdwdate - INFO - * time_diff: 213 second(s)
...
2020-02-12 22:17:19 - sdwdate - INFO - remote 2: 3kyl4i7bfdgwelmf.onion
2020-02-12 22:17:19 - sdwdate - INFO - * comment: http://www.wefightcensorship.org  https://archive.fo/GhgMU
2020-02-12 22:17:19 - sdwdate - INFO - * remote_unixtime: 1581546051
2020-02-12 22:17:19 - sdwdate - INFO - * consensus/valid-after: 2020-02-12 21:00:00
2020-02-12 22:17:19 - sdwdate - INFO - * remote_time          : 2020-02-12 22:20:51
2020-02-12 22:17:19 - sdwdate - INFO - * consensus/valid-until: 2020-02-13 00:00:00
2020-02-12 22:17:19 - sdwdate - INFO - * time_diff: 212 second(s)
...
2020-02-12 22:17:21 - sdwdate - INFO - remote 0: gmg7jl25ony5g7ws.onion
2020-02-12 22:17:21 - sdwdate - INFO - * comment: Gizmodo Media Group   https://specialprojectsdesk.com/securedrop/ https://web.archive.org/web/20170215221547/https://specialprojectsdesk.com/securedrop/
2020-02-12 22:17:21 - sdwdate - INFO - * remote_unixtime: 1581546100
2020-02-12 22:17:21 - sdwdate - INFO - * consensus/valid-after: 2020-02-12 21:00:00
2020-02-12 22:17:21 - sdwdate - INFO - * remote_time          : 2020-02-12 22:21:40
2020-02-12 22:17:21 - sdwdate - INFO - * consensus/valid-until: 2020-02-13 00:00:00
2020-02-12 22:17:21 - sdwdate - INFO - * time_diff: 259 second(s)
...
2020-02-12 22:17:21 - sdwdate - INFO - Pool differences, sorted: [212, 213, 259]
2020-02-12 22:17:21 - sdwdate - INFO - Median time difference: +213.000000000
2020-02-12 22:17:21 - sdwdate - INFO - randomize             : -0.442363838
2020-02-12 22:17:21 - sdwdate - INFO - New time difference   : +212.557636162
2020-02-12 22:17:21 - sdwdate - INFO - Old unixttime: 1581545841.977652788
2020-02-12 22:17:21 - sdwdate - INFO - New unixtime : 1581546054.535289049
2020-02-12 22:17:21 - sdwdate - INFO - Instantly setting the time by using command: /bin/date --set "@1581546054.535289049"
2020-02-12 22:20:54 - sdwdate - INFO - /bin/date output: Wed 12 Feb 2020 10:20:54 PM UTC

2020-02-12 22:20:54 - sdwdate - INFO - Success. Sleeping for 85.0 minutes.

So with this error there is no need to "randomize" by a fraction of a second!

Expected behavior Clock should be set to about one second offset from the true time. I hate it when the clock is significantly off.

Actual behavior Clock is about 5 minutes behind the true time. Repeating the command does not make it any better (it's still about 5 minutes late):

2020-02-12 23:41:00 - sdwdate - INFO - Pool differences, sorted: [1, 4, 46]
2020-02-12 23:41:00 - sdwdate - INFO - Median time difference: +4.000000000
2020-02-12 23:41:00 - sdwdate - INFO - randomize             : -0.363517316
2020-02-12 23:41:00 - sdwdate - INFO - New time difference   : +3.636482684

Screenshots If applicable, add screenshots to help explain your problem.

Additional context Add any other context about the problem here.

Solutions you've tried If applicable, any solutions or workarounds you've already tried.

Relevant documentation you've consulted A list of links to the Qubes documentation (or other relevant software documentation) pages you have already consulted.

Related, non-duplicate issues A list of links to other bug reports, feature requests, or tasks in the qubes-issues tracker (or "none" if you didn't find any). Do not describe any other unreported bugs, features, or tasks here.

marmarek commented 4 years ago

If I read it right, it does synchronize to remote time correctly:

2020-02-12 22:17:19 - sdwdate - INFO - * remote_time          : 2020-02-12 22:20:52
...
2020-02-12 22:20:54 - sdwdate - INFO - /bin/date output: Wed 12 Feb 2020 10:20:54 PM UTC

Do you mean all those "remote_time" lines are ~5min off?

sjvudp commented 4 years ago

Starting at 1:01, the clock is at 00:04 before sdwdate; however sdwdate says the time difference is like 7 seconds. It seems almost correct in sys-whonix (where I tested it), but the Dom0 panel says 00:03 when sys-whonix says 12:07. My guess was that the time comes from sys-whonix.

marmarek commented 4 years ago

Ok, can you describe what exactly is the issue? Is it about time in sys-whonix? Or dom0? or other VMs? somewhere else? Where is it correct and where is it off?

Generally (with exception to Whonix vms), dom0 takes time from a VM pointed as ClockVM (see global settings or qubes-prefs tool), and other VMs takes from dom0.

sjvudp commented 4 years ago

The time displayed in the upper right (I guess it's Dom0) is wrong as described. My guess was if that time is wrong I don't have to bother looking at the other VMs. My ClockVM is sys-net. As Tails manages to get the time right, I wonder what's the issue here. Unfortunately I couldn't check today as the last updates seem to have broken the network card (a different issue).

marmarek commented 4 years ago

Ok, so the issue is most likely within sys-net and then copied to dom0. It uses classic NTP to synchronize its clock. It should be done by systemd-timesyncd service, you can check if with: systemctl status systemd-timesyncd in sys-net. If it's not running with something like "condition failed", that's probably #4939. You can fix it by setting clockvm again, even to the same value (qubes-prefs clockvm sys-net).

sjvudp commented 4 years ago

Sorry for the delay, I still have this problem. It seems I have network connectivity (using Qubes OS right now), but the time cannot be synchronized for reasons unknown to me:

Feb 17 20:47:26 sys-net dhclient[543]: Created duid "\000\004\371\244\002j77C]\212\223\301\005\211\341^\361".
Feb 17 20:47:26 sys-net dhclient[543]: DHCPDISCOVER on ens6 to 255.255.255.255 port 67 interval 6 (xid=0xfcf1ae1d)
Feb 17 20:47:26 sys-net dhclient[543]: DHCPREQUEST on ens6 to 255.255.255.255 port 67 (xid=0xfcf1ae1d)
Feb 17 20:47:26 sys-net dhclient[543]: DHCPOFFER from 192.168.178.1
Feb 17 20:47:26 sys-net dhclient[543]: DHCPACK from 192.168.178.1 (xid=0xfcf1ae1d)
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3315] dhcp4 (ens6):   address 192.168.178.25
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3315] dhcp4 (ens6):   plen 24 (255.255.255.0)
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3315] dhcp4 (ens6):   gateway 192.168.178.1
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3316] dhcp4 (ens6):   lease time 86400
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3316] dhcp4 (ens6):   nameserver '192.168.178.1'
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3316] dhcp4 (ens6):   domain name 'fritz.box'
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3316] dhcp4 (ens6): state changed unknown -> bound
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3323] device (ens6): state change: ip-config -> ip-check (reason 'none', sys-iface-st>
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3329] device (ens6): state change: ip-check -> secondaries (reason 'none', sys-iface->
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3330] device (ens6): state change: secondaries -> activated (reason 'none', sys-iface>
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3335] manager: NetworkManager state is now CONNECTED_LOCAL
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3341] manager: NetworkManager state is now CONNECTED_SITE
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.3342] policy: set 'Wired connection 1' (ens6) as default for IPv4 routing and DNS
Feb 17 20:47:26 sys-net dhclient[543]: bound to 192.168.178.25 -- renewal in 42630 seconds.
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.4272] device (ens6): Activation: successful, device activated.
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.4281] manager: NetworkManager state is now CONNECTED_GLOBAL
Feb 17 20:47:26 sys-net NetworkManager[445]: <info>  [1581968846.4284] manager: startup complete
Feb 17 20:47:26 sys-net NetworkManager[445]: <warn>  [1581968846.4287] dns-sd-resolved[0x60fa61e0b910]: Failed: GDBus.Error:org.freedesktop.DBus.Error.NameHasNoOwner: Could not activate remote peer.
...
Feb 17 20:47:26 sys-net nm-dispatcher[478]: req:3 'up' [ens6]: new request (3 scripts)
Feb 17 20:47:26 sys-net nm-dispatcher[478]: req:3 'up' [ens6]: start running ordered scripts...
Feb 17 20:47:26 sys-net nm-dispatcher[478]: req:4 'connectivity-change': new request (3 scripts)
...
Feb 17 20:47:44 sys-net systemd[656]: Starting D-Bus User Message Bus Socket.
Feb 17 20:47:44 sys-net systemd[656]: Started Mark boot as successful after the user session has run 2 minutes.
Feb 17 20:47:44 sys-net systemd[656]: Reached target Timers.
Feb 17 20:47:44 sys-net systemd[656]: Listening on Multimedia System.
Feb 17 20:47:44 sys-net systemd[656]: Listening on D-Bus User Message Bus Socket.
...
Feb 17 20:47:57 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 134.34.3.19:123 (2.fedora.pool.ntp.org).
Feb 17 20:48:07 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 162.159.200.1:123 (2.fedora.pool.ntp.org).
Feb 17 20:48:17 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 116.203.111.0:123 (2.fedora.pool.ntp.org).
Feb 17 20:48:27 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 217.91.44.17:123 (2.fedora.pool.ntp.org).
...
Feb 17 20:49:52 sys-net systemd[704]: Started dbus-:1.13-org.a11y.atspi.Registry@0.service.
Feb 17 20:49:55 sys-net NetworkManager[445]: <info>  [1581968995.3798] agent-manager: req[0x7914800025a0, :1.42/org.freedesktop.nm-applet/1000]: agent>
Feb 17 20:49:55 sys-net systemd[704]: Created slice dbus\x2d:1.2\x2dorg.freedesktop.Notifications.slice.
Feb 17 20:49:55 sys-net systemd[704]: Started dbus-:1.2-org.freedesktop.Notifications@0.service.
Feb 17 20:50:02 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 176.96.138.245:123 (0.fedora.pool.ntp.org).
Feb 17 20:50:12 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 5.9.113.140:123 (0.fedora.pool.ntp.org).
Feb 17 20:50:13 sys-net tracker-store[870]: OK
Feb 17 20:50:14 sys-net systemd[704]: tracker-store.service: Succeeded.
Feb 17 20:50:22 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 136.243.7.20:123 (0.fedora.pool.ntp.org).
Feb 17 20:50:33 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 62.116.130.3:123 (1.fedora.pool.ntp.org).
Feb 17 20:50:34 sys-net systemd[704]: dbus-:1.2-org.freedesktop.Notifications@0.service: Succeeded.
Feb 17 20:50:43 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 185.120.22.12:123 (1.fedora.pool.ntp.org).
Feb 17 20:50:53 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 138.201.64.208:123 (1.fedora.pool.ntp.org).
Feb 17 20:51:03 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 138.201.28.101:123 (1.fedora.pool.ntp.org).
Feb 17 20:51:14 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 131.234.137.64:123 (2.fedora.pool.ntp.org).
Feb 17 20:51:24 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 80.153.195.191:123 (2.fedora.pool.ntp.org).

bash-5.0# systemctl status systemd-timesyncd
● systemd-timesyncd.service - Network Time Synchronization
   Loaded: loaded (/usr/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
  Drop-In: /usr/lib/systemd/system/systemd-timesyncd.service.d
           └─30_qubes.conf
   Active: active (running) since Mon 2020-02-17 20:47:16 CET; 32min ago
     Docs: man:systemd-timesyncd.service(8)
 Main PID: 412 (systemd-timesyn)
   Status: "Idle."
    Tasks: 2 (limit: 387)
   Memory: 1.0M
   CGroup: /system.slice/systemd-timesyncd.service
           └─412 /usr/lib/systemd/systemd-timesyncd

Feb 17 20:59:04 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 85.31.190.200:123 (2.fedora.pool.ntp.org).
Feb 17 20:59:14 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 129.70.132.35:123 (2.fedora.pool.ntp.org).
Feb 17 21:04:19 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 167.86.76.95:123 (1.fedora.pool.ntp.org).
Feb 17 21:04:29 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 141.64.5.250:123 (1.fedora.pool.ntp.org).
Feb 17 21:04:39 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 144.76.0.164:123 (1.fedora.pool.ntp.org).
Feb 17 21:04:49 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 193.158.22.13:123 (1.fedora.pool.ntp.org).
Feb 17 21:15:12 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 116.203.52.212:123 (3.fedora.pool.ntp.org).
Feb 17 21:15:22 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 77.246.126.132:123 (3.fedora.pool.ntp.org).
Feb 17 21:15:32 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 85.214.38.116:123 (3.fedora.pool.ntp.org).
Feb 17 21:15:42 sys-net systemd-timesyncd[412]: Timed out waiting for reply from 162.159.200.123:123 (3.fedora.pool.ntp.org).
bash-5.0# systemctl restart systemd-timesyncd
bash-5.0# systemctl status systemd-timesyncd
● systemd-timesyncd.service - Network Time Synchronization
   Loaded: loaded (/usr/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
  Drop-In: /usr/lib/systemd/system/systemd-timesyncd.service.d
           └─30_qubes.conf
   Active: active (running) since Mon 2020-02-17 21:20:14 CET; 6s ago
     Docs: man:systemd-timesyncd.service(8)
 Main PID: 1450 (systemd-timesyn)
   Status: "Idle."
    Tasks: 2 (limit: 387)
   Memory: 1.3M
   CGroup: /system.slice/systemd-timesyncd.service
           └─1450 /usr/lib/systemd/systemd-timesyncd

Feb 17 21:20:13 sys-net systemd[1]: Starting Network Time Synchronization...
Feb 17 21:20:14 sys-net systemd[1]: Started Network Time Synchronization.

Feb 17 21:20:13 sys-net systemd[1]: Starting Network Time Synchronization...
Feb 17 21:20:14 sys-net systemd[1]: Started Network Time Synchronization.
Feb 17 21:20:14 sys-net audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd comm="systemd" exe="/usr/lib/sy>
Feb 17 21:20:14 sys-net kernel: audit: type=1130 audit(1581970814.145:134): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd com>
Feb 17 21:20:15 sys-net xdg-desktop-por[1180]: Failed to get application states: GDBus.Error:org.freedesktop.portal.Error.Failed: Could not get window>
Feb 17 21:20:43 sys-net systemd-timesyncd[1450]: Timed out waiting for reply from 173.249.58.145:123 (1.fedora.pool.ntp.org).
Feb 17 21:20:53 sys-net systemd-timesyncd[1450]: Timed out waiting for reply from 212.18.3.18:123 (1.fedora.pool.ntp.org).
Feb 17 21:21:03 sys-net systemd-timesyncd[1450]: Timed out waiting for reply from 129.70.132.34:123 (1.fedora.pool.ntp.org).
Feb 17 21:21:14 sys-net systemd-timesyncd[1450]: Timed out waiting for reply from 80.237.128.148:123 (1.fedora.pool.ntp.org).

Still something like 5 minutes late:

bash-5.0# timedatectl status
               Local time: Mon 2020-02-17 22:18:24 CET
           Universal time: Mon 2020-02-17 21:18:24 UTC
                 RTC time: Mon 2020-02-17 21:18:24
                Time zone: Europe/Berlin (CET, +0100)
System clock synchronized: no
              NTP service: active
          RTC in local TZ: no
adrelanos commented 1 year ago

Do you still experience this issue with systemd-timesyncd?

Note: As the discussion in this ticket showed, this is unrelated to Whonix.

sjvudp commented 1 year ago

At the moment it seems OK:

● systemd-timesyncd.service - Network Time Synchronization
     Loaded: loaded (/usr/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
    Drop-In: /usr/lib/systemd/system/systemd-timesyncd.service.d
             └─30_qubes.conf
     Active: active (running) since Sun 2023-05-07 19:31:30 CEST; 2h 24min ago
       Docs: man:systemd-timesyncd.service(8)
   Main PID: 428 (systemd-timesyn)
     Status: "Initial synchronization to time server 213.172.105.106:123 (2.fedora.pool.ntp.org)."
      Tasks: 2 (limit: 367)
     Memory: 668.0K
        CPU: 14ms
     CGroup: /system.slice/systemd-timesyncd.service
             └─ 428 /usr/lib/systemd/systemd-timesyncd

May 07 19:31:30 sys-net systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization...
May 07 19:31:30 sys-net systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization.
May 07 19:32:29 sys-net systemd-timesyncd[428]: Initial synchronization to time server 213.172.105.106:123 (2.fedora.pool.ntp.org).

However I wonder: Could the problem occur if there is no network connection at the time when sys-net started (e.g. the cable was unplugged)?

Looking back in the journal, I found:

Feb 20 22:31:15 fedora-36 systemd[1]: systemd-timesyncd.service - Network Time Synchronization was skipped because of a failed condition check (ConditionPathExists=/var/run/qubes-service/clocksync).
Feb 20 22:31:15 fedora-36 systemd[1]: Reached target time-set.target - System Time Set.
...
May 07 19:32:29 sys-net systemd-timesyncd[428]: Initial synchronization to time server 213.172.105.106:123 (2.fedora.pool.ntp.org).
May 07 19:32:29 sys-net systemd-resolved[427]: Clock change detected. Flushing caches.
sjvudp commented 1 year ago

I also wonder whether the dependencies may be incomplete:

[Unit]
Description=Network Time Synchronization
Documentation=man:systemd-timesyncd.service(8)
ConditionCapability=CAP_SYS_TIME
ConditionVirtualization=!container
DefaultDependencies=no
After=systemd-sysusers.service
Before=time-set.target sysinit.target shutdown.target
Conflicts=shutdown.target
Wants=time-set.target

[Service]
AmbientCapabilities=CAP_SYS_TIME
adrelanos commented 1 year ago

Could you please re-title this bug? Because it's not really caused or related to sdwdate.

andrewdavidwong commented 1 year ago

Does this affect Qubes 4.1?

andrewdavidwong commented 1 year ago

Closing this for now as it appears that the issue no longer affects any Qubes users. If anyone believes this is a mistake, or if anyone is still affected by this issue, please leave a comment, and we'll be happy to reopen this. Thank you.