Bug 1219301

Summary:	Authentication in dovecot fails due to update of pam to 1.6.0-1.1
Product:	[openSUSE] openSUSE Tumbleweed	Reporter:	Freek de Kruijf <freek>
Component:	Other	Assignee:	E-mail List <screening-team-bugs>
Status:	RESOLVED DUPLICATE	QA Contact:	E-mail List <qa-bugs>
Severity:	Normal
Priority:	P5 - None	CC:	kukuk, suse-beta
Version:	Current
Target Milestone:	---
Hardware:	x86-64
OS:	openSUSE Tumbleweed
Whiteboard:
Found By:	---	Services Priority:
Business Priority:		Blocker:	---
Marketing QA Status:	---	IT Deployment:	---

Description Freek de Kruijf 2024-01-29 14:25:59 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.

Comment 1 Freek de Kruijf 2024-01-29 15:49:25 UTC

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.

Comment 2 Thorsten Kukuk 2024-01-29 15:55:29 UTC

(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 ***

Comment 3 Christian Boltz 2024-01-29 21:31:17 UTC

(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.

Comment 4 Thorsten Kukuk 2024-01-30 06:51:25 UTC

(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.