stopped being able to kerberos/GSSAPI authenticate with new email accounts

Mark Foley mfoley at ohprs.org
Wed Jul 12 01:39:12 EEST 2017


I've been running with Dovecot 2.2.15 on my mail server and Thunderbird on workstations with
Kerberos/GSSAPI authentication. This has been working for over a year for 10 users.

The other day, I replaced a user's workstation and set up this user with a Thunderbird client.
Unfortunately, I got the error:

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

Doing more experimentation I've found that I cannot set up *any* existing user with a new
account without getting that same message.  Interestingly, all existing users can still connect
just fine from their Tbird clients on their current workstations which were set up over a year
ago, I just can't create an account for them on a different workstation. 

I'm at a loss as to where to start on this. My config is:

$ dovconf -n:
# 2.2.15: /usr/local/etc/dovecot/dovecot.conf
# OS: Linux 4.4.38 x86_64 Slackware 14.2
auth_debug = yes
auth_debug_passwords = yes
auth_gssapi_hostname = $ALL
auth_krb5_keytab = /etc/dovecot/dovecot.keytab
auth_mechanisms = plain login gssapi
auth_use_winbind = yes
auth_username_format = %n
auth_verbose = yes
auth_verbose_passwords = plain
disable_plaintext_auth = no
info_log_path = /var/log/dovecot_info
mail_location = maildir:~/Maildir
passdb {
	  driver = shadow
}
protocols = imap
ssl_cert = </etc/ssl/certs/OHPRS/GoDaddy/Apache/2016-08-10/54e789087d419b6e.crt
ssl_key = </etc/ssl/certs/OHPRS/GoDaddy/mail.ohprs.org.key
userdb {
	  driver = passwd
}
verbose_ssl = yes

Here is the log from an existing user, configured a long time ago, that works OK:

Jul 11 17:28:31 auth-worker(5858): Debug: shadow(mark,192.168.0.99): lookup
Jul 11 17:28:31 auth-worker(5858): Info: shadow(mark,192.168.0.99): unknown user
Jul 11 17:28:31 auth: Debug: shadow(mark,192.168.0.99,<OxGMYRFUsADAqABj>): Credentials:
Jul 11 17:28:31 auth: Debug: client passdb out: OK      1       user=mark       original_user=mark at HPRS.LOCAL
Jul 11 17:28:31 auth: Debug: master in: REQUEST 3872522241      6421    1       46614c53fd96efa48a94b889ad2405d3       session_pid=6429        request_auth_token
Jul 11 17:28:31 auth-worker(5858): Debug: shadow(mark,192.168.0.99): lookup
Jul 11 17:28:31 auth-worker(5858): Debug: shadow(mark,192.168.0.99): username changed mark -> HPRS\mark
Jul 11 17:28:31 auth: Debug: master userdb out: USER    3872522241      mark    system_groups_user=HPRS\mark  uid=10001        gid=10000       home=/home/HPRS/mark    auth_token=4959011413324b3d5d2d6f77c0adf2629551d91d   auth_user=mark at HPRS.LOCAL
Jul 11 17:28:31 imap-login: Info: Login: user=<mark>, method=GSSAPI, rip=192.168.0.99, lip=192.168.0.2, mpid=6429, TLS, session=<OxGMYRFUsADAqABj>


