dovecot - Jul 2008 - A couple of dovecot issues I've noted recently...

Timo et al.,

I haven't been reading the list in a while, but wanted to report back
that we've transitioned to dovecot 1.0.15 and things look to be working
very nicely.  The platform is Solaris "Nevada" running on x86.  I
have been saving up a couple of issues to bring to your attention.

On our server, we gather all core files, and so we get a good taste of
the different things which are causing crashes.  One problem which we
see on an occasional basis is a crash in which the internal fatal error
handling code goes horribly wrong.  Here is an example.  The complete
stack trace is hugely long-- it appears that we recurse until we run
totally out of stack.  In gdb this looks like repeated calls like
this:

...
#14507 0x080b22b6 in i_internal_fatal_handler (status=83, fmt=0x0, 
    args=0x76b95d8 "\020") at failures.c:410
#14508 0x080b1e1e in i_fatal_status (status=83, 
    format=0x80cdd64 "mem_block_alloc(): Out of memory when allocating %u
bytes") at failures.c:201
#14509 0x080b1652 in mem_block_alloc (min_size=0) at data-stack.c:192
#14510 0x080b1811 in t_malloc_real (size=16, permanent=true)
    at data-stack.c:244
#14511 0x080b1890 in t_malloc0 (size=16) at data-stack.c:279
#14512 0x080b8715 in pool_datastack_create () at mempool-datastack.c:51
#14513 0x080bda2b in t_str_new (initial_size=512) at str.c:17
#14514 0x080b21f3 in internal_handler (log_type=70 'F', 
    format=0x80cdd64 "mem_block_alloc(): Out of memory when allocating %u
bytes", args=0x76b96d8 "\020") at failures.c:383
#14515 0x080b22b6 in i_internal_fatal_handler (status=83, fmt=0x0, 
    args=0x76b96d8 "\020") at failures.c:410
#14516 0x080b1e1e in i_fatal_status (status=83, 
    format=0x80cdd64 "mem_block_alloc(): Out of memory when allocating %u
bytes") at failures.c:201
#14517 0x080b1652 in mem_block_alloc (min_size=0) at data-stack.c:192
#14518 0x080b1811 in t_malloc_real (size=16, permanent=true)
    at data-stack.c:244
#14519 0x080b1890 in t_malloc0 (size=16) at data-stack.c:279
#14520 0x080b8715 in pool_datastack_create () at mempool-datastack.c:51
#14521 0x080bda2b in t_str_new (initial_size=512) at str.c:17
#14522 0x080b21f3 in internal_handler (log_type=70 'F', 
    format=0x80cdd64 "mem_block_alloc(): Out of memory when allocating %u
bytes", args=0x76b97d8 "\020") at failures.c:383
#14523 0x080b22b6 in i_internal_fatal_handler (status=83, fmt=0x0, 
    args=0x76b97d8 "\020") at failures.c:410
#14524 0x080b1e1e in i_fatal_status (status=83, 
    format=0x80cdd64 "mem_block_alloc(): Out of memory when allocating %u
bytes") at failures.c:201
#14525 0x080b1652 in mem_block_alloc (min_size=0) at data-stack.c:192
#14526 0x080b1811 in t_malloc_real (size=16, permanent=true)
    at data-stack.c:244
#14527 0x080b1890 in t_malloc0 (size=16) at data-stack.c:279
#14528 0x080b8715 in pool_datastack_create () at mempool-datastack.c:51
#14529 0x080bda2b in t_str_new (initial_size=512) at str.c:17
#14530 0x080b21f3 in internal_handler (log_type=70 'F', 
    format=0x80cdd64 "mem_block_alloc(): Out of memory when allocating %u
bytes", args=0x76b98d8 "\020") at failures.c:383
#14531 0x080b22b6 in i_internal_fatal_handler (status=83, fmt=0x0, 
    args=0x76b98d8 "\020") at failures.c:410
#14532 0x080b1e1e in i_fatal_status (status=83, 
    format=0x80cdd64 "mem_block_alloc(): Out of memory when allocating %u
