Raspberry Pi Clock

An Eccentric Anomaly: Ed Davies's Blog

The Raspberry Pi is (in)famous for not having an internal hardware clock to keep time while it's powered off. This can mean that the clock has weird values for a few minutes after the device starts up until it's got a network connection and an updated time via NTP.

There are battery-backed real-time clock boards (“hats”) available for the Pi but I haven't got one. Here's how my logging software deals with this.

When the Pi starts up the operating system sets the clock to some rather arbitrary date/time of its choosing. Raspbian sets it to some time it had shortly (maybe quite a few minutes) before it last lost power. Other systems, I understand, can set it back to a much earlier point such as the 1970 January 1st epoch.

After a short while (usually minutes but it can be up to a quarter hour in my experience) it gets a network connection and the NTP daemon sets the clock to something much closer to the true time.

It can be very confusing looking at log files with incorrect times so in practice I'd rather my logger just doesn't run until the clock as been set. It took me a while to work out a reliable method of determining when the clock was right. E.g., the obvious thing to use is ntpstat but that seems to think that the initial approximate date/time supplied by Raspbian is good enough and so reports synchronisation much too soon. Ntpq didn't make a lot of sense to me, either.

ntpdate -q seems like a good option, too, but didn't have sensible defaults for finding the NTP servers to use. It took me a while to come across ntpdate-debian which is the same as ntpdate except it defaults to finding the servers via the same configuration files as the NTP daemon, which is sensible.

My code runs ntpdate-debian as a sub-process, parses the output, then looks to see if the clock is within 0.1 seconds of the right time. If it is it assumes that all is well and it's OK to get on with the logging.

def timeOK():
    """ Try to determine if the system clock is set well enough for us to
        log sensibly. Notably, the Raspberry Pi doesn't have a hardware
        real-time clock so reverts to the epoch or some time when it was
        last running on initial boot which can be confusing. We use
        ntpdate-debian (apt install ntpdate) to check the clock's been set
        properly.
    """
    p = None
    output = None
    match = None
    
    try:
        cmd = ['/usr/sbin/ntpdate-debian', '-q']
        p = subprocess.run(
                    cmd, 
                    stdout=subprocess.PIPE, 
                    stderr=subprocess.STDOUT, 
                    close_fds=True)
        
        if p.returncode != 0:
            raise ValueError('Bad return code %d from %s' % (p.returncode, cmd[0]))
            
        output = p.stdout.decode(encoding='UTF-8')
            
        for l in output.split('\n'):
            if 'ntpdate[' in l:
                if match != None:
                    raise ValueError('Duplicate summary line in output')
                match = re.compile(r'offset\s+([+-]?\d+\.\d+)\s+sec').search(l)
                if match == None:
                    raise ValueError('Offset not found in summary line')
                    
        if match == None:
            raise ValueError('Summary line not found')
            
        offset = float(match.group(1))
        
        if abs(offset) > 0.1:
            log('Clock offset |%f| > 0.1, jump plausible', offset)
            return False
        else:
            log('Clock OK')
            return True
        
    except Exception as e:
        log('Error determining NTP date/time.')
        log(e)
        if output != None:
            log(output)
        if match != None:
            log('Match:', match)
        return False

As mentioned before, the way the logger gets started is that it's run as a cron job once every two minutes. As it starts it looks to see if there's already an instance running and if not fires up another instance of itself running under screen. That new instance then checks if the clock has been set OK and, if so, actually runs the various threads to do logging:

def main(args):
    log('started', datetime.datetime.utcnow().isoformat())
    
    try:
        options = mqttoptions.parseOptions(args, runner=True)
                    
        if not isAlreadyRunning(options):
            screenNeeded = options.screen and (not isUnderScreen())
            if screenNeeded:
                runViaScreen(args)
            else:
                if timeOK():
                    log('actually run')
                    actuallyRun(options)

    except Exception as e:
        log('exception', str(e))

The other day I fumbled and, instead of just switching off the power strip for my laptop, monitor, speakers and printer, I switched off the strip for the “always on” devices: modem, analog-telephone-adapter, cordless-phone base station, Raspberry Pi and CurrentCost meter. Oops. Here's the log file around this calamity.

mqttrunner[9447]: started 2018-06-08T10:44:02.303165
mqttrunner[9447]: already running as process 20918
mqttrunner[9629]: started 2018-06-08T10:46:02.025385
mqttrunner[9629]: already running as process 20918
mqttrunner[772]: started 2018-06-08T10:30:02.797763
mqttrunner[772]: screen -d -m -S mqttrunner /home/mqtt/projects/mqtt_utils/mqttrunner.py
mqttrunner[775]: started 2018-06-08T10:30:03.435864
mqttrunner[775]: Error determining NTP date/time.
mqttrunner[775]: Bad return code 1 from /usr/sbin/ntpdate-debian
mqttrunner[922]: started 2018-06-08T10:32:02.591008
mqttrunner[922]: screen -d -m -S mqttrunner /home/mqtt/projects/mqtt_utils/mqttrunner.py
mqttrunner[925]: started 2018-06-08T10:32:03.207588
mqttrunner[925]: Error determining NTP date/time.
mqttrunner[925]: Bad return code 1 from /usr/sbin/ntpdate-debian
mqttrunner[1039]: started 2018-06-08T10:52:02.519697
mqttrunner[1039]: screen -d -m -S mqttrunner /home/mqtt/projects/mqtt_utils/mqttrunner.py
mqttrunner[1042]: started 2018-06-08T10:52:03.131948
mqttrunner[1042]: Clock OK
mqttrunner[1042]: actually run
mqttrunner[1042]: thread runLogger starting
mqttrunner[1042]: thread runOneWire starting
mqttrunner[1042]: thread runCurrentCost starting
mqttrunner[1242]: started 2018-06-08T10:54:02.271665
mqttrunner[1242]: already running as process 1042
mqttrunner[1416]: started 2018-06-08T10:56:02.032402
mqttrunner[1416]: already running as process 1042

The numbers in square brackets are the process ids. The first two instances (9447 and 9629) start normally at two-minute intervals, find an already-running process (20918) and exit quietly. Then disaster strikes. Once I'd turned things back on again the process id sequence has restarted and process 772 is fired up. Notice how the clock now says 10:30, reset back from 10:46 last time the program started.

As there's no pre-existing process a new one (775) is run via screen. Because the network isn't up yet properly (the router might be even slower to boot that the Pi or the line hasn't synchronised yet) ntpdate-debian fails to find the date/time and the program exits. Two minutes later the same thing happens again (processes 922 and 925). Some undetermined time later (presumably in the range zero to 4 minutes depending on any interaction between NTP and cron) the program is started again (1039) but now the clock as been set and is showing a much more plausible 10:52. The call to timeOK determines that the clock is, indeed, OK and process 1042 gets on with its logging job.

Two minutes after that process 1242 runs, finds 1042 is doing the right thing and exits. And so on until the next fumble or power cut or whatever results in another restart.