Re: Authentication segfault with Dovecot 2.3.13

14 Jan 2021

      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 -n will 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 = 
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,): Performing passdb
> lookup
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,): cache expired
> Jan  6 16:29:44 mail dovecot[2208071]: auth-worker(2208404):
> Debug: conn
> unix:auth-worker (pid=2208397,uid=489): auth-worker<229>: Handling
> PASSV
> request
> Jan  6 16:29:44 mail dovecot[2208071]: auth-worker(2208404):
> Debug: conn
> unix:auth-worker (pid=2208397,uid=489): auth-worker<229>:
> sql(user@redacted,client-ip,): Performing passdb
> lookup
> Jan  6 16:29:44 mail dovecot[2208071]: auth-worker(2208404):
> Debug: conn
> unix:auth-worker (pid=2208397,uid=489): auth-worker<229>:
> sql(user@redacted,client-ip,): query: SELECT
> passwd as
> password, '127.0.0.1' as host, userid as destuser, passwd AS pass,
> 'Y'
> AS nologin, 'Y' AS nodelay, 'Y' AS proxy FROM dbmail_users WHERE
> userid='user@redacted' UNION (SELECT password as password,
> '127.0.0.1'
> as host, username as destuser, password AS pass, 'Y' AS nologin,
> 'Y' AS
> nodelay, 'Y' AS proxy FROM sasl_fake_auth WHERE
> username='user@redacted') limit 1;
> Jan  6 16:29:44 mail dovecot[2208071]: auth-worker(2208404): conn
> unix:auth-worker (pid=2208397,uid=489): auth-worker<229>:
> sql(user@redacted,client-ip,): Password mismatch
> Jan  6 16:29:44 mail dovecot[2208071]: auth-worker(2208404):
> Debug: conn
> unix:auth-worker (pid=2208397,uid=489): auth-worker<229>:
> sql(user@redacted,client-ip,): Finished passdb
> lookup
> Jan  6 16:29:44 mail dovecot[2208071]: auth-worker(2208404):
> Debug: conn
> unix:auth-worker (pid=2208397,uid=489): auth-worker<229>: Finished
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,): Finished passdb
> lookup
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug:
> auth(user@redacted,client-ip,): Auth request
> finished
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug: client in:
> AUTH#011443#011APOP#011service=pop3#011secured=tls#011session=n58h/jy4a0i5j7ZO#011lip=lan-ip#011rip=client-ip#011lport=995#011rport=18539#011local_name=mail#011resp=<hidden>
>
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,): Performing passdb
> lookup
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,): cache hit:
> <hidden>#011host=127.0.0.1#011destuser=user@redacted#011pass=THIS_SHOULD_NOT_GET_LOGGED#011nologin=Y#011nodelay=Y#011proxy=Y
>
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,): Finished passdb
> lookup
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug:
> auth(user@redacted,client-ip,): Auth request
> finished
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Debug: client passdb
> out:
> FAIL#011443#011user=user@redacted#011nodelay#011pass=<hidden>#011nodelay=Y
>
> Jan  6 16:29:44 mail dovecot[2208071]: pop3-login: Debug: Ignoring
> unknown passdb extra field: nodelay
> Jan  6 16:29:44 mail dovecot[2208071]: pop3-login: Debug: Ignoring
> unknown passdb extra field: nodelay
> Jan  6 16:29:44 mail dovecot[2208071]: pop3-login: Disconnected (auth
> failed, 1 attempts in 0 secs): user=user@redacted, client-ip, APOP,
> TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
> Jan  6 16:29:44 mail dovecot[2208071]: auth-worker(2208404):
> Debug: conn
> unix:auth-worker (pid=2208397,uid=489): Disconnected: Connection
> closed
> (fd=-1)
> Jan  6 16:29:44 mail dovecot[2208071]: auth: Fatal: master:
> service(auth): child 2208397 killed with signal 11 (core
> dumped)h-worker<1>: Handling PASSV request
>
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug: client in:
> AUTH#01179#011PLAIN#011service=imap#011session=QY6V2zy4FUm5j7YD#011lip=lan-ip#011rip=client-ip#011lport=143#011rport=18709
>
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug: client passdb
> out:
> CONT#01179
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug: client in:
> CONT<hidden>
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Performing passdb
> lookup
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): cache expired
> Jan  6 16:20:05 mail dovecot[2208071]: auth-worker(2208083):
> Debug: conn
> unix:auth-worker (pid=2208074,uid=489): auth-worker<235>: Handling
> PASSV
> request
> Jan  6 16:20:05 mail dovecot[2208071]: auth-worker(2208083):
> Debug: conn
> unix:auth-worker (pid=2208074,uid=489): auth-worker<235>:
> sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Performing passdb
> lookup
> Jan  6 16:20:05 mail dovecot[2208071]: auth-worker(2208083):
> Debug: conn
> unix:auth-worker (pid=2208074,uid=489): auth-worker<235>:
> sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): query: SELECT
> passwd as
> password, '127.0.0.1' as host, userid as destuser, passwd AS pass,
> 'Y'
> AS nologin, 'Y' AS nodelay, 'Y' AS proxy FROM dbmail_users WHERE
> userid='user@redacted' UNION (SELECT password as password,
> '127.0.0.1'
> as host, username as destuser, password AS pass, 'Y' AS nologin,
> 'Y' AS
> nodelay, 'Y' AS proxy FROM sasl_fake_auth WHERE
> username='user@redacted') limit 1;
> Jan  6 16:20:05 mail dovecot[2208071]: auth-worker(2208083): conn
> unix:auth-worker (pid=2208074,uid=489): auth-worker<235>:
> sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Password mismatch
> Jan  6 16:20:05 mail dovecot[2208071]: auth-worker(2208083):
> Debug: conn
> unix:auth-worker (pid=2208074,uid=489): auth-worker<235>:
> sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Finished passdb
> lookup
> Jan  6 16:20:05 mail dovecot[2208071]: auth-worker(2208083):
> Debug: conn
> unix:auth-worker (pid=2208074,uid=489): auth-worker<235>: Finished
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Finished passdb
> lookup
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug:
> auth(user@redacted,client-ip,<QY6V2zy4FUm5j7YD>): Auth request
> finished
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug: client in:
> AUTH#011215#011APOP#011service=pop3#011secured=tls#011session=ZJWX2zy4VzO5j7YD#011lip=lan-ip#011rip=client-ip#011lport=995#011rport=13143#011local_name=mail#011resp=<hidden>
>
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<ZJWX2zy4VzO5j7YD>): Performing passdb
> lookup
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<ZJWX2zy4VzO5j7YD>): cache hit:
> <hidden>#011host=127.0.0.1#011destuser=user@redacted#011pass=THIS_SHOULD_NOT_GET_LOGGED#011nologin=Y#011nodelay=Y#011proxy=Y
>
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<ZJWX2zy4VzO5j7YD>): Finished passdb
> lookup
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug:
> auth(user@redacted,client-ip,<ZJWX2zy4VzO5j7YD>): Auth request
> finished
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Debug: client passdb
> out:
> FAIL#011215#011user=user@redacted#011nodelay#011pass=<hidden>#011nodelay=Y
>
> Jan  6 16:20:05 mail dovecot[2208071]: pop3-login: Debug: Ignoring
> unknown passdb extra field: nodelay
> Jan  6 16:20:05 mail dovecot[2208071]: pop3-login: Debug: Ignoring
> unknown passdb extra field: nodelay
> Jan  6 16:20:05 mail dovecot[2208071]: pop3-login: Disconnected (auth
> failed, 1 attempts in 0 secs): user=user@redacted, client-ip, APOP,
> TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
> Jan  6 16:20:05 mail dovecot[2208071]: auth-worker(2208083):
> Debug: conn
> unix:auth-worker (pid=2208074,uid=489): Disconnected: Connection
> closed
> (fd=-1)
> Jan  6 16:20:05 mail dovecot[2208071]: auth: Fatal: master:
> service(auth): child 2208074 killed with signal 11 (core dumped)
>
> Jan  6 16:20:20 mail dovecot[2208071]: auth: Debug: client in:
> AUTH#011218#011APOP#011service=pop3#011secured=tls#011session=wXyB3Dy4W0i5j7YD#011lip=lan-ip#011rip=client-ip#011lport=995#011rport=18523#011local_name=mail#011resp=<hidden>
>
> Jan  6 16:20:20 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<wXyB3Dy4W0i5j7YD>): Performing passdb
> lookup
> Jan  6 16:20:20 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<wXyB3Dy4W0i5j7YD>): cache hit:
> <hidden>#011host=127.0.0.1#011destuser=user@redacted#011pass=THIS_SHOULD_NOT_GET_LOGGED#011nologin=Y#011nodelay=Y#011proxy=Y
>
> Jan  6 16:20:20 mail dovecot[2208071]: auth: Debug:
> sql(user@redacted,client-ip,<wXyB3Dy4W0i5j7YD>): Finished passdb
> lookup
> Jan  6 16:20:20 mail dovecot[2208071]: auth: Debug:
> auth(user@redacted,client-ip,<wXyB3Dy4W0i5j7YD>): Auth request
> finished
> Jan  6 16:20:20 mail dovecot[2208071]: auth: Debug: client passdb
> out:
> FAIL#011218#011user=user@redacted#011nodelay#011pass=<hidden>#011nodelay=Y
>
> Jan  6 16:20:20 mail dovecot[2208071]: pop3-login: Debug: Ignoring
> unknown passdb extra field: nodelay
> Jan  6 16:20:20 mail dovecot[2208071]: pop3-login: Debug: Ignoring
> unknown passdb extra field: nodelay
> Jan  6 16:20:20 mail dovecot[2208071]: pop3-login: Disconnected (auth
> failed, 1 attempts in 0 secs): user=user@redacted, client-ip, APOP,
> TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
> Jan  6 16:20:20 mail dovecot[2208071]: auth-worker(2208392):
> Debug: conn
> unix:auth-worker (pid=2208385,uid=489): Disconnected: Connection
> closed
> (fd=-1)
> Jan  6 16:20:20 mail dovecot[2208071]: auth: Fatal: master:
> service(auth): child 2208385 killed with signal 11 (core dumped)
>
>
> Any help is appreciated thanks
>
> Harald
> --
> ITronic
>
> Harald Leithner
> Wiedner Hauptstraße 120/5.1, 1050 Wien, Austria
> Tel: +43-1-545 0 604
> Mobil: +43-699-123 78 4 78
> Mail: leithner@itronic.at | itronic.at
--
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

Re: Authentication segfault with Dovecot 2.3.13

Aki Tuomi