Big Sur 11.1: bug in log show command affecting Ulbow and Consolation

If something is going wrong when your Mac starts up, there’s a limited range of tools available. Among the most important is the unified log, accessed using the log show command or either of my free log browsers Ulbow or Comsolation 3. The latter apps both use the log show command internally, before they work their magic with JSON-formatted log extracts.

There’s a bug in the log show command in macOS 11.1, affecting at least M1 models, which makes it very hard – at times apparently impossible – to examine the log entries during boot. I’ll illustrate this using the log show command, where it’s most obvious.

Let’s say my M1 Mac started to boot at around 15:03:15. To observe what happens in log entries made during that boot, I might use the command
log show --start '2021-01-30 15:03:11' --end '2021-01-30 15:03:50'
which I’d expect to capture the first entry, and all those in the following 35 seconds or so, probably several thousand. What I actually get is:
Skipping info and debug messages, pass --info and/or --debug to include.
Timestamp Thread Type Activity PID TTL
2021-01-30 15:03:15.451904+0000 0x0 Timesync 0x0 0 0 === system boot: [UUID]
--------------------------------------------------------------------------------------------------------------------
Log - Default: 0, Info: 0, Debug: 0, Error: 0, Fault: 0
Activity - Create: 0, Transition: 0, Actions: 0

That’s the first banner announcement of the start of the boot sequence === system boot: and then no further entries, which would appear very worrying. In fact, there are thousands of log entries which should have been shown, but log show is omitting. Change the command to look at just the last second of that time period
log show --start '2021-01-30 15:03:49' --end '2021-01-30 15:03:50'
and this is the start and end of what’s returned:
Skipping info and debug messages, pass --info and/or --debug to include.
Timestamp Thread Type Activity PID TTL
2021-01-30 15:03:49.001155+0000 0x162a Activity 0x361b 643 0 fileproviderd: (libsystem_containermanager.dylib) container_create_or_lookup_app_group_path_by_app_group_identifier
2021-01-30 15:03:49.001164+0000 0x162a Default 0x361a 643 0 fileproviderd: (libsystem_containermanager.dylib) [com.apple.containermanager:unspecified] container_create_or_lookup_app_group_path_by_app_group_identifier: success

2021-01-30 15:03:49.999781+0000 0x15e6 Activity 0x48d8 279 0 fseventsd: (libsystem_info.dylib) Resolve user group list
--------------------------------------------------------------------------------------------------------------------
Log - Default: 2,816, Info: 0, Debug: 0, Error: 304, Fault: 5
Activity - Create: 481, Transition: 0, Actions: 0

That’s over 3,000 log entries in that second alone which were omitted from the result for the first command.

To examine the boot sequence in an M1 Mac running macOS 11.1, you have to perform two separate commands:

  • the first, with a --start just before the start of boot, which will only return the first banner announcement, and nothing else;
  • the second, with a --start after the start of boot but before the next log entry, will then return the rest of the entries.

If you’re using Ulbow or Consolation 3, this is even simpler, of course, because you can examine a period which you know will include the start of boot, obtain that entry, then set the next period to cover the time after the first. Provided of course that you know about this bug. When you don’t, it’s truly infuriating trying to get entries which you know exist, but keep drawing a blank.

With macOS 11.2 due out any day this coming week, I don’t intend reporting this yet. But if it still exists in 11.2, I will be letting Apple know through Feedback.