[OpenAFS] Solaris 10 (x86): pam_afs_session

[John Tang Boyland]

Douglas E. Engert wrote:
] What shows up in /var/adm/messages if the /etc/pam.conf has:
] 
] dtlogin     auth requisite      pam_authtok_get.so.1 debug
] dtlogin     auth required       pam_dhkeys.so.1 debug
] dtlogin     auth required       pam_unix_cred.so.1 debug
] dtlogin     auth optional       pam_krb5.so.1  debug
] dtlogin     auth required       /krb5/lib/pam_afs_session.so.1 debug
] dtlogin     auth optional       pam_unix_auth.so.1 debug

At first nothing at all.  I tried rebooting and when that
still didn't work, learned about syslog.conf.  Fixed that.
And now I get lots of output.

Feb 22 14:55:12 eastside.cs.uwm.edu dtlogin[1187]: [ID 634615 user.debug] pam_authtok_get:pam_sm_authenticate: flags = 0
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 655841 user.debug] PAM-KRB5 (auth): pam_sm_authenticate flags=0
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 549540 user.debug] PAM-KRB5 (auth): attempt_krb5_auth: start: user='boyland'
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 704353 user.debug] PAM-KRB5 (auth): Forwardable tickets requested
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 912857 user.debug] PAM-KRB5 (auth): Renewable tickets requested
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 179272 user.debug] PAM-KRB5 (auth): attempt_krb5_auth: krb5_get_init_creds_password returns: SUCCESS
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 833335 user.debug] PAM-KRB5 (auth): attempt_krb5_auth returning 0
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 914654 user.debug] PAM-KRB5 (auth): pam_sm_auth finalize ccname env, result =0, env ='KRB5CCNAME=FILE:/tmp/krb5cc_920', age = 0, status = 0
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 525286 user.debug] PAM-KRB5 (auth): end: Success
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1187]: [ID 896952 user.debug] pam_unix_auth: entering pam_sm_authenticate()
Feb 22 14:55:26 eastside.cs.uwm.edu aklog[1201]: [ID 218067 user.debug] pkcs11_softtoken: Keystore access failed.
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 166327 user.debug] pam_dhkeys: user2netname failed
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 990244 auth.debug] pam_unix_cred: pam_sm_setcred(flags = 1, argc= 1)
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 741634 auth.debug] pam_unix_cred: user = boyland, rhost = NULL
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 857698 auth.debug] pam_unix_cred: state = -1, auid = -2
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 437940 auth.debug] pam_unix_cred: audit already set for -2
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 629253 user.debug] PAM-KRB5 (setcred): start: nowarn = 0, flags = 0x1
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 586274 user.debug] PAM-KRB5 (setcred): kmd auth_status: Success
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 522831 user.debug] PAM-KRB5 (setcred): attempt_refresh: set uid of user 'boyland'
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 156909 user.debug] PAM-KRB5 (setcred): User not in cred cache (No credentials cache file found)
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 735350 user.debug] PAM-KRB5 (setcred): end: Success
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 237248 user.debug] (pam_afs_session): pam_sm_setcred: entry (0x1)
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 237248 user.debug] (pam_afs_session): skipping, apparently already ran
Feb 22 14:55:26 eastside.cs.uwm.edu dtlogin[1205]: [ID 237248 user.debug] (pam_afs_session): pam_sm_setcred: exit (success)

Then, no tokens:

eastside.cs 3 % tokens     

Tokens held by the Cache Manager:

   --End of list--
eastside.cs 4 % klist
Ticket cache: FILE:/tmp/krb5cc_920
Default principal: boyland@CS.UWM.EDU

Valid starting     Expires            Service principal
02/22/08 14:52:39  02/23/08 14:52:39  krbtgt/CS.UWM.EDU@CS.UWM.EDU
        renew until 02/22/08 14:52:39


Kerberos 4 ticket cache: /tmp/tkt920
klist: You have no tickets cached
eastside.cs 5 % aklog
eastside.cs 6 %

The hand-run aklog succeeds but still logs this error:

Feb 22 14:57:29 eastside.cs.uwm.edu aklog[1233]: [ID 218067 user.debug] pkcs11_softtoken: Keystore access failed.

Now, I notice in the debug log that pam_afs_session gets run twice
and the second time decides it has already run and doesn't do anything.
This may be because on recommendation, I had added pam_afs_session to
the session stack:

other   session required        pam_unix_session.so.1
other   session required        pam_afs_session.so always_aklog

OK. So I remove the pam_afs_session line from the session stack.
....
Eureka!  It works now.

I guess, when I applied the recommended fixes, one of them (perhaps
misunderstood by me) caused a problem that ended up having the same
symptoms as the original problem, so I assumed the fixes were useless.
(It may also be that in pam_afs_session 1.5 it no longer gives up if
it has already run. I'm still using pam_afs_session 1.4)

Thanks,
John