Reading view

There are new articles available, click to refresh the page.

Reducing noise by searching LogUI’s views

App architectures can enable or constrain. My previous log browsers, Consolation and Ulbow, have been document-based, so each window represents a different log extract. As there seemed little reason to open two document windows on a single extract from the log, I’ve normally tweaked and fiddled with each window to display the entries I want to browse, an inevitable compromise that usually leaves me scrolling through thousands of entries.

LogUI is lighter in weight and not based on documents, merely windows and views. Although they’re backed by the data of a log extract, there’s no reason that you shouldn’t open several windows on the same data if that makes analysis easier. And it does, particularly when used with Search. Here’s an example.

Over the last couple of weeks, I’ve been looking at many log extracts covering app launch, one of the busiest events in macOS. In the first few seconds following a double-click to run an app, the log can accumulate well over 25,000 entries. No matter how experienced you are in dealing with them, or how efficiently you can look for milestones marking progress, it can take hours to read the launch process thoroughly in the log. This is partly because of the sheer volume of entries, but most of all because so many subsystems in macOS are involved. Any given period of tens of milliseconds can have long volleys in TCC, interspersed with a series of RunningBoard assertions, and occasional progress reports from LaunchServices. They’ll suddenly be interrupted by DAS dispatching an unrelated background activity, Wi-Fi updates, and other everyday tasks.

Try this instead.

Watch your Mac’s clock until it’s about to change minute. Just as the seconds count changes to 00, double-click the app and take your hands away from mouse/trackpad and keyboard. Once the clock reaches 10 seconds, assuming the app launch is complete, quit that app and start up LogUI. Its new window should show the time when you launched the app, so ensure its time period is correct, say anything between 5 and 30 seconds, and allow it to collect up to the 5-10 seconds required. When that’s ready, click on its Get Log button and check that it contains all the entries you require. Open second, third, fourth, and fifth windows likewise, with the same start times and settings. Once they’re all open, Get Log in each of them, and check that the number of entries is identical, indicating that each has the same log entries.

In my case, launching Pages brought over 40,000 log entries in the first 5 seconds, ending with the app running and prompting me to open a document. Even if you speed-read those at one entry every second, that would take you nearly 12 hours to work through. Let’s reduce that to a few minutes to see each of its important phases.

In a second window, type sendaction: into the Search box at the top right and press Return. That will find all entries marking the clicks/taps you triggered the launch with.

There are two paired entries 0.237 seconds apart, representing my double-tap. So we now know that we can safely ignore everything in the log that happened before the time 11:55:00.767. Leave that window open with just those entries showing, as a reminder.

Normally the first subsystem on the scene to handle those actions is LaunchServices. In the third window, change the search field 🔍 popup menu to Subsystems, type launchservices in the Search box, and press Return.

Sure enough, from a time of 00.779 seconds, only 0.012 seconds after the second tap, LaunchServices reports that it’s getting ready to launch Pages through RunningBoard, and constructs its EnvironmentDictionary for the purpose. This is the cue to move onto the fourth window, where we set the popup menu to Subsystems again, enter runningboard into the Search box, and press Return.

This details the launch request being handled by RunningBoard, which a few moments later constructs and reports an extensive job description for Pages. Another early arrival during the launch process is TCC to check the new app’s privacy access. In the fifth window, set Subsystems again, and search on tcc.

So far we’ve ignored another group of subsystems and processes that are more interesting than the drudgery of TCC, security. For a first look at how this is checked, switch the popup to Processes and search for amfid, the service for Apple Mobile File Integrity (AMFI) checking.

This shows its check entering first the path to the main executable at 00.805 seconds, two immediate security checks being called, then entering the path for one of the frameworks inside the Pages app bundle 0.05 seconds later. We can readily trace each framework check through the rest of the launch process in this view.

A more general summary of security checking milestones is provided by com.apple.syspolicy.exec, so switch the popup to Subsystems, and search on syspolicy.

This reveals how syspolicyd called a Gatekeeper process assessment on Pages, showed that the code had already been evaluated (despite it not having been run previously in this session), and allowed the launch to proceed without any further checks like an XProtect scan being made.

Finally, for a permanent record of this launch, in any of the windows click on the Save button to write all 41,712 log entries to a Rich Text file. That turned out to be 9.3 MB in size, so I’m glad I’m not still trawling through that trying to make sense of its contents.

To do this, LogUI will require a little more memory: in this case, working with five windows, each with over 40,000 log entries, LogUI took 520 MB. I think the convenience is worth that small cost, but I am going to return to Xcode to see if that can’t be managed better and reduced in size.

At the moment, LogUI doesn’t use any tricks to share a single log extract across different windows, and I’m wondering why and how that could be improved. One approach might be to obtain a single log extract as a Project, from which you can open individual windows for different searches. Although that shouldn’t be difficult to code, it would make LogUI more complex to use, and limit the flexibility of each window. Please try this out yourselves and let me know what you think. For now, I’m surprised at how useful search can be across several open windows.

