Maybe the log isn’t the most obvious place to look for wit or wisdom, but over the past week I’ve been savouring some of its high points. Here’s a selection of some of the best and worst moments since macOS switched to its Unified log in Sierra, just over ten years ago.

Password in High Sierra

From the outset, the new log censored some content to preserve security and privacy, but the rules proved too complicated for some of Apple’s engineers. When APFS was released in High Sierra 10.13, one of those working on Disk Utility wasn’t aware that the calls made to create a new encrypted APFS volume were repeated in full in the log, such as
diskmanagement: execve(2) pid=583 /System/Library/Filesystems/hfs.fs/Contents/Resources/newfs_hfs -J -v transit /dev/rdisk3s2
diskmanagement: execve(2) pid=608 /System/Library/Filesystems/apfs.fs/Contents/Resources/newfs_apfs -C disk3s2
diskmanagement: execve(2) pid=628 /System/Library/Filesystems/apfs.fs/Contents/Resources/newfs_apfs -i -E -S thisisthepassword -v transit disk4s1
where thisisthepassword was the full password entered by the user, revealed in plain text. As this was one of several security gaffes discovered in 10.13, it wasn’t fixed until the update to 10.13.4, six months later.

As a result, Apple changed the log to make string formatting for censorship more transparent, and censorship more extensive. If you’re unlucky now, you could find the only content in the log entry you’ve been looking for is <private>.

StarCraft in Catalina

RunningBoard was introduced to macOS in Catalina. What few knew at the time were the references made in its copious log entries to the StarCraft video game. These appeared when the new subsystem was being initialised and started up during boot, when it wrote
2.504005 RunningBoardServices Initializing connection
2.504438 RunningBoardServices Removing all cached process handles
2.505247 RunningBoardServices Creating connection to com.apple.runningboard
2.517294 RunningBoard Battlecruiser operational.

Its entries were also colourful later on. Each time an app it had been tracking exited, whether through user choice or because it had been killed, its log entries included
[executable<SilentKnight(501)>:579] Death sentinel fired!

Its partner LaunchServices has also been prone to dramatic language. When it created a pending app with a new LSApplication object, it looked on the bright side and wrote
com.apple.launchservices DEATH: Expecting to hear about the death of app App:"AsmAttic" asn:0x0-5b05b pid:3083 refs=4 @ 0x55402ae00, adding to sRunningBoardDeathNotificationsSetRef (pid=3083}.
com.apple.launchservices DEATH: Listening for death via runningboard notification for pending application, pid=3083.

More recently, RunningBoard has assumed that responsibility, and you can still read similar foreboding today.

MobileMe lives on in iCloud

Log entries also contain glimpses into Mac history.

MobileMe was the successor to Apple’s .Mac internet service, was released on 9 July 2008 and replaced by iCloud only three years later, on 12 October 2011. It was a misadventure that drew a spate of negative reviews and incurred the wrath of Steve Jobs. But it lives on today in iCloud, in the name of the service that splits files into packets of the right size for transfer to iCloud, MobileMe Chunking Service, MMCS. When that starts up to chunk a file for transfer, it writes
Created mmcs engine (0xaaf203f00) 'com.apple.CloudKit/(null)' com.apple.Dataclass.CloudKit DebugLevel:0

At least MobileMe did get something right.

Huzzah for the clicks

Writing to the log is usually a chore, but Apple’s engineers sometimes try to brighten up their entries.

Just recently, I came across AppKit counting clicks in a Finder window, and loving every moment, in
0.438148 [0x7cc7952a00 _mouseUp] A new Click, huzzah! count:1 needed:1
0.438148 [0x7cc7952a00 _mouseUp] correct number of clicks - SUCCESS
0.438163 [0x7cc7953000 _mouseUp] A new Click, huzzah! count:1 needed:2
0.438178 [0x7cd04a9000 _mouseUp] A new Click, huzzah! count:1 needed:1
0.438178 [0x7cd04a9000 _mouseUp] correct number of clicks - SUCCESS

What strikes me as odd, though, is the fact that I only made a single click to get those three huzzahs.

Logging by numbers in APFS

Some engineering teams write log entries according to strict rules. Among the more significant are those for APFS, whose message fields have a standard structure, containing a descriptive name, a task-specific identity number, and a description of the activity and results.

For example, a Trim performed by the APFS Space Manager might write
09.823034 spaceman_trim_free_blocks:4149: disk5 scan took 1.099817 s, trims took 1.087611 s
09.823046 spaceman_trim_free_blocks:4153: disk5 424953800 blocks free in 50405 extents, avg 8430.78
09.823048 spaceman_trim_free_blocks:4162: disk5 424953800 blocks trimmed in 50405 extents (21 us/trim, 46344 trims/s)
09.823049 spaceman_trim_free_blocks:4165: disk5 trim distribution 1:40027 2+:8815 4+:1416 16+:18 64+:12 256+:117
09.823050 spaceman_trim_free_blocks:4173: disk5 trims dropped: 51774 blocks 44663 extents, avg 1.15
09.823053 spaceman_fxc_print_stats:475: disk5 smfree 424953813/488327436 table 1988/1989 blocks 424893923 3:213729:421098016 99.98% range 73199:488254237 99.98% scans 1

Fine style in FileProvider

FileProvider is a relatively new framework supporting cloud services including iCloud Drive. Recognising how formidable its log records could be, its engineers have adopted a systematic approach to make them more readable. Their style makes good use of emoji and box-drawing Unicode characters to structure entries, although it also uses a shorthand that outsiders will find opaque. These are illustrated in the sequence of messages below.

┏2efc9 👁 processing FS tree changes
item changed <i:fileID(330653) p:root n:”c{17}s” dir child:38 m:rwx ct:1592901530.4333313 mt:1792260976.1418219 xa:c{1}m.a{3}e.f{2}s.f{4}d:{12} sver:root/c{17}s cver:330653>
✍️ FS snapshot mutation: update<s:fileID(330653) p:root n:”c{17}s/” dir child:38 m:rwx ct:1592901530.4333313 mt:1792260976.1418219 xa:c{1}m.a{3}e.f{2}s.f{4}d:{12} v:sver:root/c{17}s cver:330653> diffs:mtime|nchildren why:item changed
┏2efca ⚙️ reconciling: ⬆︎ <fs:⏯ fileID(330653) fields:mtime content:watch sver:root/c{17}s cver:330653> <-> <fp:✅ a1 content:watch sver: cver:> dir sched:utility#1792260976.353611 rank:<s:1792154500921974016 c:max> <spec:isNotIndexable>⏳
✍️ reconciliation update: <fs:▶️ fileID(330653) content:watch sver:root/c{17}s cver:330653> <-> <fp:✅ a1 content:watch sver: cver:> dir sched:utility#1792260976.353611 rank:<s:1792154500921974016 c:max> <spec:isNotIndexable>⏳
✍️ persist job: <J1 ⏳ update-item(propagated:<fileID(330653) dbver:14 domver:<nil>> diffs:mtime) why:itemChangedRemotely sched:utility#1792260976.353611 ⧗persisted>
┗2efca

FileProvider also uses an ingenious system to work around privacy protection, and avoid having to censor entries. Rather than give directory and file names in full, it omits all but the first and last characters, and gives the count of characters omitted in curly brackets, for example showing “c{17}s” for com~apple~CloudDocs.

Happy log reading!