Issue with drifting time on Raspberry 4B v1.5 and Venus OS v2.90

Question

question

pcurtis asked Sep 6, '22

Issue with drifting time on Raspberry 4B v1.5 and Venus OS v2.90

I have been asked by @mvader (Victron Energy) to repost this issue here

Has anybody else had an issue with the clock on Raspberry Pis? I have just moved my Pi 4B to OS 2.90 and noticed that I had to manually set the time, which I never had to do previously, and more importantly, that the time is drifting by nearly a minute a day. The Pi 4 is being configured as a backup/development machine and was run under 2.82 for a period and I never observed a drift but I might have missed it as my time display in the dashboard did not display seconds.

Checking against my 'operational' Pi 3B running 2.80, there in no drift and I see that there are regular connmand entries in the message log with a time slew derived from an ntp: server which is presumably used to correct the clock - there are no such entries in the Pi 4B (running 2.90~26) message log.

Searches on the Internet indicate that none of the Raspberries have a proper Real Time Clock and depend on Internet updates from ntp: servers and many resulting issues are reported. I have found nothing on how it is implemented by connmand as most Pis run Raspbian or Debian derivatives which do not use connman.

Examples of connmand ntp: calls from old Pi 3B+ message logs. Note the differences in rates: 16 secs to 2 hours [as system adapts??]. Current Pi 3B+ logs show 2 hourly calls.

Jan 15 20:36:28 raspberrypi2 daemon.info connmand[673]: ntp: time slew +0.003129 s
Jan 15 20:36:44 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.002957 s
Jan 15 20:37:02 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.000094 s
Jan 15 20:37:18 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.000618 s
Jan 15 20:37:34 raspberrypi2 daemon.info connmand[673]: ntp: time slew +0.004639 s
Jan 15 20:37:50 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.010419 s
Jan 15 20:38:06 raspberrypi2 daemon.info connmand[673]: ntp: time slew +0.002409 s
Jan 15 20:38:22 raspberrypi2 daemon.info connmand[673]: ntp: time slew +0.004451 s
Jan 15 20:38:38 raspberrypi2 daemon.info connmand[673]: ntp: time slew +0.014084 s
........
Jan 18 07:15:16 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.061522 s
Jan 18 09:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.065496 s
Jan 18 11:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.061816 s
Jan 18 13:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.078941 s
Jan 18 15:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.052677 s
Jan 18 17:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.057737 s
Jan 18 19:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.053606 s
Jan 18 21:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.070503 s
Jan 18 23:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.058321 s
Jan 19 01:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.067513 s

Raspberry Pi

2 |3000

Attachments: Up to 8 attachments (including images) can be used with a maximum of 190.8 MiB each and 286.6 MiB total.

Modifications Space

Node Red Space

Answer 1 · 2022-09-06T18:14:21Z

bathnm answered · Sep 06, 2022 at 06:14 PM

What is your NTP source? Is it the local router?

On my RPI, with the local router configured as an NTP server the RPI gives these two messages every second

Sep  6 18:11:05 raspberrypi4 daemon.info connmand[772]: ntp: time slew +0.174016 s
Sep  6 18:11:05 raspberrypi4 daemon.err connmand[772]: Failed to set hwclock

As soon as I disable the local router from being an NTP server the messages stop. I have not left it running long enough to know if it will sync with a backup server at some stage or if the clock will drift.

1

2 |3000

Attachments: Up to 8 attachments (including images) can be used with a maximum of 190.8 MiB each and 286.6 MiB total.

pcurtis commented · Sep 07, 2022 at 01:22 AM

I do not know the NTP sources, I had assumed they would be be from Internet servers. The Pi 4 is in the house on a standard WiFi router from BT, the service provider, the Pi 2 is in on the boat and connected via an old 3G tethered Samsung phone to the O2 network via Giffgaff. I am away from home so I can not check but it will be easy to use use a modern phone or collect the one from the boat for the Pi 4. I am not sure how much access to make changes in the BT provided local router.

0 ·

Answer 2 · 2022-09-06T20:05:05Z

Kevin Windrem answered · Sep 06, 2022 at 08:05 PM

I'm running a RPI4 v1.2 and VenusOS 2.90~27 and am not seeing clock drift and the clock IS set during boot.

I have not found an ntp.conf file anywhere.

I see only a couple nap entries in /data/log/messages about 2 hours apart:

Sep  6 16:10:26 raspberrypi4 daemon.info connmand[790]: ntp: time slew +20.740906 s
Sep  6 18:11:22 raspberrypi4 daemon.info connmand[790]: ntp: time slew -0.088929 s

So I think everything is working for me.

3

2 |3000

Attachments: Up to 8 attachments (including images) can be used with a maximum of 190.8 MiB each and 286.6 MiB total.

johnny-brusevold commented · Sep 06, 2022 at 11:39 PM

Connman is responsible for ntp and updating the clock

in /etc/connman/main.conf

