[Dovecot] Crash in v1.2.3: istream.c: assertion failed on line 99

[Phillip Macey]

On 14/08/2009 9:00 AM, Timo Sirainen wrote:
> On Thu, 2009-08-13 at 12:10 +1000, Phillip Macey wrote:
>   
>> Aug 12 15:52:25 fury dovecot: IMAP(zhi): Panic: file istream.c: line 99 
>> (i_stream_read): assertion failed: ((size_t)ret+old_size == _stream->pos 
>> - _stream->skip)
>>     
>
> This is kind of annoying problem. I've been adding more of these asserts to try to catch it, but no one's really found an easy way to reproduce it.
>   
Til now. It would seem that I can reproduce it at will - except that it
doesnt get logged if I have core dumps enabled :-) It could be specific
to my maildir or an email in my maildir?
> If you manage to get a core dump, it would also help to see what those values are:
>
> fr 6
> p ret
> p old_size
> p _stream.pos
> p _stream.skip
>
> (You may need to compile Dovecot without -O2 parameter to get some of those values. Easiest way would be to just remove -O2 from src/lib/Makefile; touch src/lib/istream.c; make; sudo make install)
>   
Is this what you are after? I got to this point using telnet to send a
copy command as you suggested below and then attaching gdb to the
process and stepping through.

0x080f2c2c      337             while (ioloop->running)
(gdb)
338                     io_loop_handler_run(ioloop);
(gdb)
0x080f2c23      338                     io_loop_handler_run(ioloop);
(gdb)

Program received signal SIGABRT, Aborted.
0xb7f55402 in __kernel_vsyscall ()
(gdb) Aug 14 11:26:36 eyck dovecot: IMAP(pmacey): Panic: file istream.c:
line 99 (i_stream_read): assertion failed: ((size_t)ret+old_size ==
_stream->pos - _stream->skip)
Aug 14 11:26:36 eyck dovecot: IMAP(pmacey): Raw backtrace: imap
[0x80eb000] -> imap [0x80eb05a] -> imap [0x80ea8ac] -> imap [0x80f0098]
-> imap [0x80f25ca] -> imap(i_stream_read+0x3f) [0x80eff3f] ->
imap(i_stream_read_data+0x1d) [0x80f00bd] -> imap [0x80e341f] -> imap
[0x80e393e] -> imap(message_parser_parse_next_block+0x1d) [0x80e355d] ->
imap(index_mail_cache_parse_continue+0x22) [0x809d3b2] ->
imap(maildir_save_continue+0x45) [0x808ab55] ->
imap(mail_storage_copy+0x6d) [0x80ac86d] -> imap(maildir_copy+0x4b)
[0x80888db] -> imap(cmd_copy+0x1e0) [0x805e760] -> imap [0x80647ac] ->
imap [0x806485b] -> imap(client_handle_input+0x33) [0x80649b3] ->
imap(client_input+0x5f) [0x80654ff] -> imap(io_loop_handler_run+0x100)
[0x80f3b40] -> imap(io_loop_run+0x28) [0x80f2c28] -> imap(main+0x738)
[0x806da48] -> /lib/libc.so.6(__libc_start_main+0xdc) [0x58ae8c] -> imap
[0x805d591]
bt
#0  0xb7f55402 in __kernel_vsyscall ()
#1  0x0059dd80 in raise () from /lib/libc.so.6
#2  0x0059f691 in abort () from /lib/libc.so.6
#3  0x080eb00d in default_fatal_finish (type=<value optimized out>,
status=0) at failures.c:160
#4  0x080eb05a in i_internal_fatal_handler (type=LOG_TYPE_PANIC,
status=0, fmt=0x8102a90 "file %s: line %d (%s): assertion failed: (%s)",
    args=0xbfa95a34 "Kb\021\bc") at failures.c:440
