[Dovecot] lmtp out of memory - raw backtrace

Wed Oct 31 02:09:57 EET 2012

Hi,

Our setup:
- 4 hosts with director and mailbox instance
- delivery via director lmtp into mailbox lmtp
- mailbox format: mdbox
- storage on NFS
- OS: Linux 2.6.32-44-server x86_64 Ubuntu 10.04.4 LTS 
- Dovecot 2.1.10
- Pigeonhole 0.3.3

We're getting strange "out of memory" lmtp errors/backtrace with dovecot 2.1.10
accompanied by high load caused caused by a lot of lmtp deliveries to one user.

First action would be to increase vsz_limit to a higher value, but I just
want to make sure there is no bug - before blindly increasing this limit.

I think it should not crash and corrupt mdbox, even if memory limit is reached:

Oct 29 20:14:56 10.129.3.249 dovecot: lmtp(26698, user1 at example.org): Fatal: pool_system_realloc(16777216): Out of memory
Oct 29 20:14:56 10.129.3.249 dovecot: lmtp(26698, user1 at example.org): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x4271a) [0x7f6dcbae971a] -> /usr/lib/dovecot/libdovecot.so.0(+0x42766) [0x7f6dcbae
9766] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f6dcbabd158] -> /usr/lib/dovecot/libdovecot.so.0(+0x53690) [0x7f6dcbafa690] -> /usr/lib/dovecot/libdovecot.so.0(+0x3e6f5) [0x7f6dcbae56f5] -> /usr/lib/dove
cot/libdovecot.so.0(buffer_write+0x7c) [0x7f6dcbae5e7c] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xa8033) [0x7f6dcbdda033] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_record_map_move_to_private+0x3
c) [0x7f6dcbdda4ec] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_sync_get_atomic_map+0x18) [0x7f6dcbde9c88] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xb7cf9) [0x7f6dcbde9cf9] -> /usr/lib/dovecot/lib
dovecot-storage.so.0(mail_index_sync_record+0x7e6) [0x7f6dcbdea626] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_sync_map+0x23c) [0x7f6dcbdeae4c] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_m
ap+0xa8) [0x7f6dcbddc2b8] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xb42da) [0x7f6dcbde62da] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xb458a) [0x7f6dcbde658a] -> /usr/lib/dovecot/libdovecot-storage.so.0(
mail_index_sync_begin_to+0x4f) [0x7f6dcbde6ecf] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_sync_begin+0x1e) [0x7f6dcbde6f4e] -> /usr/lib/dovecot/libdovecot-storage.so.0(mdbox_map_atomic_lock+0x5e) [0x
7f6dcbd6115e] -> /usr/lib/dovecot/libdovecot-storage.so.0(mdbox_transaction_save_commit_pre+0x46) [0x7f6dcbd64fb6] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x9d4f3) [0x7f6dcbdcf4f3] -> /usr/lib/dovecot/libdov
ecot-storage.so.0(mail_index_transaction_commit_full+0x9f) [0x7f6dcbddd97f] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_transaction_commit+0x8a) [0x7f6dcbdcf18a] -> /usr/lib/dovecot/modules/lib10_quota_plug
in.so(+0xba7f) [0x7f6dca4eca7f] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_transaction_commit_get_changes+0x3d) [0x7f6d
Oct 29 20:14:56 10.129.3.249 dovecot: lmtp(26698, user1 at example.org): Fatal: master: service(lmtp): child 26698 returned error 83 (Out of memory (service lmtp { vsz_limit=256 MB }, you may need to increase it))
Oct 30 01:15:49 10.129.3.249 dovecot: lmtp(17927, user1 at example.org): Error: mmap_anon(216690688) failed: Cannot allocate memory
Oct 30 01:15:49 10.129.3.249 dovecot: lmtp(17927, user1 at example.org): Error: mmap_anon(216690688) failed: Cannot allocate memory
Oct 30 10:32:27 10.129.3.249 dovecot: mailbox: mail: imap(user1 at example.org): <nURUbUPNBgAKgQPI>: Error: Corrupted dbox file /mail/dovecot/example.org/user1/mail/storage/m.3577 (around offset=1844402): EOF reading msg header (got 0/30 bytes)
Oct 30 10:33:44 10.129.3.249 dovecot: mailbox: mail: imap(user1 at example.org): <ZZ0pYkPN+wAKgQPp>: Error: /mail/dovecot/example.org/user1/mail/mailboxes/Lists/Cron/dbox-Mails/dovecot.index reset, view is now inconsistent
Oct 30 10:33:44 10.129.3.249 dovecot: mailbox: mail: imap(user1 at example.org): <CcYCYkPNkAAKgQPV>: Error: /mail/dovecot/example.org/user1/mail/mailboxes/Lists/postfix/dbox-Mails/dovecot.index reset, view is now inconsistent
Oct 30 10:33:44 10.129.3.249 dovecot: mailbox: mail: imap(user1 at example.org): <t+gLYkPNVQAKgQPV>: Error: /mail/dovecot/example.org/user1/mail/mailboxes/Lists/Dovecot/dbox-Mails/dovecot.index reset, view is now inconsistent
Oct 30 10:33:46 10.129.3.249 dovecot: mailbox: mail: imap(user1 at example.org): <YElVbUPNKwAKgQO/>: Error: /mail/dovecot/example.org/user1/mail/mailboxes/INBOX/dbox-Mails/dovecot.index reset, view is now inconsistent
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21404, user1 at example.org): Error: Timeout (180s) while waiting for lock for transaction log file /mail/dovecot/example.org/user1/mail/storage/dovecot.map.index.log
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21405, user1 at example.org): Error: Timeout (180s) while waiting for lock for transaction log file /mail/dovecot/example.org/user1/mail/storage/dovecot.map.index.log
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21410, user1 at example.org): Error: Timeout (180s) while waiting for lock for transaction log file /mail/dovecot/example.org/user1/mail/storage/dovecot.map.index.log
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21419, user1 at example.org): Error: Timeout (180s) while waiting for lock for transaction log file /mail/dovecot/example.org/user1/mail/storage/dovecot.map.index.log
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21404, user1 at example.org): Error: 2ZCXNsuej1CcUwAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300932.q9U9URHO029943 at common.example-hosting.net> from=MAILER-DAEMON at common.example-hosting.net: failed to store into mailbox 'INBOX': Internal error occurred. Refer to server log for more information. [2012-10-30 10:32:59]
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21404, user1 at example.org): Error: 2ZCXNsuej1CcUwAAk4785w: sieve: script /mail/dovecot/example.org/user1/.dovecot.sieve failed with unsuccessful implicit keep (user logfile /mail/dovecot/example.org/user1/.dovecot.sieve.log may reveal additional details)
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21405, user1 at example.org): Error: PFBjN8uej1CdUwAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300932.q9U9URHP029943 at common.example-hosting.net> from=MAILER-DAEMON at common.example-hosting.net: failed to store into mailbox 'INBOX': Internal error occurred. Refer to server log for more information. [2012-10-30 10:32:59]
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21410, user1 at example.org): Error: spYhE82ej1CiUwAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300932.q9U9URHQ029943 at common.example-hosting.net> from=MAILER-DAEMON at common.example-hosting.net: failed to store into mailbox 'INBOX': Internal error occurred. Refer to server log for more information. [2012-10-30 10:33:01]
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21419, user1 at example.org): Error: sOscMs2ej1CrUwAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300932.q9U9URHS029943 at common.example-hosting.net> from=MAILER-DAEMON at common.example-hosting.net: failed to store into mailbox 'INBOX': Internal error occurred. Refer to server log for more information. [2012-10-30 10:33:01]
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21410, user1 at example.org): Error: spYhE82ej1CiUwAAk4785w: sieve: script /mail/dovecot/example.org/user1/.dovecot.sieve failed with unsuccessful implicit keep (user logfile /mail/dovecot/example.org/user1/.dovecot.sieve.log may reveal additional details)
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21405, user1 at example.org): Error: PFBjN8uej1CdUwAAk4785w: sieve: script /mail/dovecot/example.org/user1/.dovecot.sieve failed with unsuccessful implicit keep (user logfile /mail/dovecot/example.org/user1/.dovecot.sieve.log may reveal additional details)
Oct 30 10:36:16 10.129.3.249 dovecot: lmtp(21419, user1 at example.org): Error: sOscMs2ej1CrUwAAk4785w: sieve: script /mail/dovecot/example.org/user1/.dovecot.sieve failed with unsuccessful implicit keep (user logfile /mail/dovecot/example.org/user1/.dovecot.sieve.log may reveal additional details)
Oct 30 10:36:46 10.129.3.249 dovecot: lmtp(21538, user1 at example.org): Error: Timeout (180s) while waiting for lock for transaction log file /mail/dovecot/example.org/user1/mail/storage/dovecot.map.index.log
Oct 30 10:36:46 10.129.3.249 dovecot: lmtp(21538, user1 at example.org): Error: +jXqE+uej1AiVAAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300933.q9U9URHi029943 at common.example-hosting.net> from=MAILER-DAEMON at common.example-hosting.net: failed to store into mailbox 'INBOX': Internal error occurred. Refer to server log for more information. [2012-10-30 10:33:31]
Oct 30 10:36:46 10.129.3.249 dovecot: lmtp(21538, user1 at example.org): Error: +jXqE+uej1AiVAAAk4785w: sieve: script /mail/dovecot/example.org/user1/.dovecot.sieve failed with unsuccessful implicit keep (user logfile /mail/dovecot/example.org/user1/.dovecot.sieve.log may reveal additional details)
Oct 30 10:36:46 10.129.3.249 dovecot: lmtp(21543, user1 at example.org): Error: Timeout (180s) while waiting for lock for transaction log file /mail/dovecot/example.org/user1/mail/storage/dovecot.map.index.log
Oct 30 10:36:46 10.129.3.249 dovecot: lmtp(21543, user1 at example.org): Error: CxDMM+uej1AnVAAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300933.q9U9URHl029943 at common.example-hosting.net> from=MAILER-DAEMON at common.example-hosting.net: failed to store into mailbox 'INBOX': Internal error occurred. Refer to server log for more information. [2012-10-30 10:33:31]
Oct 30 10:36:46 10.129.3.249 dovecot: lmtp(21543, user1 at example.org): Error: CxDMM+uej1AnVAAAk4785w: sieve: script /mail/dovecot/example.org/user1/.dovecot.sieve failed with unsuccessful implicit keep (user logfile /mail/dovecot/example.org/user1/.dovecot.sieve.log may reveal additional details)

Regards
Daniel
-- 
https://plus.google.com/103021802792276734820