dovecot - Jul 2017 - Unable to Kerberos/GSSAPI an existing user on new workstation

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///9xheyHOAR4oKi3t3MJul 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

> On July 12, 2017 at 2:54 AM Mark Foley <mfoley at ohprs.org> wrote:
> 
> 
> 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:
<snip/>
> Thanks, Mark
Hi!

Judging from the logs it seems the user is able to log in just fine. There are
no errors. Perhaps you could turn on debug logging on the client workstation and
see what thunderbird does?

You can achieve this with following

env NSPR_LOG_MODULES=all:4 NSPR_LOG_FILE=~/tbird.log.txt thunderbird

you can set it to all:5 if you think it might reveal something more.

Aki