#5  0x080ea8ac in i_panic (format=0x8102a90 "file %s: line %d (%s):
assertion failed: (%s)") at failures.c:207
#6  0x080f0098 in i_stream_read (stream=0x9b284c0) at istream.c:99
#7  0x080f25ca in i_stream_tee_read (stream=0x9b28578) at istream-tee.c:130
#8  0x080eff3f in i_stream_read (stream=0x9b285a0) at istream.c:80
#9  0x080f00bd in i_stream_read_data (stream=0x9b285a0,
data_r=0xbfa95bb8, size_r=0xbfa95bbc, threshold=1) at istream.c:361
#10 0x080e341f in message_parser_read_more (ctx=0x9b2fda0,
block_r=0xbfa95bb0, full_r=0xbfa95b4f) at message-parser.c:118
#11 0x080e393e in parse_next_body_to_eof (ctx=0x9b2fda0,
block_r=0xbfa95bb0) at message-parser.c:412
#12 0x080e355d in message_parser_parse_next_block (ctx=0x9b2fda0,
block_r=0xbfa95bb0) at message-parser.c:768
#13 0x0809d3b2 in index_mail_cache_parse_continue (_mail=0x9b29ca0) at
index-mail.c:1367
#14 0x0808ab55 in maildir_save_continue (_ctx=0x9b28698) at
maildir-save.c:426
#15 0x080ac86d in mail_storage_copy (ctx=0x9b28698, mail=0x9b23cb0) at
mail-copy.c:40
#16 0x080888db in maildir_copy (ctx=0x9b28698, mail=0x9b23cb0) at
maildir-copy.c:282
#17 0x0805e760 in cmd_copy (cmd=0x9ac0ea0) at cmd-copy.c:73
#18 0x080647ac in client_command_input (cmd=0x9ac0ea0) at client.c:611
#19 0x0806485b in client_command_input (cmd=0x9ac0ea0) at client.c:660
#20 0x080649b3 in client_handle_input (client=0x9ac0c10) at client.c:701
#21 0x080654ff in client_input (client=0x9ac0c10) at client.c:752
#22 0x080f3b40 in io_loop_handler_run (ioloop=0x9abf298) at
ioloop-epoll.c:208
#23 0x080f2c28 in io_loop_run (ioloop=0x9abf298) at ioloop.c:338
#24 0x0806da48 in main (argc=Cannot access memory at address 0x3c10
) at main.c:327
(gdb) fr 6
#6  0x080f0098 in i_stream_read (stream=0x9b284c0) at istream.c:99
99                      i_assert((size_t)ret+old_size == _stream->pos -
_stream->skip);
(gdb) p ret
$4 = 15376
(gdb) p  old_size
No symbol "old_size" in current context.
(gdb) p _stream
$5 = (struct istream_private *) 0x9b28498
(gdb) p _stream.pos
$6 = 8191
(gdb) p _stream.skip
$7 = 0
(gdb)

>> imap(i_stream_read_data+0x28) [0x4a2558] -> imap [0x4ab22e] -> 
>> imap(o_stream_send_istream+0x2e) [0x4aa63e] -> 
>> imap(maildir_save_continue+0x32) [0x443d12] -> 
>> imap(mail_storage_copy+0x6a) [0x462a1a] -> imap(maildir_copy+0x5e)  
>
> This is another thing I'm wondering. It's copying the mails by actually copying the data, instead of doing a hard link. But your dovecot -n output shows that you have it set to defaults, so it should have used a hard link. Or did you copy to a directory that was in another mount point? Or doesn't your filesystem support hard links?
>   
Mail storage is on an XFS filesystem - it should support hard links. I
have explicitly set maildir_copy_with_hardlinks=yes in the config file
rather than just relying on the defaults because I was certain that I
wanted it turned on. I just jumped onto the server and created a
hardlink by hand without any problems. 'ls -lni' looks like it works:

  22972186 -rw-r--r--  2 30332 60   81 Jul 13 16:38 dot.forward
  22972186 -rw-r--r--  2 30332 60   81 Jul 13 16:38 dot.forward.hardlink
1575505744 drwx------ 99 30332 60 8192 Aug 14 09:08 Maildir

>> I was able to fairly reliably trigger the same behaviour myself by 
>> attempting to move a bunch (thousands) of emails in my account using 
>> thunderbird - I dont know exactly what it is that triggers the crash 
>> though.     
>
> If you're still able to reproduce this, can you also try if this does
> it:
>   
Doing this also triggers the crash. See the gdb output above. The only
thing I did differently was that 'testbox' already existed and had some
emails in it so I didnt do the 'create'.
> telnet localhost 143
> a login user pass
> b select inbox
> c create testbox
> d copy 1:* testbox
>
> Instead of getting a core dump you can also attach gdb to an already
> running process: gdb -p <imap process pid>

-- 
Thanks,
  Phill Macey (CiSRA IT Services)