Welcome to macOS Sierra’s new Console: it’s buried in Terminal

Read the previews, and even some of the reviews, of macOS Sierra and you’ll be impressed with the changes that have taken place in Console, the bundled app which helps you browse your Mac’s logs. My own summary here may seem out of kilter with those.

The reason is that I spend quite a lot of time browsing my own and other Mac’s logs, trying to get to the bottom of problems. If you try to do that using Console 1.0 as shipping in Sierra, you’ll very quickly hit a wall: it is next to useless for such work. I suspect that the previewers and reviewers never actually tried to do anything purposeful using Console 1.0.

Take a quite popular purpose for which Console was used in El Capitan and earlier: checking that Time Machine backups are being completed correctly and without error. All you had to do was open Console, ensure it was set to browse All Messages, then scroll back looking for the last couple of backups. Because the logs were starting to get clogged with all sorts of junk messages, this was becoming increasingly difficult, but you could then always type in some characters in the Search box, such as TimeMachine or backup, to narrow the listing down.

None of the historic logs made available in Console 1.0 contains such information. It has been removed. You could look for such messages prospectively in the log which starts when you open Console 1.0, but that will not tell you what has been going on over the last day or two.

Thanks to some days working through Apple’s documentation, and some valuable clues from John Galt and others, I can now reveal how you can retrieve such historical information – about the last few days backups, wakes from sleep, startups, and anything else. You have to do this at Terminal’s command line. Yes, the huge step forward in logging in Sierra is to require you to type in shell commands, instead of using a pleasant GUI.

The key shell command here is log, so if you want to read all the detail, you’ll want to type man log, and then browse the several pages of opaque documentation. You may find this example gets you started more quickly and painlessly.

The first thing to check is the current mode of system logging, using the command
sudo log config --status
which should return
System mode = INFO

That is the normal mode for Sierra as deployed in use.

To view historical log data for a given ‘subsystem’ like Time Machine, you enter a command like
log show --predicate 'subsystem == "com.apple.TimeMachine"' --info

There will then be a long pause, and Terminal will start filling with entries like
Skipping debug messages, pass --debug to include.
Filtering the log data using "subsystem == "com.apple.TimeMachine""
Timestamp Thread Type Activity PID
2016-09-23 13:55:15.565447+0100 0xb645 Info 0x0 255 backupd-helper: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Not starting scheduled Time Machine backup: No destinations resolvable
2016-09-23 14:43:14.747078+0100 0x1cfd4 Info 0x0 255 backupd-helper: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Not starting scheduled Time Machine backup: No destinations resolvable
2016-09-23 15:45:01.365201+0100 0x1e93b Info 0x0 255 backupd-helper: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Not starting scheduled Time Machine backup: No destinations resolvable
2016-09-23 16:45:31.161794+0100 0x43462 Info 0x0 255 backupd-helper: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Not starting scheduled Time Machine backup: Backup already running
2016-09-25 22:52:55.167799+0100 0x3dcdea Info 0x0 27817 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Starting automatic backup
2016-09-25 22:52:55.323607+0100 0x3dcdea Info 0x0 27817 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backup

eventually ending with
Log - Default: 0, Info: 783, Debug: 0, Error: 201, Fault: 0
Activity - Create: 0, Transition: 0, Actions: 0

If you were chasing Finder problems, you might filter thus:
log show --predicate 'subsystem == "com.apple.Finder"' --info

John Galt came up with a neat tweak to the command, which selects only those lines containing the string upd: (, and then removes the thread, type, activity, and PID information, to produce a clean listing much like Console used to do before:

log show --predicate 'subsystem == "com.apple.TimeMachine"' --info | grep 'upd: (' | cut -c 1-19,140-999

which generates output like

2016-09-28 20:52:38 Starting automatic backup
2016-09-28 20:52:38 Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backups.backupdb
2016-09-28 20:52:41 Will copy (71.5 MB) from Macintosh HD
2016-09-28 20:52:41 Found 1651 files (71.5 MB) needing backup
2016-09-28 20:52:41 14.69 GB required (including padding), 3.12 TB available
2016-09-28 20:58:34 Copied 1714 items (70.8 MB) from volume Macintosh HD. Linked 13334.
2016-09-28 20:58:39 Created new backup: 2016-09-28-205839
2016-09-28 20:58:39 Starting post-backup thinning
2016-09-28 21:00:42 Deleted /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2016-09-27-195835 (36.5 MB)
2016-09-28 21:00:42 Post-backup thinning complete: 1 expired backups removed
2016-09-28 21:00:48 Backup completed successfully.

You can also get log to show current Time Machine backup entries, for which the command
log stream --style syslog --predicate 'senderImagePath contains[cd] "TimeMachine"' --info
should do the trick. You can also coax Console 1.0 to do that, although by this stage you’re probably wondering why Apple bothered including such an emasculated utility in a final release operating system.

I can see that explaining to users how to capture log segments for me to analyse by email is going to be quite exciting.