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@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@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