On 13/08/2009 10:49 PM, Charles Marcus wrote:

What version of TBird?

2.0.0.22. It is not a thunderbird issue - I can trigger the crash using telnet.

-- Thanks, Phill Macey (CiSRA IT Services)

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)

...

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? Yes, it's very likely specific to your maildir. Can you anonymize it in some way that the crash still happens but you could also send me

On Aug 13, 2009, at 10:20 PM, Phillip Macey wrote: the mails? http://dovecot.org/tools/mbox-anonymize.pl does it to mboxes, looks like it should work for maildir files also as long as you put $hdr=1; to beginning. Sorry - I cant do that. Im sure the perl script works quite well, but I cant send you any of the emails in the maildir. For a start, there are 10k emails in the source folder and >20k in the destination. What I can do is start excluding emails from the copy and see when it starts working. Maybe I can narrow it down to a particular email and then we can take it from there. I have had a play around and here are some

On 14/08/2009 12:29 PM, Timo Sirainen wrote: things that I noticed: permanent storage? fluke?).

• It seems to be an attribute of the destination folder. I can successfully move the mail into a new (empty) folder. As soon as I try to move into that specific destination, it starts crashing.
• The other thing that I think is a pattern - using thunderbird, if I select all the emails in the folder (eg Ctrl-A) and try to move them - it crashes. If I hand select a smaller subset of the emails, they tend to move successfully. The smaller the number the more likely it would be successful. I tried to figure out if there was a point at which it stopped working - but it seemed like the number kept on getting smaller as I kept trying. By the end, I was not even able to move a single email without getting a crash (restarting dovecot did not change this -

• If I move the mail into another temp folder (no problems doing this) and then try moving from the temp folder into the 'problem' folder, I still get the crash.

If you stepping through you mean you hit enter some thousand times, you could have also used "continue" command. :) I think it was only 15 or 20 times. I didnt attach gdb to the process until just before I did the copy. Maybe that means the crash happened before it got around to reading all the emails or it was something in the first couple of mails that triggered it.

...

#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 Oh, it's coming from tee_read().. I thought tee-istream was the problem. (gdb) p ret $4 = 15376 (gdb) p old_size No symbol "old_size" in current context. ok, so this was dropped out by -O2 Sorry, I thought I had got rid of that. (gdb) p _stream $5 = (struct istream_private *) 0x9b28498 (gdb) p _stream.pos $6 = 8191 (gdb) p _stream.skip $7 = 0 (gdb) But still, there is only 8 kB available but read() returned 15376 bytes. That can't be correct. Could you do one more thing:

fr 6 p *stream p *stream.real_stream p *(struct file_istream *)stream.real_stream

