Skip to content
This repository has been archived by the owner on Aug 14, 2023. It is now read-only.

apt-get update because date/time not set correctly #304

Closed
eloots opened this issue Jul 24, 2019 · 15 comments
Closed

apt-get update because date/time not set correctly #304

eloots opened this issue Jul 24, 2019 · 15 comments

Comments

@eloots
Copy link

eloots commented Jul 24, 2019

I used the new v1.11.0-rc3 image on RPi 3 B+ and the new RPi 4 B and they work but with a glitch.

I use the following (slightly minimised) version of my cloud-init yml file:

$ cat akka-pi-os-min.yml
#cloud-config
# vim: syntax=yaml
#

# Set your hostname here, the manage_etc_hosts will update the hosts file entries as well
hostname: static
manage_etc_hosts: false
# don't write debian.org into apt mirrors
apt_preserve_sources_list: true

# You could modify this for your own user information
users:
  - name: akkapi
    gecos: "Akka Cluster Pi User"
    sudo: ALL=(ALL) NOPASSWD:ALL
    shell: /bin/bash
    groups: users,docker,video
    plain_text_passwd: xxxx
    lock_passwd: false
    ssh_pwauth: true
    chpasswd: { expire: false }

package_update: false
package_upgrade: false
package_reboot_if_required: true

locale: "en_US.UTF-8"
timezone: "Europe/Amsterdam"

# Static IP address
write_files:
  - content: |
      persistent
      # Generate Stable Private IPv6 Addresses instead of hardware based ones
      slaac private

      # static IP configuration:
      interface eth0
      static ip_address=192.168.200.11/24
      # static ip6_address=fd51:42f8:caae:d92e::ff/64
      static routers=192.168.200.1
      static domain_name_servers=192.168.200.1 8.8.8.8
    path: /etc/dhcpcd.conf

  - content: |
      # Cluster #0
      192.168.200.10 node-0
      192.168.200.11 node-1
      192.168.200.12 node-2
      192.168.200.13 node-3
      192.168.200.14 node-4
    path: /etc/cluster-hosts

# These commands will be ran once on first boot only
runcmd:
  # Add cluster hosts to /etc/hosts
  - 'cat /etc/cluster-hosts >> /etc/hosts'
  - 'rm /etc/cluster-hosts'

  # Pickup the hostname changes
  - 'systemctl restart avahi-daemon'
  - date -s '24 Jul 2019 10:29'

  # Install a few extra packages - this could be done in the package section,
  # but if we do it here, the installation progress tracker will start earlier.
  - apt-get update --allow-releaseinfo-change
  - apt-get -y install unzip
  - apt-get -y install tmux
  - apt-get -y install file
  - apt-get -y install jq
  - apt-get -y install dnsutils
  - apt-get -y apt-install transport-https

  # Install OpenJDK 8
  - apt-get install -y galternatives openjdk-8-jdk

Notice the date -s '24 Jul 2019 10:29' command run in the runcmd phase.
When this line is omitted, apt-get update fails because the date and time is set approximately 3 days earlier than the actual date.

If I run the date command right before setting the current time, it outputs the following:
Sun 21 Jul 2019 04:47:52 PM CEST (to be complete: this is during a first boot at around 4:39 PM CET on July 24th).

I may be missing something obvious, but I have no clue what it could be.

This used to work flawlessly with older Hypriot images (e.g. version 1.10.0).

@StefanScherer
Copy link
Member

This might be a problem of all services starting in parallel. The Raspberry Pi has no battery powered clock, it uses a fake clock with a time stamp of the last shutdown AFAIK.
Maybe the boot order has change a little bit in Buster. Maybe there is a command to trigger ntp to sync current date.

@eloots
Copy link
Author

eloots commented Jul 25, 2019 via email

@DieterReuter
Copy link
Collaborator

@eloots Yes, please try it. Would be great to get this resolved.

@eloots
Copy link
Author

eloots commented Jul 25, 2019

@DieterReuter @StefanScherer

Here's an intermediate update - I haven't looked at modifying the boot sequence [yet], but I've run a number of experiments to observe behaviour and have come to the following conclusions.

  • The initial date that is set is somehow linked to the time the image was built. Can't tell for sure; but it's set to July 21. It would explain why testing the new image shortly after it was created worked: the clock difference on the Pi with the actual time was small enough to make apt-get update work.

