Hello Dovecot list,
We've been running a really old CentOS 5 server with the stock dovecot from
yum (1.0.7) for years and years with absolutely no problems. If it ain't
broke, don't fix it, or something like that.
Well it finally broke, but only due to the server no longer being able to handle
the load of the increasing user base (many thousands now, with hundreds of
concurrent IMAP connections any any given time)
So we upgraded to a new CentOS 7 server with SSD RAID, fast CPUs and tons of
RAM. No more load problems. We compiled the latest dovecot from source (as the
version from CentOS yum repo is already quite old, figure we might as well run
the latest version since we were upgrading anyway).
Thanks to excellent documentation on dovecot.org and fairly thorough testing,
the upgrade was quite smooth. We kept all the message UUIDs intact and tried to
match the supported authentication methods etc to the old setup, and we
didn't have any problems with clients re-downloading or re-syncing mail.
We do however have one problem, which prompted me to join this list. It is the
same problem as described in this thread from last
month:?http://dovecot.org/list/dovecot/2016-July/104899.html
Here's the excerpt from our maillog:
Sep 17 19:34:57 mail dovecot: auth: Panic: file auth-request.c: line 1049
(auth_request_lookup_credentials): assertion failed:
(request->credentials_scheme == scheme)
Sep 17 19:34:57 mail dovecot: auth: Error: Raw backtrace:
/usr/local/lib/dovecot/libdovecot.so.0(+0x89470) [0x7fa9cb8af470] ->
/usr/local/lib/dovecot/libdovecot.so.0(+0x8954e) [0x7fa9cb8af54e] ->
/usr/local/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7fa9cb851f75] ->
dovecot/auth() [0x4165bc] -> dovecot/auth() [0x4221fb] -> dovecot/auth()
[0x41620b] -> dovecot/auth(auth_request_lookup_credentials_callback+0x58)
[0x4162f8] -> dovecot/auth(passdb_handle_credentials+0x6a) [0x4254ba] ->
dovecot/auth() [0x425b62] -> dovecot/auth() [0x41c1f8] ->
/usr/local/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x4c) [0x7fa9cb8c207c]
-> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xd7)
[0x7fa9cb8c3377] ->
/usr/local/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x25)
[0x7fa9cb8c2105] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_run+0x38)
[0x7fa9cb8c22b8] ->
/usr/local/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7fa9cb857f33]
-> dovecot/auth(main+0x2eb) [0x40ccdb] ->
/lib64/libc.so.6(__libc_start_main+0xf5) [0x7fa9c9dc2b15] -> dovecot/auth()
[0x40cf15]
On the client side, it manifests as an authentication failure, and the user is
prompted to re-enter their password. The reports we've had are all from
users who have their passwords saved in a local password manager, so the client
is definitely sending the correct password. It's not related to a particular
mail client. It is also definitely not related to the particular user or
password, as the user will authenticate many times successfully and then
(seemingly) randomly be hit by this bug and prompted to re-enter their password.
We enabled verbose logging and even logging of passwords for failed
authentication attempts in an attempt to find a pattern, but so far we have not
found one.
Similar to the original poster in the above thread, we are using a MySQL
backend, and CentOS 7 on x86_64
It happens quite frequently: in the past 6 days it happened?49175 times,
according to a grep of the maillog. In the same period there were?294167
successful IMAP logins and?160322 POP3 logins.
For now we have downgraded to 2.2.4 and so far have not seen the crash recorded
in the maillog.
What can we do to help track down and fix this bug?
# dovecot -n
# 2.2.24 (a82c823): /usr/local/etc/dovecot/dovecot.conf
# OS: Linux 3.10.0-327.28.3.el7.x86_64 x86_64 CentOS Linux release 7.2.1511
(Core) ?ext4
auth_debug = yes
auth_debug_passwords = yes
auth_mechanisms = plain login digest-md5 cram-md5 ntlm rpa apop
auth_verbose = yes
auth_verbose_passwords = plain
debug_log_path = /var/log/dovecot-debug.log
default_client_limit = 5000
default_process_limit = 1000
disable_plaintext_auth = no
first_valid_uid = 89
mail_debug = yes
mail_fsync = never
mail_gid = 89
mail_location = maildir:/var/virtual/%d/%n
mail_uid = 89
namespace inbox {
? inbox = yes
? location =?
? mailbox Drafts {
? ? special_use = \Drafts
? }
? mailbox Junk {
? ? special_use = \Junk
? }
? mailbox Sent {
? ? special_use = \Sent
? }
? mailbox "Sent Messages" {
? ? special_use = \Sent
? }
? mailbox Trash {
? ? special_use = \Trash
? }
? prefix =?
}
passdb {
? args = /usr/local/etc/dovecot/dovecot-sql.conf.ext
? driver = sql
}
pop3_client_workarounds = outlook-no-nuls oe-ns-eoh
service auth {
? unix_listener /var/spool/postfix/private/auth {
? ? group = postfix
? ? mode = 0660
? ? user = postfix
? }
}
ssl_ca = <***
ssl_cert = <***
ssl_key = <***
userdb {
? args = /usr/local/etc/dovecot/dovecot-sql.conf.ext
? driver = sql
}
verbose_ssl = yes
protocol lmtp {
? mail_fsync = optimized
}
protocol lda {
? mail_fsync = optimized
}
protocol imap {
? mail_max_userip_connections = 50
}
protocol pop3 {
? mail_max_userip_connections = 20
}
--
Chris?Wik
Anu?Internet?Services
www.anu.net?|?www.cwik.ch
> On September 17, 2016 at 9:15 PM Chris Wik <chris at anu.net> wrote: > > > > Hello Dovecot list, > > > We've been running a really old CentOS 5 server with the stock dovecot from yum (1.0.7) for years and years with absolutely no problems. If it ain't broke, don't fix it, or something like that. > > > Well it finally broke, but only due to the server no longer being able to handle the load of the increasing user base (many thousands now, with hundreds of concurrent IMAP connections any any given time) > > > So we upgraded to a new CentOS 7 server with SSD RAID, fast CPUs and tons of RAM. No more load problems. We compiled the latest dovecot from source (as the version from CentOS yum repo is already quite old, figure we might as well run the latest version since we were upgrading anyway). > > > Thanks to excellent documentation on dovecot.org and fairly thorough testing, the upgrade was quite smooth. We kept all the message UUIDs intact and tried to match the supported authentication methods etc to the old setup, and we didn't have any problems with clients re-downloading or re-syncing mail. > > > We do however have one problem, which prompted me to join this list. It is the same problem as described in this thread from last month: http://dovecot.org/list/dovecot/2016-July/104899.html > > > Here's the excerpt from our maillog: > > > Sep 17 19:34:57 mail dovecot: auth: Panic: file auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme) > Sep 17 19:34:57 mail dovecot: auth: Error: Raw backtrace: /usr/local/lib/dovecot/libdovecot.so.0(+0x89470) [0x7fa9cb8af470] -> /usr/local/lib/dovecot/libdovecot.so.0(+0x8954e) [0x7fa9cb8af54e] -> /usr/local/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7fa9cb851f75] -> dovecot/auth() [0x4165bc] -> dovecot/auth() [0x4221fb] -> dovecot/auth() [0x41620b] -> dovecot/auth(auth_request_lookup_credentials_callback+0x58) [0x4162f8] -> dovecot/auth(passdb_handle_credentials+0x6a) [0x4254ba] -> dovecot/auth() [0x425b62] -> dovecot/auth() [0x41c1f8] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x4c) [0x7fa9cb8c207c] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xd7) [0x7fa9cb8c3377] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x25) [0x7fa9cb8c2105] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7fa9cb8c22b8] -> /usr/local/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7fa9cb857f33] -> dovecot/auth(main+0x2eb) [0x40ccdb] -> /lib64/libc.so.6(__libc_start_main+0xf5) [0x7fa9c9dc2b15] -> dovecot/auth() [0x40cf15] > > > On the client side, it manifests as an authentication failure, and the user is prompted to re-enter their password. The reports we've had are all from users who have their passwords saved in a local password manager, so the client is definitely sending the correct password. It's not related to a particular mail client. It is also definitely not related to the particular user or password, as the user will authenticate many times successfully and then (seemingly) randomly be hit by this bug and prompted to re-enter their password. > > > We enabled verbose logging and even logging of passwords for failed authentication attempts in an attempt to find a pattern, but so far we have not found one. > > > Similar to the original poster in the above thread, we are using a MySQL backend, and CentOS 7 on x86_64 > > > It happens quite frequently: in the past 6 days it happened 49175 times, according to a grep of the maillog. In the same period there were 294167 successful IMAP logins and 160322 POP3 logins. > > > For now we have downgraded to 2.2.4 and so far have not seen the crash recorded in the maillog. > > > What can we do to help track down and fix this bug? > > > > # dovecot -n > # 2.2.24 (a82c823): /usr/local/etc/dovecot/dovecot.conf > # OS: Linux 3.10.0-327.28.3.el7.x86_64 x86_64 CentOS Linux release 7.2.1511 (Core) ext4 > auth_debug = yes > auth_debug_passwords = yes > auth_mechanisms = plain login digest-md5 cram-md5 ntlm rpa apop > auth_verbose = yes > auth_verbose_passwords = plain > debug_log_path = /var/log/dovecot-debug.log > default_client_limit = 5000 > default_process_limit = 1000 > disable_plaintext_auth = no > first_valid_uid = 89 > mail_debug = yes > mail_fsync = never > mail_gid = 89 > mail_location = maildir:/var/virtual/%d/%n > mail_uid = 89 > namespace inbox { > inbox = yes > location = > mailbox Drafts { > special_use = \Drafts > } > mailbox Junk { > special_use = \Junk > } > mailbox Sent { > special_use = \Sent > } > mailbox "Sent Messages" { > special_use = \Sent > } > mailbox Trash { > special_use = \Trash > } > prefix = > } > passdb { > args = /usr/local/etc/dovecot/dovecot-sql.conf.ext > driver = sql > } > pop3_client_workarounds = outlook-no-nuls oe-ns-eoh > service auth { > unix_listener /var/spool/postfix/private/auth { > group = postfix > mode = 0660 > user = postfix > } > } > ssl_ca = <*** > ssl_cert = <*** > ssl_key = <*** > userdb { > args = /usr/local/etc/dovecot/dovecot-sql.conf.ext > driver = sql > } > verbose_ssl = yes > protocol lmtp { > mail_fsync = optimized > } > protocol lda { > mail_fsync = optimized > } > protocol imap { > mail_max_userip_connections = 50 > } > protocol pop3 { > mail_max_userip_connections = 20 > } > -- > Chris Wik > Anu Internet Services > www.anu.net | www.cwik.chHi! This has been fixed with https://github.com/dovecot/core/commit/6c969ac21a43cc10ee1f1a91a4f39e4864c886cb Aki Tuomi Dovecot oy
From: Aki Tuomi <aki.tuomi at dovecot.fi>? To: Dovecot Mailing List <dovecot at dovecot.org>, Chris Wik <chris at anu.net> Sent: 18/09/2016 8:06 AM Subject: Re: Panic: file auth-request.c> Sep 17 19:34:57 mail dovecot: auth: Panic: file auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme) > Sep 17 19:34:57 mail dovecot: auth: Error: Raw backtrace: /usr/local/lib/dovecot/libdovecot.so.0(+0x89470) [0x7fa9cb8af470] -> /usr/local/lib/dovecot/libdovecot.so.0(+0x8954e) [0x7fa9cb8af54e] -> /usr/local/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7fa9cb851f75] -> dovecot/auth() [0x4165bc] -> dovecot/auth() [0x4221fb] -> dovecot/auth() [0x41620b] -> dovecot/auth(auth_request_lookup_credentials_callback+0x58) [0x4162f8] -> dovecot/auth(passdb_handle_credentials+0x6a) [0x4254ba] -> dovecot/auth() [0x425b62] -> dovecot/auth() [0x41c1f8] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x4c) [0x7fa9cb8c207c] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xd7) [0x7fa9cb8c3377] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x25) [0x7fa9cb8c2105] -> /usr/local/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7fa9cb8c22b8] -> /usr/local/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7fa9cb857f33] -> dovecot/auth(main+0x2eb) [0x40ccdb] -> /lib64/libc.so.6(__libc_start_main+0xf5) [0x7fa9c9dc2b15] -> dovecot/auth() [0x40cf15] Hi! This has been fixed with https://github.com/dovecot/core/commit/6c969ac21a43cc10ee1f1a91a4f39e4864c886cb Aki Tuomi Dovecot oy Great, good to hear! In my local source of 2.2.5, the deleted lines are lines 1048-1049. In the patch the lines are 1068-1069. I think maybe we'll wait for 2.2.6 and not try to patch it ourselves, we aren't using the new features in 2.2.5 yet and 2.2.4 has been stable for us... Chris -- Chris?Wik Anu?Internet?Services www.anu.net?|?www.cwik.ch
On 9/17/2016 2:15 PM, Chris Wik <chris at anu.net> wrote:> So we upgraded to a new CentOS 7 server with SSD RAID, fast CPUs and > tons of RAM. No more load problems. We compiled the latest dovecot > from source (as the version from CentOS yum repo is already quite > old, figure we might as well run the latest version since we were > upgrading anyway).Then on 9/18/2016 6:50 AM, Chris Wik <chris at anu.net> wrote:> In my local source of 2.2.5,??? Latest dovecot version is 2.2.25 - or was that (hopefully) a typo? http://www.dovecot.org/download.html
From: Tanstaafl <tanstaafl at libertytrek.org>? To: <dovecot at dovecot.org> Sent: 19/09/2016 5:44 PM Subject: Re: Panic: file auth-request.c On 9/17/2016 2:15 PM, Chris Wik <chris at anu.net> wrote:> So we upgraded to a new CentOS 7 server with SSD RAID, fast CPUs and > tons of RAM. No more load problems. We compiled the latest dovecot > from source (as the version from CentOS yum repo is already quite > old, figure we might as well run the latest version since we were > upgrading anyway).Then on 9/18/2016 6:50 AM, Chris Wik <chris at anu.net> wrote:> In my local source of 2.2.5,??? Latest dovecot version is 2.2.25 - or was that (hopefully) a typo? http://www.dovecot.org/download.html Yes, typo, sorry. I have 2.2.25 sources and the line numbers don't match the diff. We'll wait for 2.2.26, unless someone from Dovecot would like us to test the patch? In which case I'll try removing the 2 lines and recompiling and see if it works. Chris