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:
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 <mail_cache_compress_callback>, context=0xbffff840) at mail-cache-lookup.c:134 #3 0x0807212e in mail_cache_foreach (view=0x80ba820, seq=153, callback=0x807d6a8 <mail_cache_compress_callback>, context=0xbffff840) at mail-cache-lookup.c:189 #4 0x0807d911 in mail_cache_copy (cache=0x80b3a08, view=0x40, fd=8) at mail-cache-compress.c:154 #5 0x0807dbc2 in mail_cache_compress (cache=0x80b3a08, view=0x80ba728) at mail-cache-compress.c:253 #6 0x08078298 in mail_index_sync_commit (ctx=0x80b36c0) at mail-index-sync.c:455 #7 0x08069888 in mbox_sync (ibox=0x80b3268, flags=MBOX_SYNC_LAST_COMMIT) at mbox-sync.c:1341 #8 0x08064453 in mbox_transaction_commit (_t=0x80ba728, flags=0) at mbox-transaction.c:48 #9 0x0807e876 in mailbox_transaction_commit (t=0x6e6ca9a0, flags=0) at mail-storage.c:409 #10 0x0805aaae in imap_sort (client=0x80a88a0, charset=0x80a8bc2 "US-ASCII", args=0x80b9528, sort_program=0x809e0b6) at imap-sort.c:257 #11 0x08055cd4 in cmd_sort (client=0x80a88a0) at cmd-sort.c:123 #12 0x0805660f in cmd_uid (client=0x80a88a0) at cmd-uid.c:19 #13 0x08056d8a in client_handle_input (client=0x80a88a0) at client.c:323 #14 0x08056e99 in _client_input (context=0x80a88a0) at client.c:367 #15 0x0808cc34 in io_loop_handler_run (ioloop=0x80a61d0) at ioloop-poll.c:184 #16 0x0808c379 in io_loop_run (ioloop=0x80a61d0) at ioloop.c:218 #17 0x0805d13f in main (argc=2, argv=0xbffffc04, envp=0xbffffc10) at main.c:214 #18 0x40037bb4 in __libc_start_main () from /lib/libc.so.6
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 <mail_cache_compress_callback>, context=0xbffff8f0) at mail-cache-lookup.c:134 #3 0x08068a0a in mail_cache_foreach (view=0x80a18b0, seq=237, callback=0x8073f84 <mail_cache_compress_callback>, context=0xbffff8f0) at mail-cache-lookup.c:189 #4 0x080741ed in mail_cache_copy (cache=0x809d8b0, view=0x40, fd=8) at mail-cache-compress.c:154 #5 0x0807449e in mail_cache_compress (cache=0x809d8b0, view=0x809d6e8) at mail-cache-compress.c:253 #6 0x0806eb74 in mail_index_sync_commit (ctx=0x80a1930) at mail-index-sync.c:455 #7 0x08060164 in mbox_sync (ibox=0x809d110, flags=MBOX_SYNC_LAST_COMMIT) at mbox-sync.c:1341 #8 0x0805ad2f in mbox_transaction_commit (_t=0x80a38b8, flags=0) at mbox-transaction.c:48 #9 0x08075152 in mailbox_transaction_commit (t=0x6e6ca9a0, flags=0) at mail-storage.c:409 #10 0x08052668 in init_mailbox (client=0x809cc88) at client.c:121 #11 0x080527d9 in client_create (hin=134861072, hout=1, storage=0x809cb88) at client.c:168 #12 0x08053e48 in main_init () at main.c:155 #13 0x08053f87 in main (argc=2, argv=0xbffffc04, envp=0xbffffc10) at main.c:188 #14 0x40037bb4 in __libc_start_main () from /lib/libc.so.6
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.
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.
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:
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
ok. I'm starting to understand more of the dovecot source so I'll check it out.
(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:
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 think mbox code in CVS works again. Please try and see if it fixes even the first problem.
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:
I haven't seen this one again yet.
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...
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:
Can you reproduce this easily? What about after removing indexes?
This might be fixed in CVS now. I'll release test48 tomorrow if nothing
seems to be broken.
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:
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.
Ok. Will pull test48 and retest.
- Mike
dovecot@spam.turbolink.net wrote:
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