dovecot - Mar 2009 - failed assertion in 1.1.8: istream.c: line 81

Hello,

We're having a problem in Dovecot 1.1.8 with a failed assertion on
certain mbox format mailboxes.  It happens both with deliver when it
attempts to delier to the mailbox, and with IMAP connections for the
affected box (though I'm not sure what they're doing at the time).

Mar 3 12:55:26 <snip> dovecot: Panic: IMAP(<snip>): file istream.c:
line 81 (i_stream_read): assertion failed: (_stream->skip !_stream->pos)

This is on FreeBSD 6.2, without any nfs.  The IMAP client is Squirrel
Mail, but as I said, the assertion occurs with deliver as well.

Apparently, moving the inbox out of the way fixed the problem for a
while, but then it came back.  Clearing out the dovecot index files
seemed not to have any effect.

I have a core dump available for deliver; here's a backtrace:
#0  0x282bbecb in kill () from /lib/libc.so.6
#1  0x282bbe68 in raise () from /lib/libc.so.6
#2  0x282bab78 in abort () from /lib/libc.so.6
#3  0x080b7ad8 in default_fatal_finish (type=LOG_TYPE_PANIC, status=0) at
failures.c:150
#4  0x080b7dbb in i_syslog_fatal_handler (type=LOG_TYPE_PANIC, status=0,
    fmt=0x80ca9a0 "file %s: line %d (%s): assertion failed: (%s)",
args=0xbfbfe2a4 "{\215\r\bQ") at failures.c:308
#5  0x080b7c37 in i_panic (format=0x80ca9a0 "file %s: line %d (%s):
assertion failed: (%s)") at failures.c:197
#6  0x080bb8a1 in i_stream_read (stream=0x8102e28) at istream.c:93
#7  0x080bbd3d in i_stream_read_data (stream=0x8102e28, data_r=0xbfbfe350,
size_r=0xbfbfe354, threshold=0) at istream.c:322
#8  0x0806d85b in istream_raw_mbox_get_body_size (stream=0x8102e28,
expected_body_size=11013) at istream-raw-mbox.c:562
#9  0x080736dd in mbox_sync_do (sync_ctx=0xbfbfe640, flags=0) at mbox-sync.c:151
#10 0x08075700 in mbox_sync (mbox=0x8103028, flags=0) at mbox-sync.c:1833
#11 0x08070001 in mbox_save_init (_t=0x80f2980, flags=0, keywords=0x0,
received_date=1236108538, timezone_offset=0,
    from_envelope=0x80e6100 "<snip>", input=0x80f6f28,
dest_mail=0x8106028, ctx_r=0x0)
    at mbox-save.c:318
#12 0x282ee17f in quota_save_init (t=0x80f2980, flags=0, keywords=0x0,
received_date=-1, timezone_offset=0,
    from_envelope=0x80e6100 "<snip>", input=0x80f6f28,
dest_mail=0x8106028, ctx_r=0xbfbfe9f0)
    at quota-storage.c:236
#13 0x0808e36d in mailbox_save_init (t=0x5, flags=0, keywords=0x0,
received_date=-1, timezone_offset=0,
    from_envelope=0x80e6100 "<snip>", input=0x80f6f28,
dest_mail=0x8106028, ctx_r=0xbfbfe9f0)
    at mail-storage.c:726
#14 0x0808c34a in mail_storage_copy (t=0x80f2980, mail=0xbfbfe9f0, flags=0,
keywords=0x0, dest_mail=0x8106028)
    at mail-copy.c:28
#15 0x282ee08a in quota_copy (t=0x80f2980, mail=0x80fd028, flags=0,
keywords=0x0, dest_mail=0x8106028)
    at quota-storage.c:180
#16 0x080590a4 in deliver_save (namespaces=0x80f7028, storage_r=0xbfbfeb60,
mailbox=0x80d0eeb "INBOX", mail=0x80fd028,
    flags=0, keywords=0x0) at deliver.c:237
#17 0x0805a90c in main (argc=5, argv=0xbfbfec14) at deliver.c:1093

Does anyone have any clues on how to debug this further?  I wonder if
the original bug reporter removed both the mailbox and the index files
at the same time; the current explanation is less than satisfactory.

Thanks,
Alan Ferrency
pair Networks, Inc.

On Tue, 2009-03-03 at 15:35 -0500, Alan Ferrency wrote:
> I have a core dump available for deliver; here's a backtrace:
Could you also do:
> #6  0x080bb8a1 in i_stream_read (stream=0x8102e28) at istream.c:93
fr 6
p *stream
p *stream.real_stream
p *stream.real_stream.parent
p *stream.real_stream.parent.real_stream

-------------- 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/20090303/2dc1c768/attachment-0002.bin>

On Tue, 3 Mar 2009, Timo Sirainen wrote:
> On Tue, 2009-03-03 at 15:35 -0500, Alan Ferrency wrote:
> > I have a core dump available for deliver; here's a backtrace:
>
> Could you also do:
>
> > #6  0x080bb8a1 in i_stream_read (stream=0x8102e28) at istream.c:93
>
> fr 6
> p *stream
> p *stream.real_stream
> p *stream.real_stream.parent
> p *stream.real_stream.parent.real_stream
Sure.

