At 12:52 AM -0500 3/7/07, Jim Horner wrote:

...

• If time moves backwards only max. 5 seconds, sleep until we're back in the original present instead of killing ourself. An error is still logged.

This might be a stupid question but this weekend we are about to push our clocks ahead one hour. In the fall when the clocks get set back an hour what does that do to Dovecot?

Our servers are using NTP and I'm not entirely sure how that adjusts the clock. I'm laughing at myself because whatever it does it's worked for us for years. I know I just jinxed myself.

The timezone changes only affect the display of time in a particular zone or calculation of absolute time from a zoned form. No sanely-written daemon works with zoned time values except for presentation to humans, i.e. logging. Switching the system time zone (i.e. the offset from GMT to use for presentation of time) does not change the system time. There is no clock adjustment at a DST change.

Bill Cole bill@scconsult.com

On Thu, 2007-03-08 at 11:02 -0800, Dan Price wrote:

On Wed 07 Mar 2007 at 02:28AM, Timo Sirainen wrote:

...

http://dovecot.org/releases/dovecot-1.0.rc26.tar.gz http://dovecot.org/releases/dovecot-1.0.rc26.tar.gz.sig

Most importantly this should fix mbox problems in recent RCs.

(Sorry for the long mail)

I've got rc26 up and running on our production box, and we are now migrating users onto it. In a few days we'll see higher user load than we saw in our pilot deployment. So far things look mixed. Some observations:

• I'm seeing a lot more imap-login's around than I am used to. Usually there have been just 3; maybe no big deal...? Maybe I made a settings mistake?

  # pgrep -x imap-login | wc -l 27 # pgrep -x imap | wc -l 30

Do you have login_process_per_connection=yes? If so, they're probably proxying SSL connections.

    #6  0x08087b2f in mbox_sync_rewrite (sync_ctx=0x8047800, mail_ctx=0x0, 
        end_offset=138189881, move_diff=742, extra_space=The value of variable 'extra_space' is distributed across several
    locations, and GDB cannot access its value.

    )
        at mbox-sync-rewrite.c:566
            mails = (struct mbox_sync_mail *) 0x811dc48
            offset = The value of variable 'offset' is distributed across several
    locations, and GDB cannot access its value.

Hmm. I don't think I've seen this assert-crash before. If it's happening often, compiling without -O2 might help more in debugging it.

• Dovecot is still *really* noisy on endianness switchover, and also I think it has been crashy, too:

Looks like I didn't finish fixing the endianess conversion problems. http://dovecot.org/list/dovecot-cvs/2007-March/007997.html should fix them so that it only complains "Corrupted index cache dovecot.index.cache: indexid changed"

    Error: IMAP(foobar): file client.c: line 412 (_client_input): assertion failed: (!client->handling_input)

Any chance of getting gdb backtrace from this?

Error: IMAP(foobar): Raw backtrace: 0x80b8fd3 -> 0x806c1da -> 0x8068f2d -> 0x8069169 -> 0x8069222 -> 0x806935f -> 0x806bfd7 -> 0x806bf5e -> 0x806c140 -> 0x80be67d -> 0x80be0b5 -> 0x8072fac -> 0x806722c

If not, this could be used with gdb to get it: http://dovecot.org/list/dovecot/2006-November/017682.html

On Thu 08 Mar 2007 at 10:09PM, Timo Sirainen wrote:

Do you have login_process_per_connection=yes? If so, they're probably proxying SSL connections.

Ahh. Ok. I didn't have SSL in the pilot. Should I set login_process_per_connection=no? I don't know the best practice here, I took what I thought was the default setting.

Hmm. I don't think I've seen this assert-crash before. If it's happening often, compiling without -O2 might help more in debugging it.

Ok, done. I'll see if it happens again.

Looks like I didn't finish fixing the endianess conversion problems. http://dovecot.org/list/dovecot-cvs/2007-March/007997.html should fix them so that it only complains "Corrupted index cache dovecot.index.cache: indexid changed"

Thanks!

...

    Error: IMAP(foobar): file client.c: line 412 (_client_input): assertion failed: (!client->handling_input)

Any chance of getting gdb backtrace from this?

