Beyond Scripting in Swift: Dates, Steppers, and parsing log entries

The basic idea behind The Time Machine Mechanic (T2M2) is simple: let the user set a period of 1-24 hours over which to analyse Sierra’s unified log; for that period, obtain log entries relevant to Time Machine backups; analyse those logs; give the user simple feedback in the form of a ‘traffic light’; and provide a detailed breakdown of backup performance over that period.

It has quite quickly grown into plenty of code, well beyond what most of us would consider reasonable for scripting. One reason for this is that log entries can vary more than, say, the tightly-prescribed parameters passed to a shell command. Deciphering them relies on a long series of nested
if logMessage.contains(aStringFragment) {
} else if logMessage.contains(anotherStringFragment) { …

The actions in response to each of those vary considerably too, from simply saving the log message for later concatenation to the output string, to extracting numbers from the message and using them in calculations. For the moment, at least, this makes it hard to generalise patterns into functions to be called, and modularise the code.

Writing the output string is also not amenable to generalisation. Some lines are taken straight from log messages, others require numbers to be inserted into a fixed text surround, and a few are built largely from concatenating arrays using
theArray.joined(separator: ", ")

The ViewController source, where almost all the work is done, is now approaching three hundred lines of code, and there’s a fair bit more to come too. Rather than trudge tediously through all that, this article focuses on some of the more interesting aspects of the implementation, hopefully with more general relevance.

NSStepper

To enter the period in hours, the user is provided with an editable text box and a ‘stepper’ controller. Oddly, these are separate controls, and the developer is left with the problem of integrating them. Although there are ways of linking them to the same action method, apparently, I wanted to ensure that they both clipped the number range properly.

That is easy to set up for the NSStepper control, by specifying its maximum and minimum values, but less apparent for the text box. So I created two action functions, one for each control. That for the text box performs clipping:
@IBAction func setThePeriodText(_ sender: Any) {
theTimePeriod = periodText.integerValue
if (theTimePeriod < 1) {
theTimePeriod = 1
periodText.integerValue = theTimePeriod
} else if (theTimePeriod > 24) {
theTimePeriod = 24
periodText.integerValue = theTimePeriod
}
periodStep.integerValue = theTimePeriod
}

That for the stepper doesn’t, and just sets the integer variable containing the value, and that shown in the text box:
@IBAction func stepPeriodText(_ sender: Any) {
theTimePeriod = periodStep.integerValue
periodText.integerValue = theTimePeriod
}

t2m212

The first beta release had an unfortunate bug resulting from the first function somehow becoming detached from its control, so it was never used. Amusing at first, but rapidly infuriating.

Dates

This is my first serious venture into using date and time data in Swift and macOS, and I started with some trepidation. Some older parts of macOS seem quite hard to work with in Swift, but Apple has done a good job of making NSDate or Date very accessible.

Entries extracted from Sierra’s unified log come with two timestamps: one is in system ticks, which is valuable if you’re interested in short periods of relative time, or clock drift; the other is the combined date and time stamp from the main clock, which is supplied in a standard format, e.g.
2017-04-30 20:34:49.853562+0100

I had thought about trimming this down to just the time with decimal seconds, but it is much better to use a DateFormatter to swallow the whole string and turn it into the internal Date format of decimal seconds since 1970. Getting the date format right for this can be tricky, but is made much easier with Mark Bridges’ free Date Format Creator from the App Store. You could do the same thing in a Swift playground, I’m sure, but Mark has made this so much simpler.

t2m210

After a few seconds, I worked out that the correct formatting string for this is
yyyy-MM-dd HH:mm:ss.SSSSSSZZZ

So to read my datestamps into Date variables requires code like
let dateFormatter = DateFormatter()
dateFormatter.dateFormat = "yyyy-MM-dd HH:mm:ss.SSSSSSZZZ"
tempDate = dateFormatter.date(from: dateStampString)

which puts a proper Date into the variable tempDate.

I can then do things like
let timeSinceLastBU = lastBUEnd.timeIntervalSinceNow
to get the period in decimal seconds between lastBUEnd and now, and
let timeSince = firstDate.timeIntervalSince(anotherDate)
to get the period in decimal seconds between firstDate and anotherDate. You do, though, have to be careful in dealing with the signs in such results.

Structure, parsing, output

t2m216

The action function called when the button is clicked simply assembles the log show command, runs it, collects standard output and passes that to the parsing and output function, and handles errors using an alert.

t2m213

The parser and output generator sets up some preliminaries such as the date formatter, then converts the JSON log extract into an array of dictionaries, just as used in Consolation to generate CSV output. This is far easier than trying to parse other formats line by line, as the datestamp, message, and other fields are accessed separately within the dictionary making up each log entry. Parsing therefore steps through each of the dictionaries in the array.

The only two fields which we need here are the datestamp or “timestamp” and the log message itself, “eventMessage”. Those values are extracted as strings, and the message is then parsed.

There’s a delicate balance here between under- and over-specifying the substrings to look for in the message. The art is to select sufficient in the substring to recognise all the correct messages, but never to include incorrect ones. This varies according to the message, so experience of browsing a lot of log messages is important.

For example,
if logMessage.contains("success")
is potentially dangerous, as it could include messages containing unsuccessful. This is also dependent on the order in which those substrings are tested: you might get away with it when that is, for example
if logMessage.contains("unsuccess") {
} else if if logMessage.contains("success") { …

The parser constructs arrays of Dates for later analysis. To retain access to them from other functions in the future, these are declared in the ViewController using
var startBU = [Date]()
but then need to be initialised at the start of parsing using
startBU = [Date]()

Once the log extracts have been parsed and all the relevant information extracted and prepared, the function then works through each of the possible lines of text to be output, concatenating them onto the end of the string it is building. Although arrays may seem ungainly at times, they have some neat tricks too. Concatenation into a string is simple using
theArray.joined(separator: ", ")

Performing basic statistics on the values in an array can be easy as well. Here is how to obtain maximum, minimum, and total, for example:
let addTwo: (Int, Int) -> Int = { x, y in x + y }
let sortedNumbers = copiedNumbers.sorted(by: <)
let theMin = sortedNumbers.first!
let theMax = sortedNumbers.last!
let theTotal = sortedNumbers.reduce(0, addTwo)

and obtaining a median should be straightforward too. This could of course be an unwise choice if the array was very large, but here it consists of no more than 24 integers.

t2m215

In the second beta, T2M2 does a lot using the Time Machine log entries, more than any other comparable utility. But it doesn’t probe any deeper, to assess whether, for example, irregular backups are the result of a failure in macOS scheduling and dispatch. To look at that, it needs to analyse log entries from DAS and CTS – the next step.