From /var/log/bootstrap.log:

Current default time zone: 'Etc/UTC'
Local time is now:      Sun Jul 21 09:35:00 UTC 2019.
Universal Time is now:  Sun Jul 21 09:35:00 UTC 2019.
Run 'dpkg-reconfigure tzdata' if you wish to change it.

First experiment

I changed the runcmd sequence to print the date/time at 10s intervals and observed that the time is updated correctly at about 40s into the runcmd run. So, as a poor man's solution, one could insert a sleep 50 before running apt-get update. Not optimal obviously...

Second experiment

From one of the runs, here's the time when ntpd is started (taken from /var/log/syslog)

Jul 21 14:47:32 node-1 ntpd[387]: ntpd 4.2.8p12@1.3728-o (1): Starting
Jul 21 14:47:32 node-1 dhcpcd-run-hooks[405]: wlan0: not interacting with wpa_supplicant(8)
Jul 21 14:47:32 node-1 ntpd[387]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:111
Jul 21 14:47:32 node-1 systemd[1]: Started Network Time Service.

ntpd has a min. poll interval of 64s which will grow to max 1024s in case it cannot reach any time server. From the logs, it can be seen that ntpd is started before a network address is acquired (on eth0 which is connected to a router). Hence, when the runcmd sequence starts, ntpd may actually not poll any time server, even though, in the mean time, eth0 has come up. That explains the behaviour seen in experiment 1.

I changed my runcmd phase to look as follows:

runcmd:
  - echo 'kill ntpd'
  - pkill ntpd
  - sleep 1

  # Add cluster hosts to /etc/hosts
  - 'cat /etc/cluster-hosts >> /etc/hosts'
  - 'rm /etc/cluster-hosts'

  # Pickup the hostname changes
  - echo '     '
  - echo 'Pickup the hostname changes'
  - echo '     '

  - 'systemctl restart avahi-daemon'

  - echo 'starting ntpd'
  - /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:111
  - pgrep -l -f ntp
  - date
  - sleep 1
  - date
  - sleep 1
  - date
  - sleep 1
  - date
  - sleep 1
  - date
  - sleep 1
  - date
  - sleep 1
  - date
  - sleep 1
  - date
  - sleep 1
  - date
  - sleep 1
  - date
  - sleep 1
  - date
<elided>

This results in the following output in /var/log/syslog

