On Wed, Jan 06, 2021 at 17:13:05 +0100, Harald Leithner wrote:
Hi,
we have a problem upgrading Dovecot from 2.2 to 2.3.13 on one server it seems one user triggers a segfault while trying to authenticate.
The user works fine with 2.2.36.4, our last update try mid-late 2020 was aborted because of this reason.
While debugging the problem we noticed that the "auth_debug_passwords = no" option doesn't work at least in our logfiles are the passwords logged. We replaced the password in the log with "THIS_SHOULD_NOT_GET_LOGGED"
It should. It looks like on of the places in the code (specifically the "cache hit" message) has password hiding code that's buggy/incomplete.
and the user part with "user@redacted".
I assume you did this for additional privacy, and not because you think that auth_debug_passwords=no should hide usernames as well.
The user uses APOP for authentication, but other users login successfully with APOP.
Do you only use APOP? Or are other authentication schemes affected as well?
Can you share your config? (doveconf -n will be a good start, any .ext
files may be useful as well)
Thanks,
Jeff.
Here is a stacktrace and a log dump:
Jan 6 16:29:44 mail kernel: auth[2208397]: segfault at ec ip 00007f67fc147174 sp 00007ffeed993150 error 4 in libdovecot.so.0.0.0[7f67fc06e000+fc000] Jan 6 16:29:44 mail kernel: Code: 1f 80 00 00 00 00 41 54 e8 79 fd ff ff 31 f6 49 89 c4 48 89 c7 31 c0 e8 ca f8 ff ff 4c 89 e0 41 5c c3 0f 1f 40 00 53 48 89 fb <f6> 87 ec 00 00 00 04 75 43 48 83 3d 7b aa 0a 00 00 0f 85 50 15 f4 Jan 6 16:29:44 mail systemd[1]: Started Process Core Dump (PID 2208677/UID 0). Jan 6 16:29:44 mail systemd-coredump[2208678]: Process 2208397 (auth) of user 489 dumped core.#012#012Stack trace of thread 2208397:#012#0 0x00007f67fc147174 event_create_passthrough (libdovecot.so.0 + 0x116174)#012#1 0x0000555678812d6e auth_request_finished_event (auth + 0x1bd6e)#012#2 0x00005556788159ae auth_request_log_finished (auth + 0x1e9ae)#012#3 0x0000555678816ee0 n/a (auth + 0x1fee0)#012#4 0x0000555678826dc1 passdb_handle_credentials (auth + 0x2fdc1)#012#5 0x0000555678816c7e n/a (auth + 0x1fc7e)#012#6 0x0000555678824f27 n/a (auth + 0x2df27)#012#7 0x000055567881b02d auth_request_handler_auth_begin (auth + 0x2402d)#012#8 0x000055567880dfaf n/a (auth + 0x16faf)#012#9 0x00007f67fc143a79 io_loop_call_io (libdovecot.so.0 + 0x112a79)#012#10 0x00007f67fc144ae2 io_loop_handler_run_internal (libdovecot.so.0 + 0x113ae2)#012#11 0x00007f67fc143b21 io_loop_handler_run (libdovecot.so.0 + 0x112b21)#012#12 0x00007f67fc143ce0 io_loop_run (libdovecot.so.0 + 0x112ce0)#012#13 0x00007f67fc0b96f3 master_service_run (libdovecot.so.0
- 0x886f3)#012#14 0x000055567880c2db main (auth + 0x152db)#012#15 0x00007f67fbc9d042 __libc_start_main (libc.so.6 + 0x27042)#012#16 0x000055567880c48e _start (auth + 0x1548e)
Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: client in: AUTH#011134#011PLAIN#011service=imap#011session=tgog/jy4erm5j7ZO#011lip=lan-ip#011rip=client-ip#011lport=143#011rport=47482 Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: client passdb out: CONT#011134 Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: client in: CONT<hidden> Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,
): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip, ): cache expired Jan 6 16:29:44 mail dovecot[2208071]: auth-worker(2208404): Debug: conn unix:auth-worker (pid=2208397,uid=489): auth-worker<229>: Handling PASSV request Jan 6 16:29:44 mail dovecot[2208071]: auth-worker(2208404): Debug: conn unix:auth-worker (pid=2208397,uid=489): auth-worker<229>: sql(user@redacted,client-ip, ): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth-worker(2208404): Debug: conn unix:auth-worker (pid=2208397,uid=489): auth-worker<229>: sql(user@redacted,client-ip, ): query: SELECT passwd as password, '127.0.0.1' as host, userid as destuser, passwd AS pass, 'Y' AS nologin, 'Y' AS nodelay, 'Y' AS proxy FROM dbmail_users WHERE userid='user@redacted' UNION (SELECT password as password, '127.0.0.1' as host, username as destuser, password AS pass, 'Y' AS nologin, 'Y' AS nodelay, 'Y' AS proxy FROM sasl_fake_auth WHERE username='user@redacted') limit 1; Jan 6 16:29:44 mail dovecot[2208071]: auth-worker(2208404): conn unix:auth-worker (pid=2208397,uid=489): auth-worker<229>: sql(user@redacted,client-ip, ): Password mismatch Jan 6 16:29:44 mail dovecot[2208071]: auth-worker(2208404): Debug: conn unix:auth-worker (pid=2208397,uid=489): auth-worker<229>: sql(user@redacted,client-ip, ): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth-worker(2208404): Debug: conn unix:auth-worker (pid=2208397,uid=489): auth-worker<229>: Finished Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip, ): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip, ): Auth request finished Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: client in: AUTH#011443#011APOP#011service=pop3#011secured=tls#011session=n58h/jy4a0i5j7ZO#011lip=lan-ip#011rip=client-ip#011lport=995#011rport=18539#011local_name=mail#011resp=<hidden> Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip, ): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip, ): cache hit: <hidden>#011host=127.0.0.1#011destuser=user@redacted#011pass=THIS_SHOULD_NOT_GET_LOGGED#011nologin=Y#011nodelay=Y#011proxy=Y Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip, ): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip, ): Auth request finished Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: client passdb out: FAIL#011443#011user=user@redacted#011nodelay#011pass=<hidden>#011nodelay=Y Jan 6 16:29:44 mail dovecot[2208071]: pop3-login: Debug: Ignoring unknown passdb extra field: nodelay Jan 6 16:29:44 mail dovecot[2208071]: pop3-login: Debug: Ignoring unknown passdb extra field: nodelay Jan 6 16:29:44 mail dovecot[2208071]: pop3-login: Disconnected (auth failed, 1 attempts in 0 secs): user=user@redacted, client-ip, APOP, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) Jan 6 16:29:44 mail dovecot[2208071]: auth-worker(2208404): Debug: conn unix:auth-worker (pid=2208397,uid=489): Disconnected: Connection closed (fd=-1) Jan 6 16:29:44 mail dovecot[2208071]: auth: Fatal: master: service(auth): child 2208397 killed with signal 11 (core dumped)h-worker<1>: Handling PASSV request Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: client in: AUTH#01179#011PLAIN#011service=imap#011session=QY6V2zy4FUm5j7YD#011lip=lan-ip#011rip=client-ip#011lport=143#011rport=18709 Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: client passdb out: CONT#01179 Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: client in: CONT<hidden> Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Performing passdb lookup Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): cache expired Jan 6 16:20:05 mail dovecot[2208071]: auth-worker(2208083): Debug: conn unix:auth-worker (pid=2208074,uid=489): auth-worker<235>: Handling PASSV request Jan 6 16:20:05 mail dovecot[2208071]: auth-worker(2208083): Debug: conn unix:auth-worker (pid=2208074,uid=489): auth-worker<235>: sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Performing passdb lookup Jan 6 16:20:05 mail dovecot[2208071]: auth-worker(2208083): Debug: conn unix:auth-worker (pid=2208074,uid=489): auth-worker<235>: sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): query: SELECT passwd as password, '127.0.0.1' as host, userid as destuser, passwd AS pass, 'Y' AS nologin, 'Y' AS nodelay, 'Y' AS proxy FROM dbmail_users WHERE userid='user@redacted' UNION (SELECT password as password, '127.0.0.1' as host, username as destuser, password AS pass, 'Y' AS nologin, 'Y' AS nodelay, 'Y' AS proxy FROM sasl_fake_auth WHERE username='user@redacted') limit 1; Jan 6 16:20:05 mail dovecot[2208071]: auth-worker(2208083): conn unix:auth-worker (pid=2208074,uid=489): auth-worker<235>: sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Password mismatch Jan 6 16:20:05 mail dovecot[2208071]: auth-worker(2208083): Debug: conn unix:auth-worker (pid=2208074,uid=489): auth-worker<235>: sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Finished passdb lookup Jan 6 16:20:05 mail dovecot[2208071]: auth-worker(2208083): Debug: conn unix:auth-worker (pid=2208074,uid=489): auth-worker<235>: Finished Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Finished passdb lookup Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Auth request finished Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: client in: AUTH#011215#011APOP#011service=pop3#011secured=tls#011session=ZJWX2zy4VzO5j7YD#011lip=lan-ip#011rip=client-ip#011lport=995#011rport=13143#011local_name=mail#011resp=<hidden> Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<ZJWX2zy4VzO5j7YD>): Performing passdb lookup Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<ZJWX2zy4VzO5j7YD>): cache hit: <hidden>#011host=127.0.0.1#011destuser=user@redacted#011pass=THIS_SHOULD_NOT_GET_LOGGED#011nologin=Y#011nodelay=Y#011proxy=Y Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<ZJWX2zy4VzO5j7YD>): Finished passdb lookup Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<ZJWX2zy4VzO5j7YD>): Auth request finished Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug: client passdb out: FAIL#011215#011user=user@redacted#011nodelay#011pass=<hidden>#011nodelay=Y Jan 6 16:20:05 mail dovecot[2208071]: pop3-login: Debug: Ignoring unknown passdb extra field: nodelay Jan 6 16:20:05 mail dovecot[2208071]: pop3-login: Debug: Ignoring unknown passdb extra field: nodelay Jan 6 16:20:05 mail dovecot[2208071]: pop3-login: Disconnected (auth failed, 1 attempts in 0 secs): user=user@redacted, client-ip, APOP, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) Jan 6 16:20:05 mail dovecot[2208071]: auth-worker(2208083): Debug: conn unix:auth-worker (pid=2208074,uid=489): Disconnected: Connection closed (fd=-1) Jan 6 16:20:05 mail dovecot[2208071]: auth: Fatal: master: service(auth): child 2208074 killed with signal 11 (core dumped)
Jan 6 16:20:20 mail dovecot[2208071]: auth: Debug: client in: AUTH#011218#011APOP#011service=pop3#011secured=tls#011session=wXyB3Dy4W0i5j7YD#011lip=lan-ip#011rip=client-ip#011lport=995#011rport=18523#011local_name=mail#011resp=<hidden> Jan 6 16:20:20 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<wXyB3Dy4W0i5j7YD>): Performing passdb lookup Jan 6 16:20:20 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<wXyB3Dy4W0i5j7YD>): cache hit: <hidden>#011host=127.0.0.1#011destuser=user@redacted#011pass=THIS_SHOULD_NOT_GET_LOGGED#011nologin=Y#011nodelay=Y#011proxy=Y Jan 6 16:20:20 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<wXyB3Dy4W0i5j7YD>): Finished passdb lookup Jan 6 16:20:20 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<wXyB3Dy4W0i5j7YD>): Auth request finished Jan 6 16:20:20 mail dovecot[2208071]: auth: Debug: client passdb out: FAIL#011218#011user=user@redacted#011nodelay#011pass=<hidden>#011nodelay=Y Jan 6 16:20:20 mail dovecot[2208071]: pop3-login: Debug: Ignoring unknown passdb extra field: nodelay Jan 6 16:20:20 mail dovecot[2208071]: pop3-login: Debug: Ignoring unknown passdb extra field: nodelay Jan 6 16:20:20 mail dovecot[2208071]: pop3-login: Disconnected (auth failed, 1 attempts in 0 secs): user=user@redacted, client-ip, APOP, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) Jan 6 16:20:20 mail dovecot[2208071]: auth-worker(2208392): Debug: conn unix:auth-worker (pid=2208385,uid=489): Disconnected: Connection closed (fd=-1) Jan 6 16:20:20 mail dovecot[2208071]: auth: Fatal: master: service(auth): child 2208385 killed with signal 11 (core dumped)
Any help is appreciated thanks
Harald
ITronic
Harald Leithner Wiedner Hauptstraße 120/5.1, 1050 Wien, Austria Tel: +43-1-545 0 604 Mobil: +43-699-123 78 4 78 Mail: leithner@itronic.at | itronic.at