Looks like no one’s replied in a while. To start the conversation again, simply ask a new question.

User profile for user: Nextyoyoma
Nextyoyoma Author
User level: Level 1
15 points

AD user can't log in until local admin account logs in

I have one computer where the user intermittently cannot log in to their mobile AD account. When this occurs, logging into the local administrator account and then logging out allows the user the log in normally. The issue is difficult to reproduce, but when it occurs, there is always similar output in secure.log. Here is a sanitized excerpt from the log, showing where the user rebooted and was not able to log in after. After that, you can see where I logged in with a local administrator account, and rebooted after that.


Oct 15 09:58:20 JA-S1-10656 shutdown[4788]: reboot by <EXAMPLE-USER>:

Oct 15 09:58:50 localhost com.apple.SecurityServer[21]: Session 100000 created

Oct 15 09:58:50 JA-S1-10656 com.apple.SecurityServer[21]: Entering service

Oct 15 09:58:50 JA-S1-10656 com.apple.SecurityServer[21]: Succeeded authorizing right 'com.apple.ServiceManagement.daemons.modify' by client '/usr/libexec/UserEventAgent' [11] for authorization created by '/usr/libexec/UserEventAgent' [11]

Oct 15 09:58:47 JA-S1-10656 com.apple.SecurityServer[21]: Session 100005 created

Oct 15 09:58:47 JA-S1-10656 loginwindow[63]: Login Window Started Security Agent

Oct 15 09:58:47 JA-S1-10656 SecurityAgent[178]: Echo enabled

Oct 15 09:58:49 JA-S1-10656 SecurityAgent[178]: spawn_via_launchd() failed, errno=5 label=[0x0-0x8008].com.apple.AppleSpell path=/System/Library/Services/AppleSpell.service/Contents/MacOS/AppleSpell flags=0

Oct 15 09:58:52 JA-S1-10656 com.apple.SecurityServer[21]: Succeeded authorizing right 'system.preferences' by client '/System/Library/PrivateFrameworks/Admin.framework/Versions/A/Resources/writeco nfig' [486] for authorization created by '/usr/sbin/systemsetup' [485]

Oct 15 09:59:01 JA-S1-10656 SecurityAgent[178]: Could not get the user record from OpenDirectory.

Oct 15 09:59:01 JA-S1-10656 SecurityAgent[178]: Will sleep 3 seconds and try again (retryCount = 10)

Oct 15 09:59:04 JA-S1-10656 SecurityAgent[178]: Could not get the user record from OpenDirectory.

Oct 15 09:59:04 JA-S1-10656 SecurityAgent[178]: Will sleep 3 seconds and try again (retryCount = 9)

Oct 15 09:59:07 JA-S1-10656 SecurityAgent[178]: Could not get the user record from OpenDirectory.

Oct 15 09:59:07 JA-S1-10656 SecurityAgent[178]: Will sleep 3 seconds and try again (retryCount = 8)

Oct 15 09:59:11 JA-S1-10656 SecurityAgent[178]: Could not get the user record from OpenDirectory.

Oct 15 09:59:11 JA-S1-10656 SecurityAgent[178]: Will sleep 3 seconds and try again (retryCount = 7)

Oct 15 09:59:14 JA-S1-10656 SecurityAgent[178]: Could not get the user record from OpenDirectory.

Oct 15 09:59:14 JA-S1-10656 SecurityAgent[178]: Will sleep 3 seconds and try again (retryCount = 6)

Oct 15 09:59:17 JA-S1-10656 SecurityAgent[178]: User info context values set for <EXAMPLE-USER>

Oct 15 09:59:17 JA-S1-10656 SecurityAgent[178]: Unknown user "<EXAMPLE-USER> " login attempt PASSED for auditing

Oct 15 09:59:42 JA-S1-10656 SecurityAgent[178]: User info context values set for <EXAMPLE-USER>

Oct 15 09:59:42 JA-S1-10656 SecurityAgent[178]: Unknown user "<EXAMPLE-USER> " login attempt PASSED for auditing

Oct 15 11:16:06 JA-S1-10656 SecurityAgent[178]: Could not get the user record from OpenDirectory.

Oct 15 11:16:06 JA-S1-10656 SecurityAgent[178]: Will sleep 3 seconds and try again (retryCount = 10)

