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