FreeBSD PAM KRB5 thinks accounts are expired

Sat Aug 22 12:10:21 EDT 2015

Hello all,

Since I changed my kerberos over to the LDAP backend, my FreeBSD server has
been failing ssh logins, with PAM saying that the account is expired. if I
disable kerberos auth and just go with LDAP, things are hunky-dory. The
kerberos principal started off with no expiry dates, and now has December
31, 2024 23:0 as expiry, and it is fine as I can still ssh to the Ubuntu
servers and get authenticated by gssapi-mic no problem.

Perhaps it's just too late (and I have been at this for a while), and I
just can't seen to fix it.

Any help would be greatly appreciated. Thanks in advance!

I wrote this last night before heading to bed but gmail was misbehaving and
not sending. Anyways, this morning I comment out that account line for
pam_krb5 and things work fine, but that seems to kludgy for me as i would
like to be able to properly exipre/disable accounts via kerberos and thus
prevent logins.

cory at kaitain[03:50:47]~$ kadmin -p cory/admin
Authenticating as principal cory/admin with password.
Password for cory/admin at CORY.ALBRECHT.NAME:
kadmin:  getprinc cory
Principal: cory at CORY.ALBRECHT.NAME
Expiration date: Tue Dec 31 23:00:00 EST 2024
Last password change: Fri Aug 21 20:33:59 EDT 2015
Password expiration date: Tue Dec 31 23:00:00 EST 2024
Maximum ticket life: 60 days 00:00:00
Maximum renewable life: 60 days 00:00:00
Last modified: Sat Aug 22 03:41:57 EDT 2015 (cory/admin at CORY.ALBRECHT.NAME)
Last successful authentication: Sat Aug 22 03:59:29 EDT 2015
Last failed authentication: Sat Aug 22 00:23:42 EDT 2015
Failed password attempts: 0
Number of keys: 8
Key: vno 1, aes256-cts-hmac-sha1-96, no salt
Key: vno 1, arcfour-hmac, no salt
Key: vno 1, des3-cbc-sha1, no salt
Key: vno 1, des-cbc-crc, no salt
Key: vno 1, des-cbc-md5, no salt
Key: vno 1, des-cbc-md5, Version 5 - No Realm
Key: vno 1, des-cbc-md5, Version 5 - Realm Only
Key: vno 1, des-cbc-md5, AFS version 3
MKey: vno 1
Attributes: REQUIRES_PRE_AUTH
Policy: [none]

