Looking in the log: predicates, filters, regex, and find

Consolation 3, and many other apps, offer several different ways of locating and refining information. Using my log browser as an example, this article looks at strategies and techniques which you can use to avoid becoming overwhelmed with data.

Browsing Sierra’s log – using Apple’s Console app, the log command in Terminal, or Consolation – is a sure way to develop feelings of panic, as you realise that you’re drowning in data. All you want to do is check that Time Machine is making backups properly, and you end up wading through thousands of security messages, mDNSserver entries, and more, until you just give up.

(Time Machine is a clear example for my purposes here; in fact it is already a special case in Consolation, and I have another tool specifically designed to assess backing up – T2M2, available in Downloads above.)

Consolation 3 provides four different tools for finding content in log messages. Each works differently, and knowing which to use when is key to getting the most (and least!) out of your log:

  • Predicates are used in the log show command to filter which log entries are included in the log excerpt for analysis. When you exclude entries using a predicate, they will not appear in the excerpt; you will only be able to view them if you Run command using a predicate which includes them. Consolation 3 supports complex custom predicates which can be extremely specific.
  • Plain filters determine which log entries are shown in the log display, and use simple, case-insensitive search. They are quick and simple, and are applied quickly, as you do not have to fetch a new log excerpt to change the filter.
  • Regular expression (Regex) filters are similar, but take case-sensitive expressions which are much more powerful and flexible. As with plain filters, new log excerpts are not required.
  • The standard Find command doesn’t change anything displayed in the log excerpt, but searches its displayed (hence filtered) text content for a text string. This is ideal when you just want to find a key phrase in a log entry.

Time Machine’s automatic backups should occur every hour, so you don’t want to make a logarchive of your entire log for a period of, say, four hours. In this case, you’re going to work on a live system log, with the Period set to 4 hours. To make that practical, you’re going to use predicates to greatly reduce the number of entries which appear in the log extract, as a coarse filter.

You could set up a simple Filter using the popup patterns and operators, but in this case you want a more sophisticated predicate. You might want to capture all messages which come from the Time Machine subsystem, or whose eventMessage contains backup, TimeMachine, or Time Machine. With four terms, this is best added as a saved predicate in the Predicates section of the Preferences sheet:
subsystem == "com.apple.TimeMachine" || eventMessage CONTAINS[c] "backup" || eventMessage CONTAINS[c] "Time Machine" || eventMessage CONTAINS[c] "TimeMachine"

consol50

While you have Preferences open, add some useful search terms in the Filters section, to look for each of the plain text strings start fail success error automatic manual. Then close Preferences, close the underlying window, and open a new window so that you can use those new tools.

consol51

Now set up your defaults for working with this log extract:

  • Set Log source to system.
  • Set Filter to other text or none.
  • Leave the other text box empty.
  • Set saved predicate to your new TimeMachine predicate.
  • Set filter to none.
  • Set Style to basic (any other than syslog or default will do, though), and include info messages ticked.
  • Set the Period to 4 hour.

Then click on the Save as defaults button so that other new windows will come up with these same settings.

Click on Run command now to obtain a log extract and show its entire contents using a simple style.

consol52

You should see a reasonably brief series of cycles, each starting with an entry like
08:06:52.450637 68 DAS told us to run com.apple.backupd-auto
Note the low Process ID number: this is from CTS, the dispatcher which has just been told by DAS to run an automatic backup. The first message from the backup process itself follows a little later, as
08:07:22.660630 23329 Starting automatic backup
with a higher Process ID.

The backup then takes place, with a succession of log entries, ending in
08:16:42.194558 23329 Backup completed successfully.

But CTS then has to take note, and finally schedule the next automatic backup with DAS:
08:16:42.196510 68 Submitting DASActivity: <_DASActivity: "0:com.apple.backupd-auto", Utility, 60s, [8/2/17, 9:05:07 AM - 8/2/17, 9:35:07 AM], Plugin Required, Dark-Wake Eligible>

Because you used a custom predicate, you have captured the whole process of each backup, rather than just the backup itself. If there are problems occurring somewhere, this gives you a much better chance of spotting where they are occurring.

consol53

To look for errors, you might simply use the Find… command in the Edit menu, looking for error. If there is an error in your log, this may find it in one of the eventMessages, but will not find a log entry of Error type – you would need to view more fields to do that, using a different style, such as starters+. In my case, that reveals three repeated errors in every backup cycle
08:07:29.970204 Error 5539774 68 com.apple.TimeMachine TMLogError UserEventAgent TimeMachine Failed to send message because the port couldn't be created.

consol54

It is essential to interpret this entry carefully and accurately: although an Error entry, its Process ID is CTS, not backupd, and it concerns UserEventAgent. So it is a failure not in making the backup, but in reporting that as an event to the user. Here, it is because the menubar icon doesn’t rotate any more – a puzzling but irrelevant problem.

Now explore the eventMessages contents using your filters. To see just the start time of each backup, apply the start filter, and you will see just a handful of log entries reporting the start of each backup, and of the subsequent post-backup thinning.

Filtering using fail will show the error messages found above. Interestingly, until I used this filter, I had thought that there were only two such messages each backup cycle. It was only by applying this filter that I realised that there were in fact three.

Similarly, success will show the completion times of each successful backup, automatic will show the start times of each automatic backup, and manual the same for any manual backups performed in that period.

The final challenge involves the use of regular expressions in a filter. As you saw above, using start as a simple filter isn’t specific enough to exclude entries for the start of other events such as post-backup thinning. To exclude those without excluding manual backups requires the power of Regex.

consol55

Consolation 3 and similar apps are not the right place to develop and refine Regex. I’m using Expressions (App Store, around £5), which is one of several excellent apps designed for that purpose. By putting in a line which I want to be a ‘hit’, and one which I wish to exclude, I can quickly work out a suitable Regex for the filter. One solution is:
Start(.*)backup$
which finds all messages starting with Start, provided that the line ends with backup, and not thinning.

consol56

Add that to a new filter, ensuring that you give it a name which starts with an asterisk *, so that Consolation 3 treats it as a Regex and not plain filter.

You’ll have to close the window then and open a new one, but as you have already saved its settings as defaults, it takes little time to do a fresh Run command, then try applying your new Regex filter.

consol57

That hits the sweet spot: a display of a log extract which contains only those log entries which you actually want to see. That is what predicates, filters, Regex, and find are all about.