Here is that same user set up on a new client computer, with all the same settings (as far as I
can tell. This one apparently doesn't even try kerberos.

Jul 11 18:08:25 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 18:08:25 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 18:08:25 auth: Debug: auth client connected (pid=1055)
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv2/v3 read client hello A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read certificate verify A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read finished A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write session ticket A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write change cipher spec A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write finished A [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 18:08:25 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 18:08:25 auth: Debug: client in: AUTH    1       GSSAPI  service=imap    secured session=grVG8BFU2gDAqAA5       lip=192.168.0.2 rip=192.168.0.57        lport=143       rport=58586
Jul 11 18:08:25 auth: Debug: gssapi(?,192.168.0.57,<grVG8BFU2gDAqAA5>): Using all keytab entries
Jul 11 18:08:25 auth: Debug: client passdb out: CONT    1
Jul 11 18:08:25 auth: Debug: client in: CONT    1       YIIE+ [deleted]
Jul 11 18:08:26 auth: Debug: gssapi(dsmith,192.168.0.57,<grVG8BFU2gDAqAA5>): security context state completed.
Jul 11 18:08:26 auth: Debug: client passdb out: CONT    1       YIGVB [deleted]
Jul 11 18:08:26 auth: Debug: client in: CONT    1        (previous base64 data may contain sensitive data)
Jul 11 18:08:26 auth: Debug: gssapi(dsmith,192.168.0.57,<grVG8BFU2gDAqAA5>): Negotiated security layer
Jul 11 18:08:26 auth: Debug: client passdb out: CONT    1       BQQF/wAMAAAAAAAAFuHbYgH///9r9NgQ1SHdkCg7kho=
Jul 11 18:08:26 auth: Debug: client in: CONT    1       BQQE/wAMAAAAAAAAF9wdQwEAAABtYXJrXNhf7+Xh4YGqvoA5 (previous base64 data may contain sensitive data)
Jul 11 18:08:26 auth-worker(30944): Debug: shadow(mark,192.168.0.57): lookup
Jul 11 18:08:26 auth-worker(30944): Info: shadow(mark,192.168.0.57): unknown user
Jul 11 18:08:26 auth: Debug: shadow(mark,192.168.0.57,<grVG8BFU2gDAqAA5>): Credentials:
Jul 11 18:08:26 auth: Info: gssapi(mark,192.168.0.57,<grVG8BFU2gDAqAA5>): User not authorized to log in as mark
Jul 11 18:08:28 auth: Debug: client passdb out: FAIL    1       user=mark       original_user=dsmith at HPRS.LOCAL
Jul 11 18:08:28 imap-login: Debug: Ignoring unknown passdb extra field: original_user
Jul 11 18:08:28 imap-login: Debug: SSL alert: close notify [192.168.0.57]
Jul 11 18:08:28 imap-login: Debug: SSL alert: close notify [192.168.0.57]
Jul 11 18:08:28 imap-login: Info: Disconnected (auth failed, 1 attempts in 3 secs): user=<mark>, method=GSSAPI, rip=192.168.0.57, lip=192.168.0.2, TLS, session=<grVG8BFU2gDAqAA5>

Lastly, at the risk of too much information, here is the log info for the actual user (dsmith)
for whom I'm trying to set up tbird email on his new workstation.  I get the "Kerberos/GSSAPI
ticket was not accepted by the IMAP server ..." message shown at the top of this post when this
user opens Thunderbird.  Note that this user can connect and get mail just find from his old
workstation. 

Jul 11 18:24:29 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 18:24:29 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 18:24:29 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth
Jul 11 18:24:29 auth: Debug: Read auth token secret from /usr/local/var/run/dovecot/auth-token-secret.dat
Jul 11 18:24:29 auth: Debug: auth client connected (pid=11449)
Jul 11 18:24:29 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 18:24:29 imap-login: Debug: SSL: elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Jul 11 18:24:29 auth: Debug: auth client connected (pid=11452)
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv2/v3 read client hello A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x10, ret=1: before/accept initialization [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: before/accept initialization [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv2/v3 read client hello A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read certificate verify A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read finished A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write session ticket A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write change cipher spec A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write finished A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client hello A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server hello A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write certificate A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write key exchange A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write server done A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client certificate A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2002, ret=-1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read client key exchange A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read certificate verify A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 read finished A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write session ticket A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write change cipher spec A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 write finished A [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2001, ret=1: SSLv3 flush data [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 18:24:30 imap-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully [192.168.0.57]
Jul 11 18:24:30 auth: Debug: client in: AUTH    1       GSSAPI  service=imap    secured session=dYHDKRJUJgDAqAA5       lip=192.168.0.2 rip=192.168.0.57        lport=143       rport=58662
Jul 11 18:24:30 auth: Debug: client in: AUTH    1       GSSAPI  service=imap    secured session=dYHDKRJUJADAqAA5       lip=192.168.0.2 rip=192.168.0.57        lport=143       rport=58660
Jul 11 18:24:30 auth: Debug: gssapi(?,192.168.0.57,<dYHDKRJUJgDAqAA5>): Using all keytab entries
Jul 11 18:24:30 auth: Debug: client passdb out: CONT    1
Jul 11 18:24:30 auth: Debug: gssapi(?,192.168.0.57,<dYHDKRJUJADAqAA5>): Using all keytab entries
Jul 11 18:24:30 auth: Debug: client passdb out: CONT    1
Jul 11 18:24:30 auth: Debug: client in: CONT    1       YIIE+ [deleted]
Jul 11 18:24:30 auth: Debug: gssapi(dsmith,192.168.0.57,<dYHDKRJUJADAqAA5>): security context state completed.
Jul 11 18:24:30 auth: Debug: client passdb out: CONT    1       YIGVB [deleted]
Jul 11 18:24:30 auth: Debug: client in: CONT    1       YIIE+ [deleted]
Jul 11 18:24:30 auth: Debug: gssapi(dsmith,192.168.0.57,<dYHDKRJUJgDAqAA5>): security context state completed.
Jul 11 18:24:30 auth: Debug: client passdb out: CONT    1       YIGVB [deleted]
Jul 11 18:24:30 auth: Debug: client in: CONT    1        (previous base64 data may contain sensitive data)
Jul 11 18:24:30 auth: Debug: gssapi(dsmith,192.168.0.57,<dYHDKRJUJADAqAA5>): Negotiated security layer
Jul 11 18:24:30 auth: Debug: client passdb out: CONT    1       BQQF/wAMAAAAAAAAH1+3awH////7bf0e2rfKTxNaqLg=
Jul 11 18:24:30 auth: Debug: client in: CONT    1       BQQE/wAMAAAAAAAALn6AhAEAAABkc21pdGgQuBsLom6nqscutNM= (previous base64 data may contain sensitive data)
Jul 11 18:24:30 auth: Debug: client in: CONT    1        (previous base64 data may contain sensitive data)
Jul 11 18:24:30 auth: Debug: gssapi(dsmith,192.168.0.57,<dYHDKRJUJgDAqAA5>): Negotiated security layer
Jul 11 18:24:30 auth: Debug: client passdb out: CONT    1       BQQF/wAMAAAAAAAAFRtpiAH///9zZJNlQtcDSy2+KYo=
Jul 11 18:24:30 auth: Debug: client in: CONT    1       BQQE/wAMAAAAAAAANzdOTQEAAABkc21pdGhTz0R9AmEjueuv4Kk= (previous base64 data may contain sensitive data)
Jul 11 18:24:30 auth-worker(12060): Debug: Loading modules from directory: /usr/local/lib/dovecot/auth
Jul 11 18:24:30 auth-worker(12060): Debug: shadow(dsmith,192.168.0.57): lookup
Jul 11 18:24:30 auth-worker(12060): Info: shadow(dsmith,192.168.0.57): unknown user
Jul 11 18:24:30 auth: Debug: shadow(dsmith,192.168.0.57,<dYHDKRJUJADAqAA5>): Credentials:
Jul 11 18:24:30 auth: Debug: client passdb out: OK      1       user=dsmith     original_user=dsmith at HPRS.LOCAL
Jul 11 18:24:30 auth-worker(12062): Debug: Loading modules from directory: /usr/local/lib/dovecot/auth
Jul 11 18:24:30 auth: Debug: master in: REQUEST 2956591105      11449   1       c9c09995778a3d70b6569097b3d3fe34       session_pid=12064       request_auth_token
Jul 11 18:24:30 auth-worker(12060): Debug: shadow(dsmith,192.168.0.57): lookup
Jul 11 18:24:30 auth-worker(12062): Debug: shadow(dsmith,192.168.0.57): lookup
Jul 11 18:24:30 auth-worker(12062): Info: shadow(dsmith,192.168.0.57): unknown user
Jul 11 18:24:30 auth: Debug: shadow(dsmith,192.168.0.57,<dYHDKRJUJgDAqAA5>): Credentials:
Jul 11 18:24:30 auth: Debug: client passdb out: OK      1       user=dsmith     original_user=dsmith at HPRS.LOCAL
Jul 11 18:24:30 auth: Debug: master in: REQUEST 313131009       11452   1       8af9373d65d7d3dc2f556156d6c1c979       session_pid=12066       request_auth_token
Jul 11 18:24:30 auth-worker(12062): Debug: shadow(dsmith,192.168.0.57): lookup
Jul 11 18:24:30 auth-worker(12060): Debug: shadow(dsmith,192.168.0.57): username changed dsmith -> HPRS\dsmith
Jul 11 18:24:30 auth: Debug: master userdb out: USER    2956591105      dsmith  system_groups_user=HPRS\dsmithuid=3000036      gid=10000       home=/home/HPRS/dsmith  auth_token=5e36f7c4ae98f7873aefcb9186d661e54a94f180   auth_user=dsmith at HPRS.LOCAL
Jul 11 18:24:30 imap-login: Info: Login: user=<dsmith>, method=GSSAPI, rip=192.168.0.57, lip=192.168.0.2, mpid=12064, TLS, session=<dYHDKRJUJADAqAA5>
Jul 11 18:24:30 auth-worker(12062): Debug: shadow(dsmith,192.168.0.57): username changed dsmith -> HPRS\dsmith
Jul 11 18:24:30 auth: Debug: master userdb out: USER    313131009       dsmith  system_groups_user=HPRS\dsmithuid=3000036      gid=10000       home=/home/HPRS/dsmith  auth_token=057d47a48c1d97b4c5a8b413c4b4753de41f0a19   auth_user=dsmith at HPRS.LOCAL
Jul 11 18:24:30 imap-login: Info: Login: user=<dsmith>, method=GSSAPI, rip=192.168.0.57, lip=192.168.0.2, mpid=12066, TLS, session=<dYHDKRJUJgDAqAA5>


HELP!

THX - Mark


More information about the dovecot mailing list