Hi,small correction, the devices that tries to login and triggers the segfault uses an old password and can't login and segfaults the auth process. On 2.2 the login wasn't successful too but didn't segfault.
Harald Am 06.01.2021 um 18:01 schrieb John Stoffel:
"Harald" == Harald Leithner <leith...@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: leith...@itronic.at | itronic.at Harald> [DELETED ATTACHMENT OpenPGP_0x473B935C49EA1B08.asc, application/pgp-keys] Harald> [DELETED ATTACHMENT OpenPGP_signature, application/pgp-signature]
-- 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: leith...@itronic.at | itronic.at
OpenPGP_0x473B935C49EA1B08.asc
Description: application/pgp-keys
OpenPGP_signature
Description: OpenPGP digital signature