Oct 15 11:16:09 JA-S1-10656 SecurityAgent[178]: Could not get the user record from OpenDirectory.

Oct 15 11:16:09 JA-S1-10656 SecurityAgent[178]: Will sleep 3 seconds and try again (retryCount = 9)

Oct 15 11:16:12 JA-S1-10656 SecurityAgent[178]: Could not get the user record from OpenDirectory.

Oct 15 11:16:12 JA-S1-10656 SecurityAgent[178]: Will sleep 3 seconds and try again (retryCount = 8)

Oct 15 11:16:15 JA-S1-10656 SecurityAgent[178]: User info context values set for <EXAMPLE-USER>

Oct 15 11:16:15 JA-S1-10656 SecurityAgent[178]: Unknown user "<EXAMPLE-USER> " login attempt PASSED for auditing

Oct 15 11:16:17 JA-S1-10656 SecurityAgent[178]: User info context values set for <EXAMPLE-USER>

Oct 15 11:16:17 JA-S1-10656 SecurityAgent[178]: Unknown user "<EXAMPLE-USER> " login attempt PASSED for auditing

Oct 15 11:16:18 JA-S1-10656 SecurityAgent[178]: User info context values set for <EXAMPLE-USER>

Oct 15 11:16:18 JA-S1-10656 SecurityAgent[178]: Unknown user "<EXAMPLE-USER> " login attempt PASSED for auditing

Oct 15 11:16:20 JA-S1-10656 SecurityAgent[178]: User info context values set for <EXAMPLE-USER>

Oct 15 11:16:20 JA-S1-10656 SecurityAgent[178]: Unknown user "<EXAMPLE-USER> " login attempt PASSED for auditing


____________________________________________________________


At this point, I logged in as localadmin (local administrator account)


____________________________________________________________


Oct 15 11:16:25 JA-S1-10656 SecurityAgent[178]: User info context values set for localadmin

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_authenticate(): Got user: localadmin

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_authenticate(): Got ruser: (null)

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_authenticate(): Got service: authorization

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in od_principal_for_user(): No authentication authority returned

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in od_principal_for_user(): failed: 7

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_authenticate(): Failed to determine Kerberos principal name.

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_authenticate(): Done cleanup3

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_authenticate(): Kerberos 5 refuses you

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_authenticate(): pam_sm_authenticate: ntlm

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache TTL set to 1800.

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in od_record_check_pwpolicy(): retval: 0

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in od_record_attribute_create_cfstring(): returned 3 attributes for dsAttrTypeStandard:AuthenticationAuthority

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Establishing credentials

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Got user: localadmin

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Context initialised

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Got euid, egid: 0 0

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Done getpwnam()

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Done setegid() & seteuid()

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): pam_sm_setcred: krb5 user localadmin doesn't have a principal

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Done cleanup3

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Done seteuid() & setegid()

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): Done cleanup4

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): pam_sm_setcred: ntlm

Oct 15 11:16:25 JA-S1-10656 authorizationhost[660]: in pam_sm_setcred(): pam_sm_setcred: no domain found skipping

Oct 15 11:16:25 JA-S1-10656 SecurityAgent[178]: Login Window login proceeding

Oct 15 11:16:34 JA-S1-10656 com.apple.SecurityServer[21]: Succeeded authorizing right 'system.login.console' by client '/System/Library/CoreServices/loginwindow.app' [63] for authorization created by '/System/Library/CoreServices/loginwindow.app' [63]

Oct 15 11:16:34 JA-S1-10656 loginwindow[63]: Login Window - Returned from Security Agent

Oct 15 11:16:39 JA-S1-10656 com.apple.SecurityServer[21]: Succeeded authorizing right 'system.login.done' by client '/System/Library/CoreServices/loginwindow.app' [63] for authorization created by '/System/Library/CoreServices/loginwindow.app' [63]

Oct 15 11:17:01 JA-S1-10656 su[2203]: in pam_sm_authenticate(): authentication succeeded

Oct 15 11:17:01 JA-S1-10656 su[2203]: in pam_sm_acct_mgmt(): The root_only option means root only.

Oct 15 11:17:01 JA-S1-10656 su[2203]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache TTL set to 1800.

Oct 15 11:17:01 JA-S1-10656 su[2203]: in od_record_check_pwpolicy(): retval: 0

