thr3ads.net - dovecot - [Dovecot] lmtp out of memory

If this information is useful, please help other people find it:
Share via:

Daniel Parthey

2012-Oct-31 00:09 UTC

[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 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

Timo Sirainen

2012-Oct-31 00:20 UTC

head link

[Dovecot] lmtp out of memory - raw backtrace

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 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)
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.

Possibly Parallel Threads

Search for more possibly parallel threads

dovecot - Oct 2012 - lmtp out of memory - raw backtrace

[Dovecot] lmtp out of memory - raw backtrace

[Dovecot] lmtp out of memory - raw backtrace

Possibly Parallel Threads