bytes") at failures.c:201
#14533 0x080b1652 in mem_block_alloc (min_size=0) at data-stack.c:192
#14534 0x080b1811 in t_malloc_real (size=16, permanent=true)
    at data-stack.c:244
#14535 0x080b1890 in t_malloc0 (size=16) at data-stack.c:279
#14536 0x080b8715 in pool_datastack_create () at mempool-datastack.c:51
#14537 0x080bda2b in t_str_new (initial_size=512) at str.c:17
#14538 0x080b21f3 in internal_handler (log_type=70 'F', 
...

At the top of the stack, I see this-- unfortunately I can't use
gdb to view it-- it core dumps after about 50,000 frames.  In dbx:

  [327610] i_internal_fatal_handler(status = 83, fmt = (nil), args = 0x8047798
"^P"), line 410 in "failures.c"
  [327611] i_fatal_status(status = 83, format = 0x80cdd64
"mem_block_alloc(): Out of memory when allocating %u bytes", ...),
line 201 in "failures.c"
  [327612] mem_block_alloc(min_size = 134510504U), line 192 in
"data-stack.c"
  [327613] t_malloc_real(size = 0, permanent = 0), line 244 in
"data-stack.c"
  [327614] t_buffer_get(size = 0), line 319 in "data-stack.c"
  [327615] _vstrconcat(str1 = (nil), args = 0x8047834 "\x9d?^L^H",
ret_len = 0x8047808), line 229 in "strfuncs.c"
  [327616] t_strconcat(str1 = 0x100e77f0
"tmp/compiler/venus/handoff/build20.2/CDROM/sol-x86/kits/j2sdk_1.4.2_08/patches/J2SE_Solaris_8_x86_Recommended/108994-44/SUNWcsr/.svn/prop-base",
...), line 335 in "strfuncs.c"
  [327617] mbox_list_next(ctx = 0x80f6348), line 273 in "mbox-list.c"
  [327618] mbox_mailbox_list_next(_ctx = 0x8047928), line 209 in
"mbox-list.c"
  [327619] mail_storage_mailbox_list_next(ctx = 0x8047948), line 317 in
"mail-storage.c"
  [327620] cmd_list_continue(cmd = 0x80eff2c), line 184 in
"cmd-list.c"
  [327621] client_destroy(client = (nil), reason = 0x80479d8
"??y^D^Hc??^F^H????^N^H??x^L^H^Hz^D^Hm??^K^H^P\x8b^N^H^B"), line 94 in
"client.c"
  [327622] idle_timeout(context = (nil)), line 522 in "client.c"
  [327623] io_loop_handle_timeouts(ioloop = (nil), update_run_now = 1U), line
294 in "ioloop.c"
  [327624] io_loop_handler_run(ioloop = 0x80ed6e0), line 159 in
"ioloop-poll.c"
  [327625] io_loop_run(ioloop = (nil)), line 329 in "ioloop.c"
  [327626] main(argc = 1, argv = 0x8047afc, envp = 0x8047b04), line 290 in
"main.c"


I wondered if anyone else has seen similar problems?  It seems
like once we fall into i_internal_fatal_handler(), dovecot should really
try hard to avoid further dynamic memory allocation, as heap corruption
seems to make that a bit of a disaster.

As for the crash in mbox_list_next, we see that one too with some
frequency.

A final problem, and this one affects me personally, is that
we see some errors like this:

dovecot: Jul 09 11:52:10 Error: IMAP(dp): FETCH for mailbox mail/tmp-inbox UID
92086 got too little data: 6054 vs 6057
dovecot: Jul 09 11:52:10 Info: IMAP(dp): Disconnected: Disconnected

This is frustrating because I wind up with "poisonous" messages in my
inbox which cause dovecot to disconnect me when I try to read them.
Across all of our users, we see this happen about 1000 times per month.

        -dp

-- 
Daniel Price - Solaris Kernel Engineering - dp at eng.sun.com - blogs.sun.com/dp

