[qubes-users] Help me understand sdwdate

Hi!

I'm not a complete dummy regarding time synchronization, but I don't understand what sdwdate is doing, or more specifically: I don't know whether it's working as intended.

Let me present some logs:
2021-04-07 20:16:17 - sdwdate - INFO - Running sdwdate main loop. iteration: 1 / 10000
2021-04-07 20:16:18 - sdwdate - INFO - The clock is sane.
Within build timestamp Fri 11 Oct 2019 12:55:17 AM UTC and expiration timestamp Tue 17 May 2033 10:00:00 AM UTC.
2021-04-07 20:16:18 - sdwdate - WARNING - Tor is not yet fully bootstrapped. 52 % done.
Tor reports: NOTICE BOOTSTRAP PROGRESS=52 TAG=loading_descriptors SUMMARY="Loading relay descriptors"
2021-04-07 20:16:19 - sdwdate - INFO - The clock is sane.
Within build timestamp Fri 11 Oct 2019 12:55:17 AM UTC and expiration timestamp Tue 17 May 2033 10:00:00 AM UTC.
2021-04-07 20:16:19 - sdwdate - WARNING - Tor is not yet fully bootstrapped. 57 % done.
Tor reports: NOTICE BOOTSTRAP PROGRESS=57 TAG=loading_descriptors SUMMARY="Loading relay descriptors"
2021-04-07 20:16:20 - sdwdate - INFO - The clock is sane.
Within build timestamp Fri 11 Oct 2019 12:55:17 AM UTC and expiration timestamp Tue 17 May 2033 10:00:00 AM UTC.
2021-04-07 20:16:20 - sdwdate - WARNING - Tor is not yet fully bootstrapped. 61 % done.
Tor reports: NOTICE BOOTSTRAP PROGRESS=61 TAG=loading_descriptors SUMMARY="Loading relay descriptors"
2021-04-07 20:16:22 - sdwdate - INFO - Prerequisite check: The clock is sane.
Within build timestamp Fri 11 Oct 2019 12:55:17 AM UTC and expiration timestamp Tue 17 May 2033 10:00:00 AM UTC.
Clock within consensus parameters consensus/valid-after 2021-04-07 19:00:00 and consensus/valid-until 2021-04-07 22:00:00.
2021-04-07 20:16:22 - sdwdate - INFO - Prerequisite check: Tor fully bootstrapped.
2021-04-07 20:16:22 - sdwdate - INFO - Start fetching remote times.
2021-04-07 20:16:22 - sdwdate - INFO - Initial time fetching in progress...
2021-04-07 20:16:22 - sdwdate - INFO - Running sdwdate fetch loop. iteration: 1
2021-04-07 20:16:22 - sdwdate - INFO - Requested urls ['secrdrop5wyphb5x.onion', 'pgpkeysximvxiazm.onion', '3kyl4i7bfdgwelmf.onion']
2021-04-07 20:17:12 - sdwdate - INFO - Returned urls "['secrdrop5wyphb5x.onion', 'pgpkeysximvxiazm.onion', '3kyl4i7bfdgwelmf.onion']"
2021-04-07 20:17:12 - sdwdate - INFO - remote 0: secrdrop5wyphb5x.onion
2021-04-07 20:17:12 - sdwdate - INFO - * comment: https://securedrop.org https://web.archive.org/web/20170403043247/https://securedrop.org
2021-04-07 20:17:12 - sdwdate - INFO - * status: False
2021-04-07 20:17:12 - sdwdate - INFO - * value: Timeout
2021-04-07 20:17:12 - sdwdate - INFO - remote 1: pgpkeysximvxiazm.onion
2021-04-07 20:17:12 - sdwdate - INFO - * comment: https://pgpkeys.urown.net https://web.archive.org/web/20170421213557/https://pgpkeys.urown.net
2021-04-07 20:17:12 - sdwdate - INFO - * status: False
2021-04-07 20:17:12 - sdwdate - INFO - * value: Timeout
2021-04-07 20:17:12 - sdwdate - INFO - remote 2: 3kyl4i7bfdgwelmf.onion
2021-04-07 20:17:12 - sdwdate - INFO - * comment: http://www.wefightcensorship.org https://archive.fo/GhgMU
2021-04-07 20:17:12 - sdwdate - INFO - * remote_unixtime: 1617826445
2021-04-07 20:17:12 - sdwdate - INFO - * consensus/valid-after: 2021-04-07 19:00:00
2021-04-07 20:17:12 - sdwdate - INFO - * remote_time : 2021-04-07 20:14:05
2021-04-07 20:17:12 - sdwdate - INFO - * consensus/valid-until: 2021-04-07 22:00:00
2021-04-07 20:17:12 - sdwdate - INFO - * time_diff: -187 second(s)
2021-04-07 20:17:12 - sdwdate - INFO - * timesanitycheck: sane
2021-04-07 20:17:12 - sdwdate - INFO - * time_consensus_sanity_check: sane
2021-04-07 20:17:12 - sdwdate - INFO - * remote_status: True
2021-04-07 20:17:12 - sdwdate - INFO - Pool 3: 3kyl4i7bfdgwelmf.onion, web unixtime: 1617826445, web time: Wed Apr 07 20:14:05 UTC 2021, diff: -187 seconds
2021-04-07 20:17:12 - sdwdate - INFO - Running sdwdate fetch loop. iteration: 2
2021-04-07 20:17:12 - sdwdate - INFO - Requested urls ['mprt35sjunnxfa76.onion', 'zvldz46bbxqlw4od.onion']
2021-04-07 20:18:02 - sdwdate - INFO - Returned urls "['mprt35sjunnxfa76.onion', 'zvldz46bbxqlw4od.onion']"
2021-04-07 20:18:02 - sdwdate - INFO - remote 0: mprt35sjunnxfa76.onion
2021-04-07 20:18:02 - sdwdate - INFO - * comment: https://informant.taz.de https://web.archive.org/web/20170329061908/https://informant.taz.de
2021-04-07 20:18:02 - sdwdate - INFO - * remote_unixtime: 1617826493
2021-04-07 20:18:02 - sdwdate - INFO - * consensus/valid-after: 2021-04-07 19:00:00
2021-04-07 20:18:02 - sdwdate - INFO - * remote_time : 2021-04-07 20:14:53
2021-04-07 20:18:02 - sdwdate - INFO - * consensus/valid-until: 2021-04-07 22:00:00
2021-04-07 20:18:02 - sdwdate - INFO - * time_diff: -189 second(s)
2021-04-07 20:18:02 - sdwdate - INFO - * timesanitycheck: sane
2021-04-07 20:18:02 - sdwdate - INFO - * time_consensus_sanity_check: sane
2021-04-07 20:18:02 - sdwdate - INFO - * remote_status: True
2021-04-07 20:18:02 - sdwdate - INFO - remote 1: zvldz46bbxqlw4od.onion
2021-04-07 20:18:02 - sdwdate - INFO - * comment: Transparencia https://www.transparencia.click
2021-04-07 20:18:02 - sdwdate - INFO - * status: False
2021-04-07 20:18:02 - sdwdate - INFO - * value: Timeout
2021-04-07 20:18:02 - sdwdate - INFO - Pool 1: mprt35sjunnxfa76.onion, web unixtime: 1617826493, web time: Wed Apr 07 20:14:53 UTC 2021, diff: -189 seconds
2021-04-07 20:18:02 - sdwdate - INFO - Running sdwdate fetch loop. iteration: 3
2021-04-07 20:18:02 - sdwdate - INFO - Requested urls ['ltcpool5brio2gaj.onion']
2021-04-07 20:18:06 - sdwdate - INFO - Returned urls "['ltcpool5brio2gaj.onion']"
2021-04-07 20:18:06 - sdwdate - INFO - remote 0: ltcpool5brio2gaj.onion
2021-04-07 20:18:06 - sdwdate - INFO - * comment: Help/FAQ | litecoinpool.org Help/FAQ | litecoinpool.org
2021-04-07 20:18:06 - sdwdate - INFO - * remote_unixtime: 1617826544
2021-04-07 20:18:06 - sdwdate - INFO - * consensus/valid-after: 2021-04-07 19:00:00
2021-04-07 20:18:06 - sdwdate - INFO - * remote_time : 2021-04-07 20:15:44
2021-04-07 20:18:06 - sdwdate - INFO - * consensus/valid-until: 2021-04-07 22:00:00
2021-04-07 20:18:06 - sdwdate - INFO - * time_diff: -142 second(s)
2021-04-07 20:18:06 - sdwdate - INFO - * timesanitycheck: sane
2021-04-07 20:18:06 - sdwdate - INFO - * time_consensus_sanity_check: sane
2021-04-07 20:18:06 - sdwdate - INFO - * remote_status: True
2021-04-07 20:18:06 - sdwdate - INFO - Pool 2: ltcpool5brio2gaj.onion, web unixtime: 1617826544, web time: Wed Apr 07 20:15:44 UTC 2021, diff: -142 seconds
2021-04-07 20:18:06 - sdwdate - INFO - End fetching remote times.
2021-04-07 20:18:06 - sdwdate - INFO - Pool differences, sorted: [-189, -187, -142]
2021-04-07 20:18:06 - sdwdate - INFO - Median time difference: -187.000000000
2021-04-07 20:18:06 - sdwdate - INFO - randomize : +0.611985016
2021-04-07 20:18:06 - sdwdate - INFO - New time difference : -186.388014984
2021-04-07 20:18:06 - sdwdate - INFO - Old unixttime: 1617826686.715282679
2021-04-07 20:18:06 - sdwdate - INFO - New unixtime : 1617826500.327267647
2021-04-07 20:18:06 - sdwdate - INFO - Instantly setting the time by using command: /bin/date --set "@1617826500.327267647"
2021-04-07 20:15:00 - sdwdate - INFO - /bin/date output: Wed 07 Apr 2021 08:15:00 PM UTC

What makes me wonder: My clock seems to be off by about 3 minutes (186 seconds), and sdwdate care to add a 0.6 second random offset.
That doesn't make sense to me.
I wonder: Is sdwdate setting the correct time at all here?
Or does it mean it took 3 minutes between requesting the sending the time and receiving it?

Regards,
Ulrich

1 Like

Hi Ulrich,

have you considered asking those questions over at forums.whonix.org? swdate is part of Whonix which is packaged with Qubes OS but a separate project.

Here is a thread that would probably connect you with the right people to answer your questions: