[Dovecot] UIDL bug

Thu Oct 14 00:37:59 EEST 2004

On Thu, 7 Oct 2004, Timo Sirainen wrote:

> On 6.10.2004, at 00:56, dovecot at spam.turbolink.net wrote:
>
> fr 9
> p client->cmd
>
> It looks like some command isn't being deinitialized properly. I found
> one possible reason, but I don't think it should happen at least
> often..

I haven't seen this one again yet.

> >>> And lots more of this one with IMAP users only:
> >>>
> >>> file mbox-sync-rewrite.c: line 460 (mbox_sync_rewrite): assertion
> >>> failed: (mails[idx].space > 0)
> >>
> >> Yep, this happened with me too. CVS has much more understandable (and
> >> better working and slightly faster) mbox rewriting code. But it has
> >> some other new syncing problems that I haven't yet fixed.
> >
> > ok.  I'm starting to understand more of the dovecot source so I'll
> > check
> > it out.
>
> I think mbox code in CVS works again. Please try and see if it fixes
> even the first problem.

I moved to test47 which seems to fix several crashes, (including one
problem with messages that have no body text) but causes a couple of new
problems, one with POP3.  Here is a diff between the actual mailbox and
what dovecot returns through POP3:

313c308,309
< mv7g4W3sBDM8+I/fLuH7LqwrqxcKOgcjB2Lp7Uqc9AQle3Z5elK9PK1WCSFWX7eVRTKPmlmP
---
> mv7g4W3sBDM8+I/fLuH7LqwrqxcKOgcjB2Lp7Uqc9AQle3Z5elK9PK1WCSFWX7eVRTKPmlmPPYmplY3QgL1N1YnR5cGUgL0lt
> YWdlIC9XaWR0aCA2NSAvS

The extra data "PPYmplY3QgL1N1YnR5cGUgL0lt" doesn't appear anywhere in the
mbox, I'm not sure where it's coming from.??  Pulling the same message
through with IMAP seems to be no problem...

> >>> #0  0x0807d63f in mail_cache_merge_bitmask (cache=0x6e6ca9a0,
> >>> buffer=0x80b6b58, field=0, data=0x4027ebf8, data_size=4)
> >>>     at mail-cache-compress.c:29
> >>> 29                      buf_data_size =
> >>> cache->fields[buf_field].field.field_size;
> >>
> > (gdb) p cache
> > $5 = (struct mail_cache *) 0x6e6ca9a0
> > (gdb) p cache->fields
> > Cannot access memory at address 0x6e6ca9dc
>
> Either corrupted backtrace or Dovecot somehow corrupted the stack while
> running. I added several asserts in CVS to catch all possible mistakes
> here.

Here's another new one.  I see it trying to allocate 1075105600 bytes but
it's not clear to me why:
Error: IMAP(user): pool_system_realloc(): Out of memory

corresponding backtrace:
#0  0x4004bc31 in kill () from /lib/libc.so.6
#1  0x4004b8b8 in raise () from /lib/libc.so.6
#2  0x4004d17c in abort () from /lib/libc.so.6
#3  0x080899b4 in i_internal_panic_handler (fmt=0x809cd60 "pool_system_realloc(): Out of memory", args=0xbffff454 "")
    at failures.c:374
#4  0x0808958f in i_panic (format=0x809cd60 "pool_system_realloc(): Out of memory") at failures.c:173
#5  0x0808e631 in pool_system_realloc (pool=0x809f540, mem=0x0, old_size=4096, new_size=1075105600) at mempool-system.c:97
#6  0x080886eb in buffer_alloc (buf=0x80b7898, size=134217728) at buffer.c:32
#7  0x08088b4f in buffer_copy (_dest=0x80b7898, dest_pos=99884281, _src=0x80b7898, src_pos=1360, copy_size=33) at buffer.c:56
#8  0x0806b5c4 in mbox_sync_headers_add_space (ctx=0xbffff530, size=99882921) at mbox-sync-rewrite.c:105
#9  0x0806bc91 in mbox_sync_read_and_move (sync_ctx=0xbffff920, mails=0x80bba08, seq=0, idx=42, padding=99882921, move_diff=110,
    end_offset=208003) at mbox-sync-rewrite.c:329
#10 0x0806bee2 in mbox_sync_rewrite (sync_ctx=0xbffff920, end_offset=208003, move_diff=110, extra_space=4294965629, first_seq=1,
    last_seq=134987436) at mbox-sync-rewrite.c:410