I'll see if I can find it. I've been monkeying with adding DTrace probes to Dovecot (patch forthcoming, I am hopeful) and was slightly afraid I caused this-- let me see if it happens again tonight, when we add more users.

    -dp

-- Daniel Price - Solaris Kernel Engineering - dp@eng.sun.com - blogs.sun.com/dp

On Thu 08 Mar 2007 at 01:50PM, Dan Price wrote:

On Thu 08 Mar 2007 at 10:09PM, Timo Sirainen wrote:

...

Do you have login_process_per_connection=yes? If so, they're probably proxying SSL connections.

Ahh. Ok. I didn't have SSL in the pilot. Should I set login_process_per_connection=no? I don't know the best practice here, I took what I thought was the default setting.

...

Hmm. I don't think I've seen this assert-crash before. If it's happening often, compiling without -O2 might help more in debugging it.

Ok, done. I'll see if it happens again.

...

Looks like I didn't finish fixing the endianess conversion problems. http://dovecot.org/list/dovecot-cvs/2007-March/007997.html should fix them so that it only complains "Corrupted index cache dovecot.index.cache: indexid changed"

Today I've got another new crash I haven't seen before-- this is badly impacting the user in question-- since we're crashing on their inbox. This is running on our unoptimized -g only instance-- as requested yesterday. Should we go back to rc24?

    -dp

Info: imap-login: Login: user=<foobar>, method=PLAIN, rip=XXX.YYY.61.79, lip=AAA.BBB.17.59 Info: IMAP(foobar): Effective uid=27522, gid=10, home=/home/foobar Info: IMAP(foobar): mbox: data=/home/foobar:INBOX=/var/mail/foobar:INDEX=/home/foobar/Mail/imapd-indices Info: IMAP(foobar): mbox: root=/home/foobar, index=/home/foobar/Mail/imapd-indices, inbox=/var/mail/foobar Error: IMAP(foobar): file mbox-sync-update.c: line 458 (mbox_sync_update_header_from): assertion failed: (ctx->mail.uid == 0 || ctx->mail.uid == mail->uid) Error: IMAP(foobar): Raw backtrace: 0x80bdb2f -> 0x808e51e -> 0x808d56b -> 0x80881f0 -> 0x808a1f2 -> 0x808a660 -> 0x80b21b0 -> 0x8075a8a -> 0x806ba5c -> 0x806bc10 -> 0x806da64 -> 0x806dc59 -> 0x806dd77 -> 0x80c31d9 -> 0x80c2c11 -> 0x8077d2c -> 0x8067b90 Error: child 274367 (imap) killed with signal 6

(gdb) bt full #0 0xfee505a7 in _lwp_kill () from /lib/libc.so.1 No symbol table info available. #1 0xfee4d71b in thr_kill () from /lib/libc.so.1 No symbol table info available. #2 0xfee06502 in raise () from /lib/libc.so.1 No symbol table info available. #3 0xfede4b8d in abort () from /lib/libc.so.1 No symbol table info available. #4 0x080bdfc8 in i_internal_panic_handler (fmt=0x0, args=0x8046fe4 "i!\r\bÊ\001") at failures.c:406 backtrace = 0x80eedd8 "0x80bdb2f -> 0x808e51e -> 0x808d56b -> 0x80881f0 -> 0x808a1f2 -> 0x808a660 -> 0x80b21b0 -> 0x8075a8a -> 0x806ba5c -> 0x806bc10 -> 0x806da64 -> 0x806dc59 -> 0x806dd77 -> 0x80c31d9 -> 0x80c2c11 -> 0x807"... #5 0x080bdb2f in i_panic (format=0x80d7838 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:195 No locals. #6 0x0808e51e in mbox_sync_update_header_from (ctx=0x80474b0, mail=0x81059c8) at mbox-sync-update.c:458 __PRETTY_FUNCTION__ = "mbox_sync_update_header_from" #7 0x0808d56b in mbox_sync_rewrite (sync_ctx=0x80477f0, mail_ctx=0x0, end_offset=116254496, move_diff=20, extra_space=The value of variable 'extra_space' is distributed across several locations, and GDB cannot access its value.

) at mbox-sync-rewrite.c:362 new_mail_ctx = {sync_ctx = 0x80477f0, mail = {uid = 1, idx_seq = 0, keywords = {buffer = 0x0, element_size = 0}, flags = 8 '\b', uid_broken = 0, from_offset = 0, body_size = 1613, offset = 116250425, space = 0}, seq = 9347, hdr_offset = 116250425, body_offset = 116251545, header_first_change = 4294967295, header_last_change = 0, header = 0x80fa698, hdr_md5_sum = "Ê\020©:Ô\021Ãî*ÉLñ\\\001\217ä", content_length = 18446744073709551615, hdr_pos = {1083, 4294967295, 4294967295, 1096, 1108}, parsed_uid = 1, last_uid_updated_value = 0, last_uid_value_start_pos = 0, have_eoh = 1, need_rewrite = 0, seen_imapbase = 0, pseudo = 0, updated = 0, recent = 0, dirty = 0, imapbase_rewrite = 0, imapbase_updated = 0} offset = The value of variable 'offset' is distributed across several locations, and GDB cannot access its value.

