High Sierra is the first major system upgrade since macOS switched to its new unified log. Previous major upgrades have resulted in great changes in what gets written to the log, particularly during startup. This doesn’t appear to be the case with High Sierra, either the initial 10.13 release, or the update to 10.13.1. If you’re familiar with what happens in Sierra’s log, you shouldn’t get lost in High Sierra’s.

The most obvious change, of course, is the Darwin Kernel version declared shortly after startup. In 10.13, this should read
Darwin Kernel Version 17.0.0: Thu Aug 24 21:48:19 PDT 2017; root:xnu-4570.1.46~2/RELEASE_X86_64
and in 10.13.1
Darwin Kernel Version 17.2.0: Fri Sep 29 18:27:05 PDT 2017; root:xnu-4570.20.62~3/RELEASE_X86_64
To have gone from 17.0.0 to 17.2.0 in just a month seems quite a big step.

Early kernel log entries follow the familiar pattern seen in Sierra, for the greater part. High Sierra’s kernel does seem to post more messages than that in 10.12.6, which may indicate its relative immaturity. The chart above covers less than six minutes following startup.

One early and quite obvious change is the prominence of AppleCredentialManager. Although present in Sierra, it hasn’t normally written a great deal to the log, but in High Sierra you’ll see it initialise early with
17:26:16.122248 kernel[0]: (AppleCredentialManager) AppleCredentialManager: init: called, instance = <private>.
and then post frequent bursts of log messages thereafter.

APFS

If you have a volume formatted in APFS, particularly if you have started up from it, that is another new entrant worth watching out for. It doesn’t write a great deal to the log normally, but starts up along the lines of
17:26:16.538337 (apfs) apfs_module_start:1203: load: com.apple.filesystems.apfs, v748.21.6, 748.21.6, 2017/10/19
17:26:16.614816 (apfs) nx_kernel_mount:1366: checkpoint search: largest xid 11658, best xid 11658 @ 99
17:26:16.615179 (apfs) fusion_wbc_thread_shutdown:1130: Consider Fusion WBC Elevator thread of container E75DA4BD-DF38-465C-AFD4-45B096F39D29 dead
17:26:16.615576 (apfs) apfs_sysctl_register:675: done registering sysctls.
17:26:16.616992 BSD root: disk1s1
17:26:16.616996 , major 1, minor 4
17:26:16.617499 (apfs) apfs_vfsop_mountroot:1381: apfs: mountroot called! mp <private>, vp <private>
17:26:16.617726 (apfs) dev_init:238: device accelerated crypto: 0 (compiled @ Oct 19 2017 19:45:35)
17:26:16.617736 (apfs) dev_init:241: device_handle <private> block size 4096 block count 117161676 features 0 internal
17:26:16.617972 (apfs) nx_kernel_mount:1122: initializing cache w/hash_size 16384 and cache size 40960
17:26:16.644458 (apfs) nx_kernel_mount:1366: checkpoint search: largest xid 11658, best xid 11658 @ 99
17:26:16.645608 (apfs) sanity_check_alloced_blocks:145: fs_alloc_count mismatch: fs root nodes 119974 extent 5754 omap 1672 snap_meta 1 udata: 7584906 fs_alloc_count 8092682
17:26:16.645617 (apfs) er_state_obj_get_for_recovery:3683: No ER state object - rolling is not happening, nothing to recover.
The version number given here is the same as that included in the 10.13.1 update.

Later in the log, you may come across its rather odd habit of periodically mounting and unmounting the Preboot and Recovery volumes, with messages including
17:46:34.914989 (apfs) apfs_vfsop_mount:1368: mounted volume: Preboot
17:46:35.004483 (apfs) apfs_vfsop_mount:1368: mounted volume: Recovery
Note that those were a good 20 minutes after startup.

timed

The all-singing replacement for the NTPD time service, timed, also makes its presence known. It starts early with a series of messages such as
17:26:18.230506 [com.apple.timed.data] cmd,build,version,220,git,
17:26:18.230508 [com.apple.timed.data] cmd,process,pid,83
17:26:18.230607 [com.apple.timed.data] cmd,default,d,"com.apple.timed",k,"TMAutomaticTimeOnlyEnabled",v,"1"
17:26:18.230629 [com.apple.timed.data] cmd,default,d,"com.apple.timed",k,"NtpUseServicePort",v,"0"
17:26:18.230630 [com.apple.timed.data] cmd,start

The first time that it tries to get a time check with a network server, the network connection is unlikely to be ready to oblige, and that may have to be deferred until later during startup.

Then every 15 minutes, there’s another burst of messages from timed, which typically start with
15:41:11.527340 [com.apple.timed.data] cmd,fetchTime,num,0,result,0,mach,8305472478030,tv_sec,1509550871,tv_usec,119559,delay,0.816864,dispersion,0.001022,more,1,ip,17.253.54.125,port,123,attempts,0,slept,0,use_service_port,0
and have the following at their heart:
15:41:13.434783 [com.apple.timed.text] Received time Wed Nov 1 15:41:11 2017±0.41 from "NTP"
15:41:13.434789 [com.apple.timed.data] cmd,T,src,NTP,rtc_s,8305.472478030,rtc_unc_s,0.000000000,t_s,531243671.116733909,unc_s,0.406629201,mach,8305472478030
15:41:13.434824 [com.apple.timed.data] TDTF,SynthesizedClock,rtc,8305.472478,utc,531243671.435504,utcUnc,0.093793,sf,0.99996433,sfUnc,0.00001703,utcSfCov,0.00118655,logNoise,-13.555955,timeRtc,8305.472478,timeUtc,531243671.116734,timeUnc,0.406629,timeSource,NTP,timeQuality,4,filterQuality,4,predUtc,531243671.453417,predUtcUnc,0.096392,predSf,0.99996720,predSfUnc,0.00001740,measNumber,10

