Q: Open Directory server node/module offline at workstation
Hello--
The last two mornings I've come to my SOHO desk and found a surprise: my primary workstation (2013 Mac Pro/16G RAM/OS X 10.11.6) won't do anything with the password (yes, the correct one!) I gave it to unlock the screen. It thinks about it for a couple of minutes, but then simply returns the password prompt. the prompt didn't shake at me .
I poked around in the logs, and using odutil show nodenames, I discovered the server node /LDAPv3/server.domain.tld is present in the list, but not showing as online. /Contacts, /LDAPv3, /Local/Default and /Search are all online. Trying to connect to the server using dscl failed.
Yesterday I tried odutil reset cache without obvious luck, but about the same time I also issued an su to another network user account on the workstation. Somewhere near this time, /LDAPv3/server.domain.tld came back online. Although I got logged in, things still seemed a little work and I rebooted the machine. After that, things seemed to work fine.
This morning, resetting the cache and using su to another account did not seem to have any affect. I rebooted the machine and started looking more at logs. There are many entries in system.log that seem to confirm the idea that the directory service from my server is not available, so I focused on opendirectoryd.log. The start up sequence on the workstation consistently gets logged with these entries:
2016-08-23 10:00:09.830103 CDT - AID: 0x0000000000000000 - opendirectoryd (build 406.10.1) launched... 2016-08-23 10:00:09.834208 CDT - AID: 0x0000000000000000 - Logging level limit changed to 'error' 2016-08-23 10:00:09.855424 CDT - AID: 0x0000000000000000 - Initialize trigger support 2016-08-23 10:00:10.016139 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/SystemCache.bundle' 2016-08-23 10:00:10.027722 CDT - AID: 0x0000000000000000 - Registered node with name '/Active Directory' as hidden 2016-08-23 10:00:10.027918 CDT - AID: 0x0000000000000000 - Registered node with name '/Configure' as hidden 2016-08-23 10:00:10.029216 CDT - AID: 0x0000000000000000 - Discovered configuration for node name '/Contacts' at path '/Library/Preferences/OpenDirectory/Configurations//Contacts.plist' 2016-08-23 10:00:10.029227 CDT - AID: 0x0000000000000000 - Registered node with name '/Contacts' 2016-08-23 10:00:10.029468 CDT - AID: 0x0000000000000000 - Registered node with name '/LDAPv3' as hidden 2016-08-23 10:00:10.031059 CDT - AID: 0x0000000000000000 - Registered node with name '/Local' as hidden 2016-08-23 10:00:10.031796 CDT - AID: 0x0000000000000000 - Registered node with name '/NIS' as hidden 2016-08-23 10:00:10.032018 CDT - AID: 0x0000000000000000 - Discovered configuration for node name '/Search' at path '/Library/Preferences/OpenDirectory/Configurations//Search.plist' 2016-08-23 10:00:10.032031 CDT - AID: 0x0000000000000000 - Registered node with name '/Search' 2016-08-23 10:00:10.034756 CDT - AID: 0x0000000000000000 - Discovered configuration for node name '/LDAPv3/server.domain.tld' at path '/Library/Preferences/OpenDirectory/Configurations/LDAPv3/server.domain.tld.plist' 2016-08-23 10:00:10.034793 CDT - AID: 0x0000000000000000 - Registered subnode with name '/LDAPv3/server.domain.tld' 2016-08-23 10:00:10.038333 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/legacy.bundle' 2016-08-23 10:00:10.043725 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/search.bundle' 2016-08-23 10:00:10.049433 CDT - AID: 0x0000000000000000 - '/Search' has registered, loading additional services 2016-08-23 10:00:10.049439 CDT - AID: 0x0000000000000000 - Initialize augmentation support 2016-08-23 10:00:10.052150 CDT - AID: 0x0000000000000000 - Successfully registered for Kernel identity service requests 2016-08-23 10:00:10.052162 CDT - AID: 0x0000000000000000 - Adjusting kernel ID cache (100 -> 250) and membership cache (100 -> 500) 2016-08-23 10:00:10.066338 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/PlistFile.bundle' 2016-08-23 10:00:10.071049 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/FDESupport.bundle' 2016-08-23 10:00:10.083450 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/AppleID.bundle' 2016-08-23 10:00:10.084563 CDT - AID: 0x0000000000000000 - Registered subnode with name '/Local/Default' 2016-08-23 10:00:10.094358 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/ldap.bundle' 2016-08-23 10:00:10.116316 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/AppleODClientLDAP.bundle' 2016-08-23 10:00:10.122047 CDT - AID: 0x0000000000000000 - Loaded bundle at path '/System/Library/OpenDirectory/Modules/AppleODClientPWS.bundle' 2016-08-23 10:00:15.717526 CDT - AID: 0x0000000000000000 - 338.721 - Client: SecurityAgent, UID: 92, EUID: 92, GID: 92, EGID: 92 2016-08-23 10:00:15.717526 CDT - AID: 0x0000000000000000 - 338.721, Module: SystemCache - entry user tim@/LDAPv3/server.domain.tld (0x7fc21f001420) is missing libinfo data (possible network directory issue) 2016-08-23 10:00:15.724369 CDT - AID: 0x0000000000000000 - 338.728 - Client: SecurityAgent, UID: 92, EUID: 92, GID: 92, EGID: 92 2016-08-23 10:00:15.724369 CDT - AID: 0x0000000000000000 - 338.728, Module: SystemCache - entry user tim@/LDAPv3/server.domain.tld (0x7fc21f001420) is missing libinfo data (possible network directory issue)
Please note the last four lines. These appear each startup even though I first log in using a separate local admin account (i.e., did not first log in with the normal user credentials). I interpret this to mean the error is from the local cache (which, using odutil reset cache, I've reset multiple times) -- is this a correct interpretation?
I also have ready access to a MBP and a MB, albeit primarily with local admin accounts. The MBP open directory startup sequence generally matches what I've shown above but stops before the last four lines. The MB shows the bundles loaded, and then intermittently has thrown this to the log:
2016-08-23 13:00:35.485168 CDT - AID: 0x0000000000000000 - 33434.2626406 - Client: ManagedClient, UID: 0, EUID: 0, GID: 0, EGID: 0 2016-08-23 13:00:35.485168 CDT - AID: 0x0000000000000000 - 33434.2626406, Node: /Local/Default - module configuration missing
However, there has not been any problems with login by that user. Should I interpret this to further isolate the problem to my Mac Pro or my personal account?
I had rebooted the server two days ago. Here is a short snap shot from the LDAP log at the start up:
Aug 21 15:34:29 server slapd[311]: @(#) $OpenLDAP: slapd 2.4.28 (Oct 3 2015 17:40:09) $ root@osx201.apple.com:/Library/Caches/com.apple.xbs/Binaries/OpenLDAP/OpenLDAP-510.30~3/Objects/servers/slapd Aug 21 15:34:29 server slapd[311]: daemon: SLAP_SOCK_INIT: dtblsize=8192 Aug 21 15:34:31 server slapd[311]: TLS: OPENDIRECTORY_SSL_IDENTITY identity preference overrode configured olcTLSIdentity "APPLE:server.domain.tld" Aug 21 15:34:31 server slapd[311]: slap_add_listener: opened additional listener 'ldaps:///' Aug 21 15:34:31 server slapd[311]: bdb_monitor_db_open: monitoring disabled; configure monitor database to enable Aug 21 15:34:31 server slapd[311]: slapd starting Aug 21 15:34:31 server slapd[311]: daemon: posting com.apple.slapd.startup notification Aug 21 15:34:38 server slapd[311]: SASL [conn=1033] Failure: client evidence does not match what we calculated. Probably a password error Aug 21 15:34:45 server slapd[311]: connection_input: conn=1027 deferring operation: awaiting write Aug 21 15:34:50: --- last message repeated 1 time --- Aug 21 15:34:50 server slapd[311]: connection_input: conn=1017 deferring operation: awaiting write Aug 21 15:35:02: --- last message repeated 8 times --- Aug 21 15:35:02 server slapd[311]: => bdb_idl_insert_key: c_put id failed: DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock (-30994) Aug 21 15:35:02 server slapd[311]: conn=1142 op=3: attribute "entryCSN" index add failure Aug 21 15:35:02 server slapd[311]: => bdb_idl_delete_key: c_get failed: DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock (-30994) Aug 21 15:35:02 server slapd[311]: conn=1142 op=4: attribute "entryCSN" index delete failure Aug 21 15:35:57 server slapd[311]: => bdb_idl_delete_key: c_get failed: DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock (-30994) Aug 21 15:35:57: --- last message repeated 1 time --- Aug 21 15:35:57 server slapd[311]: conn=1198 op=3: attribute "entryCSN" index delete failure Aug 21 15:35:57 server slapd[311]: conn=1198 op=4: attribute "entryCSN" index delete failure Aug 21 15:35:57 server slapd[311]: => bdb_idl_delete_key: c_get failed: DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock (-30994) Aug 21 15:35:57 server slapd[311]: conn=1220 op=4: attribute "entryCSN" index delete failure Aug 21 15:35:57 server slapd[311]: => bdb_idl_delete_key: c_get failed: DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock (-30994) Aug 21 15:35:57 server slapd[311]: conn=1220 op=3: attribute "entryCSN" index delete failure Aug 21 15:35:58 server slapd[311]: => bdb_idl_delete_key: c_get failed: DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock (-30994) Aug 21 15:35:58: --- last message repeated 1 time --- Aug 21 15:35:58 server slapd[311]: conn=1242 op=4: attribute "entryCSN" index delete failure Aug 21 15:35:58 server slapd[311]: conn=1242 op=3: attribute "entryCSN" index delete failure Aug 21 15:35:59 server slapd[311]: => bdb_idl_insert_key: c_put id failed: DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock (-30994) Aug 21 15:35:59 server slapd[311]: conn=1264 op=3: attribute "entryCSN" index add failure Aug 21 15:35:59 server slapd[311]: => bdb_idl_delete_key: c_get failed: DB_LOCK_DEADLOCK: Locker killed to resolve a deadlock (-30994) Aug 21 15:35:59 server slapd[311]: conn=1264 op=4: attribute "entryCSN" index delete failure
While I do not like seeing repeating errors in a log, I've not come across confirmation that these errors are anything but spurious Apple noise.
But I'm still searching and if anyone has any ideas/next steps, I'd appreciate the help.
Thank you.
Tim
Message was edited by: tim.rohrer Added a bit of additional error interpretation.
Mac Pro, OS X El Capitan (10.11.6), Primary workstation
Posted on Aug 23, 2016 1:19 PM