DBX does slightly better:

(dbx) where [1] __lwp_kill(0x1, 0x6), at 0xfee505a7 [2] raise(0x6), at 0xfee06502 [3] abort(0x8047008, 0x80eedd8, 0x8046fd8, 0x80bdb2f, 0x80d7838, 0x8046fe4), at 0xfede4b8d =>[4] i_internal_fatal_handler(status = 135100472, fmt = (nil), args = (nil)), line 413 in "failures.c" [5] i_panic(format = 0x80d7838 "file %s: line %d (%s): assertion failed: (%s)", ...), line 195 in "failures.c" [6] mbox_sync_update_header_from(ctx = (nil), mail = 0x81059c8), line 458 in "mbox-sync-update.c" [7] mbox_sync_rewrite(sync_ctx = 0x80477f0, mail_ctx = (nil), end_offset = 116254496ULL, move_diff = 20LL, extra_space = 0, first_seq = 9347U, last_seq = 0), line 362 in "mbox-sync-rewrite.c" [8] mbox_sync_do(sync_ctx = 0x80477f0, flags = MBOX_SYNC_UNDIRTY), line 854 in "mbox-sync.c" [9] mbox_sync(mbox = (nil), flags = 0), line 1765 in "mbox-sync.c" [10] mbox_storage_sync_init(box = (nil), flags = 0), line 1836 in "mbox-sync.c" [11] mailbox_sync_init(box = 0x80478e8, flags = MAILBOX_SYNC_FLAG_FULL_READ), line 406 in "mail-storage.c" [12] imap_sync_nonselected(box = 0x8101c10, flags = MAILBOX_SYNC_FLAG_FULL_READ), line 196 in "imap-sync.c" [13] _cmd_select_full(cmd = 0x80fbd4c, readonly = 0), line 39 in "cmd-select.c" [14] cmd_select(cmd = 0x80fbd4c), line 92 in "cmd-select.c" [15] client_handle_input(cmd = 0x80fbd4c), line 332 in "client.c" [16] client_handle_input(cmd = 0x80fbd4c), line 389 in "client.c" [17] _client_input(context = 0x80fbd08), line 432 in "client.c" [18] io_loop_handler_run(ioloop = 0x80f9500), line 199 in "ioloop-poll.c" [19] io_loop_run(ioloop = (nil)), line 311 in "ioloop.c" [20] main(argc = 1, argv = 0x8047b18, envp = 0x8047b20), line 287 in "main.c"