These suggest that timed is obtaining reference time from a network server far more frequently than with the traditional NTPD system does.

Keychains

The bad news for those with keychain problems is that accountsd no longer appears to post any useful messages about them, indeed that service seems to have become almost mute. The best candidate for looking for keychain access is with the process com.apple.securityd, but that posts a huge number of messages so you will need to apply a custom style with a filter, such as login, as shown below.

App Store

The App Store’s banner message declares a new version:
14:12:25.255126 [com.apple.commerce.CKLegacy] --------------------------------------------------------- Begin --

System Version 10.13.1 (Build 17B48)
“App Store” Version 2.3 (652)

——————————————————————-

AppleScript bugs

There are two buried warnings of potential AppleScript bugs when trying to script High Sierra’s Finder. In the words of the messages
.sdef warning for type 'unsigned integer' attribute 'id' of class 'window' in suite 'Window classes': AppleScript ID references may not work for this property because its type is not NSNumber- or NSString-derived.
.sdef warning for type 'elsv' attribute 'name' of class 'column' in suite 'Type Definitions': AppleScript name references may not work for this property because its type is not NSString-derived.

Mobile Time Machine’s snapshots

Neither of my High Sierra systems has had Time Machine turned on. Every hour, though, they still check local snapshots thus:
15:25:59.006920 [com.apple.TimeMachine.TMLogInfo] Not starting scheduled Time Machine backup: Automatic backups disabled
15:25:59.317468 [com.apple.TimeMachine.TMLogInfo] Starting age based thinning of Time Machine local snapshots on disk '/'
15:25:59.339698 [com.apple.TimeMachine.TMLogInfo] Completed thinning of Time Machine local snapshots on disk '/' in 0.0 seconds - current free space: 436.92 GB (436,915,159,040 bytes), target free space: 26.84 GB (26,843,545,600 bytes), initial free space: 436.92 GB (436,915,159,040 bytes), urgency: 2, remaining snapshots: {(
"com.apple.TimeMachine.2017-10-31-190653",
"com.apple.TimeMachine.2017-11-01-135916"
)}
This confirms that these local snapshots are removed when they age, although there is no indication as to how long they are kept for.

Occasionally, macOS makes a snapshot with
13:59:16.832115 [com.apple.TimeMachine.TMLogInfo] Created Time Machine local snapshot with name 'com.apple.TimeMachine.2017-11-01-135916' on disk '/'
which is buried in the middle of elaborate claim messages from com.apple.foundation.filecoordination.claims. I am unsure as to what exactly triggered the need for such a snapshot to be made.

Scheduling and dispatch

The DAS scheduling and dispatch system (which suffered a serious bug in Sierra) has changed. If you look for the process DuetHeuristic-BM, which carried most of its messages in Sierra, you will not see any messages at all. Look instead for com.apple.duetactivityscheduler or DuetActivityScheduler and you will see it managing its lists of activities, and calling them off when their score reaches its threshold.

The chart above shows DAS log entries over a period of 4.5 hours following a startup.

In contrast, XPC/CTS remains accessible through the same process names as in Sierra, and records very similar messages to those in 10.12.6.

Bugs and errors

High Sierra seems to suffer an old affliction, which has plagued most older releases of OS X. Some installations are prone to sending torrents of messages about mdworker problems. In my case, in some sessions, once everything was up and running, there would be bursts of over one million identical log messages in the course of 20 minutes, reading
17:27:44.575985 (Sandbox) Sandbox: mdworker(656) deny(1) system-fsctl 4a0e

It’s unclear why these should occur in such huge batches.

The other worrying feature which I have come across are bursts of messages about Bluetooth. El Capitan and Sierra have been plagued by Bluetooth bugs, which have ranged from audio breakup to spontaneous disconnect-reconnect cycles. These repeated message sequences could be encouraging, or an indication that problems will continue. They typically include messages such as
17:36:44.723856+0000 (IOUSBHostFamily) 000660.451802 Bluetooth USB Host Controller@fa113000: IOUSBHostDevice::updateIdlePolicyGated: consensus idle policy timeout 500ms
17:36:44.723889+0000 (IOUSBHostFamily) 000660.451835 BRCM20702 Hub@fa110000: IOUSBHostDevice::updateIdlePolicyGated: consensus idle policy timeout 0ms
17:36:45.830799+0000 (IOUSBHostFamily) 000661.558717 Bluetooth USB Host Controller@fa113000: IOUSBHostDevice::forcePowerGated: kPowerStateSuspended timeout 1000ms

I hope that these provide useful insight into what has changed in High Sierra, and what to expect when you browse its log. All exploration was performed using Woodpile (from Downloads above), on logs from an old MacBook Air and an iMac17,1.