There are only two ways to browse Sierra’s unified log during logging in and logging out: you can capture a logarchive using the command log
in Terminal, or using Consolation (free from Downloads above). Apple’s Console utility is only useful if you have already captured a logarchive from the command line. In my case, I saved a logarchive using Consolation, and browsed that archive in the same app.
All log entries are for Sierra 10.12.6 running on an iMac17,1. Earlier versions of Sierra may well differ in log entries.
Predicates and filters
Two useful predicates to have ready when looking at these activities are:
processImagePath CONTAINS[c] "com.apple.AccountPolicyHelper"
which picks up messages from AccountPolicyHelper, which handles parts of authentication but surprisingly doesn’t yet have its own subsystem, and
subsystem == "com.apple.securityd"
which looks at a large chunk of security-related entries, and will almost invariably need refining with a filter.
Although you may want to develop your own more refined filter terms, the following are a good start:
authentication
authenticationallowed
verify password
login.keychain-db:
and the short usernames for that Mac. login.keychain-db:
(including the end colon) is useful because it picks up attempts to open the login keychain for any user.
Logging out
There aren’t many clear signposts to the processes involved in logging out, other than a long succession of systems being exited and connections being severed. If you have Objective-See’s What’s Your Sign, it makes a distinctive entry, following which there are other signs of this phase completing:
WhatsYourSign Foundation tearing down extension context
opendirectoryd opendirectoryd Client: <private>, UID: 0, EUID: 0, GID: 0, EGID: 0
com.apple.useractivity main useractivityd useractivityd Removing client <private>, application [pid=396/397 uid=501/501 gid=20/20 asid=100008 sb=YES], from known userActivityClients.
opendirectoryd opendirectoryd ODNodeRelease completed
opendirectoryd opendirectoryd disconnect module connection
opendirectoryd opendirectoryd ODNodeRelease completed
opendirectoryd opendirectoryd Client: <private>, UID: 0, EUID: 0, GID: 0, EGID: 0
loginwindow loginwindow Login Window point of no return
com.apple.sharing AutoUnlock loginwindow Sharing Dynamic store enabled state {
501 = 0;
}
In among the messages you may find
loginwindow loginwindow -[LogoutUtilities terminateApp:] | ERROR | Application terminate returned 1
And later, the more puzzling logout entries
com.apple.AccountPolicyHelper com.apple.AccountPolicyHelper (115.43.2) AuthenticationAllowed completed: record "hoakley", result: Success (0).
opendirectoryd opendirectoryd Verify password result: 5000
opendirectoryd opendirectoryd ODRecordVerifyPassword failed with error 'Invalid credentials' (5000)
sessionlogoutd loginsupport sessionlogoutd Launched
which record the logout with an error 5000, which means the Open Directory credentials were invalid!
As everything else is packing up and going home, the new login window is started up:
loginwindow loginwindow Login Window Application Started
Logging in
Even when the login window is displayed, waiting for you to enter your password, the log is not quiet. Eventually you’ll come across a pair of entries like
com.apple.AccountPolicyHelper com.apple.AccountPolicyHelper (115.60.2) AuthenticationAllowed completed: record "hoakley", result: Success (0).
opendirectoryd opendirectoryd ODRecordAuthenticationAllowed completed
which mark the login point.
But they are not done yet: this is repeated several times a little later:
com.apple.AccountPolicyHelper com.apple.AccountPolicyHelper (115.63.2) AuthenticationAllowed completed: record "hoakley", result: Success (0).
opendirectoryd opendirectoryd Verify password result: 0
You may also see failures, such as
com.apple.AccountPolicyHelper com.apple.AccountPolicyHelper (115.66.2) AuthenticationAllowed completed: record "hoakley", result: Success (0).
opendirectoryd opendirectoryd Verify password result: 5000
opendirectoryd opendirectoryd ODRecordVerifyPassword failed with error 'Invalid credentials' (5000)
Eventually, the login window reports:
SecurityAgent loginsupport Login Window login proceeding
Later,
loginwindow loginwindow Login Window - Returned from Security Agent
A clear sign is changing status for user ID 501, as in
apsd CoreDaemon <APSSystemUser: 0x7f81cfe52340>: Changing status for uid 501 from logged out to logged in
Finally, the login keychain is opened (again, multiple times):
com.apple.securityd atomicfile loginwindow Security 0x61000007bd40 opened /Users/hoakley/Library/Keychains/login.keychain-db: 1572200 bytes
com.apple.securityd KCLogin loginwindow Security SecKeychainLogin result: 0, password was supplied
From then on, you can watch macOS starting up the very many user activities.
Fast user switching
Landmark log entries when you change user by means of fast switching, rather than logging out and in again, are broadly similar. A good overview is obtained from using the predicate
processImagePath CONTAINS[c] "com.apple.AccountPolicyHelper"
although because this switches between users, you will then see entries referring to both the previous and the next users, such as:
com.apple.AccountPolicyHelper com.apple.AccountPolicyHelper (115.72.2) AuthenticationAllowed completed: record "tester", result: Success (0).
com.apple.AccountPolicyHelper com.apple.AccountPolicyHelper (115.73.2) PasswordChangeAllowed completed: record "tester", result: Success (0).
com.apple.AccountPolicyHelper com.apple.AccountPolicyHelper (115.74.2) PasswordChangeAllowed completed: record "hoakley", result: Success (0).
com.apple.AccountPolicyHelper com.apple.AccountPolicyHelper (115.75.2) AuthenticationAllowed completed: record "hoakley", result: Success (0).
You will then find it helpful to apply filters based on the user names.
As with logout and login, simply applying the predicate
subsystem == "com.apple.securityd"
will return a large number of entries, but filtering them with login.keychain-db:
quickly shows login keychain activity.
AccountPolicyHelper serials
Apply the predicate
processImagePath CONTAINS[c] "com.apple.AccountPolicyHelper"
and you should notice a striking and potentially very useful feature: messages from AccountPolicyHelper start with a serial number, of the form
(115.123.2)
where the middle number, here 123, increments with each new message from AccountPolicyHelper. I do not know whether the first and third numbers change, or why they might change, but this serial number appears a good way of establishing that the log has not been tampered with, and the sequence of those entries irrespective of their timestamps.
If you have discovered anything further which is of use from these processes, please let us know in a comment below.