Oct 15 11:17:01 JA-S1-10656 su[2203]: in od_record_attribute_create_cfstring(): returned 3 attributes for dsAttrTypeStandard:AuthenticationAuthority

Oct 15 11:17:01 JA-S1-10656 su[2203]: in pam_sm_open_session(): No session type specified.

Oct 15 11:17:01 JA-S1-10656 su[2203]: in pam_sm_open_session(): Going to switch to (localadmin) 501's Background session

Oct 15 11:23:03 JA-S1-10656 com.apple.SecurityServer[21]: Session 100008 created

Oct 15 11:23:04 JA-S1-10656 shutdown[4030]: reboot by localadmin:

____________________________________________________________



At this point, I rebooted the machine and then logged in as the user successfully (the reboot was to try to reproduce the issue).


____________________________________________________________


Oct 15 11:23:04 JA-S1-10656 shutdown[4030]: reboot by localadmin:

Oct 15 11:23:15 localhost com.apple.SecurityServer[21]: Session 100000 created

Oct 15 11:23:15 JA-S1-10656 com.apple.SecurityServer[21]: Entering service

Oct 15 11:23:15 JA-S1-10656 com.apple.SecurityServer[21]: Succeeded authorizing right 'com.apple.ServiceManagement.daemons.modify' by client '/usr/libexec/UserEventAgent' [11] for authorization created by '/usr/libexec/UserEventAgent' [11]

Oct 15 11:23:22 JA-S1-10656 com.apple.SecurityServer[21]: Session 100005 created

Oct 15 11:23:22 JA-S1-10656 loginwindow[64]: Login Window Started Security Agent

Oct 15 11:23:23 JA-S1-10656 SecurityAgent[200]: Echo enabled

Oct 15 11:23:25 JA-S1-10656 SecurityAgent[200]: spawn_via_launchd() failed, errno=5 label=[0x0-0x8008].com.apple.AppleSpell path=/System/Library/Services/AppleSpell.service/Contents/MacOS/AppleSpell flags=0

Oct 15 11:23:26 JA-S1-10656 com.apple.SecurityServer[21]: Succeeded authorizing right 'system.preferences' by client '/System/Library/PrivateFrameworks/Admin.framework/Versions/A/Resources/writeco nfig' [346] for authorization created by '/usr/sbin/systemsetup' [345]

Oct 15 11:33:07 JA-S1-10656 SecurityAgent[200]: User info context values set for <EXAMPLE-USER>

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_authenticate(): Got user: <EXAMPLE-USER>

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_authenticate(): Got ruser: (null)

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_authenticate(): Got service: authorization

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_authenticate(): Context initialised

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_authenticate(): Stashing kcm credentials in enviroment for kcminit: <EXAMPLE-USER>@<MY-AD-DOMAIN>

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_authenticate(): pam_sm_authenticate: ntlm

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache TTL set to 1800.

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in od_record_check_pwpolicy(): retval: 0

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in od_record_attribute_create_cfstring(): returned 3 attributes for dsAttrTypeStandard:AuthenticationAuthority

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Establishing credentials

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Got user: <EXAMPLE-USER>

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Context initialised

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Got euid, egid: 0 0

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Done getpwnam()

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Done setegid() & seteuid()

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): pam_sm_setcred: init credential cache

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): pam_sm_setcred: storing credential for: <EXAMPLE-USER>@<MY-AD-DOMAIN>

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Got cache_name: API:428415818:1

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Environment done: KRB5CCNAME=428415818:1

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Cache closed

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Done cleanup2

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Done cleanup3

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Done seteuid() & setegid()

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): Done cleanup4

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): pam_sm_setcred: ntlm

Oct 15 11:33:07 JA-S1-10656 authorizationhost[4196]: in pam_sm_setcred(): pam_sm_setcred: no domain found skipping

Oct 15 11:33:07 JA-S1-10656 SecurityAgent[200]: Login Window login proceeding



Any ideas what might be going on here? We do not use an OD server, if that is helpful.

Posted on Oct 15, 2012 10:06 AM

Reply

There are no replies.

AD user can't log in until local admin account logs in

Welcome to Apple Support Community
A forum where Apple customers help each other with their products. Get started with your Apple ID.
Learn more Sign up