Sierra Log Tutorial: Exploring a startup

This is the second in a series of tutorials explaining how to access Sierra’s past logs using my free LogLogger5 tool. In the first, I went through some basics, checking Time Machine backups, and ended with a practical demonstration of how examining all log entries from around a startup will keep you busy for a very long time. This tutorial looks at ways that you can explore what happens after a startup much more purposefully and efficiently.

There are only two ways to discover what happened during a startup: you can browse past logs using the log command in Terminal, or you can use LogLogger5. The current version of Console cannot provide you with any detailed information about startup, as you cannot run it until it is too late.

What you need

A Mac running macOS Sierra 10.12 or 10.12.1. I recommend that you use 10.12.1, as that does fix a bug in the logging system which will help, but as far as I know, everything here should work on 10.12, and hopefully on 10.12.2 and later too.
A copy of LogLogger5 from here: loglogger5
(This is delivered by secure HTTPS download.)

Identify when your Mac started up

The first step in exploring a startup is to identify exactly when, according to the system clock, your Mac actually started up. As I showed last time, this uses the fact that each startup invariably has a log entry containing the text BOOT_TIME. So the first run with LogLogger5 will extract startup times over the last 8 hours, as in the last article:

llogtut17

Open LogLogger5, complete its File Save dialog as before, and set the following controls in the main dialog:

At the top, set the radio button to Pattern, so that we can enter those details.

In the line below that, set the first popup menu to read eventMessage, as BOOT_TIME appears in the message part of the log entry. Set the next popup to CONTAINS(c), which looks for a match without being case-sensitive (although this will work with plain CONTAINS, which is case-sensitive). In the final text entry box, type BOOT_TIME being careful to use the underscore character, shift-hyphen.

Although you can search for this in a specific period defined by start and end, you will get more hits if you use a time period before the present. For that, set the Period (integer) to several hours, a period within which you know your Mac has started up. Then set the Unit of time to h for hours.

Just above the bottom of the dialog, select the open in editor checkbox, so that the log excerpt will be opened for you to view. Then click on the OK button.

After a period of a few seconds, the log excerpt will open in TextEdit, and show one line for each startup which occurred in the specified time period. In my case, that reads:
Timestamp PID]
2016-11-10 20:30:02.22 syslogd[67]: (libsystem_c.dylib) BOOT_TIME: 1478809800 0

So we now know that the last startup was getting underway at just after 20:30 local time today.

Use broad filters to hone in on problems

Complete the File Save dialog to store the next log excerpt, and then run a broad filter to work out what you need to look at in more detail. One good filter setting picks up all messages containing kernel, which is good if you are looking at a system-level problem:

llogtut21

Set LogLogger’s main dialog up like this, filtering on eventMessage which CONTAINS(c) the text kernel (case insensitive). Ensure that you set the Period (integer) back to 0 in order to use start date and end date below, then adjust the time settings to start the excerpt a little before the BOOT_TIME, and end it two or three minutes later, to catch the whole of startup. You’ll also want to open the excerpt in your text editor for immediate viewing.

You may find that you need to adjust the start and end times a little after this, but from now on all the settings below the top section will remain unchanged, so I omit them from the screenshots below.

If you have got your times right, the first line in the excerpt should tell you which version of the kernel is running, a useful piece of information in itself:
2016-11-10 20:29:58.75 kernel[0]: Darwin Kernel Version 16.1.0: Thu Oct 13 21:26:57 PDT 2016; root:xnu-3789.21.3~60/RELEASE_X86_64
(that's for Sierra 10.12.1).

Shortly after that, you’ll see two lines
2016-11-10 20:30:02.51 DumpPanic[88]: Attempting to extract kernel core if it exists
2016-11-10 20:30:02.51 DumpPanic[88]: HandleKernelCore(): SadMac partition not found

which confirm that the restart did not occur after a kernel panic. If it does, then the information from that should be recovered and made available.

Lower down are various housekeeping entries, and you’ll probably see some long messages about SandboxViolation. Otherwise, if you start seeing other entries, they may well correspond to a problem.

Another good broad filter is to look for messages containing errors:

llogtut22

A lot of these will relate to security systems, like
2016-11-10 20:30:03.04 amfid[142]: (Security) [com.apple.securityd.security_exception] MacOS error: -67050

As is usual in Unix, success is an error code of 0, so you will also see reports of processes completing successfully! If you want to decode Apple’s sprawling error numbers, an excellent site to use is OSStatus.

More specific filters

Sometimes, you’ll need to narrow your filter by adding a second pattern. There’s a huge range of these which might prove useful, so I will just offer a few suggestions here.

llogtut23

Try looking at error messages returned from specific processes – here the kernel. This excerpt should be very short, such as:
2016-11-10 20:30:00.18 kernel[0]: (IO80211Family) init: error getting PHY_MODE; using MODE_UNKNOWN
2016-11-10 20:30:29.19 kernel[0]: utun_start: ifnet_disable_output returned error 12

Any more than that and you’ll want to follow them up. You may then want to broaden the time period that you are examining, something which makes sense when you are using narrow filters.

llogtut24

This combination of messages from the kernel which contain reference to Bluetooth is excellent for looking at Bluetooth problems: you can track Bluetooth starting up, and becoming fully functional.

llogtut25

This looks at a common problem which can start soon after startup, repeatedly crashing of mdworker processes, which index metadata for Spotlight search.

Discovering processImagePath names

Although log messages, as set using eventMessage, can usually be guessed quite easily, you may not know many process names which can be entered as processImagePath. Thankfully your Mac contains an excellent listing of the names of all those active processes at any time.

llogtut26

Start Activity Monitor, set it to show CPU usage according to the tools at the top, and the items listed in the first column, Process Name, are excellent candidates for use when filtering according to processImagePath. You can make this even easier if you click on the top of the PID column, as those processes with the lowest numbers are started soonest after startup: the kernel (named here kernel_task) has the PID of 0, and launchd (which launches all subsequent processes) has the PID of 1.

Try to take some time exploring the last startup on your Mac, using LogLogger5 and its log excerpts. They’ll help you understand what goes on during a normal startup, so you’ll find it easier to recognise the abnormal.