Small piwiz race condition (time sync)

[sakaki]

Hello,

during recent testing of my raspbian-nspawn-64 image, I ran into a small race condition that I believe will probably also affect vanilla Raspbian installs.

Specifically, if the user boots the current (10 July 2019) Raspbian image, with no Ethernet connected, gets to the WiFi setup screen, specifies the desired connection and passphrase, and then immediately progresses to the "Update Software" stage, they are then in effect racing the automatic time sync. This can take up to between 30s -> 1m to correct the time (after a ping-capable wlan connection has been established) from the shipped 10th July, but if the user has clicked forward immediately they may get something like the following:



Not the end of the world, but some less experienced users may be confused by the error and not know to retry (since OK-ing the above error dialog takes them to the "Setup Complete" screen), leaving them running a (slightly) out-of-date (but still functional o/c) system.

This would be an easy corner case to address in piwiz (which otherwise works very nicely).

Apologies if I am in error, and this doesn't apply to standard Raspbian.

Best, sakaki

[Gazzy]

I experienced the same error cycle, as I installed a new micro sd with buster. 10 July.

As the problem, may be a time/server issue
I’m not fully sure, as many setting, and updates are not yet complete, locale, zone, time ect. Including your local mirror.

I also found when setting up the lrg install of desktop and apps, that I had about half an hour of downloads to get with

Apt-get update
Apt-get upgrade.

To which I met a few errors, such as timing out, not being able to fetch, and I have also repeatedly been running into the Wait pending error listed above when I do apt-get update.

I do think that there are many updates pending since July 10 , and I was hoping that a new release would be pending soon, that may clear up some of these issues.

I did manage to get all the updates installed eventually with numerous apt-get upgrade runs.

But regularly I’m getting the release is not valid yet, when running apt-get update.

All my settings are done, I’m using my local city/uni repository, and my time and zone and locale are correct, I’m not sure of why the error is presenting. If I do a few apt-get updates in a row it seems to work normally.

I hope someone can work it out for future updates, I’m looking forward to a new buster using a newer stable kernel, in the next release.

Gazzy

[RonR]

After switching over to Buster Lite, I began having 'apt-get update' failures when it is run immediately after startup. When it became clear the problem was due to the time not being set, I added the following to my startup script and haven't had any problems since:

Code: Select all

# Wait For Time Synchronization
while [ "$(timedatectl status | sed -n 's|^System clock synchronized: \(.*\)|\1|p')" != "yes" ]
do
  echo -n "."
  sleep 1
done
echo ""

Many times, 10 - 15 dots (one second each) are displayed before 'timedatectl status' reports that the system clock is synchronized.

[sakaki]

Probably worth filing an issue against this then, if it also affects vanilla Raspbian Buster.

Does anyone know the correct GitHub project? I've only been able to find

https://github.com/nethunteros/piwiz

but nothing in e.g. raspberrypi or raspberrypi-ui: guess I'm just looking in the wrong place?

Best, sakaki

[sakaki]

In case it helps pin this down, looks like the following RPi4-unboxing YouTube video may show the issue occurring:

https://www.youtube.com/watch?v=ikX-NUmfvWc

The relevant section is from 11:04 onwards.

To be fair, the user does seem to have an older copy of Raspbian, since his attempts to then fix things at the command line (with apt-get update) initially don't work either, due to the (unrelated?) "testing to stable" issue.

Thanks for rMax for forwarding the link to me.

Best, sakaki

[ShiftPlusOne]

I've passed the problem on to the developer of piwiz.

Thanks, Sakaki.

[knute]

After switching over to Buster Lite, I began having 'apt-get update' failures when it is run immediately after startup. When it became clear the problem was due to the time not being set, I added the following to my startup script and haven't had any problems since:

Code: Select all

# Wait For Time Synchronization
while [ "$(timedatectl status | sed -n 's|^System clock synchronized: \(.*\)|\1|p')" != "yes" ]
do
  echo -n "."
  sleep 1
done
echo ""

Many times, 10 - 15 dots (one second each) are displayed before 'timedatectl status' reports that the system clock is synchronized.

I really like your solution! I have found that you can restart systemd-timesyncd shortly after the desktop is up and get the clock synchronized much sooner. Please see this post: https://www.raspberrypi.org/forums/view ... 8&t=251705 for more details.

[RonR]

I really like your solution! I have found that you can restart systemd-timesyncd shortly after the desktop is up and get the clock synchronized much sooner.

I really hope someone fixes the problem. Users shouldn't have to spin their wheels waiting for the O/S to be ready before running applications like APT/APT-GET.

[RonR]

If you're using timesyncd here's simpler solution

Code: Select all

#!/bin/bash
# Wait For Time Synchronization
while [ ! -f "/run/systemd/timesync/synchronized" ]
do
  echo -n "."
  sleep 1
done
echo "Sync'd"

I like your suggestion, but "/run/systemd/timesync/synchronized" is apparently a Buster addition and I have to continue supporting Stretch a little longer.

