When did my Mac last start up, and why? An exploration with Ulbow

The macOS unified log goes back a surprising period: it does weed out more ephemeral entries soon after they occur, but significant entries, which enable you to identify and explore previous startups, should be retained for around 20 days, sometimes rather more. I upgraded this iMac Pro to Catalina, and although it didn’t appear to be restarted normally during that installation, I had to restart it afterwards to get it to mount my Time Machine backup drive correctly. In this tutorial, I’m going to hunt for that startup of three days ago and examine it, using my new log browser Ulbow.

If you haven’t already prepared Ulbow for use, now’s the time to do this. Inside its Zip archive you’ll find three important Property Lists: co.eclecticlight.Ulbow.plist is a good initial Preferences file, which you should move to ~/Library/Preferences, that’s the Preferences folder inside the Library folder in your Home folder. If you’ve already used Ulbow and want to do this now, ensure that you quit the app, and leave it a while for the preferences server to catch up, or the replacement file may get overwritten.

ulbow10120

Then open the Ulbow app, create a new window if it doesn’t already make one for you, then select the Import Settings… command in the app menu. In the Open File dialog, locate and select either of the other two Property Lists, UlbowSettingsMojave.plist or UlbowSettingsSierra.plist. The first is best for Mojave and Catalina, the second for Sierra and High Sierra. Then click on the Open button to read those additions into Ulbow.

To ensure that the current settings are kept ready for when you next open a new window, or Ulbow itself, now use the Save as defaults command in the app menu. Do that whenever you’ve got Ulbow set up ready for a task which you will want to return to.

ulbow10124

I know from the System Software Overview in System Information that my Mac was last booted just over three days ago, in the afternoon or evening of Boxing Day, 26 December. Ulbow’s Help book provides information on the log message which normally marks the beginning of the startup process. To find that, open the Help book and click on the link to its Contents. Towards the bottom of the sections is one named Navigation which has that sort of useful information (as does this blog).

ulbow10125

There it tells you that the distinctive marker for that moment is
=== system boot:
followed by a UUID. That’s what I’ll use to find the time when my Mac started up three days ago.

There are three ways of finding this in Ulbow: you could set it as the Predicate, use it as a filter, or use the regular Find feature on log entries. The most efficient by far is to build it into a Predicate, and leave macOS to find it for you. I’m not very good at remembering just how to enter a new Predicate here, so I’ll cheat by copying and pasting from one of the standard sets. Open Ulbow’s Preferences, and in the top Predicates section, select the item error. This shows that the predicate named error contains the text
eventMessage CONTAINS[c] "error"
and that’s what I’ll use to locate the startup. Select that predicate, copy it, then close the preferences window. Now select the contents of the Predicate ‘combo’ box and paste that text into it, to form an ad hoc predicate. If you prefer, you can add one to the predicates in the Preferences window, but this is quick and dirty.

ulbow10126

Now select the word error in that predicate, select === system boot: in the Help book, copy it from there and paste it to replace the word error in the predicate. Then set the rest of the controls up: filter to none, style to none, and adjust the Period and relative to settings to cover the period in which you suspect the Mac booted up. Finally, when you’ve checked those carefully, click on Get log.

ulbow10127

 

This is going to take macOS a long time to complete, as it has to search six hours of log entries for that text. If you can narrow the period down, that can be a great help. What’s most important is that the Predicate should be as precise as possible, which will return the fewest entries. You can also ‘march’ your log search through time, in periods of an hour or so.

I eventually found its last boots using a combination of the predicate
eventMessage CONTAINS[c] "==="
with the filter
boot
which showed two system boots after the upgrade had completed at 13:48:01 and the restart which I called at 14:10:56.

ulbow10128

I then set Predicate back to none, to show all log entries, filter to none, and style to basic+, so that I could browse the first thousand log entries after that startup. In that minute, there were actually 130,163 log entries, so it’s as well that I have Limit entries shown enabled. I can then explore that startup using more restrictive Predicates and filters to keep the number of entries shown manageable and not overwhelming.

ulbow10129

One important entry to locate, which normally appears well within those first thousand, is the message giving the reason for the previous shutdown:
Previous shutdown cause: 1
Another matter of concern was whether support for my Promise Pegasus was correctly loaded. That also appears early as
STEX : PromiseSTEX loaded up...
and other messages.

You can use similar techniques to identify when your Mac restarted after a kernel panic, thereby looking back before the panic occurred and try to work out what caused it. This doesn’t always work, though, as kernel panics can cause long blank periods in the unified log.