Authentication segfault with Dovecot 2.3.13
Harald Leithner
leithner at itronic.at
Wed Jan 6 19:09:13 EET 2021
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 at 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 at 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 at redacted,client-ip,<tgog/jy4erm5j7ZO>): Performing passdb lookup
> Harald> Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug:
> Harald> sql(user at 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 at 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 at 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 at 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 at 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 at 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 at 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 at redacted,client-ip,<tgog/jy4erm5j7ZO>): Finished passdb lookup
> Harald> Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug:
> Harald> auth(user at 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 at redacted,client-ip,<n58h/jy4a0i5j7ZO>): Performing passdb lookup
> Harald> Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug:
> Harald> sql(user at redacted,client-ip,<n58h/jy4a0i5j7ZO>): cache hit:
> Harald> <hidden>#011host=127.0.0.1#011destuser=user at 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 at redacted,client-ip,<n58h/jy4a0i5j7ZO>): Finished passdb lookup
> Harald> Jan 6 16:29:44 mail dovecot[2208071]: auth: Debug:
> Harald> auth(user at 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 at 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 at 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 at redacted,client-ip,<QY6V2zy4FUm5j7YD>): Performing passdb lookup
> Harald> Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug:
> Harald> sql(user at 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 at 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 at 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 at 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 at 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 at 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 at 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 at redacted,client-ip,<QY6V2zy4FUm5j7YD>): Finished passdb lookup
> Harald> Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug:
> Harald> auth(user at 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 at redacted,client-ip,<ZJWX2zy4VzO5j7YD>): Performing passdb lookup
> Harald> Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug:
> Harald> sql(user at redacted,client-ip,<ZJWX2zy4VzO5j7YD>): cache hit:
> Harald> <hidden>#011host=127.0.0.1#011destuser=user at 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 at redacted,client-ip,<ZJWX2zy4VzO5j7YD>): Finished passdb lookup
> Harald> Jan 6 16:20:05 mail dovecot[2208071]: auth: Debug:
> Harald> auth(user at 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 at 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 at 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 at redacted,client-ip,<wXyB3Dy4W0i5j7YD>): Performing passdb lookup
> Harald> Jan 6 16:20:20 mail dovecot[2208071]: auth: Debug:
> Harald> sql(user at redacted,client-ip,<wXyB3Dy4W0i5j7YD>): cache hit:
> Harald> <hidden>#011host=127.0.0.1#011destuser=user at 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 at redacted,client-ip,<wXyB3Dy4W0i5j7YD>): Finished passdb lookup
> Harald> Jan 6 16:20:20 mail dovecot[2208071]: auth: Debug:
> Harald> auth(user at 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 at 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 at 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 at 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 at itronic.at | itronic.at
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_0x473B935C49EA1B08.asc
Type: application/pgp-keys
Size: 3621 bytes
Desc: not available
URL: <https://dovecot.org/pipermail/dovecot/attachments/20210106/686b4a3a/attachment.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature
Type: application/pgp-signature
Size: 665 bytes
Desc: OpenPGP digital signature
URL: <https://dovecot.org/pipermail/dovecot/attachments/20210106/686b4a3a/attachment.sig>
More information about the dovecot
mailing list