Further info regarding the timesync issue...

Running:

Code: Select all

systemctl restart systemd-timesyncd.service

following a reboot yields:

Code: Select all

Warning: The unit file, source configuration file or drop-ins of systemd-timesyncd.service changed on disk. Run 'systemctl daemon-reload' to reload units.

Something isn't right with timesync.

None of this is something a user should have to work around (but you do what you gotta do).

I hope the RPF guys are following this.

[ShiftPlusOne]

Another option:

/usr/lib/systemd/systemd-time-wait-sync

Typically, if you have a service that relies on having the time synchronised, you add a dependency on time-sync.target, which will execute the above commands before running it.

IMHO, desktop applications shouldn't make assumptions about whether the time is synchronised or which NTP client is used, which makes it a bit tricky to handle this particular case properly.

Since the default Raspbian image is set up for systemd-timesync, it should probably just poll for /run/systemd/timesync/synchronised. I don't see a proper way to tell systemd-timesync to trigger a sync or what the poll interval is in this scenario.

[RonR]

If you're using timesyncd here's simpler solution

Code: Select all

#!/bin/bash
# Wait For Time Synchronization
while [ ! -f "/run/systemd/timesync/synchronized" ]
do
  echo -n "."
  sleep 1
done
echo "Sync'd"

I like your suggestion, but "/run/systemd/timesync/synchronized" is apparently a Buster addition and I have to continue supporting Stretch a little longer.

Not sure if it's Buster only. It's documented in man systemd-timesyncd.service. I don't have a stretch system to check with.

It is Buster only -- I tested Stretch before posting the above reply. "/run/systemd/timesync/synchronized" doesn't exist under Stretch. Even the output of 'timedatectl status' is different between Buster and Stretch, requiring a minor wobulation in the code.

[RonR]

Since the default Raspbian image is set up for systemd-timesync, it should probably just poll for /run/systemd/timesync/synchronised. I don't see a proper way to tell systemd-timesync to trigger a sync or what the poll interval is in this scenario.

That's what I've had to resort to for compatibility with Buster in several installation scripts that get fired up from /etc/profile.d (except polling the output of 'timedatectl status' instead of the presence of '/run/systemd/timesync/synchronised').

Should we be concerned with?:

Running:

Code: Select all

systemctl restart systemd-timesyncd.service

following a reboot yields:

Code: Select all

Warning: The unit file, source configuration file or drop-ins of systemd-timesyncd.service changed on disk. Run 'systemctl daemon-reload' to reload units.

Do we need to put a band-aid on this also with a user-supplied 'systemctl daemon-reload' in rc.local or somewhere?

[ShiftPlusOne]

Should we be concerned with?

I wouldn't be, but I never tried to find out why systemd says it.

It could make sense if you modified a service and restarted it without running that command, but in this case, contrary to the message, no changes have been made.

[RonR]

Should we be concerned with?

I wouldn't be, but I never tried to find out why systemd says it.

It could make sense if you modified a service and restarted it without running that command, but in this case, contrary to the message, no changes have been made.

No changes of any sort anywhere have been made. Please do the following:

1. Boot a fresh copy of 2019-07-10-raspbian-buster-lite.img on an SD card in a Raspberry Pi 4.

2. Run:

Code: Select all

sudo systemctl status systemd-timesyncd.service

and note the lack of a warning in the response:

Code: Select all

pi@raspberrypi:~ $ sudo systemctl status systemd-timesyncd.service
● systemd-timesyncd.service - Network Time Synchronization
   Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
  Drop-In: /lib/systemd/system/systemd-timesyncd.service.d
           └─disable-with-time-daemon.conf
   Active: active (running) since Wed 2019-07-10 01:21:23 BST; 2 months 9 days ago
     Docs: man:systemd-timesyncd.service(8)
 Main PID: 313 (systemd-timesyn)
   Status: "Synchronized to time server for the first time 198.50.238.163:123 (2.debian.pool.ntp.org)."
    Tasks: 2 (limit: 4915)
   Memory: 2.8M
   CGroup: /system.slice/systemd-timesyncd.service
           └─313 /lib/systemd/systemd-timesyncd

Jul 10 01:21:22 raspberrypi systemd[1]: Starting Network Time Synchronization...
Jul 10 01:21:23 raspberrypi systemd[1]: Started Network Time Synchronization.
Sep 18 21:12:37 raspberrypi systemd-timesyncd[313]: Synchronized to time server for the first time 198.50.238.163:123 (2.debian.pool.ntp.org).

3. Reboot:

Code: Select all

sudo reboot

4. Run:

Code: Select all

sudo systemctl status systemd-timesyncd.service

and note the presence of a waring in the response:

Code: Select all

