On Tue, Apr 29, 2025 at 10:48:24PM +0200, Simon Josefsson wrote: > Okay that would help to confirm if this is a dovecot problem or gsasl > problem. You could try increasing the dovecot debug logging during the > gsasl test, the generic error in dovecot must be caused by something > and understanding what could explain things a bit. Maybe some file > ownership/permissions problem or additional GSSAPI flag check that > dovecot didn’t do before.
It does seem to work with mutt as the client. This is dovecot's log: Apr 29 21:19:10 auth: Debug: conn unix:login (pid=5052,uid=1000) [3]: Server accepted connection (fd=18) Apr 29 21:19:10 auth: Debug: conn unix:login (pid=5052,uid=1000) [3]: auth client connected (pid=5052) Apr 29 21:19:10 auth: Debug: conn unix:login (pid=5052,uid=1000) [3]: client in: AUTH 1 GSSAPI protocol=imap final-resp-ok session=E98AWvEz1M5/AAAB lip=127.1.0.1 rip=127.0.0.1 lport=17436 rport=52948 resp=<hidden> Apr 29 21:19:10 auth(?,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: gssapi: Using all keytab entries Apr 29 21:19:10 auth(no...@example.com,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: gssapi: security context state completed. Apr 29 21:19:10 auth: Debug: conn unix:login (pid=5052,uid=1000) [3]: client passdb out: CONT 1 YIGZBgkqhkiG9xIBAgICAG+BiTCBhqADAgEFoQMCAQ+iejB4oAMCARKicQRvKCyNoO6p6n0HP0FsFreKAgvHTivC3NDdUYW1CEL0qsGUX4nqq4NmH01nwd5CVUE6vsDXLH7s5E/GuTZ1wVH2hzGXd+rb76VkmJ5GN21noUyBvV04Ot65FJMuDVk/xDe6MM6Uu+tyd5DZkqWrrfu4 Apr 29 21:19:10 auth: Debug: conn unix:login (pid=5052,uid=1000) [3]: client in: CONT<hidden> Apr 29 21:19:10 auth(no...@example.com,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: gssapi: Negotiated security layer Apr 29 21:19:10 auth: Debug: conn unix:login (pid=5052,uid=1000) [3]: client passdb out: CONT 1 BQQF/wAMAAAAAAAAApB15wH///8zSvrjf4Q4Ghvfo8M= Apr 29 21:19:10 auth: Debug: conn unix:login (pid=5052,uid=1000) [3]: client in: CONT<hidden> Apr 29 21:19:10 auth(noahm,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: static: Performing passdb lookup Apr 29 21:19:10 auth(noahm,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: static: lookup Apr 29 21:19:10 auth(noahm,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: static: Finished passdb lookup Apr 29 21:19:10 auth(noahm,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: Auth request finished Apr 29 21:19:10 auth: Debug: conn unix:login (pid=5052,uid=1000) [3]: client passdb out: OK 1 user=noahm original_user=no...@example.com Apr 29 21:19:10 auth: Debug: conn unix:/home/noahm/dovecot-root/b/auth-master (pid=5053,uid=0): Server accepted connection (fd=19) Apr 29 21:19:10 auth: Debug: master in: REQUEST 283377665 5052 1 fc092f982d6b8c048cee7ea65413f937 session_pid=5053 request_auth_token Apr 29 21:19:10 auth(noahm,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: static: Performing userdb lookup Apr 29 21:19:10 auth(noahm,127.0.0.1,sasl:gssapi)<E98AWvEz1M5/AAAB>: Debug: static: Finished userdb lookup Apr 29 21:19:10 auth: Debug: master userdb out: USER 283377665 noahm uid=4711 gid=4711 home=/home/noahm/dovecot-root auth_mech=GSSAPI auth_token=7c6e502ac940d20740da0c4bd734a7eac67cfbf8 auth_user=no...@example.com Apr 29 21:19:10 imap-login: Info: Logged in: user=<noahm>, method=GSSAPI, rip=127.0.0.1, lip=127.1.0.1, mpid=5053, session=<E98AWvEz1M5/AAAB> This was a hacked together krb5 realm, but it does work. Yet gsasl still isn't able to authenticate to the above server: Apr 29 21:21:10 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: Server accepted connection (fd=18) Apr 29 21:21:10 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: auth client connected (pid=5098) Apr 29 21:21:10 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: client in: AUTH 1 GSSAPI protocol=imap final-resp-ok session=3PoqYfEzfrd/AAAB lip=127.1.0.1 rip=127.0.0.1 lport=17436 rport=46974 Apr 29 21:21:10 auth(?,127.0.0.1,sasl:gssapi)<3PoqYfEzfrd/AAAB>: Debug: gssapi: Using all keytab entries Apr 29 21:21:10 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: client passdb out: CONT 1 # Apr 29 21:21:10 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: client in: CONT<hidden> Apr 29 21:21:10 auth(?,127.0.0.1,sasl:gssapi)<3PoqYfEzfrd/AAAB>: Debug: gssapi: Processed incoming packet correctly, waiting for another. Apr 29 21:21:10 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: client passdb out: CONT 1 YEcGBisGAQUFAqA9MDugDTALBgkqhkiG9xIBAgKjKjAooCYbJG5vdF9kZWZpbmVkX2luX1JGQzQxNzhAcGxlYXNlX2lnbm9yZQ== Apr 29 21:21:10 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: client in: CONT<hidden> Apr 29 21:21:10 auth(?,127.0.0.1,sasl:gssapi)<3PoqYfEzfrd/AAAB>: Info: gssapi: While processing incoming data: Invalid token was supplied Apr 29 21:21:10 auth(?,127.0.0.1,sasl:gssapi)<3PoqYfEzfrd/AAAB>: Info: gssapi: While processing incoming data: Unknown error Apr 29 21:21:10 auth(?,127.0.0.1,sasl:gssapi)<3PoqYfEzfrd/AAAB>: Debug: Auth request finished Apr 29 21:21:10 auth(?,127.0.0.1,sasl:gssapi)<3PoqYfEzfrd/AAAB>: Debug: delaying auth failure Apr 29 21:21:12 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: client passdb out: FAIL 1 Apr 29 21:21:12 imap-login: Info: Login aborted: Connection closed (auth failed, 1 attempts in 2 secs) (auth_failed): user=<>, method=GSSAPI, rip=127.0.0.1, lip=127.1.0.1, session=<3PoqYfEzfrd/AAAB> Apr 29 21:21:12 auth: Debug: conn unix:login (pid=5098,uid=1000) [5]: Disconnected: Connection closed (fd=18) There are a few noticable differences in the logs that don't mean much to me (I've been out of the krb5 world for quite a while now). These stand out to me: 1. The "client in: AUTH 1" line contains an additional field on the successful log "resp=<hidden>" 2. The successful login logs "Debug: gssapi: security context state completed." fairly early in the output, but there seems to be some additional protocol activity at the same point in the unsuccessful session, and it never indicates "security context state completed". noah
