[Dovecot] lmtp out of memory - raw backtrace
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@example.org): Fatal: pool_system_realloc(16777216): Out of memory Oct 29 20:14:56 10.129.3.249 dovecot: lmtp(26698, user1@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@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@example.org): Error: mmap_anon(216690688) failed: Cannot allocate memory Oct 30 01:15:49 10.129.3.249 dovecot: lmtp(17927, user1@example.org): Error: mmap_anon(216690688) failed: Cannot allocate memory Oct 30 10:32:27 10.129.3.249 dovecot: mailbox: mail: imap(user1@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@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@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@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@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@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@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@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@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@example.org): Error: 2ZCXNsuej1CcUwAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300932.q9U9URHO029943@common.example-hosting.net> from=MAILER-DAEMON@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@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@example.org): Error: PFBjN8uej1CdUwAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300932.q9U9URHP029943@common.example-hosting.net> from=MAILER-DAEMON@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@example.org): Error: spYhE82ej1CiUwAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300932.q9U9URHQ029943@common.example-hosting.net> from=MAILER-DAEMON@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@example.org): Error: sOscMs2ej1CrUwAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300932.q9U9URHS029943@common.example-hosting.net> from=MAILER-DAEMON@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@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@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@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@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@example.org): Error: +jXqE+uej1AiVAAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300933.q9U9URHi029943@common.example-hosting.net> from=MAILER-DAEMON@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@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@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@example.org): Error: CxDMM+uej1AnVAAAk4785w: sieve: mailbox: deliver: session=<session}> msgid=<201210300933.q9U9URHl029943@common.example-hosting.net> from=MAILER-DAEMON@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@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
On 31.10.2012, at 2.09, Daniel Parthey wrote:
- 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.
Recent changes in hg should help with this for LMTP. I'll probably release 2.1.11 somewhat soon.
I think it should not crash and corrupt mdbox, even if memory limit is reached:
It should crash, because it reached the enforced vsz limit. If you don't want it to crash you can disable the limit, at the cost of potentially eating all of your memory.
Oct 30 10:32:27 10.129.3.249 dovecot: mailbox: mail: imap(user1@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)
This does look like something that should be fixed. It's not exactly a corruption so much as finding a partially written mail during rescan (because of the crash), but still it can probably be avoided.
participants (2)
-
Daniel Parthey
-
Timo Sirainen