Starting up in Catalina: sequence and waypoints in the log

Many Mac problems occur at startup, or the seeds of disaster are sown then. There are limited tools available to investigate what might be going wrong during this critical time: by far the most powerful is the unified log.

Unfortunately, accessing the log using the bundled tool Console isn’t easy in this case, as it has no simple way to browse previous entries. To do that, you have to make a logarchive and browse that instead. In practice, the only way to examine what happened during any startup is using the log show command in Terminal, or in my free GUI utility Consolation 3.

Each major release of macOS brings changes to what is written to the log. Catalina is no exception: this article is based on the startup process in its first release version, 10.15, running on a MacBook Pro 2017 without a T1/T2 chip. Other models will be slightly different, as will subsequent releases of Catalina. However, the following main entries, which act as ‘waypoints’ when you’re trying to navigate the log, should be common to most. Clock times are given here in UTC+0100, as decimal seconds.

Most importantly, the first entry remains unchanged since mid-Sierra, and can be relied on when searching for startup:
59.000000 === system boot: [UUID]
So to search your log for the beginning of a startup, use the term “=== system boot:” in the log message field.

Immediately after that, the log system now notes that entries are being made in its in-memory stores, as the boot system storage isn’t yet available to it:
59.000000 === log class: in-memory begins

Shortly after that, you’ll see a record from the kernel of its version, build time, and other details
59.002612 Darwin Kernel Version 19.0.0: Wed Sep 25 20:18:50 PDT 2019; root:xnu-6153.11.26~2/RELEASE_X86_64

Appearing early during startup is the initialisation of Apple Credential Manager
59.437393 AppleCredentialManager: init: called, instance = <private>.

Policies for key security components are loaded very early too, for Apple Mobile File Integrity, which performs many of the most important checks on signatures for instance, Sandbox, which provides the app Sandbox and other key services, and Quarantine, which determines which files need full security checks:
59.454214 kernel calling mpo_policy_init for AMFI
59.454217 kernel Security policy loaded: Apple Mobile File Integrity (AMFI)
59.454220 kernel calling mpo_policy_init for Sandbox
59.454237 kernel Security policy loaded: Seatbelt sandbox policy (Sandbox)
59.454331 kernel calling mpo_policy_init for Quarantine
59.454334 kernel Security policy loaded: Quarantine policy (Quarantine)

Another important waypoint which appears soon after startup is the SMC’s statement of the previous shutdown cause. In this case it’s 5, which indicates it was ‘clean’, and performed at the user’s command:
59.588948 AppleSMC Previous shutdown cause: 5
My detailed guide to these cause codes is here.

As the Mac steadily comes to life, you’ll see the appearance of different systems being fully configured, here some Thunderbolt features:
59.662573 AppleThunderboltNHI AppleThunderboltGenericHAL::probe

Following policy initialisations, just over 1 second since starting up, further security systems are brought up for Gatekeeper and its components:
00.079930 AppleSystemPolicy Per file malware scanning is: enabled
00.079930 AppleSystemPolicy GK status: enabled
00.080007 kernel calling mpo_policy_init for ASP
00.080010 kernel Security policy loaded: Apple System Policy (ASP)
00.080038 AppleSystemPolicy AppleSystemPolicy has been successfully started

Although macOS has been accessing files stored on the startup volume already, it’s well over a second before the full might of APFS is engaged. As this log extract comes from 10.15 before the 10.15.1 update, the version of APFS given here is now out of date:
00.086582 apfs apfs_module_start:1683: load: com.apple.filesystems.apfs, v1412.11.7, apfs-1412.11.7, 2019/09/26
00.087858 apfs cryptoAlloc:671: Using 64 buffers with size 16384, 512 buffers size 65536

APFS encryption support is also being loaded at this stage.

This makes way for the traditional announcement of the root volume
00.098635 kernel BSD root: disk1s5
00.098636 kernel , major 1, minor 7

Log entries which have been present since the first version of Mac OS X.

APFS then gets on with the job of mounting volumes fully, starting with the root, here using the VFS file system which is based on inode numbers
00.098684 apfs apfs_vfsop_mountroot:1476: apfs: mountroot called!

New for Catalina is the Volume Group formed from the System and Data volumes. Here, APFS is setting the System volume role, and completing its mount process
00.105163 apfs nx_volume_group_update:6383: Set volume (role 0x1) to aa380 xid 0
00.105187 apfs apfs_vfsop_mount:1463: mounted volume: Macintosh HD

Mounting is also performed for the hidden VM volume
00.108700 attempting kernel mount for vm volume...
00.112546 kernel mounted VM volume

At around this stage, now approaching 3 seconds since startup, various system watchdogs are set up, with multiple cryptic log entries like
01.826772 watchdogd 3802596056: <private>

Preparations are made for user login too
01.829764 loginsupport logind started

Another major system which quickly comes to dominate log entries now is Open Directory, starting with
01.878180 opendirectoryd Initialize trigger support

From about 3 seconds after startup, the log is filling rapidly with many entries from different systems as they prepare the Mac for user login. It’s about now that you’ll normally see plenty of entries from the privacy protection system, TCC, which starts by checking its data files:
02.467355 tccd Override: watchPlistChanges: watching: /Library/Apple/Library/Bundles/TCC_Compatibility.bundle/Contents/Resources/AllowApplicationsList.plist
02.468263 tccd Override: loading from: /Library/Apple/Library/Bundles/TCC_Compatibility.bundle/Contents/Resources/AllowApplicationsList.plist
2019-10-11 10:23:02.483740+0100 Info 721 160 com.apple.TCC access tccd tccd starting as: com.apple.tccd.system; UID: 0

The sheer volume of log entries here makes it most important that you specify tight limits when calling for log extracts. It’s easy to end up with Consolation overburdened with hundreds of thousands of entries, which slows all its actions down and may give the impression that it has hung. Either use narrow time periods, of around 20 seconds, to view all log entries, or apply criteria in the form of predicates, which will limit the number of log entries you have to work with. This isn’t easy, but Consolation’s lengthy Help file contains many useful suggestions, and there are even more in articles here.

Happy browsing!