The following issue has been RESOLVED. ====================================================================== http://www.dbmail.org/mantis/view.php?id=833 ====================================================================== Reported By: maximP Assigned To: paul ====================================================================== Project: DBMail Issue ID: 833 Category: IMAP daemon Reproducibility: sometimes Severity: major Priority: normal Status: resolved target: Resolution: fixed Fixed in Version: 2.3.7 ====================================================================== Date Submitted: 25-Jan-10 16:53 CET Last Modified: 28-Jan-10 13:56 CET ====================================================================== Summary: dbmail-imapd dies sometimes Description: Sometimes dbmail-imapd writes such log message:
Notice:[imap] _ic_logout(+175): [0x7f6ebb8900b0] userid:[6] and just exits (or dies) without other messages. ====================================================================== ---------------------------------------------------------------------- (0002993) maximP (reporter) - 26-Jan-10 13:19 http://www.dbmail.org/mantis/view.php?id=833#c2993 ---------------------------------------------------------------------- Valgrind says many interesting things about dbmail-imapd. Just some cuts: ==29644== 3,067,987 (58,400 direct, 3,009,587 indirect) bytes in 989 blocks are definitely lost in loss record 30 of 36 ==29644== at 0x4C23484: calloc (in /usr/lib64/valgrind/amd64-linux/vgpreload_memcheck.so) ==29644== by 0x59C4859: g_malloc0 (in /usr/lib64/libglib-2.0.so.0.1800.2) ==29644== by 0x4E4FF3C: MailboxState_new (in /usr/local/dbmail/lib/dbmail/libdbmail.so.0.0.0) ==29644== by 0x414F1E: dbmail_imap_session_mailbox_status (in /usr/local/dbmail/sbin/dbmail-imapd) ==29644== by 0x410E02: _ic_idle_enter (in /usr/local/dbmail/sbin/dbmail-imapd) ==29644== by 0x59E6D26: (within /usr/lib64/libglib-2.0.so.0.1800.2) ==29644== by 0x59E5783: (within /usr/lib64/libglib-2.0.so.0.1800.2) ==29644== by 0x699F06F: start_thread (in /lib64/libpthread-2.9.so) ==29644== by 0x6C8711C: clone (in /lib64/libc-2.9.so) ==29644== LEAK SUMMARY: ==29644== definitely lost: 58,689 bytes in 1,009 blocks. ==29644== indirectly lost: 3,009,587 bytes in 2,474 blocks. ==29644== possibly lost: 12,928,253 bytes in 23,956 blocks. ==29644== still reachable: 37,630,409 bytes in 485,357 blocks. I think memory is not freed in mailbox_notify_update() function. I applied the following patch: --- dbmail-imapsession.c.orig 2010-01-19 10:15:20.000000000 +0300 +++ dbmail-imapsession.c 2010-01-26 14:28:28.000000000 +0300 @@ -1406,6 +1406,7 @@ id = g_new0(u64_t,1); *id = MailboxState_getId(N); g_tree_replace(self->mbxinfo, id, N); + MailboxState_free(&M); } int dbmail_imap_session_mailbox_status(ImapSession * self, gboolean update) @@ -1426,7 +1427,7 @@ # "Headers Only". */ - MailboxState_T M, N = NULL; + MailboxState_T M = NULL, N = NULL; gboolean showexists = FALSE, showrecent = FALSE, unhandled = FALSE, showflags = FALSE; unsigned oldexists; and started valgrind with dbmail-imapd again. The results are better: ==30954== LEAK SUMMARY: ==30954== definitely lost: 2,498 bytes in 200 blocks. ==30954== indirectly lost: 1,322,315 bytes in 53 blocks. ==30954== possibly lost: 402,000 bytes in 823 blocks. ==30954== still reachable: 5,322,035 bytes in 18,600 blocks. But dbmail-imapd still dies sometimes (when I quickly switch between messages in Thunderbird for some time) with the message [0x92cbf00] Notice:[imap] imap_cb_read(+187): reached EOF ---------------------------------------------------------------------- (0002994) maximP (reporter) - 26-Jan-10 14:00 http://www.dbmail.org/mantis/view.php?id=833#c2994 ---------------------------------------------------------------------- Unfortunately, this change sometimes leads to *** glibc detected *** dbmail-imapd: double free or corruption (!prev): 0x00000000006fb790 *** ======= Backtrace: ========= /lib64/libc.so.6[0x7f7865be5108] /lib64/libc.so.6(cfree+0x76)[0x7f7865be6c66] dbmail-imapd(dbmail_imap_session_mailbox_status+0x404)[0x414ed4] dbmail-imapd(imap_idle_loop+0x1b6)[0x410cf6] dbmail-imapd(_ic_idle_enter+0xa5)[0x410e15] /usr/lib64/libglib-2.0.so.0[0x7f7866e9bd27] /usr/lib64/libglib-2.0.so.0[0x7f7866e9a784] /lib64/libpthread.so.0[0x7f7865ed1070] /lib64/libc.so.6(clone+0x6d)[0x7f7865c4411d] Looks like mailbox state is freed in some other place, but not always. ---------------------------------------------------------------------- (0002995) paul (administrator) - 26-Jan-10 16:13 http://www.dbmail.org/mantis/view.php?id=833#c2995 ---------------------------------------------------------------------- this particular leak has been fixed. But I'm still seeing leakage in authldap, so I'm leaving this bug open for now. ---------------------------------------------------------------------- (0002996) maximP (reporter) - 26-Jan-10 16:37 http://www.dbmail.org/mantis/view.php?id=833#c2996 ---------------------------------------------------------------------- Thank you for the rapid fix. Now I have these log messages during random message clicking in Thunderbird: Jan 26 18:20:02 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+167): incoming connection on ... Jan 26 18:20:02 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+185): incoming connection from ... Jan 26 18:20:02 inmail dbmail/imap4d[5387]: [0x697a00] Notice:[imap] dbmail_imap_session_handle_auth(+1235): [0x7fefe8089fd0] login accepted: user [(null)] from ... Jan 26 18:20:05 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:05 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:06 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+167): incoming connection on ... Jan 26 18:20:06 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+185): incoming connection from ... Jan 26 18:20:06 inmail dbmail/imap4d[5387]: [0x6975b0] Notice:[imap] dbmail_imap_session_handle_auth(+1235): [0x7fefeaff4e90] login accepted: user [(null)] ... Jan 26 18:20:22 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:22 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:31 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+167): incoming connection on ... Jan 26 18:20:31 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+185): incoming connection from ... Jan 26 18:20:31 inmail dbmail/imap4d[5387]: [0x697160] Notice:[imap] dbmail_imap_session_handle_auth(+1235): [0x7fefe8048e00] login accepted: user [(null)] from ... Jan 26 18:20:31 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+167): incoming connection on ... Jan 26 18:20:31 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+185): incoming connection from ... Jan 26 18:20:31 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:32 inmail dbmail/imap4d[5387]: [0x697b70] Notice:[imap] dbmail_imap_session_handle_auth(+1235): [0x7fefe81b15f0] login accepted: user [(null)] from ... Jan 26 18:20:32 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:38 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+167): incoming connection on ... Jan 26 18:20:38 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+185): incoming connection from ... Jan 26 18:20:38 inmail dbmail/imap4d[5387]: [0x697720] Notice:[imap] dbmail_imap_session_handle_auth(+1235): [0x7fefeaff1e00] login accepted: user [(null)] from ... Jan 26 18:20:38 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+167): incoming connection on ... Jan 26 18:20:38 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+185): incoming connection from ... Jan 26 18:20:39 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:39 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:39 inmail dbmail/imap4d[5387]: [0x697e50] Notice:[imap] dbmail_imap_session_handle_auth(+1235): [0x7fefe81d0c00] login accepted: user [(null)] from ... Jan 26 18:20:39 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+167): incoming connection on ... Jan 26 18:20:39 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[clientbase] client_init(+185): incoming connection from ... Jan 26 18:20:39 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF Jan 26 18:20:39 inmail dbmail/imap4d[5387]: [0x697a00] Notice:[imap] dbmail_imap_session_handle_auth(+1235): [0x7cb060] login accepted: user [(null)] from ... Jan 26 18:20:39 inmail dbmail/imap4d[5387]: [0x6488a0] Notice:[imap] imap_cb_read(+189): reached EOF And finally dbmail-imapd died with such error message: dbmail-imapd: dm_cram.c:72: Cram_getUsername: Assertion `Connection_T->username' failed. ---------------------------------------------------------------------- (0002998) maximP (reporter) - 27-Jan-10 10:28 http://www.dbmail.org/mantis/view.php?id=833#c2998 ---------------------------------------------------------------------- Thanks for the last fix. Now dbmail-imapd works well, though it writes Notice:[imap] imap_cb_read(+189): reached EOF and sometimes Notice:[imap] _ic_logout(+175): [0x7f5d1c1ad040] userid:[4] when I click on large message in Thunderbird, and then quickly click on another message, thus breaking the loading of the first message. After that I see such message: Notice:[clientbase] client_init(+167): incoming connection on ... Is it what is intended to happen? ---------------------------------------------------------------------- (0002999) paul (administrator) - 27-Jan-10 10:44 http://www.dbmail.org/mantis/view.php?id=833#c2999 ---------------------------------------------------------------------- the EOF message simply indicates that the client has hung up. Nothing wrong with that. the logout message is just that: the user has issued a LOGOUT command. So, in this case, TB hangs up one connection and opens a new one. TB will only maintain a certain maximum number of concurrent connections to the same imap server. I'm not familiar with TB internals but I suspect that TB will sometimes interrupt an operation that is taking too long by simply hanging up. Perfectly valid. ---------------------------------------------------------------------- (0003006) waza123 (reporter) - 28-Jan-10 00:56 http://www.dbmail.org/mantis/view.php?id=833#c3006 ---------------------------------------------------------------------- yea i'm too had a big amount of imapd crash, but don't have logs.. but i think it is what you describe. ---------------------------------------------------------------------- (0003008) paul (administrator) - 28-Jan-10 13:56 http://www.dbmail.org/mantis/view.php?id=833#c3008 ---------------------------------------------------------------------- the leak in authldap has also been fixed now. Issue History Date Modified Username Field Change ====================================================================== 25-Jan-10 16:53 maximP New Issue 26-Jan-10 13:19 maximP Note Added: 0002993 26-Jan-10 14:00 maximP Note Added: 0002994 26-Jan-10 15:33 paul Assigned To => paul 26-Jan-10 15:33 paul Status new => confirmed 26-Jan-10 16:13 paul Note Added: 0002995 26-Jan-10 16:37 maximP Note Added: 0002996 27-Jan-10 10:28 maximP Note Added: 0002998 27-Jan-10 10:44 paul Note Added: 0002999 28-Jan-10 00:56 waza123 Note Added: 0003006 28-Jan-10 13:56 paul Note Added: 0003008 28-Jan-10 13:56 paul Status confirmed => resolved 28-Jan-10 13:56 paul Resolution open => fixed 28-Jan-10 13:56 paul Fixed in Version => 2.3.7 ====================================================================== _______________________________________________ Dbmail-dev mailing list Dbmail-dev@dbmail.org http://mailman.fastxs.nl/cgi-bin/mailman/listinfo/dbmail-dev
