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