cory at VaporTrails[03:59:11]~$ ssh -vvv testforecho
OpenSSH_6.7p1 Ubuntu-5ubuntu1.3, OpenSSL 1.0.1f 6 Jan 2014
debug1: Reading configuration data /home/cory/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to testforecho [2001:470:b09d::a80:555] port 22.
debug1: connect to address 2001:470:b09d::a80:555 port 22: No route to host
debug1: Connecting to testforecho [10.128.5.85] port 22.
debug1: Connection established.
debug1: identity file /home/cory/.ssh/id_rsa type 1
debug1: key_load_public: No such file or directory
debug1: identity file /home/cory/.ssh/id_rsa-cert type -1
debug1: identity file /home/cory/.ssh/id_dsa type 2
debug1: key_load_public: No such file or directory
debug1: identity file /home/cory/.ssh/id_dsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/cory/.ssh/id_ecdsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/cory/.ssh/id_ecdsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/cory/.ssh/id_ed25519 type -1
debug1: key_load_public: No such file or directory
debug1: identity file /home/cory/.ssh/id_ed25519-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.7p1 Ubuntu-5ubuntu1.3
debug1: Remote protocol version 2.0, remote software version
OpenSSH_6.6.1_hpn13v11 FreeBSD-20140420
debug1: match: OpenSSH_6.6.1_hpn13v11 FreeBSD-20140420 pat OpenSSH_6.6.1*
compat 0x04000000
debug2: fd 3 setting O_NONBLOCK
debug3: Trying to reverse map address 10.128.5.85.
debug1: Offering GSSAPI proposal:
gss-gex-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-group1-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-group14-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-gex-sha1-A/vxljAEU54gt9a48EiANQ==,gss-group1-sha1-A/vxljAEU54gt9a48EiANQ==,gss-group14-sha1-A/vxljAEU54gt9a48EiANQ==,gss-gex-sha1-bontcUwnM6aGfWCP21alxQ==,gss-group1-sha1-bontcUwnM6aGfWCP21alxQ==,gss-group14-sha1-bontcUwnM6aGfWCP21alxQ==,gss-gex-sha1-eipGX3TCiQSrx573bT1o1Q==,gss-group1-sha1-eipGX3TCiQSrx573bT1o1Q==,gss-group14-sha1-eipGX3TCiQSrx573bT1o1Q==
debug3: load_hostkeys: loading entries for host "testforecho" from file
"/home/cory/.ssh/known_hosts"
debug3: load_hostkeys: found key type ECDSA in file
/home/cory/.ssh/known_hosts:76
debug3: load_hostkeys: loaded 1 keys
debug3: order_hostkeyalgs: prefer hostkeyalgs:
ecdsa-sha2-nistp256-cert-v01 at openssh.com,
ecdsa-sha2-nistp384-cert-v01 at openssh.com,
ecdsa-sha2-nistp521-cert-v01 at openssh.com
,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit:
gss-gex-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-group1-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-group14-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-gex-sha1-A/vxljAEU54gt9a48EiANQ==,gss-group1-sha1-A/vxljAEU54gt9a48EiANQ==,gss-group14-sha1-A/vxljAEU54gt9a48EiANQ==,gss-gex-sha1-bontcUwnM6aGfWCP21alxQ==,gss-group1-sha1-bontcUwnM6aGfWCP21alxQ==,gss-group14-sha1-bontcUwnM6aGfWCP21alxQ==,gss-gex-sha1-eipGX3TCiQSrx573bT1o1Q==,gss-group1-sha1-eipGX3TCiQSrx573bT1o1Q==,gss-group14-sha1-eipGX3TCiQSrx573bT1o1Q==,
curve25519-sha256 at libssh.org
,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ecdsa-sha2-nistp256-cert-v01 at openssh.com,
ecdsa-sha2-nistp384-cert-v01 at openssh.com,
ecdsa-sha2-nistp521-cert-v01 at openssh.com
,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,
ssh-ed25519-cert-v01 at openssh.com,ssh-rsa-cert-v01 at openssh.com,
ssh-dss-cert-v01 at openssh.com,ssh-rsa-cert-v00 at openssh.com,
ssh-dss-cert-v00 at openssh.com,ssh-ed25519,ssh-rsa,ssh-dss,null
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,
aes128-gcm at openssh.com,aes256-gcm at openssh.com,chacha20-poly1305 at openssh.com
,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,
aes128-gcm at openssh.com,aes256-gcm at openssh.com,chacha20-poly1305 at openssh.com
,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: umac-64-etm at openssh.com,umac-128-etm at openssh.com,
hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,
hmac-sha1-etm at openssh.com,umac-64 at openssh.com,umac-128 at openssh.com
,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-md5-etm at openssh.com,
hmac-ripemd160-etm at openssh.com,hmac-sha1-96-etm at openssh.com,
hmac-md5-96-etm at openssh.com,hmac-md5,hmac-ripemd160,
hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: umac-64-etm at openssh.com,umac-128-etm at openssh.com,
hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,
hmac-sha1-etm at openssh.com,umac-64 at openssh.com,umac-128 at openssh.com
,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-md5-etm at openssh.com,
hmac-ripemd160-etm at openssh.com,hmac-sha1-96-etm at openssh.com,
hmac-md5-96-etm at openssh.com,hmac-md5,hmac-ripemd160,
hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib at openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib at openssh.com,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit: curve25519-sha256 at libssh.org
,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519
debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,
aes128-gcm at openssh.com,aes256-gcm at openssh.com,chacha20-poly1305 at openssh.com
,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,
aes128-gcm at openssh.com,aes256-gcm at openssh.com,chacha20-poly1305 at openssh.com
,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc at lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5-etm at openssh.com,
hmac-sha1-etm at openssh.com,umac-64-etm at openssh.com,umac-128-etm at openssh.com,
hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,
hmac-ripemd160-etm at openssh.com,hmac-sha1-96-etm at openssh.com,
hmac-md5-96-etm at openssh.com,hmac-md5,hmac-sha1,umac-64 at openssh.com,
umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,
hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5-etm at openssh.com,
hmac-sha1-etm at openssh.com,umac-64-etm at openssh.com,umac-128-etm at openssh.com,
hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,
hmac-ripemd160-etm at openssh.com,hmac-sha1-96-etm at openssh.com,
hmac-md5-96-etm at openssh.com,hmac-md5,hmac-sha1,umac-64 at openssh.com,
umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,
hmac-ripemd160 at openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib at openssh.com
debug2: kex_parse_kexinit: none,zlib at openssh.com
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_setup: setup umac-64-etm at openssh.com
debug1: kex: server->client aes128-ctr umac-64-etm at openssh.com none
debug2: mac_setup: setup umac-64-etm at openssh.com
debug1: kex: client->server aes128-ctr umac-64-etm at openssh.com none
debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA
12:a0:50:d0:04:f9:6a:58:67:06:62:6e:00:12:94:d7
debug3: load_hostkeys: loading entries for host "testforecho" from file
"/home/cory/.ssh/known_hosts"
debug3: load_hostkeys: found key type ECDSA in file
/home/cory/.ssh/known_hosts:76
debug3: load_hostkeys: loaded 1 keys
debug3: load_hostkeys: loading entries for host "10.128.5.85" from file
"/home/cory/.ssh/known_hosts"
debug3: load_hostkeys: found key type ECDSA in file
/home/cory/.ssh/known_hosts:75
debug3: load_hostkeys: loaded 1 keys
debug1: Host 'testforecho' is known and matches the ECDSA host key.
debug1: Found key in /home/cory/.ssh/known_hosts:76
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /home/cory/.ssh/id_rsa (0x7f756bbce620),
debug2: key: /home/cory/.ssh/id_dsa (0x7f756bbc94b0),
debug2: key: /home/cory/.ssh/id_ecdsa ((nil)),
debug2: key: /home/cory/.ssh/id_ed25519 ((nil)),
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug3: start over, passed a different list
publickey,gssapi-with-mic,password,keyboard-interactive
debug3: preferred
gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup gssapi-with-mic
debug3: remaining preferred: publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-with-mic
debug1: Next authentication method: gssapi-with-mic
debug2: we sent a gssapi-with-mic packet, wait for reply
debug1: Delegating credentials
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug2: we sent a gssapi-with-mic packet, wait for reply
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug2: we sent a gssapi-with-mic packet, wait for reply
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug2: we sent a gssapi-with-mic packet, wait for reply
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug2: we did not send a packet, disable method
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /home/cory/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug1: Offering DSA public key: /home/cory/.ssh/id_dsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug1: Trying private key: /home/cory/.ssh/id_ecdsa
debug3: no such identity: /home/cory/.ssh/id_ecdsa: No such file or
directory
debug1: Trying private key: /home/cory/.ssh/id_ed25519
debug3: no such identity: /home/cory/.ssh/id_ed25519: No such file or
directory
debug2: we did not send a packet, disable method
debug3: authmethod_lookup keyboard-interactive
debug3: remaining preferred: password
debug3: authmethod_is_enabled keyboard-interactive
debug1: Next authentication method: keyboard-interactive
debug2: userauth_kbdint
debug2: we sent a keyboard-interactive packet, wait for reply
debug2: input_userauth_info_req
debug2: input_userauth_info_req: num_prompts 1
Password:
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug2: userauth_kbdint
debug2: we sent a keyboard-interactive packet, wait for reply
debug1: Authentications that can continue:
publickey,gssapi-with-mic,password,keyboard-interactive
debug2: userauth_kbdint
debug2: we sent a keyboard-interactive packet, wait for reply
Received disconnect from 10.128.5.85: 2: Too many authentication failures
for cory

