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

[Phillip Macey]

On 14/08/2009 12:29 PM, Timo Sirainen wrote:
> On Aug 13, 2009, at 10:20 PM, Phillip Macey wrote:
>> 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 
> 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
things that I noticed:
* 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 -
permanent storage? fluke?).
* 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
<io_stream_default_close_destroy>, destroy = 0x80f1750
<i_stream_crlf_destroy>,
    set_max_buffer_size = 0x80f1720 <i_stream_crlf_set_max_buffer_size>,
destroy_callback = 0, destroy_context = 0x0},
  read = 0x80f12b0 <i_stream_crlf_read_lf>, seek = 0x80f1630
<i_stream_crlf_seek>, sync = 0, stat = 0x80f11a0 <i_stream_crlf_stat>,
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
<io_stream_default_close_destroy>, destroy = 0x80f1750
<i_stream_crlf_destroy>,
      set_max_buffer_size = 0x80f1720
<i_stream_crlf_set_max_buffer_size>, destroy_callback = 0,
destroy_context = 0x0},
    read = 0x80f12b0 <i_stream_crlf_read_lf>, seek = 0x80f1630
<i_stream_crlf_seek>, sync = 0, stat = 0x80f11a0 <i_stream_crlf_stat>,
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)