[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

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: