Authentication segfault with Dovecot 2.3.13
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" and the user part with "user@redacted".
The user uses APOP for authentication, but other users login successfully with APOP.
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,<tgog/jy4erm5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
"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]
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 <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]
-- 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
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,<tgog/jy4erm5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
Hi
Am 06.01.2021 um 18:08 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 17:13:05 +0100, Harald Leithner wrote:
Hi,
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.
yes
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?
No
Can you share your config? (
doveconf -nwill be a good start, any .ext files may be useful as well)
yes here is the dovecot -n
[root@mail:~]$ doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # OS: Linux 5.9.16-100.fc32.x86_64 x86_64 Generic release 32 (Generic) # Hostname: xxxx auth_cache_negative_ttl = 10 secs auth_cache_size = 64 k auth_cache_ttl = 30 secs auth_mechanisms = CRAM-MD5 DIGEST-MD5 APOP LOGIN PLAIN auth_username_chars = abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@% auth_username_translation = %@AaBbCcDdEeFfGgHhIiJjKkLlMmNnOoPpQqRrSsTtUuVvWwXxYyZz auth_worker_max_count = 150 disable_plaintext_auth = no imap_capability = IMAP4 IMAP4rev1 ACL RIGHTS=texk NAMESPACE CHILDREN SORT QUOTA THREAD=ORDEREDSUBJECT UNSELECT IDLE login_greeting = login_log_format_elements = user=<%u> %r %m %c %k mail_max_userip_connections = 100 passdb { args = /etc/dovecot/sql.conf driver = sql } protocols = imap pop3 service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service imap-login { client_limit = 300 inet_listener imap { address = xx.xx.xx.xx port = 143 } inet_listener imaps { address = xx.xx.xx.xx port = 993 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service pop3-login { client_limit = 300 inet_listener pop3 { address = xx.xx.xx.xx port = 110 } inet_listener pop3s { address = xx.xx.xx.xx port = 995 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service stats { client_limit = 10000 } shutdown_clients = no ssl_alt_cert = </var/lib/letsencrypt-wildcard/ecdsa.pem ssl_alt_key = # hidden, use -P to show it ssl_cert = </var/lib/letsencrypt-wildcard/rsa.pem ssl_cipher_list = ECDHE-RSA-CHACHA20-POLY1305:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA:AES256-SHA ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_options = no_compression ssl_prefer_server_ciphers = yes userdb { args = static uid=5000 gid=5000 home=/dev/null driver = static } version_ignore = yes [root@mail:~]$
Thanks,
Jeff.
thx
Harald
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,<tgog/jy4erm5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
-- 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
Ok, just a quick update. I managed to reproduce it. I'll try to figure out where things went wrong.
Thanks,
Jeff.
On Wed, Jan 06, 2021 at 18:22:03 +0100, Harald Leithner wrote:
Hi
Am 06.01.2021 um 18:08 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 17:13:05 +0100, Harald Leithner wrote:
Hi,
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.
yes
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?
No
Can you share your config? (
doveconf -nwill be a good start, any .ext files may be useful as well)yes here is the dovecot -n
[root@mail:~]$ doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # OS: Linux 5.9.16-100.fc32.x86_64 x86_64 Generic release 32 (Generic) # Hostname: xxxx auth_cache_negative_ttl = 10 secs auth_cache_size = 64 k auth_cache_ttl = 30 secs auth_mechanisms = CRAM-MD5 DIGEST-MD5 APOP LOGIN PLAIN auth_username_chars = abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@% auth_username_translation = %@AaBbCcDdEeFfGgHhIiJjKkLlMmNnOoPpQqRrSsTtUuVvWwXxYyZz auth_worker_max_count = 150 disable_plaintext_auth = no imap_capability = IMAP4 IMAP4rev1 ACL RIGHTS=texk NAMESPACE CHILDREN SORT QUOTA THREAD=ORDEREDSUBJECT UNSELECT IDLE login_greeting = login_log_format_elements = user=<%u> %r %m %c %k mail_max_userip_connections = 100 passdb { args = /etc/dovecot/sql.conf driver = sql } protocols = imap pop3 service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service imap-login { client_limit = 300 inet_listener imap { address = xx.xx.xx.xx port = 143 } inet_listener imaps { address = xx.xx.xx.xx port = 993 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service pop3-login { client_limit = 300 inet_listener pop3 { address = xx.xx.xx.xx port = 110 } inet_listener pop3s { address = xx.xx.xx.xx port = 995 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service stats { client_limit = 10000 } shutdown_clients = no ssl_alt_cert = </var/lib/letsencrypt-wildcard/ecdsa.pem ssl_alt_key = # hidden, use -P to show it ssl_cert = </var/lib/letsencrypt-wildcard/rsa.pem ssl_cipher_list = ECDHE-RSA-CHACHA20-POLY1305:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA:AES256-SHA ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_options = no_compression ssl_prefer_server_ciphers = yes userdb { args = static uid=5000 gid=5000 home=/dev/null driver = static } version_ignore = yes [root@mail:~]$
Thanks,
Jeff.
thx
Harald
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,<tgog/jy4erm5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
-- 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
On Wed, Jan 06, 2021 at 14:07:06 -0500, Josef 'Jeff' Sipek wrote:
Ok, just a quick update. I managed to reproduce it. I'll try to figure out where things went wrong.
Two more questions:
(1) Why are you using a UNION in your SQL statement?
(2) Does the crash still happen if you remove the nodelay parts of the SQL statements?
Thanks,
Jeff.
Thanks,
Jeff.
On Wed, Jan 06, 2021 at 18:22:03 +0100, Harald Leithner wrote:
Hi
Am 06.01.2021 um 18:08 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 17:13:05 +0100, Harald Leithner wrote:
Hi,
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.
yes
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?
No
Can you share your config? (
doveconf -nwill be a good start, any .ext files may be useful as well)yes here is the dovecot -n
[root@mail:~]$ doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # OS: Linux 5.9.16-100.fc32.x86_64 x86_64 Generic release 32 (Generic) # Hostname: xxxx auth_cache_negative_ttl = 10 secs auth_cache_size = 64 k auth_cache_ttl = 30 secs auth_mechanisms = CRAM-MD5 DIGEST-MD5 APOP LOGIN PLAIN auth_username_chars = abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@% auth_username_translation = %@AaBbCcDdEeFfGgHhIiJjKkLlMmNnOoPpQqRrSsTtUuVvWwXxYyZz auth_worker_max_count = 150 disable_plaintext_auth = no imap_capability = IMAP4 IMAP4rev1 ACL RIGHTS=texk NAMESPACE CHILDREN SORT QUOTA THREAD=ORDEREDSUBJECT UNSELECT IDLE login_greeting = login_log_format_elements = user=<%u> %r %m %c %k mail_max_userip_connections = 100 passdb { args = /etc/dovecot/sql.conf driver = sql } protocols = imap pop3 service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service imap-login { client_limit = 300 inet_listener imap { address = xx.xx.xx.xx port = 143 } inet_listener imaps { address = xx.xx.xx.xx port = 993 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service pop3-login { client_limit = 300 inet_listener pop3 { address = xx.xx.xx.xx port = 110 } inet_listener pop3s { address = xx.xx.xx.xx port = 995 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service stats { client_limit = 10000 } shutdown_clients = no ssl_alt_cert = </var/lib/letsencrypt-wildcard/ecdsa.pem ssl_alt_key = # hidden, use -P to show it ssl_cert = </var/lib/letsencrypt-wildcard/rsa.pem ssl_cipher_list = ECDHE-RSA-CHACHA20-POLY1305:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA:AES256-SHA ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_options = no_compression ssl_prefer_server_ciphers = yes userdb { args = static uid=5000 gid=5000 home=/dev/null driver = static } version_ignore = yes [root@mail:~]$
Thanks,
Jeff.
thx
Harald
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,<tgog/jy4erm5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
-- 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
It would appear that nodelay causes the crash here. We are tracking this bug as DOV-4280 internally.
Aki
On 07/01/2021 01:05 Josef 'Jeff' Sipek <jeff.sipek@open-xchange.com> wrote:
On Wed, Jan 06, 2021 at 14:07:06 -0500, Josef 'Jeff' Sipek wrote:
Ok, just a quick update. I managed to reproduce it. I'll try to figure out where things went wrong.
Two more questions:
(1) Why are you using a UNION in your SQL statement?
(2) Does the crash still happen if you remove the nodelay parts of the SQL statements?
Thanks,
Jeff.
Thanks,
Jeff.
On Wed, Jan 06, 2021 at 18:22:03 +0100, Harald Leithner wrote:
Hi
Am 06.01.2021 um 18:08 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 17:13:05 +0100, Harald Leithner wrote:
Hi,
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.
yes
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?
No
Can you share your config? (
doveconf -nwill be a good start, any .ext files may be useful as well)yes here is the dovecot -n
[root@mail:~]$ doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # OS: Linux 5.9.16-100.fc32.x86_64 x86_64 Generic release 32 (Generic) # Hostname: xxxx auth_cache_negative_ttl = 10 secs auth_cache_size = 64 k auth_cache_ttl = 30 secs auth_mechanisms = CRAM-MD5 DIGEST-MD5 APOP LOGIN PLAIN auth_username_chars = abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@% auth_username_translation = %@AaBbCcDdEeFfGgHhIiJjKkLlMmNnOoPpQqRrSsTtUuVvWwXxYyZz auth_worker_max_count = 150 disable_plaintext_auth = no imap_capability = IMAP4 IMAP4rev1 ACL RIGHTS=texk NAMESPACE CHILDREN SORT QUOTA THREAD=ORDEREDSUBJECT UNSELECT IDLE login_greeting = login_log_format_elements = user=<%u> %r %m %c %k mail_max_userip_connections = 100 passdb { args = /etc/dovecot/sql.conf driver = sql } protocols = imap pop3 service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service imap-login { client_limit = 300 inet_listener imap { address = xx.xx.xx.xx port = 143 } inet_listener imaps { address = xx.xx.xx.xx port = 993 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service pop3-login { client_limit = 300 inet_listener pop3 { address = xx.xx.xx.xx port = 110 } inet_listener pop3s { address = xx.xx.xx.xx port = 995 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service stats { client_limit = 10000 } shutdown_clients = no ssl_alt_cert = </var/lib/letsencrypt-wildcard/ecdsa.pem ssl_alt_key = # hidden, use -P to show it ssl_cert = </var/lib/letsencrypt-wildcard/rsa.pem ssl_cipher_list = ECDHE-RSA-CHACHA20-POLY1305:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA:AES256-SHA ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_options = no_compression ssl_prefer_server_ciphers = yes userdb { args = static uid=5000 gid=5000 home=/dev/null driver = static } version_ignore = yes [root@mail:~]$
Thanks,
Jeff.
thx
Harald
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,<tgog/jy4erm5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
-- 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
Hi,
- legacy customer requirement...
- we will try to remove nodelay
thanks
Am 07.01.2021 um 00:05 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 14:07:06 -0500, Josef 'Jeff' Sipek wrote:
Ok, just a quick update. I managed to reproduce it. I'll try to figure out where things went wrong.
Two more questions:
(1) Why are you using a UNION in your SQL statement?
(2) Does the crash still happen if you remove the nodelay parts of the SQL statements?
Thanks,
Jeff.
Thanks,
Jeff.
On Wed, Jan 06, 2021 at 18:22:03 +0100, Harald Leithner wrote:
Hi
Am 06.01.2021 um 18:08 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 17:13:05 +0100, Harald Leithner wrote:
Hi,
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.
yes
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?
No
Can you share your config? (
doveconf -nwill be a good start, any .ext files may be useful as well)yes here is the dovecot -n
[root@mail:~]$ doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # OS: Linux 5.9.16-100.fc32.x86_64 x86_64 Generic release 32 (Generic) # Hostname: xxxx auth_cache_negative_ttl = 10 secs auth_cache_size = 64 k auth_cache_ttl = 30 secs auth_mechanisms = CRAM-MD5 DIGEST-MD5 APOP LOGIN PLAIN auth_username_chars = abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@% auth_username_translation = %@AaBbCcDdEeFfGgHhIiJjKkLlMmNnOoPpQqRrSsTtUuVvWwXxYyZz auth_worker_max_count = 150 disable_plaintext_auth = no imap_capability = IMAP4 IMAP4rev1 ACL RIGHTS=texk NAMESPACE CHILDREN SORT QUOTA THREAD=ORDEREDSUBJECT UNSELECT IDLE login_greeting = login_log_format_elements = user=<%u> %r %m %c %k mail_max_userip_connections = 100 passdb { args = /etc/dovecot/sql.conf driver = sql } protocols = imap pop3 service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service imap-login { client_limit = 300 inet_listener imap { address = xx.xx.xx.xx port = 143 } inet_listener imaps { address = xx.xx.xx.xx port = 993 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service pop3-login { client_limit = 300 inet_listener pop3 { address = xx.xx.xx.xx port = 110 } inet_listener pop3s { address = xx.xx.xx.xx port = 995 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service stats { client_limit = 10000 } shutdown_clients = no ssl_alt_cert = </var/lib/letsencrypt-wildcard/ecdsa.pem ssl_alt_key = # hidden, use -P to show it ssl_cert = </var/lib/letsencrypt-wildcard/rsa.pem ssl_cipher_list = ECDHE-RSA-CHACHA20-POLY1305:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA:AES256-SHA ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_options = no_compression ssl_prefer_server_ciphers = yes userdb { args = static uid=5000 gid=5000 home=/dev/null driver = static } version_ignore = yes [root@mail:~]$
Thanks,
Jeff.
thx
Harald
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,<tgog/jy4erm5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
-- 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
-- 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
Hi,
just a confirmation after removing 'nodelay' we didn't notice any further segfaults.
thanks
Harald
Am 07.01.2021 um 09:05 schrieb Harald Leithner:
Hi,
- legacy customer requirement...
- we will try to remove nodelay
thanks
Am 07.01.2021 um 00:05 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 14:07:06 -0500, Josef 'Jeff' Sipek wrote:
Ok, just a quick update. I managed to reproduce it. I'll try to figure out where things went wrong.
Two more questions:
(1) Why are you using a UNION in your SQL statement?
(2) Does the crash still happen if you remove the nodelay parts of the SQL statements?
Thanks,
Jeff.
Thanks,
Jeff.
On Wed, Jan 06, 2021 at 18:22:03 +0100, Harald Leithner wrote:
Hi
Am 06.01.2021 um 18:08 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 17:13:05 +0100, Harald Leithner wrote:
Hi,
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.
yes
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?
No
Can you share your config? (
doveconf -nwill be a good start, any .ext files may be useful as well)yes here is the dovecot -n
[root@mail:~]$ doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # OS: Linux 5.9.16-100.fc32.x86_64 x86_64 Generic release 32 (Generic) # Hostname: xxxx auth_cache_negative_ttl = 10 secs auth_cache_size = 64 k auth_cache_ttl = 30 secs auth_mechanisms = CRAM-MD5 DIGEST-MD5 APOP LOGIN PLAIN auth_username_chars = abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@% auth_username_translation = %@AaBbCcDdEeFfGgHhIiJjKkLlMmNnOoPpQqRrSsTtUuVvWwXxYyZz auth_worker_max_count = 150 disable_plaintext_auth = no imap_capability = IMAP4 IMAP4rev1 ACL RIGHTS=texk NAMESPACE CHILDREN SORT QUOTA THREAD=ORDEREDSUBJECT UNSELECT IDLE login_greeting = login_log_format_elements = user=<%u> %r %m %c %k mail_max_userip_connections = 100 passdb { args = /etc/dovecot/sql.conf driver = sql } protocols = imap pop3 service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service imap-login { client_limit = 300 inet_listener imap { address = xx.xx.xx.xx port = 143 } inet_listener imaps { address = xx.xx.xx.xx port = 993 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service pop3-login { client_limit = 300 inet_listener pop3 { address = xx.xx.xx.xx port = 110 } inet_listener pop3s { address = xx.xx.xx.xx port = 995 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service stats { client_limit = 10000 } shutdown_clients = no ssl_alt_cert = </var/lib/letsencrypt-wildcard/ecdsa.pem ssl_alt_key = # hidden, use -P to show it ssl_cert = </var/lib/letsencrypt-wildcard/rsa.pem ssl_cipher_list = ECDHE-RSA-CHACHA20-POLY1305:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA:AES256-SHA
ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_options = no_compression ssl_prefer_server_ciphers = yes userdb { args = static uid=5000 gid=5000 home=/dev/null driver = static } version_ignore = yes [root@mail:~]$
Thanks,
Jeff.
thx
Harald
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,<tgog/jy4erm5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb lookup Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
-- 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
-- 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
Hi!
This has been fixed with https://github.com/dovecot/core/commit/225e2e040c5725753eb80a725d3d36878ba9a...
Aki
On 11/01/2021 13:24 Harald Leithner <leithner@itronic.at> wrote:
Hi,
just a confirmation after removing 'nodelay' we didn't notice any further segfaults.
thanks
Harald
Am 07.01.2021 um 09:05 schrieb Harald Leithner:
Hi,
- legacy customer requirement...
- we will try to remove nodelay
thanks
Am 07.01.2021 um 00:05 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 14:07:06 -0500, Josef 'Jeff' Sipek wrote:
Ok, just a quick update. I managed to reproduce it. I'll try to figure out where things went wrong.
Two more questions:
(1) Why are you using a UNION in your SQL statement?
(2) Does the crash still happen if you remove the nodelay parts of the SQL statements?
Thanks,
Jeff.
Thanks,
Jeff.
On Wed, Jan 06, 2021 at 18:22:03 +0100, Harald Leithner wrote:
Hi
Am 06.01.2021 um 18:08 schrieb Josef 'Jeff' Sipek:
On Wed, Jan 06, 2021 at 17:13:05 +0100, Harald Leithner wrote: > Hi, >
> 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.
yes
> 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?
No
Can you share your config? (
doveconf -nwill be a good start, any .ext files may be useful as well)yes here is the dovecot -n
[root@mail:~]$ doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # OS: Linux 5.9.16-100.fc32.x86_64 x86_64 Generic release 32 (Generic) # Hostname: xxxx auth_cache_negative_ttl = 10 secs auth_cache_size = 64 k auth_cache_ttl = 30 secs auth_mechanisms = CRAM-MD5 DIGEST-MD5 APOP LOGIN PLAIN auth_username_chars = abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@% auth_username_translation = %@AaBbCcDdEeFfGgHhIiJjKkLlMmNnOoPpQqRrSsTtUuVvWwXxYyZz auth_worker_max_count = 150 disable_plaintext_auth = no imap_capability = IMAP4 IMAP4rev1 ACL RIGHTS=texk NAMESPACE CHILDREN SORT QUOTA THREAD=ORDEREDSUBJECT UNSELECT IDLE login_greeting = login_log_format_elements = user=<%u> %r %m %c %k mail_max_userip_connections = 100 passdb { args = /etc/dovecot/sql.conf driver = sql } protocols = imap pop3 service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service imap-login { client_limit = 300 inet_listener imap { address = xx.xx.xx.xx port = 143 } inet_listener imaps { address = xx.xx.xx.xx port = 993 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service pop3-login { client_limit = 300 inet_listener pop3 { address = xx.xx.xx.xx port = 110 } inet_listener pop3s { address = xx.xx.xx.xx port = 995 } process_limit = 15 process_min_avail = 1 service_count = 0 vsz_limit = 512 M } service stats { client_limit = 10000 } shutdown_clients = no ssl_alt_cert = </var/lib/letsencrypt-wildcard/ecdsa.pem ssl_alt_key = # hidden, use -P to show it ssl_cert = </var/lib/letsencrypt-wildcard/rsa.pem ssl_cipher_list = ECDHE-RSA-CHACHA20-POLY1305:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA:AES256-SHA
ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_options = no_compression ssl_prefer_server_ciphers = yes userdb { args = static uid=5000 gid=5000 home=/dev/null driver = static } version_ignore = yes [root@mail:~]$
Thanks,
Jeff.
thx
Harald
> 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,<tgog/jy4erm5j7ZO>): Performing passdb > lookup > Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: > sql(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): 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,<tgog/jy4erm5j7ZO>): Finished passdb > lookup > Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: > auth(user@redacted,client-ip,<tgog/jy4erm5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Performing passdb > lookup > Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: > sql(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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,<n58h/jy4a0i5j7ZO>): Finished passdb > lookup > Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug: > auth(user@redacted,client-ip,<n58h/jy4a0i5j7ZO>): 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
-- 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
-- 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
participants (4)
-
Aki Tuomi
-
Harald Leithner
-
John Stoffel
-
Josef 'Jeff' Sipek