On Wed, 2008-07-09 at 17:09 -0700, Dan Price wrote:
> ?  [327616] t_strconcat(str1 = 0x100e77f0
>
"tmp/compiler/venus/handoff/build20.2/CDROM/sol-x86/kits/j2sdk_1.4.2_08/patches/J2SE_Solaris_8_x86_Recommended/108994-44/SUNWcsr/.svn/prop-base",
...), line 335 in "strfuncs.c"
>   [327617] mbox_list_next(ctx = 0x80f6348), line 273 in
"mbox-list.c"
You don't have a separate mail directory, so users sometimes list their
entire home directory which can contain a huge directory tree, causing
out of memory?
> I wondered if anyone else has seen similar problems?  It seems
> like once we fall into i_internal_fatal_handler(), dovecot should really
> try hard to avoid further dynamic memory allocation, 
?In other fatal handlers there was actually code to avoid infinitely
recursing, but looks like I forgot to add it to internal_handler().
Fixed: http://hg.dovecot.org/dovecot-1.0/rev/c311c66a2d1b

Also v1.1+ sets aside an "out of memory" buffer which is used when
logging the "out of memory" error.
> as heap corruption
> seems to make that a bit of a disaster.
What heap corruption?
> A final problem, and this one affects me personally, is that
> we see some errors like this:
> 
> dovecot: Jul 09 11:52:10 Error: IMAP(dp): FETCH for mailbox mail/tmp-inbox
UID 92086 got too little data: 6054 vs 6057
> dovecot: Jul 09 11:52:10 Info: IMAP(dp): Disconnected: Disconnected
> 
> This is frustrating because I wind up with "poisonous" messages
in my
> inbox which cause dovecot to disconnect me when I try to read them.
> Across all of our users, we see this happen about 1000 times per month.
v1.1 fixes these automatically, although it still disconnects the first
time. Deleting dovecot.index.cache fixes this of course.

But as for why it happens in the first place, that's a bit difficult to
guess. Is the difference always 3 bytes? Anything else than Dovecot
modifying the mboxes?
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20080720/8f607f22/attachment-0002.bin>

On Sun 20 Jul 2008 at 06:05PM, Timo Sirainen wrote:
> On Wed, 2008-07-09 at 17:09 -0700, Dan Price wrote:
> 
> You don't have a separate mail directory, so users sometimes list their
> entire home directory which can contain a huge directory tree, causing
> out of memory?
I rely on users to set their mail directory in their IMAP
client appropriately-- this is because we have a historical mix
of users with ~/Mail, ~/mail, and in some weird cases other
dir names in their home directories where they store their mail.

I don't know why (it seems obvious now) but I hadn't worked out that
it was a recursive directory walk which might be causing this.  I can
now hunt down these users and help them.  Thanks!
> Also v1.1+ sets aside an "out of memory" buffer which is used
when
> logging the "out of memory" error.
Thanks.  I've applied your patch and will roll it out as soon as
I can.
> What heap corruption?
Sorry, never mind.
> > A final problem, and this one affects me personally, is that
> > we see some errors like this:
> > 
> > dovecot: Jul 09 11:52:10 Error: IMAP(dp): FETCH for mailbox
mail/tmp-inbox UID 92086 got too little data: 6054 vs 6057
...
>
> But as for why it happens in the first place, that's a bit difficult to
> guess. Is the difference always 3 bytes? Anything else than Dovecot
> modifying the mboxes?
Seems to be 3 in most cases.  Take a look; I've marked the ones which
aren't offset by 3:

$ grep 'got too little' * | awk '{print $6, $17, $19}' | sort |
uniq -c
   6 IMAP(dp): 2490 2493 3
   1 IMAP(dp): 5193 5196 3
   3 IMAP(dp): 6054 6057 3
 678 IMAP(helen): 1499 1710 211  <--
  22 IMAP(mimi): 2573 2690 117   <--
 208 IMAP(rav): 5651 5654 3
  69 IMAP(rav): 7549 7552 3
  22 IMAP(will): 3032 3035 3
 397 IMAP(will): 3213 3216 3
   6 IMAP(will): 3861 3864 3
 106 IMAP(will): 444 447 3

My first step will be to blow away the dovecot index files for all
of these users.  Thanks so much for your help.

	-dp

-- 
Daniel Price - Solaris Kernel Engineering - dp at eng.sun.com - blogs.sun.com/dp