Jul 21 14:47:32 node-1 ntpd[387]: ntpd 4.2.8p12@1.3728-o (1): Starting
Jul 21 14:47:32 node-1 dhcpcd-run-hooks[405]: wlan0: not interacting with wpa_supplicant(8)
Jul 21 14:47:32 node-1 ntpd[387]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:111
Jul 21 14:47:32 node-1 systemd[1]: Started Network Time Service.
Jul 21 14:47:32 node-1 dhcpcd[377]: eth0: waiting for carrier
Jul 21 14:47:32 node-1 ntpd[414]: proto: precision = 0.815 usec (-20)
Jul 21 14:47:32 node-1 kernel: [   95.372024] bcmgenet fd580000.genet: configuring instance for external RGMII (no delay)
Jul 21 14:47:32 node-1 kernel: [   95.372274] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Jul 21 14:47:32 node-1 ntpd[414]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature
Jul 21 14:47:32 node-1 ntpd[414]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2019-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37
Jul 21 14:47:32 node-1 ntpd[414]: Listen and drop on 0 v6wildcard [::]:123
Jul 21 14:47:32 node-1 ntpd[414]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Jul 21 14:47:32 node-1 dhcpcd[377]: wlan0: waiting for carrier
Jul 21 14:47:32 node-1 ntpd[414]: Listen normally on 2 lo 127.0.0.1:123
Jul 21 14:47:32 node-1 ntpd[414]: Listen normally on 3 lo [::1]:123
Jul 21 14:47:32 node-1 ntpd[414]: Listening on routing socket on fd #20 for interface updates
Jul 21 14:47:32 node-1 ntpd[414]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Jul 21 14:47:32 node-1 kernel: [   95.406526] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jul 21 14:47:32 node-1 kernel: [   95.406757] brcmfmac: power management disabled
Jul 21 14:47:32 node-1 ntpd[414]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Jul 21 14:47:32 node-1 dhcpcd[377]: wlan0: carrier acquired
Jul 21 14:47:32 node-1 systemd[1]: Started OpenBSD Secure Shell server.
Jul 21 14:47:32 node-1 dhcpcd[377]: DUID 00:01:00:01:24:c7:37:84:dc:a6:32:06:9f:7e
Jul 21 14:47:32 node-1 dhcpcd[377]: wlan0: IAID 32:06:9f:7e
Jul 21 14:47:32 node-1 dhcpcd[377]: wlan0: adding address fe80::1659:c918:f18e:abd8
Jul 21 14:47:32 node-1 dhcpcd[377]: wlan0: carrier lost
Jul 21 14:47:32 node-1 dhcpcd[377]: wlan0: deleting address fe80::1659:c918:f18e:abd8
Jul 21 14:47:33 node-1 ntpd[414]: error resolving pool 0.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Jul 21 14:47:33 node-1 kernel: [   96.391831] bcmgenet fd580000.genet eth0: Link is Down
Jul 21 14:47:34 node-1 ntpd[414]: error resolving pool 1.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Jul 21 14:47:35 node-1 kernel: [   97.853048] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
Jul 21 14:47:35 node-1 kernel: [   97.861438] Bridge firewalling registered
Jul 21 14:47:35 node-1 cloud-init[391]: Cloud-init v. 18.3 running 'modules:config' at Sun, 21 Jul 2019 14:47:33 +0000. Up 95.90 seconds.
Jul 21 14:47:35 node-1 systemd[1]: Started Apply the settings specified in cloud-config.
Jul 21 14:47:35 node-1 ntpd[414]: error resolving pool 2.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Jul 21 14:47:36 node-1 ntpd[414]: error resolving pool 3.debian.pool.ntp.org: Temporary failure in name resolution (-3)
Jul 21 14:47:36 node-1 avahi-daemon[355]: Joining mDNS multicast group on interface docker0.IPv4 with address 172.17.0.1.
Jul 21 14:47:37 node-1 dhcpcd[377]: eth0: carrier acquired
Jul 21 14:47:37 node-1 kernel: [  100.551944] bcmgenet fd580000.genet eth0: Link is Up - 1Gbps/Full - flow control off
Jul 21 14:47:37 node-1 kernel: [  100.552005] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Jul 21 14:47:37 node-1 dhcpcd[377]: eth0: IAID 32:06:9f:7d
Jul 21 14:47:37 node-1 dhcpcd[377]: eth0: adding address fe80::ed33:90d:fd0e:4f7d
Jul 21 14:47:37 node-1 dhcpcd[377]: eth0: probing address 192.168.200.11/24
Jul 21 14:47:37 node-1 avahi-daemon[355]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::ed33:90d:fd0e:4f7d.
Jul 21 14:47:37 node-1 avahi-daemon[355]: New relevant interface eth0.IPv6 for mDNS.
Jul 21 14:47:37 node-1 avahi-daemon[355]: Registering new address record for fe80::ed33:90d:fd0e:4f7d on eth0.*.
Jul 21 14:47:38 node-1 dhcpcd[377]: eth0: soliciting an IPv6 router
Jul 21 14:47:40 node-1 ntpd[414]: Listen normally on 4 eth0 [fe80::ed33:90d:fd0e:4f7d%2]:123
Jul 21 14:47:40 node-1 ntpd[414]: new interface(s) found: waking up resolver
Jul 21 14:47:42 node-1 dhcpcd[377]: eth0: using static address 192.168.200.11/24
Jul 21 14:47:42 node-1 avahi-daemon[355]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.200.11.
Jul 21 14:47:42 node-1 avahi-daemon[355]: New relevant interface eth0.IPv4 for mDNS.
Jul 21 14:47:42 node-1 dhcpcd[377]: eth0: adding route to 192.168.200.0/24
Jul 21 14:47:42 node-1 avahi-daemon[355]: Registering new address record for 192.168.200.11 on eth0.IPv4.
Jul 21 14:47:42 node-1 dhcpcd[377]: eth0: adding default route via 192.168.200.1
Jul 21 14:47:43 node-1 ntpd[414]: Listen normally on 5 eth0 192.168.200.11:123
Jul 21 14:47:43 node-1 ntpd[414]: new interface(s) found: waking up resolver
Jul 21 14:48:03 node-1 cloud-init[650]: Regenerating machine id
Jul 21 14:48:03 node-1 cloud-init[650]: kill ntpd
Jul 21 14:48:03 node-1 ntpd[414]: ntpd exiting on signal 15 (Terminated)
Jul 21 14:48:03 node-1 systemd[1]: ntp.service: Succeeded.
Jul 21 14:48:04 node-1 cloud-init[650]:
Jul 21 14:48:04 node-1 cloud-init[650]: Pickup the hostname changes
Jul 21 14:48:04 node-1 cloud-init[650]:
Jul 21 14:48:04 node-1 avahi-daemon[355]: Got SIGTERM, quitting.
Jul 21 14:48:04 node-1 avahi-daemon[355]: Leaving mDNS multicast group on interface docker0.IPv4 with address 172.17.0.1.
Jul 21 14:48:04 node-1 systemd[1]: Stopping Avahi mDNS/DNS-SD Stack...
Jul 21 14:48:04 node-1 avahi-daemon[355]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::ed33:90d:fd0e:4f7d.
Jul 21 14:48:04 node-1 systemd[1]: avahi-daemon.service: Succeeded.
Jul 21 14:48:04 node-1 avahi-daemon[355]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.200.11.
Jul 21 14:48:04 node-1 avahi-daemon[355]: avahi-daemon 0.7 exiting.
Jul 21 14:48:04 node-1 systemd[1]: Stopped Avahi mDNS/DNS-SD Stack.
Jul 21 14:48:04 node-1 systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Jul 21 14:48:04 node-1 avahi-daemon[668]: Process 355 died: No such process; trying to remove PID file. (/run/avahi-daemon//pid)
Jul 21 14:48:04 node-1 avahi-daemon[668]: Found user 'avahi' (UID 107) and group 'avahi' (GID 113).
Jul 21 14:48:04 node-1 avahi-daemon[668]: Successfully dropped root privileges.
Jul 21 14:48:04 node-1 avahi-daemon[668]: avahi-daemon 0.7 starting up.
Jul 21 14:48:04 node-1 avahi-daemon[668]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
Jul 21 14:48:04 node-1 avahi-daemon[668]: Successfully called chroot().
Jul 21 14:48:04 node-1 avahi-daemon[668]: Successfully dropped remaining capabilities.
Jul 21 14:48:04 node-1 avahi-daemon[668]: No service file found in /etc/avahi/services.
Jul 21 14:48:04 node-1 avahi-daemon[668]: Joining mDNS multicast group on interface docker0.IPv4 with address 172.17.0.1.
Jul 21 14:48:04 node-1 avahi-daemon[668]: New relevant interface docker0.IPv4 for mDNS.
Jul 21 14:48:04 node-1 avahi-daemon[668]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::ed33:90d:fd0e:4f7d.
Jul 21 14:48:04 node-1 avahi-daemon[668]: New relevant interface eth0.IPv6 for mDNS.
Jul 21 14:48:04 node-1 avahi-daemon[668]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.200.11.
Jul 21 14:48:04 node-1 avahi-daemon[668]: New relevant interface eth0.IPv4 for mDNS.
Jul 21 14:48:04 node-1 avahi-daemon[668]: Network interface enumeration completed.
Jul 21 14:48:04 node-1 avahi-daemon[668]: Registering new address record for 172.17.0.1 on docker0.IPv4.
Jul 21 14:48:04 node-1 avahi-daemon[668]: Registering new address record for fe80::ed33:90d:fd0e:4f7d on eth0.*.
Jul 21 14:48:04 node-1 avahi-daemon[668]: Registering new address record for 192.168.200.11 on eth0.IPv4.
Jul 21 14:48:04 node-1 cloud-init[650]: starting ntpd
Jul 21 14:48:04 node-1 ntpd[671]: ntpd 4.2.8p12@1.3728-o (1): Starting
Jul 21 14:48:04 node-1 ntpd[671]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:111
Jul 21 14:48:04 node-1 ntpd[673]: proto: precision = 0.797 usec (-20)
Jul 21 14:48:04 node-1 ntpd[673]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature
Jul 21 14:48:04 node-1 ntpd[673]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2019-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37
Jul 21 14:48:04 node-1 ntpd[673]: Listen and drop on 0 v6wildcard [::]:123
Jul 21 14:48:04 node-1 ntpd[673]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Jul 21 14:48:04 node-1 ntpd[673]: Listen normally on 2 lo 127.0.0.1:123
Jul 21 14:48:04 node-1 ntpd[673]: Listen normally on 3 eth0 192.168.200.11:123
Jul 21 14:48:04 node-1 ntpd[673]: Listen normally on 4 lo [::1]:123
Jul 21 14:48:04 node-1 ntpd[673]: Listen normally on 5 eth0 [fe80::ed33:90d:fd0e:4f7d%2]:123
Jul 21 14:48:04 node-1 ntpd[673]: Listening on routing socket on fd #22 for interface updates
Jul 21 14:48:04 node-1 ntpd[673]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Jul 21 14:48:04 node-1 ntpd[673]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Jul 21 14:48:04 node-1 cloud-init[650]: 673 ntpd
Jul 21 14:48:04 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:04 PM CEST
Jul 21 14:48:05 node-1 avahi-daemon[668]: Server startup complete. Host name is node-1.local. Local service cookie is 1993834064.
Jul 21 14:48:05 node-1 ntpd[673]: Soliciting pool server 91.121.216.238
Jul 21 14:48:06 node-1 ntpd[673]: Soliciting pool server 85.88.55.5
Jul 21 14:48:06 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:06 PM CEST
Jul 21 14:48:07 node-1 ntpd[673]: Soliciting pool server 45.87.76.3
Jul 21 14:48:07 node-1 ntpd[673]: Soliciting pool server 51.255.138.215
Jul 21 14:48:07 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:07 PM CEST
Jul 21 14:48:08 node-1 ntpd[673]: Soliciting pool server 193.190.253.212
Jul 21 14:48:08 node-1 ntpd[673]: Soliciting pool server 91.121.216.238
Jul 21 14:48:08 node-1 ntpd[673]: Soliciting pool server 51.38.2.120
Jul 21 14:48:08 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:08 PM CEST
Jul 21 14:48:09 node-1 ntpd[673]: Soliciting pool server 77.109.90.72
Jul 21 14:48:09 node-1 ntpd[673]: Soliciting pool server 194.78.244.172
Jul 21 14:48:09 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:09 PM CEST
Jul 21 14:48:10 node-1 ntpd[673]: Soliciting pool server 193.190.147.153
Jul 21 14:48:10 node-1 ntpd[673]: Soliciting pool server 2a0e:f780::3
Jul 21 14:48:10 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:10 PM CEST
Jul 21 14:48:11 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:11 PM CEST
Jul 21 14:48:12 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:12 PM CEST
Jul 21 14:48:13 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:13 PM CEST
Jul 25 12:34:05 node-1 ntpd[673]: receive: Unexpected origin timestamp 0xe0def9ae.6ea976cf does not match aorg 0000000000.00000000 from server@194.78.244.172 xmt 0xe0e4203d.464bd615
Jul 25 12:34:05 node-1 ntpd[673]: receive: Unexpected origin timestamp 0xe0def9ae.6eaeeaef does not match aorg 0000000000.00000000 from server@51.38.2.120 xmt 0xe0e4203d.45d9925a
Jul 25 12:34:05 node-1 systemd[1]: Starting Daily man-db regeneration...
Jul 25 12:34:05 node-1 systemd[1]: Starting Rotate log files...
Jul 25 12:34:05 node-1 cloud-init[650]: Thu 25 Jul 2019 02:34:05 PM CEST
Jul 25 12:34:05 node-1 systemd[1]: logrotate.service: Succeeded.

The sequence of interesting events after the restart of ntpd:

Jul 21 14:48:04 node-1 cloud-init[650]: starting ntpd
Jul 21 14:48:04 node-1 ntpd[671]: ntpd 4.2.8p12@1.3728-o (1): Starting
Jul 21 14:48:04 node-1 cloud-init[650]: 673 ntpd
Jul 21 14:48:04 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:04 PM CEST
Jul 21 14:48:06 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:06 PM CEST
Jul 21 14:48:07 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:07 PM CEST
Jul 21 14:48:08 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:08 PM CEST
Jul 21 14:48:09 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:09 PM CEST
Jul 21 14:48:10 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:10 PM CEST
Jul 21 14:48:11 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:11 PM CEST
Jul 21 14:48:12 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:12 PM CEST
Jul 21 14:48:13 node-1 cloud-init[650]: Sun 21 Jul 2019 04:48:13 PM CEST
Jul 25 12:34:05 node-1 ntpd[673]: receive: Unexpected origin timestamp 0xe0def9ae.6ea976cf does not match aorg 0000000000.00000000 from server@194.78.244.172 xmt 0xe0e4203d.464bd615
Jul 25 12:34:05 node-1 ntpd[673]: receive: Unexpected origin timestamp 0xe0def9ae.6eaeeaef does not match aorg 0000000000.00000000 from server@51.38.2.120 xmt 0xe0e4203d.45d9925a
Jul 25 12:34:05 node-1 systemd[1]: Starting Daily man-db regeneration...
Jul 25 12:34:05 node-1 systemd[1]: Starting Rotate log files...
Jul 25 12:34:05 node-1 cloud-init[650]: Thu 25 Jul 2019 02:34:05 PM CEST

This shows that the correct time is set by ntpd 9 to 10 seconds after it is restarted.

So, here's what I think is a correct solution to this problem: ntpd should only be started when eth0 is up. From the above log, eth0 is up at:

Jul 21 14:47:42 node-1 dhcpcd[377]: eth0: using static address 192.168.200.11/24

This is 10s after ntpd is started.

Jul 21 14:47:32 node-1 ntpd[387]: ntpd 4.2.8p12@1.3728-o (1): Starting

Other

There's a way to set the correct time from time servers using ntpdate:

$ sudo ntpdate -u -s 0.debian.pool.ntp.org 1.debian.pool.ntp.org 2.debian.pool.ntp.org 3..debian.pool.ntp.org`

That could be done as part of the runcmd sequence, but there's a catch 22: ntpdate isn't installed on buster by default. It can't be installed during the execution of runcmd as apt-get update needs to run first and that doesn't work because of the clock skew...

If the v1.11.0 image would be changed to also include ntpdate, that would enable a simple and fast fix.

WDYT?

@eloots
Copy link
Author

eloots commented Jul 25, 2019

This is the temp. workaround I have in my cloud-init build definition:

# Static IP address
write_files:
  - content: |
      persistent
      # Generate Stable Private IPv6 Addresses instead of hardware based ones
      slaac private

      # static IP configuration:
      interface eth0
      static ip_address=192.168.200.11/24
      # static ip6_address=fd51:42f8:caae:d92e::ff/64
      static routers=192.168.200.1
      static domain_name_servers=192.168.200.1 8.8.8.8
    path: /etc/dhcpcd.conf
  # Pickup the hostname changes
  - 'systemctl restart avahi-daemon'

  # Workaround for Hypriot initial date/time setting
  - date
  - service ntp --full-restart
  - sleep 15
  - date

@Legion2
Copy link

Legion2 commented Jul 30, 2019

I'm using the packages: option of cloud-config to install packages on first boot. This worked with version 1.10.0 but with 1.11.1 it does not.
Example config:

package_update: true
package_upgrade: true
package_reboot_if_required: true

packages:
  - fail2ban
  - vim
  - unzip
  - tree
  - ssmtp
  - rsync
  - ntfs-3g
  - file
  - pv

the cloud-init-output.log contains:

Release file for http://raspbian.raspberrypi.org/raspbian/dists/buster/InRelease is not valid yet (invalid for another 4d 10h 10min 22s). Updates for this repository will not be applied.
...
2019-07-26 06:36:31,308 - util.py[WARNING]: Package update failed
...
2019-07-26 06:36:31,562 - util.py[WARNING]: Failed to install packages: ['fail2ban', 'vim', 'unzip', 'tree', 'ssmtp', 'rsync', 'ntfs-3g', 'file']

@eloots
Copy link
Author

eloots commented Aug 1, 2019

@Legion2 The problem you're seeing is the one described in this issue. What can be confusing is that 1.10.0 may have worked if you used it shortly after is was released (this is true for any version btw - see explanation in the comments above).

You can use the workaround I describe above (install packages in the runcmd phase & restart the ntp service + introduce a delay to allow for ntp to set the date/time correctly.

I don't know why this did worked with the previous version of Hypriot (<= 1.10.0) on all Raspberry Pi's up-to RPi 3 B+... I think that the problem actually existed in that case too, but it occurred only with a low frequency: I've seen this happen occasionally and I flashed quite a large number of cards (more than 200).
All in all, as Stefan said, the "root cause" is that the RPi doesn't have an RTC (Real Time Clock).

@muelli
Copy link

muelli commented Aug 3, 2019

it uses a fake clock with a time stamp of the last shutdown AFAIK

I think I get away with editing /etc/fake-hwclock.data, i.e. virt-edit -a ${IMAGE} --edit "s/.*/$(date '+%Y-%m-%d %X')/" /etc/fake-hwclock.data

@Legion2
Copy link

Legion2 commented Aug 4, 2019

Maybe the fake-hwclock should be set by the flash tool. This will make the time offset only a few minutes, when you start the image after you flashed it on the sd card.

@eloots
Copy link
Author

eloots commented Aug 4, 2019 via email

@eloots
Copy link
Author

eloots commented Aug 9, 2019

@StefanScherer @DieterReuter @Legion2
I went ahead and created a fix (or hack) that solves this problem in an easy manner by a small adaptation of the flash command. A PR is waiting for review in HypriotOS/flash.
In short, what it does is to add a date -s command as the first command in the runcmd section of cloud-init (and if such a section is not present, it adds it first at the end of the file).

@Legion2
Copy link

Legion2 commented Jan 12, 2020

I think this is now fixed with hypriot/flash#162 and released in v1.12.0 and version 2.5.0 of flash tool.

@eloots
Copy link
Author

eloots commented Jan 13, 2020

@Legion2 indeed. Closing

@eloots eloots closed this as completed Jan 13, 2020
@Rumpick
Copy link

Rumpick commented Mar 1, 2020

Would it not be better to fix this in the cloud-init start up than in the flash tool? I came across this issue after having imaged 2 SD cards already and had several more to go. Since the flash tool is only *nix compatible, it isn't a real universal solution.
Could we use something like cat </dev/tcp/time.nist.gov/13 to get the real date and use that to check if ntp has successfully updated yet? (as a personal hack, are while loops supported in runcmd?)

@n3me5is-git
Copy link

n3me5is-git commented Aug 14, 2020

I usually resolve with a configuration script, written with cloud-init write_files.

If you want to use NTP (already installed with the last OS image)

# Write config files 
write_files:
  - content: |
      #!/bin/bash
      # Force update time (NTP will be used instead of systemd-timesyncd). Ntp is installed by default on this image
      systemctl stop ntp
      ntpd -q -g
      systemctl start ntp
      # Wait for time update
      sleep 5
      # Start APT install 
      apt-get update -y
      # Install packages
      apt-get install -y ...............................

    path: /scripts/init_config.sh
    permissions: 0777

If you want to use the default NTP client (systemd-timesyncd) usually used with ubuntu/debian/raspbian you have to uninstall ntp package because you can not use both systems

# Write config files 
write_files:
  - content: |
      #!/bin/bash
      # Set NTP with default systemd-timesyncd (and remove ntp package, because you can not use both) and reboot the service to force update the time
      apt-get purge -y --auto-remove ntp
      timedatectl set-ntp true
      systemctl stop systemd-timesyncd
      systemctl start systemd-timesyncd
      # Wait for time update
      sleep 5
      # Start APT install 
      apt-get update -y
      # Install packages
      apt-get install -y ...............................

    path: /scripts/init_config.sh
    permissions: 0777

I usually use the second way if I don't need a full ntp client/server.

Then you can run the script with cloud-init runcmd

# Execute commands to complete initialization
runcmd:
  # Pickup the hostname changes
  - 'systemctl restart avahi-daemon'
  # Activate WiFi interface (comment if you don't need it)
  - 'ifup wlan0'
  # Wait wifi connecting
  - 'sleep 15'
  # Execute the initial configuration
  - [ bash, -c, "cd /scripts && ./init_config.sh" ]

You can also put all your commands here if you like. I prefer separating the things putting them inside scripts, because I do also other configurations. If you want to install packages you need always to wait for the wifi coming up and then the time sync.

P.S. If you want to install and enable byobu for a target user (not working if you use the cloud-init module) you can use

apt install -y byobu
su target_user -c byobu-enable

Hope this help.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants