User avatar
sakaki
Posts: 402
Joined: Sun Jul 16, 2017 1:11 pm

Small piwiz race condition (time sync)

Fri Sep 13, 2019 5:47 pm

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:

Image

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
Posts: 31
Joined: Tue Aug 27, 2019 1:40 am

Re: Small piwiz race condition (time sync)

Sun Sep 15, 2019 5:40 am

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
Posts: 623
Joined: Tue Apr 12, 2016 10:29 pm
Location: US

Re: Small piwiz race condition (time sync)

Sun Sep 15, 2019 6:58 am

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.

User avatar
sakaki
Posts: 402
Joined: Sun Jul 16, 2017 1:11 pm

Re: Small piwiz race condition (time sync)

Sun Sep 15, 2019 7:24 am

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

User avatar
sakaki
Posts: 402
Joined: Sun Jul 16, 2017 1:11 pm

Re: Small piwiz race condition (time sync)

Mon Sep 16, 2019 8:51 am

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
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 6074
Joined: Fri Jul 29, 2011 5:36 pm
Location: The unfashionable end of the western spiral arm of the Galaxy

Re: Small piwiz race condition (time sync)

Mon Sep 16, 2019 10:58 am

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

Thanks, Sakaki.

knute
Posts: 477
Joined: Thu Oct 23, 2014 12:14 am
Location: Texas
Contact: Website

Re: Small piwiz race condition (time sync)

Tue Sep 17, 2019 3:20 pm

RonR wrote:
Sun Sep 15, 2019 6:58 am
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
Posts: 623
Joined: Tue Apr 12, 2016 10:29 pm
Location: US

Re: Small piwiz race condition (time sync)

Tue Sep 17, 2019 6:24 pm

knute wrote:
Tue Sep 17, 2019 3:20 pm
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.

jcyr
Posts: 483
Joined: Sun Apr 23, 2017 1:31 pm
Location: Atlanta

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 1:15 am

RonR wrote:
Tue Sep 17, 2019 6:24 pm
knute wrote:
Tue Sep 17, 2019 3:20 pm
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.
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"
It's um...uh...well it's kinda like...and it's got a bit of...

RonR
Posts: 623
Joined: Tue Apr 12, 2016 10:29 pm
Location: US

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 3:36 am

jcyr wrote:
Wed Sep 18, 2019 1:15 am
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.

jcyr
Posts: 483
Joined: Sun Apr 23, 2017 1:31 pm
Location: Atlanta

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 12:55 pm

RonR wrote:
Wed Sep 18, 2019 3:36 am
jcyr wrote:
Wed Sep 18, 2019 1:15 am
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's um...uh...well it's kinda like...and it's got a bit of...

ShiftPlusOne
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 6074
Joined: Fri Jul 29, 2011 5:36 pm
Location: The unfashionable end of the western spiral arm of the Galaxy

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 1:27 pm

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.

jcyr
Posts: 483
Joined: Sun Apr 23, 2017 1:31 pm
Location: Atlanta

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 1:46 pm

ShiftPlusOne wrote:
Wed Sep 18, 2019 1:27 pm
Another option:

/usr/lib/systemd/systemd-time-wait-sync
Tried that... didn't work! The dependency seemed to be met as soon as the timesyncd service issued a "READY=1" indication to systemd, which it does as soon as it is initialized instead of when the time is actually synchronized.

Might be wrong but I didn't pursue it when I discovered the /run/systemd/.../synchronized file method.
It's um...uh...well it's kinda like...and it's got a bit of...

jcyr
Posts: 483
Joined: Sun Apr 23, 2017 1:31 pm
Location: Atlanta

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 1:50 pm

ShiftPlusOne wrote:
Wed Sep 18, 2019 1:27 pm
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.
Indeed it is a thorny problem, given that many will prefer NTP. There are plenty of cases where an app will depend on the time being synchronized. The apt update case is just one, git log timestamps out of order is another.

I wish the NTP daemon had a config option to force it to update the clock instead of giving up when there is too much spread between the system clock and the network time. Alas, there isn't.
It's um...uh...well it's kinda like...and it's got a bit of...

RonR
Posts: 623
Joined: Tue Apr 12, 2016 10:29 pm
Location: US

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 5:26 pm

jcyr wrote:
Wed Sep 18, 2019 12:55 pm
RonR wrote:
Wed Sep 18, 2019 3:36 am
jcyr wrote:
Wed Sep 18, 2019 1:15 am
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
Posts: 623
Joined: Tue Apr 12, 2016 10:29 pm
Location: US

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 5:49 pm

ShiftPlusOne wrote:
Wed Sep 18, 2019 1:27 pm
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?:
RonR wrote:
Wed Sep 18, 2019 3:36 am
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
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 6074
Joined: Fri Jul 29, 2011 5:36 pm
Location: The unfashionable end of the western spiral arm of the Galaxy

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 8:05 pm

RonR wrote: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
Posts: 623
Joined: Tue Apr 12, 2016 10:29 pm
Location: US

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 8:28 pm

ShiftPlusOne wrote:
Wed Sep 18, 2019 8:05 pm
RonR wrote: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

[email protected]:~ $ 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

[email protected]:~ $ 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).

User avatar
davidcoton
Posts: 4243
Joined: Mon Sep 01, 2014 2:37 pm
Location: Cambridge, UK

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 8:41 pm

RonR wrote:
Wed Sep 18, 2019 8:28 pm
ShiftPlusOne wrote:
Wed Sep 18, 2019 8:05 pm
RonR wrote: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 :o ) so systemd-timesyncd.service doesn't realise a reboot has occurred in between -- the reboot occurred at time 0, after all.
[/WildGuess]
Signature retired

RonR
Posts: 623
Joined: Tue Apr 12, 2016 10:29 pm
Location: US

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 8:47 pm

davidcoton wrote:
Wed Sep 18, 2019 8:41 pm
[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 :o ) 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.

User avatar
davidcoton
Posts: 4243
Joined: Mon Sep 01, 2014 2:37 pm
Location: Cambridge, UK

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 8:58 pm

RonR wrote:
Wed Sep 18, 2019 8:47 pm
Regardless of the reason/explanation, it's not right.
True, but understanding why it goes wrong may help put it right.
Signature retired

ShiftPlusOne
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 6074
Joined: Fri Jul 29, 2011 5:36 pm
Location: The unfashionable end of the western spiral arm of the Galaxy

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 10:34 pm

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
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 6074
Joined: Fri Jul 29, 2011 5:36 pm
Location: The unfashionable end of the western spiral arm of the Galaxy

Re: Small piwiz race condition (time sync)

Wed Sep 18, 2019 10:53 pm

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
Posts: 477
Joined: Thu Oct 23, 2014 12:14 am
Location: Texas
Contact: Website

Re: Small piwiz race condition (time sync)

Thu Sep 19, 2019 4:42 pm

ShiftPlusOne wrote:
Wed Sep 18, 2019 10:53 pm
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.

User avatar
davidcoton
Posts: 4243
Joined: Mon Sep 01, 2014 2:37 pm
Location: Cambridge, UK

Re: Small piwiz race condition (time sync)

Thu Sep 19, 2019 4:46 pm

knute wrote:
Thu Sep 19, 2019 4:42 pm
Thanks very much for digging into that, that is really interesting.
+1 or more.
Signature retired

Return to “General discussion”