I’ve now got two groups of issues which I want to investigate further: why Time Machine backups can become irregular, and getting the best out of Sierra’s new logs. The best way to make progress in these two directions happens to be the same: I need to instrument Sierra so that I can gather more information.

Because Sierra’s new logs don’t appear to contain any entries concerning launchd and the mechanism by which periodic backups are launched, I can’t study those for errors. What I need is another process which, like those backups, is launched every hour. If that becomes irregular when backups do, the only common mechanism is launchd, and the case is proved.

Looking at logs and the log command is made more difficult by the lack of a tool which will write distinctive entries to the logs. For example, I know that to reliably capture an event in the log using a filter, the capture window (the period between the start and end times) has to be quite wide. But without a tool to write my own distinctive entries in the log, it’s not easy to be precise as to how wide that filter window needs to be.

So my next job has been to write a simple command line tool which writes an otherwise unique entry into the logs, blowhole. Armed with this, I can test the limitations and bugs in the log command better, and I can set it to be run hourly as a monitor of launchd.

For once, Apple’s documentation of the calls required to write new-style log entries is extensive, even coming with a Swift example project. From that, I have distilled my little command line tool named blowhole, which simply writes a log entry out and quits.

Although I am sure there is a way of doing this without creating a whole class, this Swift 3 code works robustly:
import os.log
public class Blowhole {
static let gen_log = OSLog(subsystem: "co.eclecticlight.blowhole", category: "general")
public init() {
}
func writeLogEntry () {
os_log("Blowhole snorted!", log: Blowhole.gen_log, type: .default)
}
}
let myBlowhole = Blowhole()
myBlowhole.writeLogEntry()

Compiled as a command tool, it is here: blowholef

When you run that, the log will contain an entry like
2017-02-10 13:35:38.415904+0000 0x7de872 Default 0x0 61811 blowhole: [co.eclecticlight.blowhole.general] Blowhole snorted!
which provides a full timestamp of the entry, the thread number, type (Default by choice), that it is not an Activity, ran with the process ID number of 18111, and added the message Blowhole snorted!. Note that, unlike many log entries, this has a distinctive subsystem of co.eclecticlight.blowhole.general.

Insights into the use of log and Consolation

Using that as a known log entry, which was timed at 13:35:38.4, I found that the smallest time window using log or Consolation which would reliably find that entry had a start time of 13:35:38, and an end time of 13:36:30. In other words, log, LogLogger, and Consolation can only reliably find events within a window from less than 1 second before the index event, to around 52 seconds after the index event. That was independent of the predicate used to filter the entries.

Important point 1: when setting start and end times in log or Consolation, ensure the start time is at least 1 second before the events you wish to view, and the end time is at least 1 minute later than the last entry you wish to view. Windows smaller than a minute in length are too short to reliably show the events which took place at any time within them.

I next explored different types of predicate filter to locate the same index log entry.

Given a suitable window, log and Consolation are able to find that log entry using a wide variety of methods, such as

• eventMessage CONTAINS[c] any of the text included in the log message, Blowhole snorted!.
• processImagePath or sendImagePath CONTAINS[c] the process name, blowhole, but not ==.
• subsystem == co.eclecticlight.blowhole, but not co.eclecticlight or co.eclecticlight.blowhole.general.
• subsystem CONTAINS[c] co.eclecticlight.blowhole or any part of it.
• similarly for other operators such as BEGINSWITH.

Important point 2: when using a subsystem in a predicate, don’t over- or under-specify it. Normally it should be of the form com.company.product. If you’re unsure, use the CONTAINS operator instead of ==.

Monitoring launchd and periodic processes

It’s a simple job to install the blowhole tool so that it is run periodically by launchd. First, it needs to be copied into an appropriate directory, which is permitted by SIP. I chose to
sudo cp ~/Documents/blowhole /usr/local/bin/blowhole

The next step is to set up a LaunchAgent property list, stored in ~/Library/LaunchAgents and named co.eclecticlight.blowhole.plist, which tells launchd to run it every hour. You can do this simply by hand, using a text editor, but I still like the more friendly approach of Lingon X, which makes it a breeze.

This immediately brought out a curious difference between the behaviour of Blowhole and Time Machine backups. Over the first three hours of periodic running, Blowhole made its log entries at almost precisely hourly intervals:
14:18:25
15:18:26
16:18:25

This contrasts with the start of periodic backups over the same period:
13:10:19
14:06:20
15:14:21
16:06:46

Why should backup times be so varied in comparison? Perhaps they are not simply being initiated by launchd after all…