Mrten
2013-Jun-08 11:27 UTC
[Dovecot] crash/mem violation in auth_worker + 50G logs in 2.1.7
Hi,
This morning I discovered what seemed to be a deliberate crash in
auth_worker:
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: #007Can't read
dir of '/etc/mysql/conf.d/' (Errcode: 2)
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: Fatal error in
defaults handling. Program aborted
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: *** glibc
detected *** dovecot/auth worker: waiting for connection: free():
invalid pointer: 0x00007fffa0863160 ***
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: ======Backtrace:
========Jun 7 23:02:09 localhost dovecot: auth-worker: Error:
/lib/x86_64-linux-gnu/libc.so.6(+0x7eb96)[0x7f22d42f9b96]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error:
/usr/lib/libmysqlclient.so.18(free_root+0x90)[0x7f22d37988c0]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error:
/usr/lib/libmysqlclient.so.18(free_defaults+0x4b)[0x7f22d3796e6b]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error:
/usr/lib/libmysqlclient.so.18(mysql_read_default_options+0x13c)[0x7f22d377d00c]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error:
/usr/lib/libmysqlclient.so.18(mysql_real_connect+0x8e)[0x7f22d377eb4e]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error:
/usr/lib/dovecot/modules/auth/libdriver_mysql.so(+0x1fc6)[0x7f22d3c52fc6]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: dovecot/auth
worker: waiting for connection(+0x2be1d)[0x7f22d515be1d]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: dovecot/auth
worker: waiting for connection(db_sql_connect+0xd)[0x7f22d514aedd]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: dovecot/auth
worker: waiting for connection(+0x23d70)[0x7f22d5153d70]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: dovecot/auth
worker: waiting for connection(passdb_init+0x2a)[0x7f22d515158a]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: dovecot/auth
worker: waiting for connection(auths_init+0x59)[0x7f22d513dfe9]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: dovecot/auth
worker: waiting for connection(main+0x345)[0x7f22d513d5f5]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error:
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7f22d429c76d]
Jun 7 23:02:09 localhost dovecot: auth-worker: Error: dovecot/auth
worker: waiting for connection(+0xd7d9)[0x7f22d513d7d9]
There follows a memory map but I snipped that.
This repeated until I killed dovecot (12 hours later), by then 54GB of
logs had accumulated. Besides leaving me impressed with the logserver
:), I was wondering if this is a known problem.
I don't know what triggered this at 23:02 (shown above is the first set
of problem logentries). Can't really have been an upgrade, since I
backported the raring dovecot Ubuntu package for my precise server, no
automated upgrades there.
I did go look for the /etc/mysql/conf.d directory mentioned, it wasn't
there, but there was a /etc/mysql/my.cnf trying to !includedir it. Since
there is no mysql on the server besides libmysqlclient I removed the
directory and haven't seen the problem return yet. Sounds like the
reason for happening, however, the memory error after that probably
warrants research?
If it is in libmysqlclient, that's another non-default snag because
that's the lib I get from Percona, not the Ubuntu default one.
Shouldn't dovecot recognize that the auth worker is crashing?
One more thing, this is (one line from many) from audit.log (I have
auditd logging audit records)
type=ANOM_ABEND msg=audit(1370682566.377:3499876): auid=4294967295
uid=108 gid=115 ses=4294967295 pid=23187 comm="auth"
reason="memory
violation" sig=6
108 is the dovecot user, so it probably is related.
I realise I'm way off defaults here but I wanted to report anyway.
(dovecot -n attached)
thanks for any insight,
Maarten.
-------------- next part --------------
# 2.1.7: /etc/dovecot/dovecot.conf
# OS: Linux 3.2.0-43-virtual x86_64 Ubuntu 12.04.2 LTS
auth_cache_negative_ttl = 0
auth_cache_size = 10 M
auth_cache_ttl = 5 mins
auth_failure_delay = 3 secs
auth_username_chars =
abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-@
disable_plaintext_auth = no
log_timestamp = "%Y-%m-%d %H:%M:%S "
mail_save_crlf = yes
maildir_stat_dirs = yes
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 = /etc/dovecot/extra/dovecot-sql.conf.ext
driver = sql
}
plugin {
fts = squat
quota = maildir:User quota
quota_rule = *:bytes=10G
quota_rule2 = Trash:bytes=+100M
trash = /etc/dovecot/conf.d/trash
var_domainpart = %d
var_remote = %r
var_service = %Ls
var_user = %u
var_userpart = %n
}
protocols = imap pop3
service auth-worker {
user = $default_internal_user
}
service auth {
unix_listener /var/spool/exim4/private/auth {
mode = 0660
}
unix_listener auth-userdb {
group = root
mode = 0600
user = root
}
user = $default_internal_user
}
service imap-login {
chroot = login
inet_listener imap {
port = 0
}
inet_listener imaps {
address = *
}
process_limit = 128
process_min_avail = 3
service_count = 1
user = $default_internal_user
vsz_limit = 64 M
}
service imap {
drop_priv_before_exec = yes
executable = imap imap_postlogin
process_limit = 256
vsz_limit = 512 M
}
service imap_postlogin {
executable = script-login /etc/dovecot/imap_helper.sh
}
service pop3-login {
chroot = login
process_limit = 128
process_min_avail = 3
service_count = 1
user = $default_internal_user
}
service pop3 {
drop_priv_before_exec = yes
executable = pop3 pop3_postlogin
process_limit = 256
vsz_limit = 512 M
}
service pop3_postlogin {
executable = script-login /etc/dovecot/pop3_helper.sh
}
ssl_cert = </etc/dovecot/ssl/mail.ii.nl/certificate
ssl_cipher_list = TLSv1:@STRENGTH:!RC4:!NULL
ssl_key = </etc/dovecot/ssl/mail.ii.nl/key
userdb {
driver = prefetch
}
verbose_proctitle = yes
protocol imap {
imap_client_workarounds = tb-extra-mailbox-sep tb-lsub-flags delay-newmail
imap_max_line_length = 64 k
mail_max_userip_connections = 20
mail_plugins = " quota imap_quota fts fts_squat"
}
protocol pop3 {
mail_max_userip_connections = 5
mail_plugins = " quota"
pop3_client_workarounds = outlook-no-nuls oe-ns-eoh
pop3_enable_last = yes
pop3_logout_format = io=%i/%o, top=%t/%p, retr=%r/%b, del=%d/%m, size=%s
pop3_uidl_format = %08Xu%08Xv
}
Timo Sirainen
2013-Jun-13 03:11 UTC
[Dovecot] crash/mem violation in auth_worker + 50G logs in 2.1.7
On Sat, 2013-06-08 at 13:27 +0200, Mrten wrote:> Hi, > > This morning I discovered what seemed to be a deliberate crash in > auth_worker: > > Jun 7 23:02:09 localhost dovecot: auth-worker: Error: #007Can't read > dir of '/etc/mysql/conf.d/' (Errcode: 2) > Jun 7 23:02:09 localhost dovecot: auth-worker: Error: Fatal error in > defaults handling. Program aborted > Jun 7 23:02:09 localhost dovecot: auth-worker: Error: *** glibc > detected *** dovecot/auth worker: waiting for connection: free(): > invalid pointer: 0x00007fffa0863160 ***..> /usr/lib/libmysqlclient.so.18(free_defaults+0x4b)[0x7f22d3796e6b] > Jun 7 23:02:09 localhost dovecot: auth-worker: Error: > /usr/lib/libmysqlclient.so.18(mysql_read_default_options+0x13c)[0x7f22d377d00c] > Jun 7 23:02:09 localhost dovecot: auth-worker: Error: > /usr/lib/libmysqlclient.so.18(mysql_real_connect+0x8e)[0x7f22d377eb4e]It crashes in mysql_real_connect() internally, which also starts the whole mysql session. So this is a bug in MySQL library.> This repeated until I killed dovecot (12 hours later), by then 54GB of > logs had accumulated. Besides leaving me impressed with the logserver > :), I was wondering if this is a known problem. > > Shouldn't dovecot recognize that the auth worker is crashing?Looks like there was a generic problem with how crash during initialization was handled. This should fix all of them: http://hg.dovecot.org/dovecot-2.2/rev/754d244b8249> One more thing, this is (one line from many) from audit.log (I have > auditd logging audit records) > > type=ANOM_ABEND msg=audit(1370682566.377:3499876): auid=4294967295 > uid=108 gid=115 ses=4294967295 pid=23187 comm="auth" reason="memory > violation" sig=6 > > 108 is the dovecot user, so it probably is related.Yeah, that's the same abort() crash.