Login
Inside the Unified Log 5: Navigation
The greatest challenge in using the Unified log is how to navigate its many thousands of entries, to find those you want to read. Success depends on the combination of two aids: time and waypoints (or landmarks).
Time
No matter how you obtain log extracts, you need to know when to look for those entries. The more precisely you can work out the time of interest, the quicker and easier it will be to locate the entries you’re interested in. While the log command offers alternatives, LogUI works throughout using the local time applicable when you access the log, allowing for your current time zone and any seasonal adjustment to it, when accessing the live log in that Mac.
However, the underlying times given in log extracts are those recorded by the Mac or device whose log you’re accessing. If its system clock was five minutes slow when those entries were written to its log, then you need to allow for that. For example, when I first started my Mac yesterday its clock might have been 1 minute slow. An event that occurred at 10:56 yesterday by the room clock would therefore appear in the log entries for 10:55.
One important time you can discover is the boot time of the Mac. Mints offers a Boot button to retrieve boot times over the last 24 hours. If the logs were written by a different Mac or device, then you’ll need to search for the time of that last boot. Fortunately the first two log entries are easily recognised:11:41:37.562774+0100 === system boot: D3CEA9B4-F045-434D-8D12-C6E794A02F14
11:41:42.758780+0100 kprintf initialized
The long gap between the first two entries is accounted for by the firmware phase of the boot process. If necessary you can search for a message containing === (three equals signs). Mints provides the time of the first of those for each boot, and its UUID.
There are two occasions when time can become confusing, when clock corrections are applied, and when clocks are moved forward or back to add or remove summer or seasonal time changes. Fortunately the latter only change twice each year, although when they do, you really don’t want to see what happened in the log, and those changes aren’t even applied at a predictable time.
Clock corrections, like kernel boot, are readily found by the === text in their message. They normally happen in pairs, with the first correction the larger, and the second often far smaller. Here’s an example seen in consecutive log entries:08:26:16.140474+0100 /usr/libexec/sandboxd[80] ==> com.apple.sandboxd
08:26:10.043353+0100 === system wallclock time adjusted
08:26:10.044335+0100 Sandbox: distnoted(72) deny(1) file-read-metadata /private
08:26:10.044601+0100 2 duplicate reports for Sandbox: distnoted(72) deny(1) file-read-metadata /private
08:26:10.044606+0100 Sandbox: distnoted(72) deny(1) file-read-metadata /Library
08:26:10.089204+0100 === system wallclock time adjusted
08:26:10.091850+0100 started normally
The first adjustment dropped the clock back by 6.1 seconds, from 08:26:16.140474 to 08:26:10.043353. This means that you’ll see times of 08:26:12 both before the correction and afterwards. The second adjustment, from 08:26:10.044606 to 08:26:10.089204, was far smaller at 0.045 seconds, and at least went in the right direction.
The most substantial clock corrections are made shortly after booting. Although macOS does make them later, the size of those should be smaller.
Waypoints
Even working with times resolved to the second, those can still leave you browsing thousands of log entries. To locate more precisely you need details of one or more entries that will be sufficiently distinctive to focus in on a few dozen. These are waypoints for navigation.
LogUI provides three methods for locating these waypoints:
- using a search predicate to determine which log entries are extracted from the log;
- applying search text to filter out all entries that don’t contain a term;
- searching a rich text export of the log extract.
Predicates
These are best used when the time period of your extract needs to be relatively long, so would return a large number of entries. For example, if you can only narrow the time down to several minutes, and are looking for the time that a specific app was launched, you can look for that app’s job description when it’s created and written to the log by RunningBoard.*
Over a period of two minutes, RunningBoard might write thousands of entries in the log, so looking for your app’s job description among them would be time-consuming. Set the start time and period to cover the whole of the time you want to search, then set a predicate for the subsystem com.apple.runningboard.
When LogUI fetches that log extract, there might still be over 2,000 entries, so now is the time to apply search text to filter those further.
Search filter
To filter those 2,000 entries and show only those containing job descriptions created by RunningBoard, enter the text constructed job in LogUI’s search box, with its menu set to Messages, and press Return. You’ll now see that list reduced to just a handful, and looking through them you can discover exactly when your waypoint occurred.
My example for this article starts with a period of just 2 minutes, in which there were more than 100,000 log entries.
Using the com.apple.runningboard predicate whittled those down to 13,443 entries.
Searching within those for constructed job left me with just 8 entries to look through.
Search rich text
Sometimes you can’t devise the right combination of predicate and search filter to discover what you’re looking for, which might be an error reported in a subsystem or a process that you can’t identify. One good way forward is to narrow your log extract as much as you can, then save the extract as Rich Text, open that in a suitable editor, and search through it for the word error. That will discover every log entry containing the word error anywhere, rather than confining it to the message text.
Using time and waypoints
Armed with your waypoint and the exact time of its entry in the log, you can now set that as the start time, set a period of a couple of seconds, and get a full log extract containing all the detail you might need. This should give you further clues to allow you to move through time using predicates and search filters to discover what happened. This is much quicker and less frustrating than trying to scan through thousands of log entries in search of vague clues.
Key points
- Use time and waypoints to find log entries.
- Mints’ Boot button gives times of each boot in the last 24 hours.
- Reduce the number of log entries returned using a predicate.
- Narrow those down using a search filter.
- Search all text by exporting the log extract as Rich Text.
* Sadly, the days of being able to access freely RunningBoard’s informative job descriptions in the log are over. As of macOS Tahoe, all you’ll see is the dreaded <private> of censorship. If you want to examine these now, you’ll have to remove log privacy protection first. Thanks, Apple, for providing such useful tools then rendering them next to useless.
