Re: Cyrus-imapd 2.4.17: processes stick on mailbox locking resulting in total mailsystem failure
Ivan Kuznetsov <[email protected]>
| Newsgroups | gmane.mail.imap.cyrus |
|---|---|
| Organization | SOLVO ltd |
| Message-ID | <[email protected]> |
Hello I have gdb'ed the locked process, backtrace is below. It seems that problem occurs when imapd process catch a signal when is inside malloc() call. The signal handler has a malloc() call too, so finally there is interlock between two mallocs I have only a few time to investigate because locked processes list grows up dramatically. So I didn't found what the signal was. But it seems that there is a bug in imapd code... (gdb) thread apply all bt Thread 1 (Thread 0x7ff6ead5f840 (LWP 22980)): #0 0x00007ff6e83e282c in __lll_lock_wait_private () from /lib64/libc.so.6 #1 0x00007ff6e835e7e5 in _L_lock_16773 () from /lib64/libc.so.6 #2 0x00007ff6e835b833 in malloc () from /lib64/libc.so.6 #3 0x000056193edc9910 in xzmalloc () #4 0x000056193edb2664 in seqset_init () #5 0x000056193ed821b0 in index_tellchanges () #6 0x000056193ed8232b in index_check () #7 0x000056193ed6382e in idle_update () #8 <signal handler called> #9 0x00007ff6e83580f0 in _int_malloc () from /lib64/libc.so.6 #10 0x00007ff6e835b7dc in malloc () from /lib64/libc.so.6 #11 0x00007ff6e956f4b8 in CRYPTO_malloc () from /lib64/libcrypto.so.10 #12 0x00007ff6e96397ec in EVP_PKEY_CTX_dup () from /lib64/libcrypto.so.10 #13 0x00007ff6e962b360 in EVP_MD_CTX_copy_ex () from /lib64/libcrypto.so.10 #14 0x00007ff6e999ab3d in tls1_mac () from /lib64/libssl.so.10 #15 0x00007ff6e998db02 in ssl3_read_bytes () from /lib64/libssl.so.10 #16 0x00007ff6e998a644 in ssl3_read_internal () from /lib64/libssl.so.10 #17 0x000056193edb9745 in prot_fill () #18 0x000056193eda9ad7 in getword () #19 0x000056193ed670e7 in cmd_idle () #20 0x000056193ed7848d in cmdloop () #21 0x000056193ed79769 in service_main () #22 0x000056193ed62875 in main () 13.12.2018 17:50, Ivan Kuznetsov пишет: > Jonk, thank you for the idea. Somewhat looks strange as old mail server > worked w/o this problem 5+ years. But the system environment changed > dramatically, may be some filesystem quircks are significant for this > locks... > > I will try gdb'ing the process when problem occurs once more > > 13.12.2018 17:34, John Wade пишет: >> Without running gdb on the process, I have no idea, but your problem >> sounds similar to something we hit a very long time ago: >> >> See https://www.oakton.edu/user/3/jwade/cyrus/Readme.html >> >> In our cases, the problem was the imapd process that was holding the >> lock was trying to obtain a second lock on the same file. What does >> a stack trace look like on the imapd process that is holding the lock? >> It would appear the lock process has changed since I last looked at >> this, so this may not be a help at all. >> >> Good luck, >> John >> >> >> >> On 12/13/2018 5:21 AM, Ivan Kuznetsov wrote: >>> Hello >>> >>> We had a company mail server under Oracle Linux 6 (a clone of RHEL6) >>> with cyrus-imapd 2.3.16 working for years w/o problems. There are >9M >>> messages in ~9500 mailboxes in two partitions. Daily mail traffic is >>> 20-50K messages. >>> >>> Some weeks ago we migrated the server to a new one under Oracle Linux >>> 7 with cyrus-imapd 2.4.17 (cyrus-imapd-2.4.17-13.el7.x86_64 rpm) and >>> now have problem. Some times a week one of imapd processes locks an >>> "INBOX" mailbox with corresponding >>> /var/lib/imap/lock/user/<user>.lock file and does not unlock it >>> anymore. Other imapd processes trying to access this mailbox sticks >>> waiting to obtain the lock. The bigger problem is that lmtpd >>> processes trying to deliver new mail to this mailbox hangs too. The >>> number of lmtpd processes is limited (maxchild=32) to limit the >>> server load, so free lmtpd pool become empty after a time, and mail >>> delivery stopsto all the mailboxes. MTA (postfix) mail queue blows up >>> quickly >>> >>> Example lsof output: >>> >>> lmtpd 8182 cyrus 18uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 8183 cyrus 18uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 8187 cyrus 18uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 8771 cyrus 18uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 8834 cyrus 18uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 9123 cyrus 18uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 9631 cyrus 18uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 10343 cyrus 18uR REG 249,0 0 >>> 202944402 /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 10437 cyrus 18uR REG 249,0 0 >>> 202944402 /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 11411 cyrus 18uR REG 249,0 0 >>> 202944402 /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 11413 cyrus 18uR REG 249,0 0 >>> 202944402 /var/lib/imap/lock/user/smilovsky.lock >>> lmtpd 11506 cyrus 18uR REG 249,0 0 >>> 202944402 /var/lib/imap/lock/user/smilovsky.lock >>> >>> [root@hippo4 bin]# lsof /var/lib/imap/lock/user/smilovsky.lock | grep >>> '^imapd' >>> imapd 9132 cyrus 19uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> imapd 9154 cyrus 19uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> imapd 10311 cyrus 19uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> imapd 10746 cyrus 19uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> imapd 11843 cyrus 19uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> imapd 12059 cyrus 19uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> imapd 21885 cyrus 19uR REG 249,0 0 202944402 >>> /var/lib/imap/lock/user/smilovsky.lock >>> >>> In this case the root cause imapd process is 21885. strace shows that >>> the process waits on a futex forever: >>> >>> [root@hippo4 bin]# strace -tt -f -p 21885 >>> strace: Process 21885 attached >>> 13:07:28.264713 futex(0x7f6dcc5ac760, FUTEX_WAIT_PRIVATE, 2, >>> NULL^Cstrace: Process 21885 detached >>> <detached ...> >>> >>> Killing the process frees the lock, all the other stuck processes >>> runs and the problem disappears in a few seconds. >>> >>> Investigation shows that this process has a long-term connection from >>> a user MUA (Thunderbird) and deletes mail messages time-to-time. This >>> may be a Thunderbird 'filter' thread >>> >>> [root@hippo4 bin]# grep 'imap\[21885\]' /var/log/maillog >>> [...] >>> Dec 13 09:59:11 hippo4 imap[21885]: starttls: TLSv1.2 with cipher >>> DHE-RSA-AES256-SHA (256/256 bits new) no authentication >>> Dec 13 09:59:11 hippo4 imap[21885]: login: thunder.solvo.ru >>> [172.16.85.69] smilovsky CRAM-MD5+TLS User logged in >>> SESSIONID=<hippo.solvo.ru-21885-1544684350-1> >>> Dec 13 09:59:11 hippo4 imap[21885]: client id: "name" "Thunderbird" >>> "version" "52.5.2" >>> Dec 13 09:59:11 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> Dec 13 09:59:12 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> Dec 13 09:59:12 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> Dec 13 09:59:12 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> Dec 13 10:01:45 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> Dec 13 10:01:53 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> Dec 13 10:03:17 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> Dec 13 10:09:06 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> Dec 13 10:09:19 hippo4 imap[21885]: Expunged 1 messages from >>> user.smilovsky >>> >>> Problem is sporadic, I didn't see any correlation with server load, >>> time of day, user name and so on >>> >>> Removing "maxchild=" parameter for lmtp just delay the final as the >>> server system resources are limited. Now I wrote a patrol script >>> counting locks and killing imapd if locks number is growing up. The >>> trouble is I can't reliably determine the root cause imapd and kill >>> them one-by-one >>> >>> Any ideas more? >>> >>> Ivan Kuznetsov, SOLVO ltd >>> ---- >>> Cyrus Home Page: http://www.cyrusimap.org/ >>> List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/ >>> To Unsubscribe: >>> https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus >> > -- С уважением, Иван Кузнецов Руководитель технического отдела Компания "СОЛВО" +7(812)60-60-555 +7(495)66-83-003 +7(921)740-72-61 http://www.solvo.ru ---- Cyrus Home Page: http://www.cyrusimap.org/ List Archives/Info: http://lists.andrew.cmu.edu/pipermail/info-cyrus/ To Unsubscribe: https://lists.andrew.cmu.edu/mailman/listinfo/info-cyrus