#11 0x08068a20 in mbox_sync_handle_missing_space (mail_ctx=0xbffff7c0) at mbox-sync.c:633
#12 0x08068ef5 in mbox_sync_loop (sync_ctx=0xbffff920, mail_ctx=0xbffff7c0, min_message_count=0, partial=0) at mbox-sync.c:885
#13 0x080695ad in mbox_sync_do (sync_ctx=0xbffff920, flags=25) at mbox-sync.c:1115
#14 0x08069b26 in mbox_sync (ibox=0x80b4eb0, flags=25) at mbox-sync.c:1327
#15 0x0806475f in mbox_transaction_commit (_t=0x80b7e20, flags=3) at mbox-transaction.c:48
#16 0x0807f3fa in mailbox_transaction_commit (t=0x0, flags=3) at mail-storage.c:409
#17 0x08057c29 in imap_expunge (box=0x80b4eb0, next_search_arg=0x0) at imap-expunge.c:42
#18 0x08054195 in cmd_expunge (client=0x80aa4f0) at cmd-expunge.c:45
#19 0x08056eda in client_handle_input (client=0x80aa4f0) at client.c:323
#20 0x08056fe9 in _client_input (context=0x80aa4f0) at client.c:367
#21 0x0808d614 in io_loop_handler_run (ioloop=0x80a7e30) at ioloop-poll.c:184
#22 0x0808cd59 in io_loop_run (ioloop=0x80a7e30) at ioloop.c:218
#23 0x0805d447 in main (argc=2, argv=0xbffffbb4, envp=0xbffffbc0) at main.c:214
#24 0x40037bb4 in __libc_start_main () from /lib/libc.so.6
(gdb)

And still seeing this one:

POP3(mkuker): file mbox-lock.c: line 493 (mbox_lock): assertion failed: (lock_type == F_RDLCK || ibox->mbox_lock_type != F_RDLCK)

backtrace:
#0  0x4004bc31 in kill () from /lib/libc.so.6
#1  0x4004b8b8 in raise () from /lib/libc.so.6
#2  0x4004d17c in abort () from /lib/libc.so.6
#3  0x0807fa58 in i_internal_panic_handler (fmt=0x8089740 "file %s: line %d (%s): assertion failed: (%s)",
    args=0xbffff964 "\b\b\001") at failures.c:374
#4  0x0807f633 in i_panic (format=0x8089740 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:173
#5  0x0805c897 in mbox_lock (ibox=0x1, lock_type=1, lock_id_r=0xbffff9cc) at mbox-lock.c:500
#6  0x080606db in mbox_sync (ibox=0x809e110, flags=MBOX_SYNC_LAST_COMMIT) at mbox-sync.c:1250
#7  0x0805af53 in mbox_transaction_commit (_t=0x80a1b40, flags=0) at mbox-transaction.c:48
#8  0x08075bee in mailbox_transaction_commit (t=0x0, flags=0) at mail-storage.c:409
#9  0x08053391 in fetch_deinit (ctx=0x80a05c0) at commands.c:220
#10 0x08053754 in cmd_retr (client=0x809dc88, args=0x809fe43 "9") at commands.c:369
#11 0x08052da8 in client_input (context=0x809dc88) at client.c:378
#12 0x080836b8 in io_loop_handler_run (ioloop=0x809c0e0) at ioloop-poll.c:184
#13 0x08082dfd in io_loop_run (ioloop=0x809c0e0) at ioloop.c:218
#14 0x080541da in main (argc=2, argv=0xbffffbf4, envp=0xbffffc00) at main.c:191
#15 0x40037bb4 in __libc_start_main () from /lib/libc.so.6
(gdb) fr 10
#10 0x08053754 in cmd_retr (client=0x809dc88, args=0x809fe43 "9") at commands.c:369
369             fetch(client, msgnum, (uoff_t)-1);
(gdb) print *client
$1 = {socket = 0, io = 0x809ddb0, input = 0x809dd00, output = 0x809dd6c, cmd = 0, cmd_context = 0x80a05c0, storage = 0x809db90,
  mailbox = 0x809e110, last_input = 1097675982, last_output = 1097675982, bad_counter = 0, messages_count = 16, deleted_count = 8,
  message_sizes = 0x809e338, total_size = 598422, deleted_size = 226860, last_seen = 9, deleted_bitmask = 0x80aafd0 "",
  seen_bitmask = 0x80aafa0 "", deleted = 1, waiting_input = 0}
(gdb)

Let me know if you need some more information.  I'm trying to track down
some of these a bit more as well as getting CVS-able...

- Mike