Bugzilla – Bug 1219301
Authentication in dovecot fails due to update of pam to 1.6.0-1.1
Last modified: 2024-01-30 06:51:25 UTC
In both fully update Tumbleweed systems, snapshot 20240125, I can't access dovecot. The first Tumbleweed system is my desktop. Until a few days back access was normal. To test I have VM with Tumbleweed and configured dovecot like in the desktop. In the VM IO use telnet 127.0.0.1 143 to access dovecot. Below is the log (base64 encrypted password replaced with <base64 encrypted password>): yastdev:~ # echo -en "\0user\0password" | openssl base64 <base64 encrypted user/password> yastdev:~ # telnet 127.0.0.1 143 Trying 127.0.0.1... Connected to 127.0.0.1. Escape character is '^]'. * OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ STARTTLS AUTH=PLAIN] Dovecot ready. a authenticate plain + <base64 encrypted user/password> a NO [AUTHENTICATIONFAILED] Authentication failed. a logout * BYE Logging out a OK Logout completed. Connection closed by foreign host. I enabled all auth logging in 10-logging.conf. The logging of dovecot is below: Jan 29 15:01:40 yastdev dovecot[1412]: auth: Debug: Loading modules from directory: /usr/lib64/dovecot/modules/auth Jan 29 15:01:40 yastdev dovecot[1412]: auth: Debug: Module loaded: /usr/lib64/dovecot/modules/auth/lib20_auth_var_expand_crypt.so Jan 29 15:01:40 yastdev dovecot[1412]: auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat Jan 29 15:01:40 yastdev dovecot[1412]: auth: Debug: auth client connected (pid=1841) Jan 29 15:02:26 yastdev dovecot[1412]: auth: Debug: client in: AUTH 1 PLAIN service=imap secured session=vWF4GBYQRNF/AAAB lip=127.0.0.1 rip=127.0.0.1 lport=143 rport=53572 Jan 29 15:02:26 yastdev dovecot[1412]: auth: Debug: client passdb out: CONT 1 Jan 29 15:02:36 yastdev dovecot[1412]: auth: Debug: client in: CONT 1 <base64 encrypted user/password> (previous base64 data may contain sensitive data) Jan 29 15:02:36 yastdev dovecot[1412]: auth: Debug: pam(freek,127.0.0.1,<vWF4GBYQRNF/AAAB>): Performing passdb lookup Jan 29 15:02:36 yastdev dovecot[1412]: auth-worker(1848): Debug: Loading modules from directory: /usr/lib64/dovecot/modules/auth Jan 29 15:02:36 yastdev dovecot[1412]: auth-worker(1848): Debug: Module loaded: /usr/lib64/dovecot/modules/auth/lib20_auth_var_expand_crypt.so Jan 29 15:02:36 yastdev dovecot[1412]: auth-worker(1848): Debug: conn unix:auth-worker (pid=1842,uid=471): Server accepted connection (fd=13) Jan 29 15:02:36 yastdev dovecot[1412]: auth-worker(1848): Debug: conn unix:auth-worker (pid=1842,uid=471): Sending version handshake Jan 29 15:02:36 yastdev dovecot[1412]: auth-worker(1848): Debug: conn unix:auth-worker (pid=1842,uid=471): auth-worker<1>: Handling PASSV request Jan 29 15:02:36 yastdev dovecot[1412]: auth-worker(1848): Debug: conn unix:auth-worker (pid=1842,uid=471): auth-worker<1>: pam(freek,127.0.0.1,<vWF4GBYQRNF/AAAB>): Performing passdb lookup Jan 29 15:02:36 yastdev dovecot[1412]: auth-worker(1848): Debug: conn unix:auth-worker (pid=1842,uid=471): auth-worker<1>: pam(freek,127.0.0.1,<vWF4GBYQRNF/AAAB>): lookup service=dovecot Jan 29 15:02:36 yastdev dovecot[1412]: auth-worker(1848): Debug: conn unix:auth-worker (pid=1842,uid=471): auth-worker<1>: pam(freek,127.0.0.1,<vWF4GBYQRNF/AAAB>): #1/1 style=1 msg=Password: Jan 29 15:02:36 yastdev auth[1848]: pam_unix(dovecot:auth): authentication failure; logname= uid=0 euid=0 tty=dovecot ruser=freek rhost=127.0.0.1 user=freek Jan 29 15:02:38 yastdev dovecot[1412]: auth-worker(1848): conn unix:auth-worker (pid=1842,uid=471): auth-worker<1>: pam(freek,127.0.0.1,<vWF4GBYQRNF/AAAB>): pam_authenticate() failed: Authentication service cannot retrieve authentication info Jan 29 15:02:38 yastdev dovecot[1412]: auth-worker(1848): Debug: conn unix:auth-worker (pid=1842,uid=471): auth-worker<1>: pam(freek,127.0.0.1,<vWF4GBYQRNF/AAAB>): Finished passdb lookup Jan 29 15:02:38 yastdev dovecot[1412]: auth-worker(1848): Debug: conn unix:auth-worker (pid=1842,uid=471): auth-worker<1>: Finished: password_mismatch Jan 29 15:02:38 yastdev dovecot[1412]: auth: Debug: pam(freek,127.0.0.1,<vWF4GBYQRNF/AAAB>): Finished passdb lookup Jan 29 15:02:38 yastdev dovecot[1412]: auth: Debug: auth(freek,127.0.0.1,<vWF4GBYQRNF/AAAB>): Auth request finished Jan 29 15:02:40 yastdev dovecot[1412]: auth: Debug: client passdb out: FAIL 1 user=freek Jan 29 15:02:47 yastdev dovecot[1412]: imap-login: Disconnected: Aborted login by logging out (auth failed, 1 attempts in 21 secs): user=<freek>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<vWF4GBYQRNF/AAAB> Can't find what's wrong.
I went back to snapshot 20240122 and authentication works. Setting Tumbleweed on 20240123 and installing only pam-1.6.0-1.1 made it not working. So there is something wrong in pam-1.6.0-1.1.
(In reply to Freek de Kruijf from comment #1) > I went back to snapshot 20240122 and authentication works. Setting > Tumbleweed on 20240123 and installing only pam-1.6.0-1.1 made it not working. > > So there is something wrong in pam-1.6.0-1.1. Nothing is wrong in pam-1.6.0, you did run into a long standing bug in the apparmor profile. *** This bug has been marked as a duplicate of bug 1219139 ***
(In reply to Thorsten Kukuk from comment #2) > Nothing is wrong in pam-1.6.0, you did run into a long standing bug in the > apparmor profile. "long standing bug" is an interesting description for something that was reported 5 days ago ;-) Anyway - SR 1142650 sent.
(In reply to Christian Boltz from comment #3) > (In reply to Thorsten Kukuk from comment #2) > > Nothing is wrong in pam-1.6.0, you did run into a long standing bug in the > > apparmor profile. > > "long standing bug" is an interesting description for something that was > reported 5 days ago ;-) That the bug got only reported 5 days ago does not mean that it did not exist for longer. pam_unix.so is calling unix_chkpwd since ~25 years or even longer. So the apparmor profile was incomplete from day 1. That nobody run into it earlier was only by pure luck.