(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 *stream $13 = {v_offset = 745472, stream_errno = 0, mmaped = 0, blocking = 1, closed = 0, readable_fd = 0, seekable = 0, eof = 0, real_stream = 0x9b28498} (gdb) p *stream.real_stream $14 = {iostream = {refcount = 1, close = 0x8100330 , destroy = 0x80f1750 , set_max_buffer_size = 0x80f1720 , destroy_callback = 0, destroy_context = 0x0}, read = 0x80f12b0 , seek = 0x80f1630 , sync = 0, stat = 0x80f11a0 , istream = { v_offset = 745472, stream_errno = 0, mmaped = 0, blocking = 1, closed = 0, readable_fd = 0, seekable = 0, eof = 0, real_stream = 0x9b28498}, fd = 11, abs_start_offset = 0, statbuf = {st_dev = 0, __pad1 = 0, __st_ino = 0, st_mode = 0, st_nlink = 0, st_uid = 0, st_gid = 0, st_rdev = 0, __pad2 = 0, st_size = -1, st_blksize = 0, st_blocks = 0, st_atim = {tv_sec = 1250213196, tv_nsec = 0}, st_mtim = {tv_sec = 1250213196, tv_nsec = 0}, st_ctim = { tv_sec = 1250213196, tv_nsec = 0}, st_ino = 0}, buffer = 0x9b3b4b0 "what is stored in this buffer? I dont know so I have blanked it out. Let me know if you need to know more about its contents. This string was 365 characters long"..., w_buffer = 0x9b3b4b0 "what is stored in this buffer? I dont know so I have blanked it out. Let me know if you need to know more about its contents. This string was 365 characters long"..., buffer_size = 8192, max_buffer_size = 8192, skip = 0, pos = 8191, parent = 0x9b29a30, parent_start_offset = 0, line_str = 0x0, return_nolf_line = 0} (gdb) p *(struct file_istream *)stream.real_stream $15 = {istream = {iostream = {refcount = 1, close = 0x8100330 , destroy = 0x80f1750 , set_max_buffer_size = 0x80f1720 , destroy_callback = 0, destroy_context = 0x0}, read = 0x80f12b0 , seek = 0x80f1630 , sync = 0, stat = 0x80f11a0 , istream = { v_offset = 745472, stream_errno = 0, mmaped = 0, blocking = 1, closed = 0, readable_fd = 0, seekable = 0, eof = 0, real_stream = 0x9b28498}, fd = 11, abs_start_offset = 0, statbuf = {st_dev = 0, __pad1 = 0, __st_ino = 0, st_mode = 0, st_nlink = 0, st_uid = 0, st_gid = 0, st_rdev = 0, __pad2 = 0, st_size = -1, st_blksize = 0, st_blocks = 0, st_atim = {tv_sec = 1250213196, tv_nsec = 0}, st_mtim = {tv_sec = 1250213196, tv_nsec = 0}, st_ctim = { tv_sec = 1250213196, tv_nsec = 0}, st_ino = 0}, buffer = 0x9b3b4b0 "what is stored in this buffer? I dont know so I have blanked it out. Let me know if you need to know more about its contents. This string was 365 characters long"..., w_buffer = 0x9b3b4b0 "what is stored in this buffer? I dont know so I have blanked it out. Let me know if you need to know more about its contents. This string was 365 characters long"..., buffer_size = 8192, max_buffer_size = 8192, skip = 0, pos = 8191, parent = 0x9b29a30, parent_start_offset = 0, line_str = 0x0, return_nolf_line = 0}, skip_left = 0, file = 1, autoclose_fd = 0, seen_eof = 0} (gdb)

...

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. For some reason that's not working. I can look into that also, but I also really want to get that istream crash fixed. :) No problem - the hardlinking bit doesnt really break anything for us so its not as big an issue anyway. If we hadnt bumped into this bug, I probably wouldnt even have known it was not working :-)

-- Thanks, Phill Macey (CiSRA IT Services)

See if this helps: http://hg.dovecot.org/dovecot-1.2/rev/4c42e72a3954

Also you could check if you have any mails with CRs in them:

perl -ne 's/\r$//;print if /\r/' *

On Aug 17, 2009, at 1:31 AM, Phillip Macey wrote:

...

Also you could check if you have any mails with CRs in them:

perl -ne 's/\r$//;print if /\r/' *

This didn't print anything - I was sort of expecting it to at least
print something (especially since your update seemed to fix the
crash...)

Hmm. That is strange. What about in the destination mailbox where you
copied the messages? I'm now wondering if there's still a data
corruption bug.

On Aug 17, 2009, at 2:01 AM, Phillip Macey wrote:

On 17/08/2009 3:36 PM, Timo Sirainen wrote:

...

On Aug 17, 2009, at 1:31 AM, Phillip Macey wrote:

...

...

Also you could check if you have any mails with CRs in them:

perl -ne 's/\r$//;print if /\r/' *

This didn't print anything - I was sort of expecting it to at
least print something (especially since your update seemed to fix
the crash...)

Hmm. That is strange. What about in the destination mailbox where
you copied the messages? I'm now wondering if there's still a data
corruption bug.

Ok, I don't know what I did wrong the first time around - this time
it printed a whole heap of stuff for both the source and destination
mailboxes. Sorry about the false alarm.

Great, thanks. Time for v1.2.4 tomorrow then I guess. :)