==> debug.log <==
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_dispatch(): calling
pam_sm_authenticate() in /usr/lib/pam_krb5.so.5
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_user(): entering
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_USER
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_user(): returning
PAM_SUCCESS
Aug 22 03:59:16 testforecho sshd[1786]: in pam_sm_authenticate(): Got user:
cory
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_RUSER
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:16 testforecho sshd[1786]: in pam_sm_authenticate(): Got
ruser: (null)
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_SERVICE
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:16 testforecho sshd[1786]: in pam_sm_authenticate(): Got
service: sshd
Aug 22 03:59:16 testforecho sshd[1786]: in pam_sm_authenticate(): Context
initialised
Aug 22 03:59:16 testforecho sshd[1786]: in pam_sm_authenticate(): Done
krb5_cc_register()
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): entering:
'auth_as_self'
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): returning
NULL
Aug 22 03:59:16 testforecho sshd[1786]: in pam_sm_authenticate(): Created
principal: cory
Aug 22 03:59:16 testforecho sshd[1786]: in pam_sm_authenticate(): Done
krb5_parse_name()
Aug 22 03:59:16 testforecho sshd[1786]: in pam_sm_authenticate(): Got
principal: cory at CORY.ALBRECHT.NAME
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_authtok(): entering
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_RHOST
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_HOST
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_OLDAUTHTOK
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): entering:
'try_first_pass'
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): returning
''
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_AUTHTOK
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): entering:
'use_first_pass'
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): returning
NULL
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): entering:
'authtok_prompt'
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): returning
NULL
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_subst(): entering:
'Password:'
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_subst(): returning
PAM_SUCCESS

==> auth.log <==
Aug 22 03:59:16 testforecho sshd[1784]: Postponed keyboard-interactive for
cory from 10.128.6.2 port 40294 ssh2 [preauth]