(To add insult to injury, it's spam of course...)


(gdb) p *stream
$1 = {v_offset = 676764, stream_errno = 0, mmaped = 0, blocking = 1, closed = 0,
seekable = 1, eof = 0,
  real_stream = 0x8102e00}
(gdb) p *stream.real_stream
$2 = {iostream = {refcount = 1, close = 0x80c925c
<io_stream_default_close_destroy>,
    destroy = 0x806c654 <i_stream_raw_mbox_destroy>,
    set_max_buffer_size = 0x806c6c0
<i_stream_raw_mbox_set_max_buffer_size>, destroy_callback = 0,
destroy_context = 0x0},
  read = 0x806c7b8 <i_stream_raw_mbox_read>, seek = 0x806d1a8
<i_stream_raw_mbox_seek>,
  sync = 0x806d1f8 <i_stream_raw_mbox_sync>, stat = 0x806d228
<i_stream_raw_mbox_stat>, istream = {v_offset = 676764,
    stream_errno = 0, mmaped = 0, blocking = 1, closed = 0, seekable = 1, eof =
0, real_stream = 0x8102e00}, fd = -1,
  abs_start_offset = 0, statbuf = {st_dev = 0, st_ino = 0, st_mode = 0, st_nlink
= 0, st_uid = 0, st_gid = 0, st_rdev = 0,
    st_atimespec = {tv_sec = 1236108538, tv_nsec = 0}, st_mtimespec = {tv_sec =
1236108538, tv_nsec = 0}, st_ctimespec = {
      tv_sec = 1236108538, tv_nsec = 0}, st_size = -1, st_blocks = 0, st_blksize
= 0, st_flags = 0, st_gen = 0,
    st_lspare = 0, st_birthtimespec = {tv_sec = 0, tv_nsec = 0}},
  buffer = 0x8112000 "\nFrom his something she hough her arzil though
familiar whisper her psychic the mill yannis followed <a
href=\"http://thhgjdirect.com/stop-serzone/\"
rel=\"nofollow\">attorney louisiana serzone</a> duin
s"..., w_buffer = 0x0,
  buffer_size = 0, max_buffer_size = 8192, skip = 0, pos = 0, parent =
0x810b128, parent_start_offset = 0, line_str = 0x0,
  return_nolf_line = 0}
(gdb) p *stream.real_stream.parent
$3 = {v_offset = 676764, stream_errno = 0, mmaped = 0, blocking = 1, closed = 0,
seekable = 1, eof = 0,
  real_stream = 0x810b100}
(gdb) p *stream.real_stream.parent.real_stream
$4 = {iostream = {refcount = 2, close = 0x80bce70 <i_stream_file_close>,
destroy = 0x80bcebc <i_stream_file_destroy>,
    set_max_buffer_size = 0x80bbf70
<i_stream_default_set_max_buffer_size>, destroy_callback = 0,
destroy_context = 0x0},
  read = 0x80bceec <i_stream_file_read>, seek = 0x80bd194
<i_stream_file_seek>, sync = 0x80bd210 <i_stream_file_sync>,
  stat = 0x80bd234 <i_stream_file_stat>, istream = {v_offset = 676764,
stream_errno = 0, mmaped = 0, blocking = 1,
    closed = 0, seekable = 1, eof = 0, real_stream = 0x810b100}, fd = 10,
abs_start_offset = 0, statbuf = {st_dev = 58,
    st_ino = 8290386, st_mode = 33152, st_nlink = 1, st_uid = 5509, st_gid =
1000, st_rdev = 33543528, st_atimespec = {
      tv_sec = 1236108527, tv_nsec = 0}, st_mtimespec = {tv_sec = 1236097582,
tv_nsec = 0}, st_ctimespec = {
      tv_sec = 1236097582, tv_nsec = 0}, st_size = 687419, st_blocks = 1376,
st_blksize = 4096, st_flags = 0, st_gen = 0,
    st_lspare = 0, st_birthtimespec = {tv_sec = 0, tv_nsec = 0}},
  buffer = 0x8112000 "\nFrom his something she hough her arzil though
familiar whisper her psychic the mill yannis followed <a
href=\"http://thhgjdirect.com/stop-serzone/\"
rel=\"nofollow\">attorney louisiana serzone</a> duin
s"...,
  w_buffer = 0x8112000 "\nFrom his something she hough her arzil though
familiar whisper her psychic the mill yannis followed <a
href=\"http://thhgjdirect.com/stop-serzone/\"
rel=\"nofollow\">attorney louisiana serzone</a> duin
s"...,
  buffer_size = 8192, max_buffer_size = 8192, skip = 0, pos = 8192, parent =
0x0, parent_start_offset = 0, line_str = 0x0,
  return_nolf_line = 0}

Thanks,
Alan Ferrency
pair Networks, Inc.

On Tue, 2009-03-03 at 15:35 -0500, Alan Ferrency wrote:
> Mar 3 12:55:26 <snip> dovecot: Panic: IMAP(<snip>): file
istream.c:
> line 81 (i_stream_read): assertion failed: (_stream->skip !>
_stream->pos)
Fixed: http://hg.dovecot.org/dovecot-1.1/rev/6aaf6a306c94

-------------- 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/20090305/92ff4554/attachment-0002.bin>

Thanks!

Is this going into the 1.1 branch for a future release, curiously?

And do I still need the previous patch(es) you sent?  I expect not.

Alan Ferrency
pair Networks, Inc.


On Thu, 5 Mar 2009, Timo Sirainen wrote:
> On Tue, 2009-03-03 at 15:35 -0500, Alan Ferrency wrote:
> > Mar 3 12:55:26 <snip> dovecot: Panic: IMAP(<snip>): file
istream.c:
> > line 81 (i_stream_read): assertion failed: (_stream->skip !>
> _stream->pos)
>
> Fixed: http://hg.dovecot.org/dovecot-1.1/rev/6aaf6a306c94
>
>