Bugs in the logs: Sierra’s new logging system is a game of chance

We tend to trust what is written in a log. Even though they’re not entered by hand in meticulous copperplate script, in the way a ship’s captain might have done, we assume that what we see in our Mac’s logs is a faithful reflection of events as they occurred. In many circumstances, the contents of the log may have important consequences: not only could we make diagnostic decisions on their basis, but log entries are used in forensic analysis as evidence of what happened, and when.

I’d like to show you two excerpts from the same log on the same Mac for the exact same period which may shake your faith in Sierra’s new logging system – or at least introduce the scepticism of quantum physics. Each row has been distilled from the original, and gives the time, the process number, the name of the process, and the message.

08:18:22.698632 112 opendirectoryd: ODQueryCreateWithNode completed 08:18:22.696430 112 opendirectoryd: ODQueryCreateWithNode completed 08:18:22.696497 112 opendirectoryd: (SystemCache) cache miss with id type: 0 08:18:22.696569 112 opendirectoryd: (SystemCache) cache miss with id type: 0 08:18:22.696647 112 opendirectoryd: <private> completed 08:18:22.930275 90818 backupd: (CoreFoundation) Sending Updated Preferences to System CFPrefsD 08:18:22.949815 378 SystemUIServer: (CoreFoundation) Loading Preferences From System CFPrefsD For Search List 08:18:22.949841 378 SystemUIServer: (CoreFoundation) Loading Preferences From User CFPrefsD For Search List 08:18:22.961416 90818 backupd: (TimeMachine) [com.apple.TimeMachine.TMLogInfo] Starting post-backup thinning 08:18:26.162290 210 trustd: [com.apple.securityd.policy] cert[2]: AnchorTrusted =(leaf)[force]> 0 08:18:26.162972 141 amfid: (Security) [com.apple.securityd.security_exception] CSSM Exception: -2147411889 CSSMERR_CL_UNKNOWN_TAG 08:18:26.162989 141 amfid: (Security) [com.apple.securityd.security_exception] CSSM Exception: -2147411889 CSSMERR_CL_UNKNOWN_TAG [same message repeated until] 08:18:26.163443 141 amfid: (Security) [com.apple.securityd.security_exception] CSSM Exception: -2147411889 CSSMERR_CL_UNKNOWN_TAG 08:18:26.163492 141 amfid: (Security) [com.apple.securityd.security_exception] MacOS error: -67050 08:18:26.163504 141 amfid: (Security) [com.apple.securityd.security_exception] MacOS error: -67050 08:18:45.663020 446 cloudd: (CloudKitDaemon) [Operation 0x7fe3ffd4bfa0] Initialized with context 0x7fe3ffda74f0. Background: 0, cellular: 1, QOS: 0x19 08:18:45.663124 446 cloudd: (CloudKitDaemon) [Operation 0x7fe3ffee8af0] Initialized with context 0x7fe3ffda74f0. Background: 0, cellular: 1, QOS: 0x19

08:18:22.700891 112 opendirectoryd: Client: <private>, UID: 0, EUID: 0, GID: 0, EGID: 0 08:18:22.701019 112 opendirectoryd: queuing request to connection - '<private>' 08:18:22.701174 112 opendirectoryd: queuing request to connection - '<private>' 08:18:22.698632 112 opendirectoryd: ODQueryCreateWithNode completed 08:18:22.685099 112 opendirectoryd: ODQueryCreateWithNode completed 08:18:22.685166 112 opendirectoryd: (SystemCache) cache miss with id type: 0 08:18:22.685238 112 opendirectoryd: (SystemCache) cache miss with id type: 0 08:18:22.685316 112 opendirectoryd: <private> completed 08:18:22.701999 112 opendirectoryd: <private> failed with error '<private>' (2) 08:18:22.748402 112 opendirectoryd: Client: <private>, UID: 0, EUID: 0, GID: 0, EGID: 0 08:18:22.748960 90881 diskmanagementd: (CoreFoundation) Loading Preferences From System CFPrefsD For Search List 08:18:26.160442 112 opendirectoryd: Client: <private>, UID: 0, EUID: 0, GID: 0, EGID: 0 08:18:26.160728 112 opendirectoryd: Client: <private>, UID: 0, EUID: 0, GID: 20, EGID: 20 08:18:26.161208 112 opendirectoryd: Client: <private>, UID: 501, EUID: 501, GID: 20, EGID: 20 08:18:26.196773 112 opendirectoryd: Client: <private>, UID: 501, EUID: 501, GID: 20, EGID: 20 08:18:26.203721 90882 blowhole: [co.eclecticlight.blowhole.general] Blowhole snorted!