(dbx) dump fmt = (nil) args = (nil) status = 135100472 (dbx) up
Current function is i_panic 195 panic_handler(format, args); (dbx) dump format = 0x80d7838 "file %s: line %d (%s): assertion failed: (%s)" args = 0x8047018 "hu^D^Hk\xd5^H^H\xb0t^D^H\xc8Y^P^Hhu^D^H\xd7\xd6^H^HHq^D^H`^N\xfb\xfe\xf8p^D^H\xc0\xa6^O^H\x84w^D^H\x98\xaf\xff\xfe\w^D^H^P^D" (dbx) up
Current function is mbox_sync_update_header_from 458 i_assert(ctx->mail.uid == 0 || ctx->mail.uid == mail->uid); (dbx) dump ctx = (nil) mail = 0x81059c8 __PRETTY_FUNCTION__ = "mbox_sync_update_header_from" (dbx) up
Current function is mbox_sync_rewrite 362 mbox_sync_update_header_from(mail_ctx, &mails[idx]); (dbx) dump first_nonexpunged = 168U move_diff = 20LL ret = 0 mails = 0x81059c8 idx = 0 padding_per_mail = 4U first_nonexpunged_idx = 0 expunged_space = 0 orig_next_uid = 56593U sync_ctx = 0x80477f0 extra_space = 0 mail_ctx = (nil) dest_offset = 0 count = 20U last_seq = 0 orig_prev_msg_uid = 56592U next_move_diff = 16ULL end_offset = 116254496ULL __PRETTY_FUNCTION__ = "mbox_sync_rewrite" start_offset = 116250373ULL offset = 0 first_seq = 9347U next_end_offset = 116250425ULL (dbx) up
Current function is mbox_sync_do 854 if (mbox_sync_rewrite(sync_ctx, (dbx) dump ret = 134510760 flags = MBOX_SYNC_UNDIRTY sync_ctx = 0x80477f0 mail_ctx = RECORD st = (nil) __PRETTY_FUNCTION__ = "mbox_sync_do" partial = 0 i = 0 (dbx) up
Current function is mbox_sync 1765 ret = mbox_sync_do(&sync_ctx, flags); (dbx) dump leave_dirty = 200U sync_view = 0x81030d8 ret = 0 changed = 1 mbox = (nil) flags = 0 sync_ctx = RECORD delay_writes = 200U seq = 4294967295U lock_id = 3U offset = 18446744073709551615ULL index_sync_ctx = 0x81030a0 (dbx) up
Current function is mbox_storage_sync_init 1836 ret = mbox_sync(mbox, mbox_sync_flags); (dbx) dump ret = 0 mbox = 0x80478e8 flags = 0 mbox_sync_flags = 0 box = (nil) (dbx) up
Current function is mailbox_sync_init 406 return box->v.sync_init(box, flags); (dbx) dump flags = MAILBOX_SYNC_FLAG_FULL_READ box = 0x80478e8 (dbx) up
Current function is imap_sync_nonselected 196 ctx = mailbox_sync_init(box, flags); (dbx) dump ctx = (nil) flags = MAILBOX_SYNC_FLAG_FULL_READ box = 0x8101c10 sync_rec = RECORD status = RECORD (dbx) up
Current function is _cmd_select_full 39 if (imap_sync_nonselected(box, MAILBOX_SYNC_FLAG_FULL_READ) < 0) { (dbx) dump client = 0x80fbd08 storage = 0x80fba20 box = 0x8101c10 cmd = 0x80fbd4c status = RECORD readonly = 0 mailbox = 0x80fc020 "Mail/work" (dbx) up
Current function is cmd_select 92 return _cmd_select_full(cmd, FALSE);

-- Daniel Price - Solaris Kernel Engineering - dp@eng.sun.com - blogs.sun.com/dp

On Fri, 2007-03-09 at 11:23 -0800, Dan Price wrote:

#7 0x0808d56b in mbox_sync_rewrite (sync_ctx=0x80477f0, mail_ctx=0x0, end_offset=116254496, move_diff=20, extra_space=The

5th try at fixing this code: http://dovecot.org/list/dovecot-cvs/2007-March/008017.html

Wonder if I'm still missing something..

On Sat, 2007-03-10 at 13:55 +0200, Timo Sirainen wrote:

On Fri, 2007-03-09 at 22:25 +0200, Timo Sirainen wrote:

...

On Fri, 2007-03-09 at 11:23 -0800, Dan Price wrote:

...

#7 0x0808d56b in mbox_sync_rewrite (sync_ctx=0x80477f0, mail_ctx=0x0, end_offset=116254496, move_diff=20, extra_space=The

5th try at fixing this code: http://dovecot.org/list/dovecot-cvs/2007-March/008017.html

Wonder if I'm still missing something..

Once more: http://dovecot.org/list/dovecot-cvs/2007-March/008023.html

Still wrong: http://dovecot.org/list/dovecot-cvs/2007-March/008041.html

There are also several other mbox fixes in CVS. I've been running stress tests for a while now and fixing things whenever they show up. rc27 should be a pretty good mbox-release :)