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
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:
<device> part can be used to distinguish between the different message
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:
as a future-proof permanent record of every “raw” message, independent of the processing applied to it later - i.e. even before these messages get “decoded”
as a way to “replay” the original data at a later time, for testing or simulation purposes, but also to be able to completely rebuild all time-series and redo all statistics and other processing - this has proven invaluable to support major changes to the software, since a new installation can quickly be fed all historical data as if it were coming in real-time
The structure and format of these log files have remained the same for many years now:
- there is one log file for every day, running from midnight to midnight (UTC!)
- the name of these log files is “
YYYYMMDD.txt”, e.g. “
- each entry in the log is one line of text
- the format of each line is: “
L HH:MM:SS.TTT <device> <message...>“
Here is an example of some log entries, taken from the “
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
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
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:
- a retained message at “
serial/mydev” sets up the serial port and starts the hub’s listener
sendtois set to “
logger/mydev”, directing all incoming data to the timestamping service
- these messages will then be re-published as “
- since the logger is listening to “
logger/+/+”, it gets a copy of each timestamped message
- as a result, all this data also ends up being stored in daily log files
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.