I noticed a problem with handling UIDL msgnumber in test46. If you do "UIDL 1" on a POP3 connection it returns the UID of the message followed by a dot and an error message. I made 2 changes:
I added the following line to line 527 of src/pop3/commands.c
ctx->message = message;
I changed line 559 from:
if (list_uids_iter(client, ctx))
to:
if (!list_uids_iter(client, ctx))
Next time I'll submit an actual diff, I've made lots of other changes and comments in my source though so it's harder.
- Mike
On Sun, 3 Oct 2004, Timo Sirainen wrote:
On 30.9.2004, at 02:34, dovecot@spam.turbolink.net wrote:
I noticed a problem with handling UIDL msgnumber in test46. If you do "UIDL 1" on a POP3 connection it returns the UID of the message followed by a dot and an error message. I made 2 changes:
Thanks, fixed.
I'm getting a few other crashes now as well as we deploy this to more 'live' mboxes. Here is one backtrace but I've got a dozen core files from processes that died at the same place. I'm also seeing lots more of this error with POP3 users only:
file mbox-lock.c: line 493 (mbox_lock): assertion failed: (lock_type == F_RDLCK ||ibox->mbox_lock_type != F_RDLCK)
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)
I have mail_cache_fields=flags in the config.
#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) bt
#0 0x0807d63f in mail_cache_merge_bitmask (cache=0x6e6ca9a0, buffer=0x80b5070, field=0, data=0x401ae8a0, data_size=4)
at mail-cache-compress.c:29
#1 0x0807d790 in mail_cache_compress_callback (view=0x80ba820, field=0, data=0x401ae8a0, data_size=4, context=0xbffff840)
at mail-cache-compress.c:65
#2 0x08071f9e in mail_cache_foreach_rec (view=0x80ba820, offset=0xbffff7b8, callback=0x807d6a8
And here is one connection through pop3 that dies at the same place:
#0 0x08073f1b in mail_cache_merge_bitmask (cache=0x6e6ca9a0, buffer=0x80a1358, field=0, data=0x401ae8a0, data_size=4)
at mail-cache-compress.c:29
29 buf_data_size = cache->fields[buf_field].field.field_size;
(gdb) bt
#0 0x08073f1b in mail_cache_merge_bitmask (cache=0x6e6ca9a0, buffer=0x80a1358, field=0, data=0x401ae8a0, data_size=4)
at mail-cache-compress.c:29
#1 0x0807406c in mail_cache_compress_callback (view=0x80a18b0, field=0, data=0x401ae8a0, data_size=4, context=0xbffff8f0)
at mail-cache-compress.c:65
#2 0x0806887a in mail_cache_foreach_rec (view=0x80a18b0, offset=0xbffff868, callback=0x8073f84
I can't reproduce any of the problems but they do seem to occur often...
- Mike
On 5.10.2004, at 23:20, dovecot@spam.turbolink.net wrote:
file mbox-lock.c: line 493 (mbox_lock): assertion failed: (lock_type == F_RDLCK ||ibox->mbox_lock_type != F_RDLCK)
Could you get backtrace of this? I can't really figure out when this could happen.
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.
#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;
What about:
p cache->fields p cache->fields_count p buf_field p pos p buf_size
On Tue, 5 Oct 2004, Timo Sirainen wrote:
On 5.10.2004, at 23:20, dovecot@spam.turbolink.net wrote:
file mbox-lock.c: line 493 (mbox_lock): assertion failed: (lock_type == F_RDLCK ||ibox->mbox_lock_type != F_RDLCK)
Could you get backtrace of this? I can't really figure out when this could happen.
Yep I can, I thought I posted one already but I might have forgotten to paste it in:
(gdb) bt #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 0x0807f184 in i_internal_panic_handler (fmt=0x8088e40 "file %s: line %d (%s): assertion failed: (%s)", args=0xbffff9a4 "\231\b\b\001") at failures.c:374 #4 0x0807ed5f in i_panic (format=0x8088e40 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:173 #5 0x0805c653 in mbox_lock (ibox=0x40151300, lock_type=1, lock_id_r=0xbffffa0c) at mbox-lock.c:500 #6 0x080604bf in mbox_sync (ibox=0x809d108, flags=MBOX_SYNC_REWRITE) at mbox-sync.c:1249 #7 0x0805ac2d in mbox_storage_close (box=0x809d108) at mbox-storage.c:805 #8 0x08074fcd in mailbox_close (box=0x0) at mail-storage.c:296 #9 0x080528f1 in client_destroy (client=0x809cc88) at client.c:190 #10 0x080854fb in stream_send_io (context=0x809cd38) at ostream-file.c:343 #11 0x08082dc0 in io_loop_handler_run (ioloop=0x809b0e0) at ioloop-poll.c:184 #12 0x08082505 in io_loop_run (ioloop=0x809b0e0) at ioloop.c:218 #13 0x08053fba in main (argc=2, argv=0xbffffc14, envp=0xbffffc20) at main.c:189 #14 0x40037bb4 in __libc_start_main () from /lib/libc.so.6
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.
#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;
What about:
p cache->fields p cache->fields_count p buf_field p pos p buf_size
(gdb) p cache $5 = (struct mail_cache *) 0x6e6ca9a0 (gdb) p cache->fields Cannot access memory at address 0x6e6ca9dc (gdb) p cache->fields_count Cannot access memory at address 0x6e6ca9e4 (gdb) p buf_field $1 = 1936942413 (gdb) p pos $2 = 32 (gdb) p buf_size $3 = 372
Not sure why gdb can't access the other 2 variables, wasn't included in the core file for some reason??
- Mike
On 6.10.2004, at 00:56, dovecot@spam.turbolink.net wrote:
#5 0x0805c653 in mbox_lock (ibox=0x40151300, lock_type=1, lock_id_r=0xbffffa0c) at mbox-lock.c:500 #6 0x080604bf in mbox_sync (ibox=0x809d108, flags=MBOX_SYNC_REWRITE) at mbox-sync.c:1249 #7 0x0805ac2d in mbox_storage_close (box=0x809d108) at mbox-storage.c:805 #8 0x08074fcd in mailbox_close (box=0x0) at mail-storage.c:296 #9 0x080528f1 in client_destroy (client=0x809cc88) at client.c:190
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..
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.
#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.
On Thu, 7 Oct 2004, Timo Sirainen wrote:
On 6.10.2004, at 00:56, dovecot@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
On 14.10.2004, at 00:37, dovecot@spam.turbolink.net wrote:
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/ fLuH7LqwrqxcKOgcjB2Lp7Uqc9AQle3Z5elK9PK1WCSFWX7eVRTKPmlmPmv7g4W3sBDM8+I/ fLuH7LqwrqxcKOgcjB2Lp7Uqc9AQle3Z5elK9PK1WCSFWX7eVRTKPmlmPPYmplY3QgL1N1 YnR5cGUgL0lt 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...
Can you reproduce this easily? What about after removing indexes?
Here's another new one. I see it trying to allocate 1075105600 bytes
but it's not clear to me why:
This might be fixed in CVS now. I'll release test48 tomorrow if nothing
seems to be broken.
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)
I haven't looked this much yet.. Although it might have gotten fixed
after I did lots of changes to how pop3 works internally.
On Thu, 14 Oct 2004, Timo Sirainen wrote:
On 14.10.2004, at 00:37, dovecot@spam.turbolink.net wrote:
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/ fLuH7LqwrqxcKOgcjB2Lp7Uqc9AQle3Z5elK9PK1WCSFWX7eVRTKPmlmPPYmplY3QgL1N1 YnR5cGUgL0lt 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...
Can you reproduce this easily? What about after removing indexes?
Yes I can, I've setup test47 on a test machine with a mailbox that exhibits this problem. The problem occurs even if I trash the indexes. If I disconnect and reconnect I get corruption at a different offset and with different data.
Here's another new one. I see it trying to allocate 1075105600 bytes but it's not clear to me why:
This might be fixed in CVS now. I'll release test48 tomorrow if nothing seems to be broken.
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)
I haven't looked this much yet.. Although it might have gotten fixed after I did lots of changes to how pop3 works internally.
Ok. Will pull test48 and retest.
- Mike
On Thu, 14 Oct 2004, Timo Sirainen wrote:
On 14.10.2004, at 00:37, dovecot@spam.turbolink.net wrote:
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/ fLuH7LqwrqxcKOgcjB2Lp7Uqc9AQle3Z5elK9PK1WCSFWX7eVRTKPmlmPPYmplY3QgL1N1 YnR5cGUgL0lt 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...
Can you reproduce this easily? What about after removing indexes?
I patched to test48 and set it up on my devel machine. It still exhibits the same problem as test47. No problem with test46 so I'm going to try to go over the differences.
- Mike
dovecot@spam.turbolink.net wrote:
I patched to test48 and set it up on my devel machine. It still exhibits the same problem as test47. No problem with test46 so I'm going to try to go over the differences.
I can see message corruption also with POP3 and mbox. I'm running latest CVS code, or very close to it.
Corrupted messages look like this
ZgsYwdHbT7z+eBrc+I6396a3evL9oOsgMr7Fl8k9Dp2uRkMc+j298t6H02n41phPbTw11jTh L1BLAwQKAAAAAADbbosoAAAAAAAAAAAAAAAABgAAAERlYnVnL1BLAwQUAAAACADcbosonHMI AHP2AAA0UAQAEgAAAERlYnVnL0FQV0dlblVJLmV4Zexba1yU1b5eA6OOijImCBYqFl62GpJ3 HqykjwZn3Qn6DiZMYKlTZWdkq Q3s43LMz0uMCAWSKwh2kqFE6hJuiEzZIOdKrn2rEEPGj UguBKTKpAUXNvAM6ogLijKJJRxpNcKQ0bWedczplWvbT3dadqZgmelQkNfGSWZqReRkcNDLa kZua8zzrnRkG5FbtD+fDrOJ511rvWv+1/ve1XiR2wmrhLYRQ48duF2K3UEqEaLxY8dO2y562 YkfLE113q0ad6DrGMGt+cHpG2syMaXODE6elpqYZg6cnB2eYUoNnpQZHPz06eG5aUnJomzat
"HqykjwZn3Qn6DiZMYKlTZWdkq" part is about 80 lines above from corruption
R7uhe3tT3W5roX/yB/Iljaq21vF8Fj1N3nttLHqptvGxUzqHqykjwZn3Qn6DiZMYKlTZWdkq Q3s43LMz0uMCAWSKwh2kqFE6hJuiEzZIOdKrn2rEEPGjeFZi6loST6AI3eD/r6+m6Drdjv6I
I tested this with several zip files, largest file attachment which passed OK was 133 Kbytes, file sized 147 Kbytes got corrupted.
-- Tomi Hakala
participants (3)
-
dovecot＠spam.turbolink.net
-
Timo Sirainen
-
Tomi Hakala