Re: Authentication segfault with Dovecot 2.3.13

7 Jan 2021

      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 = </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