A primer on predicates for LogUI

All good log browsers provide tools to narrow down the log entries they display. Without those, it would be easy to waste all day wandering through tens of thousands of entries. One common tool provided by macOS, directly and in the log command tool, is filtering using predicates. Although LogUI provides easy access to simple predicates, to get the best from them, it’s worth digging a little deeper, as I do here.

Instant predicates

LogUI’s instant predicates filter log entries according to any of four basic predicate types:

  • subsystem, such as com.apple.sharing, the field shown in yellow in log extracts;
  • eventMessage, the text message listed in white/black at the end of each entry;
  • processImagePath, such as mediaanalysisd, shown in blue, the name of the process making that entry;
  • senderImagePath, such as libxpc.dylib, shown in red, the name of the process sending that entry.

These are quick to enter in the text box to the right of the popup menu in the window’s toolbar, but in many circumstances can prove too broad, and need narrowing down further. In other situations, you want to browse entries from two subsystems, or using a combination of criteria. The best way to do that is to write a short predicate. For single use, you can do that in the one-off predicate editor using the Set button.

When you want to reuse that, you can add it to the predicate popup menu using Settings Predicate (currently a bit kludgy).

Predicates

macOS can use predicates in other situations, most commonly for Spotlight search. If you’re interested in those, see Apple’s Predicate Programming Guide. Here I’ll describe predicates as they’re more commonly used to filter log entries, as they’re usually much simpler.

Each simple predicate consist of three parts:

  • the name of one of the fields in a log entry, such as subsystem or eventMessage. This sets where the filter looks in each entry;
  • an operator, which might be == for ‘equals’ exactly, or for text is commonly CONTAINS[c] for case-insensitive contains;
  • text or a numeric value to look for, such as “error” or 513. Only those entries equalling or containing (or whatever the operator means) this in the specified field will then be returned from the log and displayed.

Here are some basic examples.

eventMessage CONTAINS[c] "error"
entries will only be those with the text error in their message field.

subsystem == "com.apple.duetactivityscheduler"
entries will all have that text, ignoring case, but only that text, as the name of their subsystem.

subsystem CONTAINS[c] "com.apple.xpc"
entries will have any subsystem containing that text, which also includes com.apple.xpc.activity.

Fields

Although you can use any of the fields shown in LogUI (and some that aren’t), the most commonly used are, in order as they are shown in LogUI’s window:

  • eventType (red) – matches the type of event, such as logEvent (1024), traceEvent (768), activityCreateEvent (513), or activityTransitionEvent (514). Can be given as characters (case-sensitive) without quotation marks, or using the digits given in parentheses. Use these only with the operators == or !=, as they are treated as numbers rather than text.
  • category (green) – this matches the category, and varies according to subsystem. This is given as text in quotation marks, and is normally lower-case.
  • messageType (white/black) – matches the type of message for logEvent and traceEvent, and includes default (0), release (0), info (1), debug (2), error (16), and fault (17). Can be given as characters (case-sensitive) without quotation marks, or digits as shown in parentheses. Use these only with the operators == or !=, as they are treated as numbers rather than text.
  • senderImagePath (red) – this matches the text pattern in the name of the sender, which might be the name of a library, extension, or executable.
  • processImagePath (blue) – this matches the text pattern in the name of the process that originated the event.
  • subsystem (yellow) – this matches the subsystem specifier, e.g. com.apple.TimeMachine, given as text in quotation marks. You may find it best to use CONTAINS[c] rather than ==, to allow for differences in case and extended subsystem specifiers.
  • eventMessage (white/black) – for this, you specify a text pattern, or text, within the message, given as text in quotation marks.

Operators

The following comparisons and other operators are available:

  • == (two equals signs) for equality
  • != or <> for inequality
  • >= or => for greater than or equal to
  • <= or =< for less than or equal to
  • > for greater than
  • < for less than
  • AND or && for logical and
  • OR or || for logical or
  • NOT or ! for logical not
  • BEGINSWITH, CONTAINS, ENDSWITH, LIKE, MATCHES for string comparisons, using regex expressions when desired; strings can be compared with case insensitivity and diacritic insensitivity by appending [cd] to the operator, e.g. CONTAINS[c] means case-insensitive comparison
  • FALSE, TRUE, NULL have their expected literal meanings.

There are others as well, but you’ll seldom use them to filter log entries.

Building complex predicates

To see the scheduling and dispatch of background activities by DAS-CTS, you need to look at log extracts showing both their entries. Use the predicate
subsystem == "com.apple.duetactivityscheduler" OR subsystem CONTAINS "com.apple.xpc"
to do that. The first part of it includes those entries from DAS, and the second includes those for XPC and its relatives that run CTS. Using an OR between the two parts combines both sets of entries in the one extract.

