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 <client_connected>) at master-service.c:566 No locals. #24 0x00007f1176e8152e in main (argc=1, argv=0x7f11789dc390) at main.c:400 set_roots = {0x7f11770a4960, 0x0} login_set = {auth_socket_path = 0x7f11789d4048 "\001", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, callback = 0x7f1176e96880 <login_client_connected>, failure_callback = 0x7f1176e96580 <login_client_failed>, request_auth_token = 1} service_flags = <optimized out> storage_service_flags = <optimized out> username = 0x0 c = <optimized out>
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:
No, not particularly. 8000 Mails (2GB total), the largest mail is 20MB.
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:
Do you run Dovecot in High-Peformance mode or Security mode?
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:
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:
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>:
Hi Timo,
thanks for your answer.
#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 <cmd_fetch_continue>, context = 0x7f11789f4da0, module_contexts = {arr = {buffer = 0x7f11789f4d00, element_size = 8}, v = 0x7f11789f4d00, v_modifiable = 0x7f11789f4d00}, parser = 0x7f11789df950, state = CLIENT_COMMAND_STATE_WAIT_OUTPUT, sync = 0x0, uid = 1, cancel = 0, param_error = 0, search_save_result = 0, search_save_result_used = 0, temp_executed = 1, tagline_sent = 0} (gdb) p *client.command_queue.next Cannot access memory at address 0x0
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
participants (4)
-
Bernhard Schmidt
-
Patrick Domack
-
Steffen Kaiser
-
Timo Sirainen