OOM in Dovecot 2.2.13 imap
Hi,
we run Dovecot 2.2.13 on Debian Wheezy with a couple thousand mailboxes. We have two users that repeatedly trigger an OOM condition with IMAP.
Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal: pool_system_realloc(268435456): Out of memory Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x6c15f) [0x7f11766cc15f] -> /usr/lib/dovecot/libdovecot.so.0(+0x6c1be) [0x7f11766cc1be] -> /usr/lib/dovecot/libdovecot.so.0(i_error+0) [0x7f1176685568] -> /usr/lib/dovecot/libdovecot.so.0(+0x81e80) [0x7f11766e1e80] -> /usr/lib/dovecot/libdovecot.so.0(+0x86cda) [0x7f11766e6cda] -> /usr/lib/dovecot/libdovecot.so.0(+0x86f96) [0x7f11766e6f96] -> /usr/lib/dovecot/libdovecot.so.0(+0x87b48) [0x7f11766e7b48] -> /usr/lib/dovecot/libdovecot.so.0(o_stream_sendv+0xcd) [0x7f11766e60cd] -> /usr/lib/dovecot/libdovecot.so.0(o_stream_send+0x1a) [0x7f11766e615a] -> /usr/lib/dovecot/modules/lib30_imap_zlib_plugin.so(+0x5849) [0x7f1175692849] -> /usr/lib/dovecot/modules/lib30_imap_zlib_plugin.so(+0x5982) [0x7f1175692982] -> /usr/lib/dovecot/modules/lib30_imap_zlib_plugin.so(+0x5b62) [0x7f1175692b62] -> /usr/lib/dovecot/libdovecot.so.0(o_stream_flush+0x4d) [0x7f11766e5d6d] -> /usr/lib/dovecot/libdovecot.so.0(+0x85e2c) [0x7f11766e5e2c] -> dovecot/imap USER IP UID fetch [0x7f1176e8d269] -> /usr/lib/dovecot/libdovecot.so.0(+0x879d5) [0x7f11766e79d5] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x4e) [0x7f11766dcfbe] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xd7) [0x7f11766ddfb7] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x9) [0x7f11766dd049] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f11766dd0c8] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f117668a7b3] -> dovecot/imap USER IP UID fetch [0x7f1176e8152e] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xfd) [0x7f11762f3ead] -> dovecot/imap USER IP UID fetch [0x7f1176e8169d] Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal: master: service(imap): child 33659 killed with signal 6 (core dumped)
The gdb backtrace looks like this:
gdb) bt full
#0 0x00007f1176307475 in raise () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1 0x00007f117630a6f0 in abort () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#2 0x00007f11766cc155 in default_fatal_finish (type=<optimized out>, status=status@entry=83) at failures.c:193
backtrace = 0x7f11789d4088 "/usr/lib/dovecot/libdovecot.so.0(+0x6c15f) [0x7f11766cc15f] -> /usr/lib/dovecot/libdovecot.so.0(+0x6c1be) [0x7f11766cc1be] -> /usr/lib/dovecot/libdovecot.so.0(i_error+0) [0x7f1176685568] -> /usr/lib/d"...
#3 0x00007f11766cc1be in i_internal_fatal_handler (ctx=0x7fff5ffedfb0, format=<optimized out>, args=<optimized out>) at failures.c:657
status = 83
#4 0x00007f1176685568 in i_fatal_status (status=status@entry=83, format=format@entry=0x7f1176702ba8 "pool_system_realloc(%lu): Out of memory") at failures.c:295
ctx = {type = LOG_TYPE_FATAL, exit_status = 83, timestamp = 0x0}
args = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7fff5ffee0a0, reg_save_area = 0x7fff5ffedfe0}}
#5 0x00007f11766e1e80 in pool_system_realloc (pool=<optimized out>, mem=0x0, old_size=134217728, new_size=268435456) at mempool-system.c:134
__FUNCTION__ = "pool_system_realloc"
#6 0x00007f11766e6cda in o_stream_grow_buffer (fstream=fstream@entry=0x7f11789f41c0, bytes=<optimized out>) at ostream-file.c:440
size = 268435456
new_size = <optimized out>
end_size = <optimized out>
#7 0x00007f11766e6f96 in o_stream_add (fstream=fstream@entry=0x7f11789f41c0, data=0x7f11789fe549, size=12113) at ostream-file.c:501
unused = <optimized out>
sent = <optimized out>
i = <optimized out>
#8 0x00007f11766e7b48 in o_stream_file_sendv (stream=0x7f11789f41c0, iov=<optimized out>, iov_count=<optimized out>) at ostream-file.c:588
fstream = 0x7f11789f41c0
size = <optimized out>
total_size = <optimized out>
added = <optimized out>
optimal_size = <optimized out>
i = <optimized out>
ret = 0
__FUNCTION__ = "o_stream_file_sendv"
#9 0x00007f11766e60cd in o_stream_sendv (stream=0x7f11789f4250, iov=iov@entry=0x7fff5ffee1a0, iov_count=iov_count@entry=1) at ostream.c:239
_stream = 0x7f11789f41c0
i = <optimized out>
total_size = 12113
ret = <optimized out>
__FUNCTION__ = "o_stream_sendv"
#10 0x00007f11766e615a in o_stream_send (stream=<optimized out>, data=<optimized out>, size=size@entry=12113) at ostream.c:217
iov = {iov_base = 0x7f11789fe549, iov_len = 12113}
#11 0x00007f1175692849 in o_stream_zlib_send_outbuf (zstream=0x7f11789f9340) at ostream-zlib.c:94
ret = <optimized out>
size = 12113
#12 0x00007f1175692982 in o_stream_zlib_send_flush (zstream=zstream@entry=0x7f11789f9340, final=final@entry=true) at ostream-zlib.c:189
zs = 0x7f11789f9420
len = <optimized out>
done = false
ret = <optimized out>
flush = <optimized out>
__FUNCTION__ = "o_stream_zlib_send_flush"
#13 0x00007f1175692b62 in o_stream_zlib_flush (stream=0x7f11789f9340) at ostream-zlib.c:235
zstream = 0x7f11789f9340
ret = <optimized out>
#14 0x00007f11766e5d6d in o_stream_flush (stream=stream@entry=0x7f11789f93d0) at ostream.c:157
_stream = 0x7f11789f9340
ret = 1
__FUNCTION__ = "o_stream_flush"
#15 0x00007f11766e5e2c in o_stream_default_cork (_stream=0x7f11789f9340, set=<optimized out>) at ostream.c:429
No locals.
#16 o_stream_default_cork (_stream=0x7f11789f9340, set=<optimized out>) at ostream.c:422
No locals.
#17 0x00007f1176e8d269 in client_output (client=0x7f11789f4470) at imap-client.c:1019
ret = 0
__FUNCTION__ = "client_output"
#18 0x00007f11766e79d5 in stream_send_io (fstream=0x7f11789f41c0) at ostream-file.c:468
ostream = 0x7f11789f4250
ret = <optimized out>
#19 0x00007f11766dcfbe in io_loop_call_io (io=0x7f1178a5bbe0) at ioloop.c:441
ioloop = 0x7f11789dc750
t_id = 2
__FUNCTION__ = "io_loop_call_io"
#20 0x00007f11766ddfb7 in io_loop_handler_run_internal (ioloop=ioloop@entry=0x7f11789dc750) at ioloop-epoll.c:220
ctx = 0x7f11789dd3e0
events = 0x0
event = 0x7f11789de250
list = 0x7f11789dee40
io = <optimized out>
tv = {tv_sec = 297, tv_usec = 43980}
events_count = <optimized out>
msecs = <optimized out>
ret = 1
i = <optimized out>
call = <optimized out>
__FUNCTION__ = "io_loop_handler_run_internal"
#21 0x00007f11766dd049 in io_loop_handler_run (ioloop=ioloop@entry=0x7f11789dc750) at ioloop.c:488
No locals.
#22 0x00007f11766dd0c8 in io_loop_run (ioloop=0x7f11789dc750) at ioloop.c:465
__FUNCTION__ = "io_loop_run"
#23 0x00007f117668a7b3 in master_service_run (service=0x7f11789dc5e0, callback=callback@entry=0x7f1176e96a00
I already deleted the index, but the issue persists.
Bernhard
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Mon, 23 Jun 2014, Bernhard Schmidt wrote:
we run Dovecot 2.2.13 on Debian Wheezy with a couple thousand mailboxes. We have two users that repeatedly trigger an OOM condition with IMAP.
Do those users have mailboxes extra ordinary large or is one message of them extra ordinary large?
Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal: pool_system_realloc(268435456): Out of memory
this number likely mean 256MB, is one of your memory limits that large? You can see all limits with dovecot -a (note the "-a" instead of "-n"). Memory limits are vsz_limit, IMHO.
I had to increase some vsz_limits, because one particular large message caused an out of memory during LMTP.
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBU6g76nz1H7kL/d9rAQJeqggApw27K6NvoVJNs8zH/MeqY8sRYzooOziQ fJ6pIJS2I86ChaG/DjJkmlds17GSdBaM55FS94yrC+arBZMh/jVTe4KXcyzQMyzq GtPQzWsW3LJdFGTF7RMai74bKU/ca+uIlNCtS2rznsH6p6BnJJWlE9Nml6vPEfQg CbvED7gs+L+dclwTuKjew/6XINBaVda7k5Ow2QO+Hn7nWbnldx7QBr7sbjWPIyHy SU6VO2tUPir+bjs16yd7uEUsTzYbpK33UUKOPBX5Dw3PWzYTh8oUpCuUW0LbSjIP Og2x+PZ1U+0Mz5yPB7sQIegXhuon0K7bOTuNUWuErmRBItFBMTsIUg== =s88s -----END PGP SIGNATURE-----
On 23.06.2014 16:38, Steffen Kaiser wrote:
On Mon, 23 Jun 2014, Bernhard Schmidt wrote:
we run Dovecot 2.2.13 on Debian Wheezy with a couple thousand mailboxes. We have two users that repeatedly trigger an OOM condition with IMAP.
Do those users have mailboxes extra ordinary large or is one message of them extra ordinary large?
No, not particularly. 8000 Mails (2GB total), the largest mail is 20MB.
Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal: pool_system_realloc(268435456): Out of memory
this number likely mean 256MB, is one of your memory limits that large? You can see all limits with dovecot -a (note the "-a" instead of "-n"). Memory limits are vsz_limit, IMHO.
No memory limits outside of dovecot. In dovecot there are the default settings
default_vsz_limit = 256 M service imap { [...] vsz_limit = 18446744073709551615 B }
Since the largest IMAP processes I can observe are at around 70MB VIRT (43MB RSS) I suspect vsz_limit is doing what it is supposed to do (limit memory consumption of a run-away process) and something went wrong in that mailbox. Thus the backtrace, hoping for someone to confirm.
Regards, Bernhard
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Mon, 23 Jun 2014, Bernhard Schmidt wrote:
On 23.06.2014 16:38, Steffen Kaiser wrote:
On Mon, 23 Jun 2014, Bernhard Schmidt wrote:
we run Dovecot 2.2.13 on Debian Wheezy with a couple thousand mailboxes. We have two users that repeatedly trigger an OOM condition with IMAP.
Do those users have mailboxes extra ordinary large or is one message of them extra ordinary large?
No, not particularly. 8000 Mails (2GB total), the largest mail is 20MB.
Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal: pool_system_realloc(268435456): Out of memory
this number likely mean 256MB, is one of your memory limits that large? You can see all limits with dovecot -a (note the "-a" instead of "-n"). Memory limits are vsz_limit, IMHO.
No memory limits outside of dovecot. In dovecot there are the default settings
default_vsz_limit = 256 M service imap { [...] vsz_limit = 18446744073709551615 B }
Do you run Dovecot in High-Peformance mode or Security mode?
Since the largest IMAP processes I can observe are at around 70MB VIRT (43MB RSS) I suspect vsz_limit is doing what it is supposed to do (limit memory consumption of a run-away process) and something went wrong in that mailbox. Thus the backtrace, hoping for someone to confirm.
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBU6kXYnz1H7kL/d9rAQIxWggAn9OnpE8oqc9tWGZIkbRYsRiBeXZNETFy CNBYmEQxhP2aYHd1zqFsdrpuve4ZrgBL56AE9Vv9HnZcnrD9yin1aFgN2efmAiBX J7j8o5cpGtZRfBmTJzNXm5+ZT6rSlZTYGfkuooQHw3xSZhlTCMCkUlOFbUXTgbHW Dm6jrZo2Obu2rRgd6QazynD1/uJwiNQV8BEGELTJyHFtegSOjyv575SfuRmgIrIT DeYJm/m6RcYI4cUdQUqm6xS6Q+siHAFx2sDIOmKBHKKW8GY4uYLOtvRJIJ5pHG02 p9ncYIRi5IRUwIMgrOYU47zPYFIrwFVsOGPcSoyCavYBr9tK33sEqw== =ML0o -----END PGP SIGNATURE-----
On 23.6.2014, at 15.18, Bernhard Schmidt berni@birkenwald.de wrote:
we run Dovecot 2.2.13 on Debian Wheezy with a couple thousand mailboxes. We have two users that repeatedly trigger an OOM condition with IMAP.
Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal: pool_system_realloc(268435456): Out of memory .. #6 0x00007f11766e6cda in o_stream_grow_buffer (fstream=fstream@entry=0x7f11789f41c0, bytes=<optimized out>) at ostream-file.c:440 size = 268435456 new_size = <optimized out> end_size = <optimized out> .. #11 0x00007f1175692849 in o_stream_zlib_send_outbuf (zstream=0x7f11789f9340) at ostream-zlib.c:94 ret = <optimized out> size = 12113 #12 0x00007f1175692982 in o_stream_zlib_send_flush (zstream=zstream@entry=0x7f11789f9340, final=final@entry=true) at ostream-zlib.c:189
This is most likely because of the IMAP COMPRESS extension, which causes the output stream buffer to get really large. So the easiest fix would be to just disable imap_zlib plugin and it'll probably work. But this should get fixed properly.. I just can't figure out how this can happen. What was the IMAP client doing that caused it? Could you run a few more gdb commands:
#17 0x00007f1176e8d269 in client_output (client=0x7f11789f4470) at imap-client.c:1019
Assuming client_output is again in frame 17, run:
f 17 p *client.command_queue p *client.command_queue.next
Actually, I think these fix it:
http://hg.dovecot.org/dovecot-2.2/rev/5740cb57d02c http://hg.dovecot.org/dovecot-2.2/rev/00b3aa3842b7
On 3.7.2014, at 21.28, Timo Sirainen tss@iki.fi wrote:
On 23.6.2014, at 15.18, Bernhard Schmidt berni@birkenwald.de wrote:
we run Dovecot 2.2.13 on Debian Wheezy with a couple thousand mailboxes. We have two users that repeatedly trigger an OOM condition with IMAP.
Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal: pool_system_realloc(268435456): Out of memory .. #6 0x00007f11766e6cda in o_stream_grow_buffer (fstream=fstream@entry=0x7f11789f41c0, bytes=<optimized out>) at ostream-file.c:440 size = 268435456 new_size = <optimized out> end_size = <optimized out> .. #11 0x00007f1175692849 in o_stream_zlib_send_outbuf (zstream=0x7f11789f9340) at ostream-zlib.c:94 ret = <optimized out> size = 12113 #12 0x00007f1175692982 in o_stream_zlib_send_flush (zstream=zstream@entry=0x7f11789f9340, final=final@entry=true) at ostream-zlib.c:189
This is most likely because of the IMAP COMPRESS extension, which causes the output stream buffer to get really large. So the easiest fix would be to just disable imap_zlib plugin and it'll probably work. But this should get fixed properly.. I just can't figure out how this can happen. What was the IMAP client doing that caused it? Could you run a few more gdb commands:
#17 0x00007f1176e8d269 in client_output (client=0x7f11789f4470) at imap-client.c:1019
Assuming client_output is again in frame 17, run:
f 17 p *client.command_queue p *client.command_queue.next
Just as a random follow up for other people that might google this.
I also started to have this issue. I tried the two patches but they
didn't help.
I came to find out, this can also be caused from a disk full issue,
atleast when using maildir.
Quoting Timo Sirainen tss@iki.fi:
Actually, I think these fix it:
http://hg.dovecot.org/dovecot-2.2/rev/5740cb57d02c http://hg.dovecot.org/dovecot-2.2/rev/00b3aa3842b7
On 3.7.2014, at 21.28, Timo Sirainen tss@iki.fi wrote:
On 23.6.2014, at 15.18, Bernhard Schmidt berni@birkenwald.de wrote:
we run Dovecot 2.2.13 on Debian Wheezy with a couple thousand mailboxes. We have two users that repeatedly trigger an OOM condition with IMAP.
Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal:
pool_system_realloc(268435456): Out of memory .. #6 0x00007f11766e6cda in o_stream_grow_buffer
(fstream=fstream@entry=0x7f11789f41c0, bytes=<optimized out>) at
ostream-file.c:440 size = 268435456 new_size = <optimized out> end_size = <optimized out> .. #11 0x00007f1175692849 in o_stream_zlib_send_outbuf
(zstream=0x7f11789f9340) at ostream-zlib.c:94 ret = <optimized out> size = 12113 #12 0x00007f1175692982 in o_stream_zlib_send_flush
(zstream=zstream@entry=0x7f11789f9340, final=final@entry=true) at
ostream-zlib.c:189This is most likely because of the IMAP COMPRESS extension, which
causes the output stream buffer to get really large. So the easiest
fix would be to just disable imap_zlib plugin and it'll probably
work. But this should get fixed properly.. I just can't figure out
how this can happen. What was the IMAP client doing that caused it?
Could you run a few more gdb commands:#17 0x00007f1176e8d269 in client_output (client=0x7f11789f4470) at
imap-client.c:1019Assuming client_output is again in frame 17, run:
f 17 p *client.command_queue p *client.command_queue.next
Hi Timo,
thanks for your answer.
we run Dovecot 2.2.13 on Debian Wheezy with a couple thousand mailboxes. We have two users that repeatedly trigger an OOM condition with IMAP.
Jun 23 12:53:21 lxmhs74 dovecot: imap(USER): Fatal: pool_system_realloc(268435456): Out of memory .. #6 0x00007f11766e6cda in o_stream_grow_buffer (fstream=fstream@entry=0x7f11789f41c0, bytes=<optimized out>) at ostream-file.c:440 size = 268435456 new_size = <optimized out> end_size = <optimized out> .. #11 0x00007f1175692849 in o_stream_zlib_send_outbuf (zstream=0x7f11789f9340) at ostream-zlib.c:94 ret = <optimized out> size = 12113 #12 0x00007f1175692982 in o_stream_zlib_send_flush (zstream=zstream@entry=0x7f11789f9340, final=final@entry=true) at ostream-zlib.c:189
This is most likely because of the IMAP COMPRESS extension, which causes the output stream buffer to get really large. So the easiest fix would be to just disable imap_zlib plugin and it'll probably work. But this should get fixed properly.. I just can't figure out how this can happen. What was the IMAP client doing that caused it? Could you run a few more gdb commands:
#17 0x00007f1176e8d269 in client_output (client=0x7f11789f4470) at imap-client.c:1019
Assuming client_output is again in frame 17, run:
f 17 p *client.command_queue p *client.command_queue.next
#0 0x00007f1176307475 in raise () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) f 17
#17 0x00007f1176e8d269 in client_output (client=0x7f11789f4470) at
imap-client.c:1019
1019 imap-client.c: No such file or directory.
(gdb) p *client.command_queue
$1 = {prev = 0x0, next = 0x0, client = 0x7f11789f4470, pool =
0x7f11789f4c60, tag = 0x7f11789f4d60 "9", name = 0x7f11789f4d68 "UID
fetch",
args = 0x7f11789f4d78 "3044 (UID RFC822.SIZE BODY.PEEK[])", cmd_flags
= COMMAND_FLAG_BREAKS_SEQS,
func = 0x7f1176e83d10
We could easily live without IMAP COMPRESS for now, but if this backtrace confirms your suspicion we will gladly try a build with your patches applied.
Thanks, Bernhard
On 3.7.2014, at 23.56, Bernhard Schmidt berni@birkenwald.de wrote:
#17 0x00007f1176e8d269 in client_output (client=0x7f11789f4470) at imap-client.c:1019
Assuming client_output is again in frame 17, run:
f 17 p *client.command_queue p *client.command_queue.next .. We could easily live without IMAP COMPRESS for now, but if this backtrace confirms your suspicion we will gladly try a build with your patches applied.
Yeah, I'm pretty sure my patches will fix it. I'm planning on v2.2.14 hopefully this week, although looks like either I'd have to leave some reported bugs unfixed or delay it..
participants (4)
-
Bernhard Schmidt
-
Patrick Domack
-
Steffen Kaiser
-
Timo Sirainen