Arbitrary delay when starting/accessing RTC?

[PeterAOBell]

I have a Raspberry Pi running ArchLinux performing a number of crucial functions on my LAN.

It is setup as a dns server/relay and dhcp server, including pxe boot (dnsmasq)
It also controls the APC UPS supplying it and the router (apcupsd)
It acts as an ntp server/relay

Now, this is all working fine but, because of unreliable power (an average of two powercuts a day) and an ISP service which isn't totally reliable, I was getting fed up with incorrect times from the ntp service (Pi boots much more quickly than the router obtains an Internet connection).

So, I've added an RTC. I've been having 'fun' configuring the rtc this afternoon and have arrived at a systemd service, rtc.service:
$this->bbcode_second_pass_code('', '[Unit]
Description=RTC clock
Requires=systemd-modules-load.service
After=systemd-modules-load.service

[Service]
Type=oneshot
ExecStart=/usr/sbin/rtc.sh

[Install]
WantedBy=multi-user.target
')

and the bash script:
$this->bbcode_second_pass_code('', '#!/bin/bash
echo ds1307 0x68 >/sys/bus/i2c/devices/i2c-1/new_device
sleep 2
hwclock -s
')

My concern is with the arbitrary sleep between entering the new device, and being able to access the hwclock - in my experience , such 'fixes' can result in race hazards. Now, when invoking the script from console, a sleep 1 was sufficient, but when running under systemctl/systemd at boot time, I found it necessary to increase the sleep to 2 seconds.

Is the delay between writing the new device and being able to access the hardware clock expected. Am I simply covering the fact that I'm trying to access the hwclock before some required system service has fully started?

Advice would be much appreciated.

[PeterAOBell]

Okay, I have revised my script to overcome my concern with using an arbitrary delay:
$this->bbcode_second_pass_code('', '#!/bin/bash
echo ds1307 0x68 >/sys/bus/i2c/devices/i2c-1/new_device
for (( c = 1; c <= 10; c++ ))
do
hwclock -s >/dev/null 2>&1
if [ $? -eq 0 ]
then break
fi
sleep 1
done
')

This seems to be working well.

However, I have another concern over the system time/date settings - if I look in the journal/dmesg, I see that at boot the system time starts off at zero. It then appears to set to 'real' time for a brief moment, then reverts to zero time before being set to 'real' time permanently. I cannot understand why this should happen and wonder whether what I'm seeing is caused by some vagaries of the logging/journal system - possibly events being recorded out of true sequence, or one part of the system recognising the 'updated' time before another part.

Can anyone shed any light on this?

Here is a 'reverse' journal:
$this->bbcode_second_pass_code('', 'Apr 05 20:45:15 director systemd[1]: Reached target Login Prompts.
Apr 05 20:45:15 director systemd[1]: Starting Login Prompts.
Apr 05 20:45:15 director systemd[1]: Started Serial Getty on ttyAMA0.
Apr 05 20:45:15 director ntpd[139]: ntpd 4.2.6p5@1.2349-o Tue Mar 11 05:55:13 UTC 2014 (1)
Apr 05 20:45:15 director systemd[1]: Starting Serial Getty on ttyAMA0...
Apr 05 20:45:15 director systemd[1]: Started Getty on tty1.
Apr 05 20:45:15 director dnsmasq[138]: dnsmasq: syntax check OK.
Apr 05 20:45:15 director systemd[1]: Starting Getty on tty1...
Apr 05 20:45:15 director systemd[1]: Starting Network Time Service...
Apr 05 20:45:14 director systemd[1]: Starting A lightweight DHCP and caching DNS server...
Apr 05 20:45:14 director systemd[1]: Started OpenSSH Daemon.
Apr 05 20:45:14 director systemd[1]: Starting OpenSSH Daemon...
Apr 05 20:45:14 director systemd[1]: Reached target Network.
Apr 05 20:45:14 director systemd[1]: Starting Network.
Apr 05 20:45:14 director systemd[1]: Started Login Service.
Apr 05 20:45:14 director systemd-logind[119]: New seat seat0.
Apr 05 20:45:14 director systemd[1]: Started Network connectivity (eth0).
Apr 05 20:45:14 director systemd[1]: Time has been changed
Jan 01 08:00:06 director systemd[1]: Starting D-Bus System Message Bus Socket.
Jan 01 08:00:06 director systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
Jan 01 08:00:06 director systemd[1]: Starting Avahi mDNS/DNS-SD Stack Activation Socket.
Jan 01 08:00:06 director systemd[1]: Reached target System Initialization.
Jan 01 08:00:06 director systemd[1]: Starting System Initialization.
Jan 01 08:00:06 director systemd[1]: Started Update UTMP about System Boot/Shutdown.
Jan 01 08:00:06 director systemd-udevd[87]: Could not apply link config to ifb1
Jan 01 08:00:06 director systemd-udevd[86]: Could not apply link config to ifb0
Jan 01 08:00:06 director systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Jan 01 08:00:06 director systemd[1]: Started Create Volatile Files and Directories.
Jan 01 08:00:06 director systemd[1]: Started Trigger Flushing of Journal to Persistent Storage.
Apr 05 20:45:14 director avahi-daemon[120]: Registering new address record for 10.2.0.1 on eth0.IPv4.
Apr 05 20:45:14 director avahi-daemon[120]: New relevant interface eth0.IPv4 for mDNS.
Apr 05 20:45:14 director avahi-daemon[120]: Joining mDNS multicast group on interface eth0.IPv4 with address 10.2.0.1.
Jan 01 08:00:09 director avahi-dnsconfd[114]: Successfully connected to Avahi daemon.
Jan 01 08:00:09 director avahi-daemon[120]: Service "director" (/services/sftp-ssh.service) successfully established.
Jan 01 08:00:09 director avahi-daemon[120]: Service "director" (/services/ssh.service) successfully established.
Jan 01 08:00:09 director avahi-daemon[120]: Server startup complete. Host name is director.local. Local service cookie is 2769922426.
Jan 01 08:00:09 director avahi-daemon[120]: Registering HINFO record with values 'ARMV6L'/'LINUX'.
Jan 01 08:00:09 director dbus[121]: [system] Successfully activated service 'org.freedesktop.systemd1'
-- Reboot --
')

It is the -3 second change in time which makes me suspect that the journal messages are being recorded out of sequence - some of the systemd messages being recorded 3 seconds late?