[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.
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.
On 13/6/2013 05:11 , Timo Sirainen wrote:
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
OK, thanks for the fix!
M.
participants (2)
-
Mrten
-
Timo Sirainen