FallbackTimeservers=0.europe.pool.ntp.org,1.europe.pool.ntp.org,2.europe.pool.ntp.org,3.europe.pool.ntp.org

I think you can add ntp servers manually with connmanctrl

root@raspberrypi2:~# connmanctl
connmanctl> services
*AO Wired                ethernet_b827ebd1b69b_cable
connmanctl>config ethernet_b827ebd1b69b_cable --timeservers 8.8.8.8
connmanctl>exit

that command just adds a line to the bottom

/data/var/lib/connman/ethernet_b827ebd1b69b_cable/settings

[ethernet_b827ebd1b69b_cable]
Name=Wired
AutoConnect=true
Modified=2022-09-06T23:04:14.356521Z
IPv4.method=dhcp
IPv4.DHCP.LastAddress=192.168.1.100
IPv6.method=auto
IPv6.privacy=disabled
IPv6.DHCP.DUID=00010001c792bc9db827ebd1b69b
Timeservers=8.8.8.8;

0 ·

pcurtis johnny-brusevold commented · Sep 07, 2022 at 01:47 AM

Is there a way to find out which, if any, time server is being used by connmand?

0 ·

pcurtis commented · Sep 07, 2022 at 01:41 AM

That is a large time slew being corrected which is consistent with what I need to correct every day rather than once

0 ·

Answer 3 · 2022-09-07T05:38:37Z

bathnm answered · Sep 07, 2022 at 05:38 AM

Hi All,

the ntp process is part of conman and so there is no specific ntp.conf. It would seem that when conman detects the server is part of the local LAN it increases it's polling of nap to once a second. This then creates lots of log file entries as the clock will be slewed to keep it in sync with NTP. Disable the local ntp server and it reverts to one of many servers on the internet at which point it reduces it's sync time to many hours.

1

2 |3000

Attachments: Up to 8 attachments (including images) can be used with a maximum of 190.8 MiB each and 286.6 MiB total.

johnny-brusevold commented · Sep 07, 2022 at 08:13 AM

@Bathnm

My pi3+ updates ntp exactly every 2 hours (between all the error lines)

Sep  7 03:28:09 raspberrypi2 daemon.info connmand[738]: ntp: time slew -0.056099 s
Sep  7 05:28:09 raspberrypi2 daemon.info connmand[738]: ntp: time slew -0.053523 s
Sep  7 07:28:09 raspberrypi2 daemon.info connmand[738]: ntp: time slew -0.108575 s

i get these error messages every minute

Sep  7 07:23:38 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: Address family not supported by protocol
Sep  7 07:24:38 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: Address family not supported by protocol
Sep  7 07:25:38 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: Address family not supported by protocol
Sep  7 07:26:39 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: Address family not supported by protocol
Sep  7 07:27:39 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: Address family not supported by protocol
Sep  7 07:28:09 raspberrypi2 daemon.info connmand[738]: ntp: time slew -0.108575 s
Sep  7 07:28:39 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: Address family not supported by protocol
Sep  7 07:29:40 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: Address family not supported by protocol
Sep  7 07:30:40 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: Address family not supported by protocol
Sep  7 07:31:40 raspberrypi2 daemon.err dnsmasq[687]: failed to send packet: A

