Unable to Kerberos/GSSAPI an existing user on new workstation

[Mark Foley]

My last message probably contained too much information. This one is more succient.

I have a user, 'mark', who has been running a Thunderbird client on Windows to Dovecot server
with Kerberos/GSSAPI authentication for over a year.  I created a new Tbird account on a new
Linux workstation for 'mark', also with Kerberos/GSSAPI and that worked just fine. 

I have another user, 'dsmith', who has been running a Thunderbird client on Windows to Dovecot
server with Kerberos/GSSAPI authentication for over a year as well, no problems. I created a
new Tbird account on the same new Linux workstation as above for 'dsmith', also with
KerberosGSSAPI and that DID NOT WORK! I get the message in Thunderbird:

  "The Kerberos/GSSAPI ticket was not accepted by the IMAP server ...  please check that you
  are logged into the Kerberos/GSSAPI realm."

I created/recreated the smith account numerous time with slightly different settings hoping
something will work, but I always get the same message.

Why? I need to figure this out ASAP.

Here is the dovecot log when user dsmith attempts to connect to dovecot from the Tbird client:

Jul 11 19:29:43 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 19:29:43 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 19:29:43 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth
Jul 11 19:29:43 auth: Debug: Read auth token secret from /usr/local/var/run/dovecot/auth-token-secret.dat
Jul 11 19:29:43 auth: Debug: auth client connected (pid=1578)
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv2/v3 read client hello A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read certificate verify A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read finished A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write session ticket A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write change cipher spec A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write finished A [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 19:29:46 imap-login: Debug: SSL alert: close notify [192.168.0.57]
Jul 11 19:29:46 imap-login: Info: Disconnected (no auth attempts in 3 secs): user=<>, rip=192.168.0.57, lip=192.168.0.2, TLS, session=<jR0sExNUTADAqAA5>
Jul 11 19:30:17 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 19:30:17 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 19:30:17 auth: Debug: auth client connected (pid=3148)
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv2/v3 read client hello A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read certificate verify A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read finished A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write session ticket A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write change cipher spec A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write finished A [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 19:30:17 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 19:30:17 auth: Debug: client in: AUTH    1       GSSAPI  service=imap    secured session=iDUNFRNUUgDAqAA5       lip=192.168.0.2 rip=192.168.0.57        lport=143       rport=58962
Jul 11 19:30:17 auth: Debug: gssapi(?,192.168.0.57,<iDUNFRNUUgDAqAA5>): Using all keytab entries
Jul 11 19:30:17 auth: Debug: client passdb out: CONT    1
Jul 11 19:30:17 auth: Debug: client in: CONT    1       YIIE+ [deleted]
Jul 11 19:30:18 auth: Debug: gssapi(dsmith,192.168.0.57,<iDUNFRNUUgDAqAA5>): security context state completed.
Jul 11 19:30:18 auth: Debug: client passdb out: CONT    1       YIGVB [deleted]
Jul 11 19:30:18 auth: Debug: client in: CONT    1        (previous base64 data may contain sensitive data)
Jul 11 19:30:18 auth: Debug: gssapi(dsmith,192.168.0.57,<iDUNFRNUUgDAqAA5>): Negotiated security layer
Jul 11 19:30:18 auth: Debug: client passdb out: CONT    1       BQQF/wAMAAAAAAAAFxWx/AH///9xheyHOAR4oKi3t3M=
Jul 11 19:30:18 auth: Debug: client in: CONT    1       BQQE/wAMAAAAAAAANRcNbgEAAABkc21pdGjS3NSV6TWvt53rOLY= (previous base64 data may contain sensitive data)
Jul 11 19:30:18 auth-worker(3149): Debug: Loading modules from directory: /usr/local/lib/dovecot/auth
Jul 11 19:30:18 auth-worker(3149): Debug: shadow(dsmith,192.168.0.57): lookup
Jul 11 19:30:18 auth-worker(3149): Info: shadow(dsmith,192.168.0.57): unknown user
Jul 11 19:30:18 auth: Debug: shadow(dsmith,192.168.0.57,<iDUNFRNUUgDAqAA5>): Credentials:
Jul 11 19:30:18 auth: Debug: client passdb out: OK      1       user=dsmith     original_user=dsmith at HPRS.LOCAL
Jul 11 19:30:18 auth: Debug: master in: REQUEST 432275457       3148    1       3f58f611e9a6450ad7291105a93bbe1f       session_pid=3150        request_auth_token
Jul 11 19:30:18 auth-worker(3149): Debug: shadow(dsmith,192.168.0.57): lookup
Jul 11 19:30:18 auth-worker(3149): Debug: shadow(dsmith,192.168.0.57): username changed dsmith -> HPRS\dsmith
Jul 11 19:30:18 auth: Debug: master userdb out: USER    432275457       dsmith  system_groups_user=HPRS\dsmithuid=3000036      gid=10000       home=/home/HPRS/dsmith  auth_token=9ad7ad520ac8da70d07b3353b1c9c4e6ef394004   auth_user=dsmith at HPRS.LOCAL
Jul 11 19:30:18 imap-login: Info: Login: user=<dsmith>, method=GSSAPI, rip=192.168.0.57, lip=192.168.0.2, mpid=3150, TLS, session=<iDUNFRNUUgDAqAA5>

Thanks, Mark