The first log capture was made within a minute of the events being logged, and the second was made around five minutes later, covering the exact same time period. I had previously assumed that such oddities were the result of a bug in the log show command which retrieves entries from the log, but there is clear evidence here that this cannot be the sole cause. These sequences were extracted from showing all entries over a five minute period, and are from the middle of the capture, not the start or end.

Over this period, there is only one log entry which appears identically in the two different captures:
08:18:22.698632 112 opendirectoryd: ODQueryCreateWithNode completed

Four other entries, all from opendirectoryd, are identical in all respects but have different timestamps.

The first capture shows two important entries for Time Machine backup which are omitted from the second; the second shows a deliberate log entry made by a timed process run by launchd which is nowhere to be found in the first; the first capture contains a duplicated macOS error code from the security system which is omitted completely from the second. In fact, the two captures bear only a passing resemblance to one another, and have entirely different readings.

Which might be an accurate reflection of events in those seconds?

The explanation for this rests, I think, in three issues: the mechanism by which the new log operates, bug(s) in that mechanism, and quantum physics.

Traditional Unix log systems, as OS X had before Sierra, are fairly simple: a process writes out a message to a text log file, which eventually gets written to disk. That’s slow and resource-intensive, and cannot cope with the finely granular entries being made by macOS in Sierra.

To accelerate and refine the system, the log is held in memory as well as on disk. Many log entries, after compression, are written out to log files on disk, but some are kept only in memory. According to Apple, Info level entries are normally only retained in memory, but the more common Default level entries always go to disk. Depending on the rate at which log entries are being written, older Info entries should be aged out of memory and lost relatively quickly.

That doesn’t explain the disparities shown above, which occur at both Info and Default levels, as the later capture still shows abundant Info entries, establishing that those have not yet become old enough to be purged. It may explain how four of the entries changed time, though, and time sequence was lost in the later capture.

There are clearly bugs in the new logging system, which relate to the entries themselves (which should surely never change time), and their retrieval (log show command).

Quantum physics comes into play because the new log system makes such intense and sustained measurements of macOS, that those measurements may well be altering the behaviour of macOS – one of the well-known problems in quantum physics.

Do these issues render the new log system useless, or unfit for purpose?

Well, we now don’t have any serious alternative. If you need to study the logs, these are all there is in Sierra, apart from a few residual old-style logs which don’t record much of any use at all. But to get anything useful from the new log, you need the right tool (Consolation or log, not Console), skill in using that tool, and chance working in your favour.

3Comments

Add yours

1

jonbirge on July 14, 2018 at 4:07 pm

In addition to the log bugs, there’s the fact that while you get ludicrous levels of granularity on mundane junk, you don’t get ANY logs on critically important things like failed login attempts. Apple is really screwing up these days when it comes to security. They don’t seem to take anything seriously on the Mac OS X side. They seem more interested in crap like animojis. It’s embarrassing.

LikeLike
2

Paul on September 15, 2018 at 4:23 pm

You’re talking about the “observer effect.” The idea that methods of observation can influence what’s being observed. This is often confused with the Heisenberg Uncertainty Principle but doesn’t have anything whatsoever to do with it. It’s an everyday phenomenon, dealt with by physicists and social scientists long before the advent of quantum theory. The Heisenberg principle has nothing to do with observation, and it has nothing to do with anything large enough or slow enough to be observed in everyday reality.

LikeLiked by 1 person
- 3
  
  hoakley on September 15, 2018 at 4:58 pm
  
  Thank you.
  Yes, noting that I didn’t name Heisenberg (who I gather may have confused his own Principle in this respect) or his Uncertainty Principle, the effect to which I am referring is indeed commonly known as the Observer Effect. As I wasn’t practising science before 1927, I can’t attest to how well-known it was then, but it certainly attracted a great deal more attention with the advent of quantum mechanics.
  I’ll leave it to the log user to decide whether any of this is connected to “everyday reality”!
  Howard.
  
  LikeLike

Share this:

Like this:

Related