While preparing the Debian packages of Dovecot 2.4.1, I encountered what
appears to be a regression that impacts the ability of some clients to
successfully negotiate gssapi/krb5 authentication.
The regression has so far been observed in gsasl, which was able to
successfully authenticate to 2.3.19 but cannot authenticate to 2.4.1.
Mutt is able to successfully authenticate with 2.3.19 and 2.4.1.
Doveconf output is attached.
The debug logs for both failed (gsasl) and successful (mutt)
authentications follow. Note that all logs are from an ephemeral debug
environment, and sensitive data is not redacted.
I can provide additional information as needed, and can test different
code and/or configuration changes.
Failed authentication dovecot debug log:
Apr 30 13:40:09 auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Apr 30 13:40:09 auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Apr 30 13:40:09 auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libmech_gssapi.so
Apr 30 13:40:09 auth: Debug: Read auth token secret from /home/noahm/dovecot-root/b/auth-token-secret.dat
Apr 30 13:40:09 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: Server accepted connection (fd=18)
Apr 30 13:40:09 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: auth client connected (pid=6791)
Apr 30 13:40:09 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: client in: AUTH 1 GSSAPI protocol=imap final-resp-ok session=FhRIDv8zdMzAqAHa lip=172.18.0.205 rip=192.168.1.218 lport=17436 rport=52340
Apr 30 13:40:09 auth(?,192.168.1.218,sasl:gssapi)<FhRIDv8zdMzAqAHa>: Debug: gssapi: Using all keytab entries
Apr 30 13:40:09 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: client passdb out: CONT 1 #
Apr 30 13:40:09 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: client in: CONT 1 # (previous base64 data may contain sensitive data)
Apr 30 13:40:09 auth(?,192.168.1.218,sasl:gssapi)<FhRIDv8zdMzAqAHa>: Debug: gssapi: Processed incoming packet correctly, waiting for another.
Apr 30 13:40:09 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: client passdb out: CONT 1 YEcGBisGAQUFAqA9MDugDTALBgkqhkiG9xIBAgKjKjAooCYbJG5vdF9kZWZpbmVkX2luX1JGQzQxNzhAcGxlYXNlX2lnbm9yZQ==
Apr 30 13:40:09 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: client in: CONT 1 YIIDAAYJKoZIhvcSAQICAQBuggLvMIIC66ADAgEFoQMCAQ6iBwMFACAAAACjggIDYYIB/zCCAfugAwIBBaENGwtFWEFNUExFLkNPTaIfMB2gAwIBA6EWMBQbBGltYXAbDGRvdmVjb3QtdGVzdKOCAcIwggG+oAMCARKhAwIBAqKCAbAEggGsj4jD3VOwvfNdLxjc2hqxFsBYyCvjdOCX0R1So6ANZEYnEWddqZwMCuz7BxXv4z+cXaL6g6iGlVkU4RxQyJQHDFUQC8JroTlyMQ+XsIM4zuwn5N4/xRsgKa+SisK92UNMYyl9hVIPKvu/A54cU0zYTdDjYfDGnkurG2RgXDrKIzMpU2LtpoBEtwl3F1H+rzKFJAqe96e39C85GjK1D4s8/TOm3IcHJ5eofeHxI2GeUodysi+DlurRQTSnsUkGa1LXSgkY+4QdlMf+4goNRG5xNdZ8OA2CLY97TPAFqIeej1Amvb9uQBIKvWfbTjDdItBWOhuvAetlNfqnxlcCbnjbCmFTOIbVsHhNW8W1JIElL28mGydbMPimi9brc250E+ImO0Bxp3gMn5oXGV0tUJl5Y8W1lHlEUU7vKK0V7khUob0b3P3lCGQVJyWZEGNodgpr5zkTbR2M8orP4eI9SYoYp2UB0Ag+JkeYSNoQrKZNxSoKBYLVPGzwwGNPBKl7T0CdXlDAOhfZS/FSxdoy8LGRhuTdv7ghQAvstOllibSbjN3wos8ZC8wH2I5LFkekgc4wgcugAwIBEqKBwwSBwMCJkwg3LL7QqlEOunOjvQzpXmA/LMbdtEDyW9b0EQNFL9KFkNuRKDC3V8SFkmG1KlEEHFp2GQNij6AN89xvmEGvhj3tqC280awJs8ve3Bbr7GHRJoFO/sikSRsol1HD/K3sC9OMDufEEItsWf94uu8SmEBpB2OBOzedtfw+PRpoWyYUJYEfAL9T4w0KmBD26KVcehzIv8e3vOl52aT3x9Ovjnw8RfFkZa+t/iGhMpYpf8ApWExZDWBZ6uzVJxcAPg== (previous base64 data may contain sensitive data)
Apr 30 13:40:09 auth(?,192.168.1.218,sasl:gssapi)<FhRIDv8zdMzAqAHa>: Debug: Auth request finished
Apr 30 13:40:09 auth(?,192.168.1.218,sasl:gssapi)<FhRIDv8zdMzAqAHa>: Debug: delaying auth failure
Apr 30 13:40:11 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: client passdb out: FAIL 1
Apr 30 13:40:11 auth: Debug: conn unix:login (pid=6791,uid=1000) [1]: Disconnected: Connection closed (fd=18)
And the corresponding client log:
noahm@42b23a0b5002:~$ gsasl -m GSSAPI -d --no-starttls --imap dovecot-test 17436
Trying 'dovecot-test'...
* OK [CAPABILITY IMAP4rev1 LOGIN-REFERRALS ID ENABLE IDLE SASL-IR LITERAL+ STARTTLS AUTH=PLAIN AUTH=GSSAPI] Dovecot ready.
. CAPABILITY
* CAPABILITY IMAP4rev1 LOGIN-REFERRALS ID ENABLE IDLE SASL-IR LITERAL+ STARTTLS AUTH=PLAIN AUTH=GSSAPI
. OK Pre-login capabilities listed, post-login capabilities have more.
. AUTHENTICATE GSSAPI
+ YEcGBisGAQUFAqA9MDugDTALBgkqhkiG9xIBAgKjKjAooCYbJG5vdF9kZWZpbmVkX2luX1JGQzQxNzhAcGxlYXNlX2lnbm9yZQ==
YIIDAAYJKoZIhvcSAQICAQBuggLvMIIC66ADAgEFoQMCAQ6iBwMFACAAAACjggIDYYIB/zCCAfugAwIBBaENGwtFWEFNUExFLkNPTaIfMB2gAwIBA6EWMBQbBGltYXAbDGRvdmVjb3QtdGVzdKOCAcIwggG+oAMCARKhAwIBAqKCAbAEggGsj4jD3VOwvfNdLxjc2hqxFsBYyCvjdOCX0R1So6ANZEYnEWddqZwMCuz7BxXv4z+cXaL6g6iGlVkU4RxQyJQHDFUQC8JroTlyMQ+XsIM4zuwn5N4/xRsgKa+SisK92UNMYyl9hVIPKvu/A54cU0zYTdDjYfDGnkurG2RgXDrKIzMpU2LtpoBEtwl3F1H+rzKFJAqe96e39C85GjK1D4s8/TOm3IcHJ5eofeHxI2GeUodysi+DlurRQTSnsUkGa1LXSgkY+4QdlMf+4goNRG5xNdZ8OA2CLY97TPAFqIeej1Amvb9uQBIKvWfbTjDdItBWOhuvAetlNfqnxlcCbnjbCmFTOIbVsHhNW8W1JIElL28mGydbMPimi9brc250E+ImO0Bxp3gMn5oXGV0tUJl5Y8W1lHlEUU7vKK0V7khUob0b3P3lCGQVJyWZEGNodgpr5zkTbR2M8orP4eI9SYoYp2UB0Ag+JkeYSNoQrKZNxSoKBYLVPGzwwGNPBKl7T0CdXlDAOhfZS/FSxdoy8LGRhuTdv7ghQAvstOllibSbjN3wos8ZC8wH2I5LFkekgc4wgcugAwIBEqKBwwSBwMCJkwg3LL7QqlEOunOjvQzpXmA/LMbdtEDyW9b0EQNFL9KFkNuRKDC3V8SFkmG1KlEEHFp2GQNij6AN89xvmEGvhj3tqC280awJs8ve3Bbr7GHRJoFO/sikSRsol1HD/K3sC9OMDufEEItsWf94uu8SmEBpB2OBOzedtfw+PRpoWyYUJYEfAL9T4w0KmBD26KVcehzIv8e3vOl52aT3x9Ovjnw8RfFkZa+t/iGhMpYpf8ApWExZDWBZ6uzVJxcAPg==
. NO [AUTHENTICATIONFAILED] Authentication failed.
gsasl: server error
Successful authentication (mutt) dovecot debug log:
Apr 30 13:32:30 auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Apr 30 13:32:30 auth: Debug: Loading modules from directory: /usr/lib/dovecot/modules/auth
Apr 30 13:32:30 auth: Debug: Module loaded: /usr/lib/dovecot/modules/auth/libmech_gssapi.so
Apr 30 13:32:30 auth: Debug: Read auth token secret from /home/noahm/dovecot-root/b/auth-token-secret.dat
Apr 30 13:32:30 auth: Debug: conn unix:login (pid=6788,uid=1000) [1]: Server accepted connection (fd=18)
Apr 30 13:32:30 auth: Debug: conn unix:login (pid=6788,uid=1000) [1]: auth client connected (pid=6788)
Apr 30 13:32:30 auth: Debug: conn unix:login (pid=6788,uid=1000) [1]: client in: AUTH 1 GSSAPI protocol=imap final-resp-ok session=4aLx8v4z8JPAqAHa lip=172.18.0.205 rip=192.168.1.218 lport=17436 rport=37872 resp=YIIDAAYJKoZIhvcSAQICAQBuggLvMIIC66ADAgEFoQMCAQ6iBwMFACAAAACjggIDYYIB/zCCAfugAwIBBaENGwtFWEFNUExFLkNPTaIfMB2gAwIBA6EWMBQbBGltYXAbDGRvdmVjb3QtdGVzdKOCAcIwggG+oAMCARKhAwIBAqKCAbAEggGsj4jD3VOwvfNdLxjc2hqxFsBYyCvjdOCX0R1So6ANZEYnEWddqZwMCuz7BxXv4z+cXaL6g6iGlVkU4RxQyJQHDFUQC8JroTlyMQ+XsIM4zuwn5N4/xRsgKa+SisK92UNMYyl9hVIPKvu/A54cU0zYTdDjYfDGnkurG2RgXDrKIzMpU2LtpoBEtwl3F1H+rzKFJAqe96e39C85GjK1D4s8/TOm3IcHJ5eofeHxI2GeUodysi+DlurRQTSnsUkGa1LXSgkY+4QdlMf+4goNRG5xNdZ8OA2CLY97TPAFqIeej1Amvb9uQBIKvWfbTjDdItBWOhuvAetlNfqnxlcCbnjbCmFTOIbVsHhNW8W1JIElL28mGydbMPimi9brc250E+ImO0Bxp3gMn5oXGV0tUJl5Y8W1lHlEUU7vKK0V7khUob0b3P3lCGQVJyWZEGNodgpr5zkTbR2M8orP4eI9SYoYp2UB0Ag+JkeYSNoQrKZNxSoKBYLVPGzwwGNPBKl7T0CdXlDAOhfZS/FSxdoy8LGRhuTdv7ghQAvstOllibSbjN3wos8ZC8wH2I5LFkekgc4wgcugAwIBEqKBwwSBwHCqBBzSB3g1k9BBC5M8XG5NpM35pvpLMHWjw0HIXloN2XjibgczTBt6l+q4DuWo6OWCuf5U+g+BrQ17y52AnCwUk/l722toAEhxwEKA/f3K+7i/lXBzjfCxGTmD2TTO6NUVZUM6TTa6CvwKgGwzGZLh/kQ90VnyzaOyTErL5oiNtl8ZKfguMt38yV8THESf8ZGjxUCKUUa1n3UNClhVk/0Kl88qGD1h11it0yFoNNK5/tbqI5e+sdi+pK4VHsvjPw== (previous base64 data may contain sensitive data)
Apr 30 13:32:30 auth(?,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: gssapi: Using all keytab entries
Apr 30 13:32:30 auth(noahm@example.com,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: gssapi: security context state completed.
Apr 30 13:32:30 auth: Debug: conn unix:login (pid=6788,uid=1000) [1]: client passdb out: CONT 1 YIGZBgkqhkiG9xIBAgICAG+BiTCBhqADAgEFoQMCAQ+iejB4oAMCARKicQRvsiRFdcazky9GL2l//v2J+U606pbiLSCahGZ2wUxpp05eo9kGAl7j/UQfkzmlOWW7aMfMzPrJTveYBZiDpcfyeTt/wJfAHiEk5A24KYKTIt2ialxe6YOvrmz1e4B+mULZAghrfq5ftdUkQfh0CP/W
Apr 30 13:32:30 auth: Debug: conn unix:login (pid=6788,uid=1000) [1]: client in: CONT 1 (previous base64 data may contain sensitive data)
Apr 30 13:32:30 auth(noahm@example.com,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: gssapi: Negotiated security layer
Apr 30 13:32:30 auth: Debug: conn unix:login (pid=6788,uid=1000) [1]: client passdb out: CONT 1 BQQF/wAMAAAAAAAAFUr00gH/////HIlwJEVFPtqhtCU=
Apr 30 13:32:30 auth: Debug: conn unix:login (pid=6788,uid=1000) [1]: client in: CONT 1 BQQE/wAMAAAAAAAAIfpD4AH///9ub2FobalxyQ7OjgY973Gakw== (previous base64 data may contain sensitive data)
Apr 30 13:32:30 auth(noahm,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: static: Performing passdb lookup
Apr 30 13:32:30 auth(noahm,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: static: lookup
Apr 30 13:32:30 auth(noahm,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: static: Finished passdb lookup
Apr 30 13:32:30 auth(noahm,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: Credentials: 70656e63696c
Apr 30 13:32:30 auth(noahm,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: Auth request finished
Apr 30 13:32:30 auth: Debug: conn unix:login (pid=6788,uid=1000) [1]: client passdb out: OK 1 user=noahm original_user=noahm(a)EXAMPLE.COM
Apr 30 13:32:30 auth: Debug: conn unix:/home/noahm/dovecot-root/b/auth-master (pid=6790,uid=0): Server accepted connection (fd=19)
Apr 30 13:32:30 auth: Debug: master in: REQUEST 4221435905 6788 1 6b8a10b34adc8ace171603fc8d378730 session_pid=6790 request_auth_token
Apr 30 13:32:30 auth(noahm,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: static: Performing userdb lookup
Apr 30 13:32:30 auth(noahm,192.168.1.218,sasl:gssapi)<4aLx8v4z8JPAqAHa>: Debug: static: Finished userdb lookup
Apr 30 13:32:30 auth: Debug: master userdb out: USER 4221435905 noahm uid=4711 gid=4711 home=/home/noahm/dovecot-root auth_mech=GSSAPI auth_token=705494201f3425a0145e2f7af1edca82fee2ee17 auth_user=noahm(a)EXAMPLE.COM
The corresponding client-side logs generated by mutt are:
[2025-04-30 13:32:30] Connecting to dovecot-test...
[2025-04-30 13:32:30] Connected to dovecot-test:17436 on fd=4
[2025-04-30 13:32:30] 4< * OK [CAPABILITY IMAP4rev1 LOGIN-REFERRALS ID ENABLE IDLE SASL-IR LITERAL+ STARTTLS AUTH=PLAIN AUTH=GSSAPI] Dovecot ready.
[2025-04-30 13:32:30] imap_authenticate: Trying method gssapi
[2025-04-30 13:32:30] imap_auth_gsasl: using mech GSSAPI
[2025-04-30 13:32:30] Authenticating (GSSAPI)...
[2025-04-30 13:32:30] 4> a0000 AUTHENTICATE GSSAPI YIIDAAYJKoZIhvcSAQICAQBuggLvMIIC66ADAgEFoQMCAQ6iBwMFACAAAACjggIDYYIB/zCCAfugAwIBBaENGwtFWEFNUExFLkNPTaIfMB2gAwIBA6EWMBQbBGltYXAbDGRvdmVjb3QtdGVzdKOCAcIwggG+oAMCARKhAwIBAqKCAbAEggGsj4jD3VOwvfNdLxjc2hqxFsBYyCvjdOCX0R1So6ANZEYnEWddqZwMCuz7BxXv4z+cXaL6g6iGlVkU4RxQyJQHDFUQC8JroTlyMQ+XsIM4zuwn5N4/xRsgKa+SisK92UNMYyl9hVIPKvu/A54cU0zYTdDjYfDGnkurG2RgXDrKIzMpU2LtpoBEtwl3F1H+rzKFJAqe96e39C85GjK1D4s8/TOm3IcHJ5eofeHxI2GeUodysi+DlurRQTSnsUkGa1LXSgkY+4QdlMf+4goNRG5xNdZ8OA2CLY97TPAFqIeej1Amvb9uQBIKvWfbTjDdItBWOhuvAetlNfqnxlcCbnjbCmFTOIbVsHhNW8W1JIElL28mGydbMPimi9brc250E+ImO0Bxp3gMn5oXGV0tUJl5Y8W1lHlEUU7vKK0V7khUob0b3P3lCGQVJyWZEGNodgpr5zkTbR2M8orP4eI9SYoYp2UB0Ag+JkeYSNoQrKZNxSoKBYLVPGzwwGNPBKl7T0CdXlDAOhfZS/FSxdoy8LGRhuTdv7ghQAvstOllibSbjN3wos8ZC8wH2I5LFkekgc4wgcugAwIBEqKBwwSBwHCqBBzSB3g1k9BBC5M8XG5NpM35pvpLMHWjw0HIXloN2XjibgczTBt6l+q4DuWo6OWCuf5U+g+BrQ17y52AnCwUk/l722toAEhxwEKA/f3K+7i/lXBzjfCxGTmD2TTO6NUVZUM6TTa6CvwKgGwzGZLh/kQ90VnyzaOyTErL5oiNtl8ZKfguMt38yV8THESf8ZGjxUCKUUa1n3UNClhVk/0Kl88qGD1h11it0yFoNNK5/tbqI5e+sdi+pK4VHsvjPw==
[2025-04-30 13:32:30] 4< + YIGZBgkqhkiG9xIBAgICAG+BiTCBhqADAgEFoQMCAQ+iejB4oAMCARKicQRvsiRFdcazky9GL2l//v2J+U606pbiLSCahGZ2wUxpp05eo9kGAl7j/UQfkzmlOWW7aMfMzPrJTveYBZiDpcfyeTt/wJfAHiEk5A24KYKTIt2ialxe6YOvrmz1e4B+mULZAghrfq5ftdUkQfh0CP/W
[2025-04-30 13:32:30] 4>
[2025-04-30 13:32:30] 4< + BQQF/wAMAAAAAAAAFUr00gH/////HIlwJEVFPtqhtCU=
[2025-04-30 13:32:30] 4> BQQE/wAMAAAAAAAAIfpD4AH///9ub2FobalxyQ7OjgY973Gakw==
[2025-04-30 13:32:30] 4< a0000 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE REPLACE SNIPPET=FUZZY PREVIEW=FUZZY PREVIEW SPECIAL-USE STATUS=SIZE SAVEDATE COMPRESS=DEFLATE INPROGRESS NOTIFY LITERAL+] Logged in