To see the reports posted by XProtect Remediator, you need to look at those entries made by its subsystem that have the right category, using the predicate
subsystem == "com.apple.XProtectFramework.PluginAPI" AND category == "XPEvent.structured"
Using the AND operator ensures that the only entries shown come from that one subsystem, and they are given just that category.

Time Machine involves a combination of different subsystems and messages. To get a good overview of relevant entries, you can use
subsystem == "com.apple.TimeMachine" OR
(subsystem == "com.apple.duetactivityscheduler" AND eventMessage CONTAINS[c] "Rescoring all") OR
(subsystem == "com.apple.xpc.activity" AND eventMessage CONTAINS[c] "com.apple.backupd-auto") OR
eventMessage CONTAINS[c] "backup" OR
eventMessage CONTAINS[c] "Time Machine" OR eventMessage CONTAINS[c] "TimeMachine"

I’ve broken this down into separate lines, but you shouldn’t do that in the predicate. Taking it line by line it becomes simpler to understand. Use parentheses () to group each part of the predicate carefully as shown.

You can see other examples in the Help book for my free utility Mints: the Further Information pages towards the end give each of the predicates that Mints uses for its log extracts.

Quick summary

  • [field name] [operator] [text or numeric value]
  • common field names: senderImagePath, processImagePath, subsystem, eventMessage
  • common operators: ==, CONTAINS[c]
  • filter info: “text”
  • combine filters using AND, OR.

LogUI build 37 now has more power for browsing the log

By anyone’s standards, the macOS log contains a great many entries, and being able to filter out the noise is essential. This is accomplished by applying predicates to determine which entries are extracted and shown in a log browser like LogUI. However, using predicates requires knowledge about the log and its entries, and forms the greatest barrier for most users. This new version of LogUI improves features to help you use predicates to make the log more accessible.

This all happens in the toolbar of its browser window.

The section at the left of the lower row of tools now provides two methods to apply your own predicates: a one-off predicate editor, and an editor for custom entries in its popup menu.

One-off predicates

Click on the Set button to open the one-off predicate editor.

Here you can compose and paste in your own custom predicates that will extract only the log entries that you’re interested in. In this example, only entries whose subsystem is com.apple.duetactivityscheduler, or contains com.apple.xpc, will be gathered and displayed. Those tell you what’s going on with DAS and CTS scheduling and dispatch of background activities.

LogUI keeps that one-off predicate, even after a restart, as it’s automatically written to its preference file.

Once you’ve clicked Save, selecting the [ … ] item in the predicate menu will apply that predicate to each log extract you obtain.

There’s also an additional standard predicate using the senderImagePath.

Custom menu predicates

Predicates listed in that menu below blowhole are custom predicates saved to LogUI’s preferences using its new Predicate tab in its Settings. This editor is very basic at the moment, and its use a little awkward. This is because SwiftUI much prefers menu contents to be static, so adding items to the predicate menu doesn’t go down too well. This editor allows you to add one predicate at a time, in plain text format.

Click on the Append button here and there’ll be a new predicate named XProtect Remediator with the predicate shown. You can only add one new predicate, then need to quit the app before adding another. I’m sorry that’s so laborious, but once you have set up your custom predicates you can return to using LogUI fully.

The Settings General pane now contains a button to Reset Predicates back to their defaults.

Predicates

A basic predicate is composed of a log field name, like subsystem, followed by an operator such as == (equals) or CONTAINS[c] (case-insensitive contains), and a filter term, usually a string like "com.apple.xpc". So the predicate
subsystem CONTAINS[c] "com.apple.xpc"
will return all log entries with their subsystem containing the text com.apple.xpc. You can combine those basic elements into a more selective predicate using combinators such as AND and OR, so
subsystem == "com.apple.duetactivityscheduler" OR subsystem CONTAINS|c] "com.apple.xpc"
returns entries with a subsystem of precisely com.apple.duetactivityscheduler together with those whose subsystem contains the text com.apple.xpc.

Some years ago I wrote a primer here, and you’ll find some useful predicates in the Further Information section in the Help book for Mints. I’ll be writing more here to help you get the best out of LogUI.

There are a couple of oddities with predicates. SwiftUI tends to like using typographic double-quotation marks, but the macOS predicate builder doesn’t accept them as a substitute for straight marks. So LogUI changes all styled marks to straight ones automatically for you, to ensure those shouldn’t cause a problem. However, when it encounters errors it can behave erratically; while I’m trying to make this more robust, I apologise in advance if using a broken predicate upsets LogUI. It’s worth being careful to check your predicates before trying to use them.

LogUI version 1.0 build 37 is now available from here: logui137

My next task is to improve editing and saving predicates to its preferences, to make them accessible as menu customisations.

❌