==> debug.log <==
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): entering:
'echo_pass'
Aug 22 03:59:16 testforecho sshd[1786]: in openpam_get_option(): returning
NULL
Aug 22 03:59:16 testforecho sshd[1786]: in pam_vprompt(): entering
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_CONV
Aug 22 03:59:16 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_vprompt(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_set_item(): entering:
PAM_AUTHTOK
Aug 22 03:59:29 testforecho sshd[1786]: in pam_set_item(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_AUTHTOK
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_authtok(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate(): Got
password
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_get_option(): entering:
'no_user_check'
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_get_option(): returning
NULL
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_get_option(): entering:
'no_user_check'
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_get_option(): returning
NULL
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate(): Done
getpwnam()
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_get_option(): entering:
'forwardable'
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_get_option(): returning
NULL
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate():
Credential options initialised
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate(): Got TGT
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate():
Credentials stashed
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_get_option(): entering:
'debug'
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_get_option(): returning
''
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate():
Credentials stash verified
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_data(): entering:
'ccache'
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_data(): returning
PAM_NO_MODULE_DATA
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate():
Credentials stash not pre-existing
Aug 22 03:59:29 testforecho sshd[1786]: in pam_set_data(): entering:
'ccache'
Aug 22 03:59:29 testforecho sshd[1786]: in pam_set_data(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate():
Credentials stash saved
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate(): Done
cleanup
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate(): Done
cleanup2
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_authenticate(): Done
cleanup3
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_dispatch():
/usr/lib/pam_krb5.so.5: pam_sm_authenticate(): success
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_dispatch(): calling
pam_sm_acct_mgmt() in /usr/lib/pam_krb5.so.5
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_USER
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_acct_mgmt(): Got user:
cory
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_data(): entering:
'ccache'
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_data(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_acct_mgmt(): Got
credentials
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_acct_mgmt(): Context
initialised
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_acct_mgmt(): Got ccache
MEMORY:0x804016880
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_acct_mgmt(): Got principal
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_acct_mgmt(): Done
kuserok()
Aug 22 03:59:29 testforecho sshd[1786]: in pam_sm_acct_mgmt(): Done cleanup
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_dispatch():
/usr/lib/pam_krb5.so.5: pam_sm_acct_mgmt(): permission denied
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_dispatch(): calling
pam_sm_acct_mgmt() in /usr/local/lib/pam_ldap.so
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_CONV
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_data(): entering:
'PADL-LDAP-AUTH-DATA'
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_data(): returning
PAM_NO_MODULE_DATA
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_user(): entering
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_item(): entering:
PAM_USER
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_item(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_user(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_data(): entering:
'PADL-LDAP-SESSION-DATA'
Aug 22 03:59:29 testforecho sshd[1786]: in pam_get_data(): returning
PAM_NO_MODULE_DATA
Aug 22 03:59:29 testforecho sshd[1786]: in pam_set_data(): entering:
'PADL-LDAP-SESSION-DATA'
Aug 22 03:59:29 testforecho sshd[1786]: in pam_set_data(): returning
PAM_SUCCESS
Aug 22 03:59:29 testforecho sshd[1786]: in openpam_dispatch():
/usr/local/lib/pam_ldap.so: pam_sm_acct_mgmt(): success

==> auth.log <==
Aug 22 03:59:29 testforecho sshd[1784]: error: PAM: user account has
expired for cory from 10.128.6.2

==> messages <==
Aug 22 03:59:29 testforecho sshd[1784]: error: PAM: user account has
expired for cory from 10.128.6.2

==> auth.log <==
Aug 22 03:59:29 testforecho sshd[1784]: Disconnecting: Too many
authentication failures for cory [preauth]

root at testforecho:/var/log # cat /etc/pam.d/sshd
#
# $FreeBSD: releng/10.1/etc/pam.d/sshd 197769 2009-10-05 09:28:54Z des $
#
# PAM configuration for the "sshd" service
#

# auth
auth            sufficient      pam_opie.so             no_warn
no_fake_prompts
auth            requisite       pam_opieaccess.so       no_warn allow_local
auth            sufficient      pam_krb5.so             no_warn
try_first_pass debug
auth            sufficient      /usr/local/lib/pam_ldap.so      no_warn
use_first_pass debug
#auth           sufficient      pam_ssh.so              no_warn
use_first_pass
auth            required        pam_unix.so             no_warn
use_first_pass

# account
account         required        pam_nologin.so
account required        pam_krb5.so     debug
account         required        /usr/local/lib/pam_ldap.so      no_warn
ignore_authinfo_unavail ignore_unknown_user debug
account         required        pam_login_access.so
account         required        pam_unix.so

# session
#session        optional        pam_ssh.so              want_agent
session         required        pam_permit.so

# password
password        sufficient      pam_krb5.so             no_warn
try_first_pass
password        required        pam_unix.so             no_warn
use_first_pass