stopped being able to kerberos/GSSAPI authenticate with new email accounts
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 =
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@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@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@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@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@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@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@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
participants (1)
-
Mark Foley