Mark Foley
2017-Jul-11 22:39 UTC
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 =
</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///9r9NgQ1SHdkCg7khoJul 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////7bf0e2rfKTxNaqLgJul 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+KYoJul 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
Maybe Matching Threads
- Cannot Authenticate user with Kerberos/GSSAPI
- Unable to Kerberos/GSSAPI an existing user on new workstation
- Looking for GSSAPI config [was: Looking for NTLM config example]
- Looking for GSSAPI config [was: Looking for NTLM config example]
- My dovecot works fine against Active Directory 2003, but not against AD2008
Wisdom of the Ancients