pi@raspberrypi:~ $ sudo systemctl status systemd-timesyncd.service
Warning: The unit file, source configuration file or drop-ins of systemd-timesyncd.service changed on disk. Run 'systemctl daemon-reload' to reload units.
● systemd-timesyncd.service - Network Time Synchronization
   Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
  Drop-In: /lib/systemd/system/systemd-timesyncd.service.d
           └─disable-with-time-daemon.conf
   Active: active (running) since Wed 2019-09-18 21:14:39 BST; 47s ago
     Docs: man:systemd-timesyncd.service(8)
 Main PID: 315 (systemd-timesyn)
   Status: "Synchronized to time server for the first time 198.50.238.163:123 (2.debian.pool.ntp.org)."
    Tasks: 2 (limit: 4915)
   Memory: 3.1M
   CGroup: /system.slice/systemd-timesyncd.service
           └─315 /lib/systemd/systemd-timesyncd

Sep 18 21:14:38 raspberrypi systemd[1]: Starting Network Time Synchronization...
Sep 18 21:14:39 raspberrypi systemd[1]: Started Network Time Synchronization.
Sep 18 21:15:22 raspberrypi systemd-timesyncd[315]: Synchronized to time server for the first time 198.50.238.163:123 (2.debian.pool.ntp.org).

[davidcoton]

Should we be concerned with?

I wouldn't be, but I never tried to find out why systemd says it.

It could make sense if you modified a service and restarted it without running that command, but in this case, contrary to the message, no changes have been made.

No changes of any sort anywhere have been made. ...

[Wild Guess]
The shutdown process saves the date and time to be read at reboot.
systemd-timesyncd.service regards that info as part of its configuration.
Therefore, it warns of a change.
Possibly the timestamp of the changed file matches the current time (it would, because that is its purpose ) so systemd-timesyncd.service doesn't realise a reboot has occurred in between -- the reboot occurred at time 0, after all.
[/WildGuess]

[RonR]

[Wild Guess]
The shutdown process saves the date and time to be read at reboot.
systemd-timesyncd.service regards that info as part of its configuration.
Therefore, it warns of a change.
Possibly the timestamp of the changed file matches the current time (it would, because that is its purpose ) so systemd-timesyncd.service doesn't realise a reboot has occurred in between -- the reboot occurred at time 0, after all.
[/WildGuess]

Regardless of the reason/explanation, it's not right.

[davidcoton]

Regardless of the reason/explanation, it's not right.

True, but understanding why it goes wrong may help put it right.

[ShiftPlusOne]

Went down the rabbit hole a bit:

https://github.com/systemd/systemd/blob ... it.c#L3969

That's what's getting triggered.

So, at the time that unit is loaded the mtime is older than at present, although the file contents are identical.

I've put some debug code to record the mtime of those files at various points during boot, but so far they come back identical. So, it's not quite solved yet.

[ShiftPlusOne]

Code: Select all

$ for unit in $(dbus-send --system --print-reply --reply-timeout=2000 --type=method_call --dest=org.freedesktop.systemd1 /org/freedesktop/systemd1 org.freedesktop.systemd1.Manager.ListUnits | grep "object path" | sed -n 's|^.* "\(.*\)".*$|\1|p' | sort -u); do if busctl --system get-property org.freedesktop.systemd1 $unit org.freedesktop.systemd1.Unit NeedDaemonReload | grep true; then echo $unit; fi; done;

b true
/org/freedesktop/systemd1/unit/dhcpcd_2eservice
b true
/org/freedesktop/systemd1/unit/getty_40tty1_2eservice
b true
/org/freedesktop/systemd1/unit/rc_2dlocal_2eservice
b true
/org/freedesktop/systemd1/unit/systemd_2dtimesyncd_2eservice

What those services all have in common is that they all have a drop-in file. So I'm guessing it ends up here https://github.com/systemd/systemd/blob ... it.c#L4602

Then wouldn't be comparing the mtime of the file when it was loaded, but the clock at the time it's loaded to the mtime. Units which don't have dropin files don't compare dropin_mtime so they don't trigger the warning.

Edit: Just to confirm, date +%s before fake-hwclock runs is 1550139119 and 1568847399 after. The mtime of the file is 1568069874. So 1550139119 < 1568069874, giving you the warning. False positive. Safe to ignore.

Edit2: For completeness 1550139119 is February 14th, the release date of systemd 241 https://github.com/systemd/systemd/comm ... 237f629b39 . When it's built, it looks at the modification date of the changelog and sets that as its epoch time. At boot, if there is no RTC, it uses that as the initial time. https://github.com/systemd/systemd/blob ... build#L652

To sum up, systemd uses its release date as the initial time. Then it compares the time at boot to the modification time of the drop in file, which is newer. That triggers the warning. I still don't understand why this doesn't affect units without drop in files, but I've had enough digging through systemd for a day.

[knute]

To sum up, systemd uses its release date as the initial time. Then it compares the time at boot to the modification time of the drop in file, which is newer. That triggers the warning. I still don't understand why this doesn't affect units without drop in files, but I've had enough digging through systemd for a day.

Thanks very much for digging into that, that is really interesting.

[davidcoton]

Thanks very much for digging into that, that is really interesting.

+1 or more.