Sep  7 07:43:20 raspberrypi2 user.warn kernel: [31141.010883] ICMPv6: process `sysctl' is using deprecated sysctl (syscall) net.ipv6.neigh.default.base_reachable_time - use net.ipv6.neigh.default.base_reachable_time_ms instead

0 ·

Answer 4 · 2022-09-09T13:49:01Z

pcurtis answered · Sep 09, 2022 at 01:49 PM

When everything is stable on RPI 3B+ I could only see an auto update cron job once per day as well as 2 hourly ntp: time slew messages. I Do not get dnsmask or other errors but there are a few using and stopped using dnsmasq messages earlier in the log so it was called and working in 2.80

Rst get Jan 18 02:05:01 raspberrypi2 cron.info CROND[9352]: (root) CMDOUT (arguments: -auto -delay)
Jan 18 02:05:01 raspberrypi2 cron.info CROND[9352]: (root) CMDOUT (Auto-update disabled, exit.)
Jan 18 03:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.088345 s
Jan 18 05:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.061114 s
Jan 18 07:15:16 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.061522 s
// .......
Jan 18 23:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.058321 s
Jan 19 01:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.067513 s
Jan 19 02:05:01 raspberrypi2 cron.info CROND[31907]: (root) CMD (/opt/victronenergy/swupdate-scripts/check-updates.sh -auto -delay)
Jan 19 02:05:01 raspberrypi2 cron.info CROND[31906]: (root) CMDOUT (*** Checking for updates ***)
Jan 19 02:05:01 raspberrypi2 cron.info CROND[31906]: (root) CMDOUT (arguments: -auto -delay)
Jan 19 02:05:01 raspberrypi2 cron.info CROND[31906]: (root) CMDOUT (Auto-update disabled, exit.)
Jan 19 03:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.059231 s
Jan 19 05:15:15 raspberrypi2 daemon.info connmand[673]: ntp: time slew -0.063633 s

2 |3000

Attachments: Up to 8 attachments (including images) can be used with a maximum of 190.8 MiB each and 286.6 MiB total.

Answer 5 · 2022-09-27T16:20:39Z

I believe I now understand the problem thanks to various suggestions and subsequent measurements. The good news is that it is nothing to do with the Venus OS version or Raspberry Pi version. The bad news is that it seems none of the RPIs have a decent Real Time Clock and depend on frequent corrections. In the case of the Venus OS this is done by the connmand daemon using ntp: . It first uses anything available from the router then tries a set of predefined internet sources. In my case the BT provided router at home does not provide usable time codes over the WiFi but does over ethernet. The working system on the boat uses an old tethered Android 4.2 phone and the provider is GiffGaff. Changing to use a spare Android 12 phone on my development system at home with Venus OS 2.90 on a RPI 4B v1.5 led to it working perfectly.

Excerpts from /data/log/message after change to my Tethered mobile to providing internet access show an initial large correction (after being powered off) of a 53 sec time slew then ntp: calls every 2 hours giving minor corrections. Also, for completeness, I show the daily check for updates so this is all the end of the message log should show every day.

Sep 24 07:36:52 raspberrypi4 authpriv.notice login[1382]: ROOT LOGIN  on '/dev/ttyS0'
Sep 24 07:36:52 raspberrypi4 authpriv.notice login[1383]: ROOT LOGIN  on '/dev/tty1'
Sep 24 07:37:03 raspberrypi4 daemon.info connmand[724]: wlan0 {del} route 82.165.8.211 gw 192.168.40.55 scope 0 <UNIVERSE>
Sep 24 07:37:07 raspberrypi4 user.info kernel: [   33.117493] cam-dummy-reg: disabling
Sep 24 07:37:34 raspberrypi4 daemon.info connmand[724]: ntp: time slew +53.434105 s
Sep 24 07:38:27 raspberrypi4 daemon.err connmand[724]: Failed to set hwclock
Sep 24 09:38:27 raspberrypi4 daemon.info connmand[724]: ntp: time slew +0.091484 s
//............... Various Halts, Restarts and other changes
Sep 24 11:17:41 raspberrypi4 daemon.info avahi-daemon[10246]: Server startup complete. Host name is venus.local. Local service cookie is 2855583568.
Sep 24 11:17:42 raspberrypi4 daemon.info avahi-daemon[10246]: Service "Victron" (/services/raymarine.service) successfully established.
Sep 24 11:17:42 raspberrypi4 daemon.info avahi-daemon[10246]: Service "Victron" (/services/garmin.service) successfully established.
Sep 24 11:18:05 raspberrypi4 daemon.info connmand[724]: ntp: time slew +0.006726 s
Sep 24 13:18:05 raspberrypi4 daemon.info connmand[724]: ntp: time slew -0.082924 s
// ......
Sep 25 01:18:05 raspberrypi4 daemon.info connmand[724]: ntp: time slew -0.085927 s
Sep 25 02:05:01 raspberrypi4 cron.info CROND[14455]: (root) CMD (/opt/victronenergy/swupdate-scripts/check-updates.sh -auto -delay)
Sep 25 02:05:01 raspberrypi4 cron.info CROND[14454]: (root) CMDOUT (*** Checking for updates ***)
Sep 25 02:05:01 raspberrypi4 cron.info CROND[14454]: (root) CMDOUT (arguments: -auto -delay)
Sep 25 02:05:01 raspberrypi4 cron.info CROND[14454]: (root) CMDOUT (Sleeping for 2711 seconds)
Sep 25 02:50:12 raspberrypi4 cron.info CROND[14454]: (root) CMDOUT (Retrieving latest version... (from https://updates.victronenergy.com/feeds/venus/candidate/images/raspberrypi4/venus-swu-3-large-raspberrypi4.swu))
Sep 25 02:50:12 raspberrypi4 cron.info CROND[14454]: (root) CMDOUT (installed: 20220830160938 v2.90~26)
Sep 25 02:50:12 raspberrypi4 cron.info CROND[14454]: (root) CMDOUT (available: 20220923153209 v2.91~1)
Sep 25 03:18:05 raspberrypi4 daemon.info connmand[724]: ntp: time slew -0.090963 s

Dedicated mobile routers should work better than a tethered phone whilst in one country but certainly roaming phones tend to change time codes with location as I have found to my cost with early and late alarms and odd calendar entries whilst travelling - any software for boats or even campers should take that into account. A better solution is to disable time correction from the router [how?] and use time from the Internet servers, an external RTC or the best suggestion I have seen is from a GPS. I guess it is too late to suggest that an RTC would be useful to @Rob Duthie for his Stetson Hat.

If will leave this open for comments for a while and see if the title needs editing to better reflect the real issue and close it.

question