Timestamps and logging Jan 2016

Keeping track of time across different systems is not as straightforward as it might seem: every clock has its own notion of time, and always drifts around to a certain extent. There’s an entire community around the challenge of trying to keep track of time as accurately as possible. In an absolute sense, you can’t actually win in this game - it’s very Heisenberg-like, in that there will always be some uncertainty, even if only at the femtosecond level!

Fortunately, this isn’t a big deal for simple home monitoring and automation scenarios, except that with battery-powered nodes without accurate crystal this issue need addressing.

The simplest solution is to timestamp all data in a single place, based on a single clock source - preferably a stable one, obviously. In Linux, tracking real time is well-understood - all you need when network connected, are the ntp, ntpdate, or chrony tools (thanks for the tip, Thomas!) to keep its time-of-day clock time accurate to within a milliseconds or so.

Hub timestamping service

JET/Hub provides a simple millisecond-timestamping service for anything arriving via MQTT:

The <device> part can be used to distinguish between the different message sources.

The contents of these message can be anything - they also pass through without change. Note that the timestamped topics change endlessly - these messages should not be published with the RETAIN flag set, else the MQTT server will have to store an unbounded number of messages!

Logging raw incoming data

A mechanism introduced in JeeMon and HouseMon many years ago, was the “logger”, which takes all incoming (presumably plain text) data, and saves it to disk. This mechanism is also included in the hub, and serves two purposes:

The structure and format of these log files have remained the same for many years now:

Here is an example of some log entries, taken from the “20160128.txt” file:

L 12:27:51.979 usb-USB0 OK 3 65 112 8 0
L 12:27:52.941 usb-USB0 OK 9 161 25 58 235 31 159 228 5 13 219 234 62
L 12:27:55.937 usb-USB0 OK 9 161 25 58 235 33 159 230 5 13 219 234 62
L 12:27:58.936 usb-USB0 OK 9 161 25 58 235 35 159 224 5 14 219 198 61
L 12:28:00.574 usb-USB0 OK 19 96 16 1 28 13 28 0
L 12:28:01.934 usb-USB0 OK 9 161 25 58 235 37 159 224 5 14 219 198 61
L 12:28:03.080 usb-USB0 OK 6 199 149 143 0

This functionality is included in the hub - it subscribes to MQTT topic “logger/+/+”, causing it to receive all timestamped messages (and only those), which it then saves to the proper log file. With automatic daily roll-over to a new log file at 0:00 UTC. The file paths include the year, so that no more than a few hundred text files end up in a single directory - the above example was actually copied from the file located at “logger/2016/20160128.txt”.

The hub has a heartbeat

For completeness, this is probably a good place to mention that the hub also implements a one-tick-per-second “heartbeat” - i.e. a periodic message, published to the “hub/1hz” topic. The value of this text message is the current time in milliseconds since Jan 1st, 1970 (as commonly used in JavaScript). The hub will continuously adjust its heartbeat timing to happen exactly on the second mark, as you can see in this example:

$ jet sub hub/1hz
hub/1hz = 1453988511000
hub/1hz = 1453988512000
hub/1hz = 1453988513000
hub/1hz = 1453988514000
hub/1hz = 1453988515000
hub/1hz = 1453988516000
hub/1hz = 1453988517000
...

An issue to watch out for, is that these messages can end up a few milliseconds late - even before propagating through MQTT - since Unix / Linux do not offer any real-time guarantees.

One use for this heartbeat is to detect and track clock skew in other machines on the network.

Tying it all together

The serial port interface, timestamping, and raw logging services are built into the hub but fully independent of each other. And - by design - they can be chained together very nicely:

This addresses a major design goal for the hub: to keep raw serial data collection and logging going at all times, even when other parts of JET are in development, being replaced, or failing.

Weblog © Jean-Claude Wippler. Generated by Hugo.