[Dovecot] GSSAPI auth failing for kmail
Hi, have dovecot 2.0.13 running fine on a NetBSD box, with lots of clients happily authenticating to it with GSSAPI.
I've just updated an ArchLinux box to latest new version which has meant its switched from using heimdal to using mit krb5 and its kmail is now also slightly newer.
Thunderbird successfully authenticates to dovecot from this machine but kmail now fails. Kmail reports:
Unable to authenticate via GSSAPI. The server ... replied: SASL(-1): generic failure: GSSAPI Error: Invalid token was supplied (Token header is malformed or corrupt)
The dovecot log reports:
Feb 27 13:42:18 bats dovecot: auth: GSSAPI(mark@ECS.VUW.AC.NZ,130.195.5.88): Invalid base64 data in continued response
Any suggestions on how to track down what specifically has changed and how to fix it?
cheers mark
On Mon, 2012-02-27 at 14:17 +1300, Mark Davies wrote:
Feb 27 13:42:18 bats dovecot: auth: GSSAPI(mark@ECS.VUW.AC.NZ,130.195.5.88): Invalid base64 data in continued response
Looks like kmail is sending some kind of garbage to Dovecot. Set auth_debug_passwords=yes to make Dovecot log the auth traffic.
On 02/27/12 23:32, Timo Sirainen wrote:
Looks like kmail is sending some kind of garbage to Dovecot. Set auth_debug_passwords=yes to make Dovecot log the auth traffic.
Yeah, I did a network trace and it seems kmail is not sending the full authentication request before trying to carry on.
8 0.043625 130.195.5.88 130.195.5.13 IMAP 898 Request: 1 AUTHENTICATE GSSAPI YIICWgYJKoZIhvcSAQICAQBuggJJMI[...]jLyNiRZFsc9zFxpdwrZAB/WXRRS1zsM4SlDfE59CW1xfKAkqe 9 0.044919 130.195.5.13 130.195.5.88 IMAP 70 Response: + 10 0.045413 130.195.5.88 130.195.5.13 IMAP 80 Request: 2 LIST "" "" 11 0.045486 130.195.5.13 130.195.5.88 IMAP 122 Response: 1 NO [ALERT] Invalid base64 data in continued response
now to figure out why its started truncating it.
cheers mark
On 27.2.2012, at 12.50, Mark Davies wrote:
On 02/27/12 23:32, Timo Sirainen wrote:
Looks like kmail is sending some kind of garbage to Dovecot. Set auth_debug_passwords=yes to make Dovecot log the auth traffic.
Yeah, I did a network trace and it seems kmail is not sending the full authentication request before trying to carry on.
8 0.043625 130.195.5.88 130.195.5.13 IMAP 898 Request: 1 AUTHENTICATE GSSAPI YIICWgYJKoZIhvcSAQICAQBuggJJMI[...]jLyNiRZFsc9zFxpdwrZAB/WXRRS1zsM4SlDfE59CW1xfKAkqe
It uses SASL-IR to send the first seponse.
9 0.044919 130.195.5.13 130.195.5.88 IMAP 70 Response: +
Dovecot says "OK, give me more".
10 0.045413 130.195.5.88 130.195.5.13 IMAP 80 Request: 2 LIST "" ""
kmail thinks the authentication is done and sends LIST command, even though it should finish the authentication. Clearly a kmail bug.
You could try what happens if you remove SASL-IR from Dovecot's imap_capability list. Maybe kmail is buggy only with SASL-IR.
On 02/28/12 00:11, Timo Sirainen wrote:
Looks like kmail is sending some kind of garbage to Dovecot. Set auth_debug_passwords=yes to make Dovecot log the auth traffic.
Yeah, I did a network trace and it seems kmail is not sending the full authentication request before trying to carry on.
8 0.043625 130.195.5.88 130.195.5.13 IMAP 898 Request: 1 AUTHENTICATE GSSAPI YIICWgYJKoZIhvcSAQICAQBuggJJMI[...]jLyNiRZFsc9zFxpdwrZAB/WXRRS1zsM4SlDfE59CW1xfKAkqe
It uses SASL-IR to send the first seponse.
9 0.044919 130.195.5.13 130.195.5.88 IMAP 70 Response: +
Dovecot says "OK, give me more".
I poked some more at the kmail end of this but I cant see what its doing differently from what it used to (but clearly there is something).
The new kmail sends
1 AUTHENTICATE GSSAPI YIICWgYJKoZIhvcSAQICAQBugg[...]wfuKg4VUptzPwb\r\n
and receives
- \r\n
from dovecot, which it doesn't like and reports clientAuthenticate: sasl_client_step failed with: -1
an older (working kmail) sends
1 AUTHENTICATE GSSAPI YIICiAYJKoZIhvcSAQICAQBugg[...]MpPurY7cZfRSEw==\r\n
and receives
- YIGaBgkqhkiG9xIBAgI[...]iYoSGi9/uKVGyE64TAvkf25rCbFkNqk1D12g==\r\n
and carries on.
So what is it that differs in the two cases to cause dovecot to respond differently?
cheers mark
On 29.2.2012, at 12.34, Timo Sirainen wrote:
On 29.2.2012, at 12.15, Mark Davies wrote:
1 AUTHENTICATE GSSAPI YIICWgYJKoZIhvcSAQICAQBugg[...]wfuKg4VUptzPwb\r\n
and receives
- \r\n
from dovecot, which it doesn't like and reports clientAuthenticate: sasl_client_step failed with: -1
Oh, yes, this is a bug in Dovecot..
Hmm. Or it looked like a bug, since it replied only with "+", so I thought all auth mechanisms would have such a bug, but no.. So I'm not really sure why it's not sending more data. I don't have a Kerberos setup to test this with. v2.1's GSSAPI code is anyway identical to v2.0's.
On 02/29/12 23:41, Timo Sirainen wrote:
Oh, yes, this is a bug in Dovecot..
Hmm. Or it looked like a bug, since it replied only with "+", so I thought all auth mechanisms would have such a bug, but no.. So I'm not really sure why it's not sending more data. I don't have a Kerberos setup to test this with. v2.1's GSSAPI code is anyway identical to v2.0's.
With auth debugging on a successful connection gives:
Mar 2 00:33:34 bats dovecot: auth: Debug: auth client connected (pid=1584) Mar 2 00:33:34 bats dovecot: auth: Debug: client in: AUTH 1 GSSAPI service=imap lip=130.195.5.13 rip=130.195.5.88 lport=143 rport=49116 Mar 2 00:33:34 bats dovecot: auth: Debug: gssapi(?,130.195.5.88): Using all keytab entries Mar 2 00:33:34 bats dovecot: auth: Debug: client out: CONT 1 Mar 2 00:33:34 bats dovecot: auth: Debug: client in: CONT<hidden> Mar 2 00:33:34 bats dovecot: auth: Debug: gssapi(mark@ECS.VUW.AC.NZ,130.195.5.88): security context state completed. Mar 2 00:33:34 bats dovecot: auth: Debug: client out: CONT 1 YIGaBgkqhkiG9xIBAgICAG+BijCBh6ADAgEFoQMCAQ+iezB5oAMCARKicgRwXldfEmBHqH3DiVbw7aXtx54iBNjo1Rv/KxBSK5G3TmYFm3YskYN/23EiaOQ0Tdyi4bc4jhv5cFWMpH/xM89wAFJVW8Ue27/fmCasfDWXE+i4TKA3UCm78Wy8YyiNVae8X341LspBk86R1Zl5MNRMvA== Mar 2 00:33:34 bats dovecot: auth: Debug: client in: CONT<hidden> Mar 2 00:33:34 bats dovecot: auth: Debug: gssapi(mark@ECS.VUW.AC.NZ,130.195.5.88): Negotiated security layer Mar 2 00:33:34 bats dovecot: auth: Debug: client out: CONT 1 BQQF/wAMAAwAAAAA47846FHFUOykdXinGYvMKwH///8= Mar 2 00:33:34 bats dovecot: auth: Debug: client in: CONT<hidden> Mar 2 00:33:34 bats dovecot: auth: Debug: client out: OK 1 user=mark
and the failing kmail gives
Mar 2 00:38:08 bats dovecot: auth: Debug: auth client connected (pid=2720) Mar 2 00:38:08 bats dovecot: auth: Debug: client in: AUTH 1 GSSAPI service=imap lip=130.195.5.13 rip=130.195.5.88 lport=143 rport=49118 resp=<hidden> Mar 2 00:38:08 bats dovecot: auth: Debug: gssapi(?,130.195.5.88): Using all keytab entries Mar 2 00:38:08 bats dovecot: auth: Debug: gssapi(mark@ECS.VUW.AC.NZ,130.195.5.88): security context state completed. Mar 2 00:38:08 bats dovecot: auth: Debug: client out: CONT 1 Mar 2 00:38:08 bats dovecot: auth: Debug: client in: CONT<hidden> Mar 2 00:38:08 bats dovecot: auth: GSSAPI(mark@ECS.VUW.AC.NZ,130.195.5.88): Invalid base64 data in continued response Mar 2 00:38:08 bats dovecot: auth: Debug: client out: FAIL 1 reason=Invalid base64 data in continued response
so what bit of the code should I be looking at to see what happens between the "security context state completed" and the "client out"?
cheers mark
On Fri, 2012-03-02 at 00:49 +1300, Mark Davies wrote:
so what bit of the code should I be looking at to see what happens between the "security context state completed" and the "client out"?
All of the code is in mech-gssapi.c
Are these working vs. non-working Dovecots in same or different servers?
On 03/02/12 00:52, Timo Sirainen wrote:
so what bit of the code should I be looking at to see what happens between the "security context state completed" and the "client out"?
All of the code is in mech-gssapi.c
Yes, I'm just trying to work out the flow of the calls in and out of there.
Are these working vs. non-working Dovecots in same or different servers?
All the working and non working connections are against a single dovecot instance, just using different clients.
cheers mark
On Fri, 2012-03-02 at 00:57 +1300, Mark Davies wrote:
On 03/02/12 00:52, Timo Sirainen wrote:
so what bit of the code should I be looking at to see what happens between the "security context state completed" and the "client out"?
All of the code is in mech-gssapi.c
Yes, I'm just trying to work out the flow of the calls in and out of there.
The problem is that that mech_gssapi_sec_context() calls gss_accept_sec_context(), which is supposed to return some output in output_token, but it doesn't. So I don't think there's anything in Dovecot code that is helpful in debugging this. You'd have to look into the GSSAPI/Kerbereros libraries.
Are these working vs. non-working Dovecots in same or different servers?
All the working and non working connections are against a single dovecot instance, just using different clients.
Oh. So GSSAPI in general is working, just not with kmail. I think if you downgraded to Dovecot v2.0 in your current system it would fail as well. The difference between your previously working system and currently working system is the GSSAPI/Kerberos libraries.
On 03/02/12 01:04, Timo Sirainen wrote:
The difference between your previously working system and currently working system is the GSSAPI/Kerberos libraries.
Just to close this thread off, seems that the bug was in the cyrus-sasl libraries that kmail uses. Reverting from the 2.1.25 version that the latest was trying to use to 2.1.23 that was on the older systems got it working again. When I get a moment I'll try and work out what specifically changed.
cheers mark
participants (2)
-
Mark Davies
-
Timo Sirainen