Sierra Log Tutorial: Getting started, Time Machine errors, and restarts

You’ll have discovered by now that Sierra’s new Console app doesn’t do most of the things that the app used to in El Capitan. This is the first in a series of tutorials showing how you can use my free app LogLogger5 to get useful information from Sierra’s logs. This is the introductory article, which shows how to get the app started, and how to perform two of the commonest and most basic tasks.

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.)

Getting started

LogLogger5 comes compressed as a Zip file, which you should decompress, and move the app to your preferred folder, such as /Applications. It is not fussy where it is run from, though.

The first time that you run LogLogger5, as a downloaded app, your Mac’s Gatekeeper protection system will check the app, and discover that it does not have a signature. This is to allow users to modify the app when they wish, without breaking any signature. However, if you just double-click on the app, Gatekeeper will refuse to run it, showing this alert.

llogtut11

To run it the first time, you must either select the app and use the Finder’s Open command, or select the app and bring up the contextual menu in Finder and use the Open command from there.

llogtut12

llogtut13

The Finder will then show its standard alert, in which you should click the Open button. Once this has been done, you will not have to go through that process again (unless you download another copy and run that) – the app then runs normally from a double-click, the Dock, etc.

llogtut14

The first thing that LogLogger5 then does is to prompt you to save the first log excerpt, using a standard File Save dialog. If you want to navigate further, click on the disclose (down) arrow at the upper right.

LogLogger5 is designed to help you save a whole series of log excerpts when you are exploring your logs. By all means save them to whichever folder you wish, but I recommend that you use the suggested file names, as they will automatically increment from LogLoggerOut00.text to LogLoggerOut01.text, and so on. If you want to use your own custom file names, that auto-increment system should work if you only have a single period in the name, if the two characters before that period are 00 to begin with, and if the extension is left as .text (or .txt). It aims to be a bit more flexible too, but those should be safe rules.

Checking that Time Machine backups are completing without errors

One of the commonest reasons for wanting to access your logs is to ensure that your backups are being made without problems. This is extremely simple and efficient using LogLogger5. Once you have provided the name and location of the log excerpt file to save, in the File Save dialog, LogLogger5’s main dialog will be displayed.

llogtut15

There are three important controls which you need to check.

At the top, the Filter: radio button should be set to the first option, TimeMachine.

Halfway down, the Period (integer) text box should be set to the number of hours (of hourly backups) that you want to inspect. Normally 2 to 4 are sufficient; the greater this period, the longer this will take. On that same line, set the Unit of time to h for hours, rather than its default of s for seconds.

Almost at the bottom of the dialog, check the box to open in editor, so that once the log excerpt has been created, it will automatically be opened using TextEdit (or your chosen default text editor).

Then click on the OK button.

LogLogger5 then assembles the shell command using log show, and executes it. There will be a short pause of several seconds while the log excerpt is prepared, saved to the file, and opened for you to inspect.

llogtut16

You can then resize TextEdit’s window to check through your backup entries for errors. They should read something like:
2016-11-07 13:19:49.23 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Starting automatic backup
2016-11-07 13:19:49.58 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backups.backupdb
2016-11-07 13:19:50.69 UserEventAgent[67]: (TimeMachine) [com.apple.TimeMachine.TMLogError] Failed to send message because the port couldn't be created.
2016-11-07 13:19:53.34 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Will copy (662.3 MB) from Macintosh HD
2016-11-07 13:19:53.34 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Found 658 files (662.3 MB) needing backup
2016-11-07 13:19:53.37 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] 14.95 GB required (including padding), 3.07 TB available
2016-11-07 13:23:04.13 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Copied 931 items (642.1 MB) from volume Macintosh HD. Linked 9886.
2016-11-07 13:23:09.47 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Created new backup: 2016-11-07-132308
2016-11-07 13:23:09.51 UserEventAgent[67]: (TimeMachine) [com.apple.TimeMachine.TMLogError] Failed to send message because the port couldn't be created.
2016-11-07 13:23:10.39 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Starting post-backup thinning
2016-11-07 13:23:10.39 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] No post-backup thinning needed: no expired backups exist
2016-11-07 13:23:10.42 backupd[1553]: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Backup completed successfully.

repeated every hour or so. Note the “Failed to send message” entry above refers to an irrelevant issue (and a bug in macOS).

Meanwhile, LogLogger5 will have gone back to its File Save dialog. As you’re done now, just click on its cancel button, and the app will quit.

Checking a restart (or startup)

When your Mac starts up, it invariably makes a log entry to mark the start of that process, which contains the text BOOT_TIME. This is invaluable for identifying the exact time of each startup or restart, so that you can check out any problems with them.

To locate log entries containing BOOT_TIME, we’re going to put that in as a filter pattern or predicate which will only return those lines containing that text.

llogtut17

Run LogLogger5 again, and complete the File Save dialog as before. In the main dialog, ensure the following controls are set.

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-07 08:10:20.85 syslogd[66]: (libsystem_c.dylib) BOOT_TIME: 1478506214 0

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

Viewing all log entries

Instead of quitting LogLogger5 by cancelling the next dialog, we’ll use that startup time to see just how many entries are made in the log around a startup or restart.

In the File Save dialog, agree to the next log excerpt being made and saved to the next filename. Then in the main dialog, we’ll set up to get a complete log extract for just two minutes around BOOT_TIME.

llogtut18

At the top, set the radio button to none, which turns all filtering off, and will save every log entry to our text file.

Set the Period (integer) to 0 (zero), which means that start and end times will be used instead.

Ensure the start date line is checked (enabled), and that today’s date has been automatically entered for the start date. Then in that same row, set the time to a few seconds before the time of the BOOT_TIME, as shown in the last log excerpt, which should still be open in TextEdit.

Ensure the end date line is also checked, that today’s date has been automatically entered, and then set the end time to just two minutes after the start time, which should be after the BOOT_TIME entry. So if your BOOT_TIME was 11:10:30, set the start time to, say, 11:10:10, and the end time to 11:12:10.

This log excerpt is going to be very large, so you may prefer to turn open in editor off – that is up to you. Then click on the OK button.

Here, my resulting log extract for just those two minutes contains over 127,000 entries, and is 17.6 MB in size. Unless you are seriously bored, you will not want to browse that: looking for problems with an extension, or other details, would be a nightmare. So the next tutorial will look at filter predicates which you can use to hone in on problems, to investigate them.