I felt quite proud of myself for having finally tracked down entries about keychains in Sierra’s unified log. For if there’s one aspect of macOS which still causes a lot of users a lot of problems, its the keychain.

It doesn’t seem to matter what you choose in respect of keychains, whether to keep them locally or to put them in iCloud, sooner or later something will come along and start throwing lots of authentication dialogs at you. When that happens, it is very hard to discover what has gone wrong, and what you can do to return your Mac to normal.

Buried away in Sierra’s log is a clear account as to what is going on. com.apple.securityd, the main macOS security service, gives a running commentary on the use of keychains, with entries like
18:07:55.279195 0x7facca5314f0 opened /System/Library/Keychains/SystemRootCertificates.keychain: 385940 bytes
18:07:58.926898 0x7fbc055810c0 opened /Library/Keychains/System.keychain: 170992 bytes
18:08:09.174422 0x7f9aa2e277e0 opened /Library/Keychains/apsd.keychain: 50592 bytes
18:08:41.218261 0x7fee38517e20 opened /Users/hoakley/Library/Keychains/login.keychain-db: 1646112 bytes
18:08:41.251729 0x7fee38415460 opened /Users/hoakley/Library/Keychains/loginMPro.keychain-db: 549908 bytes
shortly after starting up, and thereafter.

One reason that these have been hard to spot is the fact that they are posted by com.apple.securityd, which often posts copiously. Digging through all its messages would take a great deal of time, particularly in the period following startup. There is also the inevitable lack of documentation, which was scant in the first place and hasn’t been properly revised for nine years, and the fact that it wasn’t easy to follow keychain activity in the old logs either.

Here at last was an opportunity to perform some automated log analysis which might reveal abnormal activity with keychains, which would be valuable both for the diagnosis of keychain problems, and possibly to watch for the sort of tricks that malware could get up to. You might even start wondering why smarter anti-malware software doesn’t do this already.

The next step was to see how this might have changed in High Sierra, and that was where it all came unstuck. Using Woodpile on Sierra’s logs, one easy way to pick up the opening of keychains was to look at the accountsd process, but trying that in High Sierra proved fruitless. I went back to looking first at com.apple.securityd, then showing all log entries.

In 10.12.6, filtering all log entries on the text keychain returned many hits, a few of which are highlighted above. The system and user keychains are recorded as being opened very frequently throughout the period following startup, particularly once the user has entered their password to unlock their main keychain.

In 10.13 and 10.13.1, there was just a single message
13:23:09.973440 Attempting to unlock login keychain "/Users/hoakley/Library/Keychains/login.keychain-db"

On other occasions when macOS unlocks a keychain, all that is now recorded in the log are entries such as
13:22:45.341882 SecKeychainOpen
which tell you nothing beyond the calling of the global function SecKeychainOpen.

Having now searched appropriate periods of High Serra logs from 10.13 and 10.13.1 on two different Macs, I have been unable to find any trace of the detailed messages which are posted in Sierra. In short, useful information about the opening of keychains has all but vanished from the logs in High Sierra.

In Unix and similar systems, logs are intended to support diagnostics and faultfinding, debugging, system management, and security auditing. In each of those cases, information about keychain unlocking and access is of signal importance. Reasons for removing messages from the log revolve around security and privacy concerns – neither of which apply here. In fact, security management and auditing are significantly enhanced by the inclusion of detailed messages about keychain access.

I therefore struggle to understand the reason for Apple removing detailed messages about keychain access from High Sierra’s log.

There is another possibility: that it happened in ignorance or error, when parts of securityd and its supporting services were being rewritten for High Sierra. There is some other evidence that this may be the explanation: most unusually for Apple, log messages about keychains contain a spelling error, of commited for committed. Such spelling errors indicate poor quality assurance, and can cause serious problems when searching log messages, for example. However, that spelling error is present in Sierra too.

When Apple detailed the new unified log to developers in June 2016, its stated goals included maximising the information collected while minimising observer effects, by wanting as much logging on all the time as possible. Little more than a year later, Apple is already stepping back from that, and removing log content which is of importance to macOS diagnostics, faultfinding, system management, security auditing, and security assessment.

It may seem like small print, but this is a big deal.