Having discovered how little the new Console 1.0 can do, and the need to use its command line sibling, log, I have now spent some hours learning what works in log, and what doesn’t (yet). This article offers some tips on how to get the most out of Sierra’s new logging system, and its current limitations.

Why change?

Before looking at log itself, I had better explain what has happened to the traditional log system, and how the new logs are so different from what we used in El Capitan and earlier.

Traditional logs are text files, and seriously inefficient. They waste a lot of storage space for limited and highly unstructured data, and impose significant overhead on processes which need to write to them. The new system was designed to address those shortcomings, and provide a modern, structured, and efficient log system. As you will see, it has met those goals, but at a significant cost in terms of usability.

log revealed

log has five basic commands, in addition to log help, although for the advanced user and system administrator only one of those is generally useful.

log collect is the biggest disappointment, as it is intended to dump a chunk of existing log entries into a special .logarchive file, which can them be browsed using Console. If you know that your Mac had a kernel panic at 06:20:10 this morning, and restarted at 06:21:00, then it would be really helpful to be able to export the section of logs from, say, 06:19:30 to 06:22:00, then examine it in Console.

In theory, you should be able to do this sort of thing with a command like
sudo log collect --output ~/Documents/logcoll.logarchive --start '2016-09-30 06:19:30' --size 20m

Although the man page doesn’t seem to mention it, log collect needs to be run as root, using sudo. The above command should dump around 20 MB of log starting from 06:19:30 local Mac time into the file logcoll.logarchive. In practice, it ignores the size given, and possibly even the start time, and you just end up with a vast file which is a pain to do anything with.

It would be really good if the options worked, and perhaps even supported an --end time to be specified.

log config is mainly aimed at developers, although it may sometimes be useful if you are trying to solve a problem in a specific app.

log erase (which I suspect also requires sudo) is probably more damaging than useful.

log stream is for prospective collection, one of the few things that Console 1.0 does well.

This leaves the log show command, which is of greatest use for historical data. Although it does support some other options, for our purposes this will normally be used with the following:
log show --predicate [] --style syslog --start [] --end [] --info --last []
where [] represent values which we supply. I’ll take each of those options in turn.

--predicate filters the log content according to the criteria supplied, as predicates. At a simple level, these are straightforward, but can get elaborate and at times confusing. The main types of predicate which you are likely to use are:

• eventMessage, as in eventMessage contains "launchd", which selects entries where the message content contains the string launchd
• messageType, as in messageType == error, which selects entries which are classified as errors
• processID, as in processID < 100, which selects entries from processes with IDs less than 100, i.e. early and low-level
• subsystem, as in subsystem == "com.apple.TimeMachine", which selects entries for that specified ‘subsystem’. One neat way to discover subsystems is to use Console 1.0’s info panel; select a log entry and it will give you the applicable subsystem. You will also note how many important processes are not associated with subsystems, which limits the value of this predicate
• eventType, processImagePath, senderImagePath, and category are also described in the man page, but so far I have seen little use for them.

You can combine predicates using and or &&, and or, according to Cocoa’s predicate-based filtering.

--style is omitted if you want the output in full form, set to syslog for more compact text form, or to json if you want JSON which you can parse into other software (a powerful feature).

--start and --end set starting and finishing dates and times for the log extraction, given in standard UTC format. These are very valuable for limiting the amount of output, but you will then have to work out the correct values to use.

--info shows all messages down to info level, which is ideal for most purposes.

--last specifies a period of log to extract, for the last minutes, hours, or days, e.g. 3m for 3 minutes, 2h for 2 hours, or 1d for one day. This is an alternative to giving start and end times.

The output from log show is often then piped through additional tools such as grep and cut, and may then be poured into a text file. We shall see these in examples below.

Example commands

John Galt’s suggested command to inspect log entries for Time Machine backups is:
log show --predicate 'subsystem == "com.apple.TimeMachine"' --info | grep 'upd: (' | cut -c 1-19,140-999

This filters log entries to those for the Time Machine subsystem, and accesses them down to info level. That output is passed through grep to extract only those entries containing the string ‘upd: (‘, and then cuts out a chunk of text from the middle of each line. Note how the predicate is given inside single quotes, to ensure that the command line copes with its spaces properly.

An alternative which just captures the last couple of backups might be
log show --predicate 'subsystem == "com.apple.TimeMachine"' --style syslog --info --last 3h | cut -c 1-22,43-999

This uses the same predicate, but works on the syslog format output, and only uses log entries over the last 3 hours. The final cut gives a slightly different layout.

If you want to look in detail at a relatively short section of log, use
log show --style syslog --start '2016-09-30 06:58:10' --end '2016-09-30 06:59:00' --info

This does not use a predicate filter, so will result in many log entries, but does restrict the time window. Note that the dates and times are given in single quotes to ensure that they are properly handled.

To capture just the errors logged over a period, try something like
log show --predicate 'messageType == error' --style syslog --start '2016-09-30 06:58:10' --end '2016-09-30 06:59:00' --info | cut -c 1-22,43-999
or, to capture just those over the last minute,
log show --predicate 'messageType == error' --style syslog --info --last 1m | cut -c 1-22,43-999

Bear in mind that the logs can contain 70,000 or more entries in any given minute, so these could still be very hefty log excerpts.

Here are the two commands to create an empty text file, and then dump a short log extract to it:
touch ~/Documents/logrestart.text
(which creates the empty file, and)
log show --start '2016-09-30 06:58:10' --end '2016-09-30 06:59:50' --info > ~/Documents/logrestart.text
which then extracts the log excerpt into that text file, ready for you to browse.

Strategies

Here are some suggestions as to how you can use these commands in common situations.

To check your Time Machine backups, you can use either of the commands above,
log show --predicate 'subsystem == "com.apple.TimeMachine"' --info | grep 'upd: (' | cut -c 1-19,140-999
or
log show --predicate 'subsystem == "com.apple.TimeMachine"' --style syslog --info --last 3h | cut -c 1-22,43-999

If you’d prefer to put their output into a text file rather than the Terminal window, create the file first using
touch ~/Documents/logtmbackups.text
then pipe log’s output into that
log show --predicate 'subsystem == "com.apple.TimeMachine"' --style syslog --info --last 1d | cut -c 1-22,43-999 > ~/Documents/logtmbackups.text

To look for a startup entry,
log show --predicate 'eventMessage contains "BOOT_TIME"' --style syslog --info | cut -c 1-22,43-999

To look for a system waking up,
log show --predicate 'eventMessage contains "System Wake"' --style syslog --info | cut -c 1-22,43-999

You can then look at errors immediately before and after that date and time, e.g.
log show --predicate 'messageType == error' --style syslog --start '2016-09-30 06:57:10' --end '2016-09-30 06:59:00' --info | cut -c 1-22,43-999
and if that doesn’t tell you what went wrong, try dumping that window into a text file and browsing through it, with
touch ~/Documents/logrestart.text
log show --start '2016-09-30 06:57:10' --end '2016-09-30 06:59:00' --info > ~/Documents/logrestart.text

To look for error messages from an app, you will need to discover that app’s identifier, such as com.company.product. Then roll that into a command like
log show --predicate '(messageType == error) and (subsystem == "com.company.product")' --style syslog --info | cut -c 1-22,43-999

If you come up with some neat log commands, and solutions, please share them here. My next task is to package these into something which doesn’t require Terminal, so that I can send tools out to those whose problems I am trying to diagnose. I will make those tools available here.