[Dovecot] mbox bug in 1.0.0
Hi folks. We're moving users from rc24 and 27 to 1.0.0. On four mailboxes so far we've seen these errors after the move (quick and dirty anonymizing follows): Apr 23 13:22:41 server.umn.edu dovecot: [ID 107833 local6.info] imap-login: Login: user=<USER>, pid=<9046>, method=PLAIN, rip=***.***.***.***, lip=***.***.***.***, TLS Apr 23 13:22:41 server.umn.edu dovecot: [ID 107833 local6.error] [9073] IMAP(USER): mbox /var/mail/user: seq=1 uid=8808 uid_broken=0 originally needed 10 bytes, now needs 23 bytes Apr 23 13:22:41 server.umn.edu dovecot: [ID 107833 local6.error] [9073] IMAP(USER): Raw backtrace: 0x7b800 -> 0x43434 -> 0x3e018 -> 0x3fc34 -> 0x40080 -> 0x6d3cc -> 0x29a88 -> 0x21324 -> 0x214c0 -> 0x22f48 -> 0x22ec0 -> 0x230c0 -> 0x81c18 -> 0x814e4 -> 0x2b5cc -> 0x1dc58 Points of interest: 1. I can't reproduce this. It still happens after the user's .imap directories are removed. If I make a copy of the mailbox on another machine running the same version of Dovecot with the same config, the problem doesn't occur. Weird. 2. So far, have only seen it on quite large mailboxes (close to or over 100MB). Most large boxes have not had the problem, but the ones that have are all large. Any thoughts? Dovecot -n output below. -Brian Hayden OIT Internet Services U of Minnesota # dovecot -n # /etc/opt/dovecot/dovecot.conf syslog_facility: local6 protocols: imap imaps pop3 pop3s listen(default): *:143 listen(imap): *:143 listen(pop3): *:110 ssl_listen(default): *:993 ssl_listen(imap): *:993 ssl_listen(pop3): *:995 ssl_cert_file: /etc/opt/openssl/certs/dovecot.pem ssl_key_file: /etc/opt/openssl/private/dovecot.pem shutdown_clients: no login_dir: /var/opt/dovecot/run/dovecot/login login_executable(default): /opt/dovecot/libexec/dovecot/imap-login login_executable(imap): /opt/dovecot/libexec/dovecot/imap-login login_executable(pop3): /opt/dovecot/libexec/dovecot/pop3-login login_log_format_elements: user=<%u> pid=<%p> method=%m rip=%r lip=%l %c login_processes_count: 32 login_max_processes_count: 4096 max_mail_processes: 8192 first_valid_uid: 100 default_mail_env: mbox:~/:INBOX=/var/mail/%u mail_location: mbox:~/:INBOX=/var/mail/%u mail_full_filesystem_access: yes mbox_lazy_writes: no mail_executable(default): /opt/dovecot/libexec/dovecot/imap mail_executable(imap): /opt/dovecot/libexec/dovecot/imap mail_executable(pop3): /opt/dovecot/libexec/dovecot/pop3 mail_plugin_dir(default): /opt/dovecot/lib/dovecot/imap mail_plugin_dir(imap): /opt/dovecot/lib/dovecot/imap mail_plugin_dir(pop3): /opt/dovecot/lib/dovecot/pop3 mail_log_prefix: [%p] %Us(%u): imap_client_workarounds(default): delay-newmail outlook-idle tb-extra-mailbox-sep imap_client_workarounds(imap): delay-newmail outlook-idle tb-extra-mailbox-sep imap_client_workarounds(pop3): outlook-idle pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %08Xu%08Xv namespace: type: private separator: / location: mbox:~/:INBOX=/var/mail/%u inbox: yes hidden: yes auth default: username_format: %Lu verbose: yes debug: yes passdb: driver: pam args: session=yes * userdb: driver: passwd
On Mon, 2007-04-23 at 13:40 -0500, bhayden@umn.edu wrote:
Apr 23 13:22:41 server.umn.edu dovecot: [ID 107833 local6.error] [9073] IMAP(USER): mbox /var/mail/user: seq=1 uid=8808 uid_broken=0 originally needed 10 bytes, now needs 23 bytes
Anything else than Dovecot accessing these mboxes (besides MDA)?
10 bytes could be used for "Status: O\n" and 13 bytes could be used for "X-UID: 8808\n". But why wouldn't it figure out initially that it needed to write the X-UID header also? Hmm.
Do you have a core file from that crash? It would show a bit more information. If not, see http://dovecot.org/bugreport.html
If these happen frequently, I could also send a debug patch that writes the broken mbox headers to some temp file. That with the core file would provide enough information to figure out what exactly is the problem.
On May 13 2007, Timo Sirainen wrote:
On Mon, 2007-04-23 at 13:40 -0500, bhayden@umn.edu wrote:
Apr 23 13:22:41 server.umn.edu dovecot: [ID 107833 local6.error] [9073] IMAP(USER): mbox /var/mail/user: seq=1 uid=8808 uid_broken=0 originally needed 10 bytes, now needs 23 bytes
Anything else than Dovecot accessing these mboxes (besides MDA)?
Nope. Dovecot IMAP and deliver.
Do you have a core file from that crash? It would show a bit more information. If not, see http://dovecot.org/bugreport.html
I finally got around to generating one. It's 3MB, and was generated from 1.0.0. Would you like a copy, or do you want me to check on some state myself and send you results?
If these happen frequently, I could also send a debug patch that writes the broken mbox headers to some temp file. That with the core file would provide enough information to figure out what exactly is the problem.
I can do that, too, if necessary. Thanks much for your help,
-Brian Hayden Internet Services University of MN
On Tue, 2007-06-19 at 09:04 -0500, bhayden@umn.edu wrote:
Do you have a core file from that crash? It would show a bit more information. If not, see http://dovecot.org/bugreport.html
I finally got around to generating one. It's 3MB, and was generated from 1.0.0. Would you like a copy, or do you want me to check on some state myself and send you results?
What OS do you use? I also need the imap binary which produced the core file, but I'm not sure if gdb can debug other OSes binaries. So I can debug at least Solaris/Sparc and Linux/x86/x86-64 but probably not anything else.
Otherwise we could begin with:
bt full p mails[idx] p *mail_ctx p *sync_ctx
It would have been nice also to have mbox-sync-rewrite.c compiled without -O2, otherwise gdb optimizes some information away.
On Jun 19 2007, bhayden@umn.edu wrote:
On May 13 2007, Timo Sirainen wrote:
On Mon, 2007-04-23 at 13:40 -0500, bhayden@umn.edu wrote:
Apr 23 13:22:41 server.umn.edu dovecot: [ID 107833 local6.error] [9073] IMAP(USER): mbox /var/mail/user: seq=1 uid=8808 uid_broken=0 originally needed 10 bytes, now needs 23 bytes
Anything else than Dovecot accessing these mboxes (besides MDA)?
Nope. Dovecot IMAP and deliver.
Do you have a core file from that crash? It would show a bit more information. If not, see http://dovecot.org/bugreport.html
So, I'm including a backtrace for this. Sorry if you replied earlier and I missed it! Please let me know what else you might need. We're seeing this on about three dozen inboxes (which is a very small percentage, but a large enough number to hear about it :) ).
(dbx) where [1] 0xff1c16e8(0x6, 0x0, 0xff1a4d28, 0xffffffff, 0xff1e8298, 0x6), at 0xff1c16e8 [2] _getutxline(0x9d8b0, 0x1, 0xb00e0, 0xa8244, 0xff1eb298, 0x0), at 0xff140158 =>[3] i_internal_panic_handler(fmt = 0x93b88 "mbox %s: seq=%u uid=%u uid_broken=%d originally needed %llu bytes, now needs %u bytes", args = 0xffbfe7d0), line 403 in "failures.c" [4] i_panic(format = 0x93b88 "mbox %s: seq=%u uid=%u uid_broken=%d originally needed %llu bytes, now needs %u bytes", ...), line 183 in "failures.c" [5] mbox_sync_rewrite(sync_ctx = 0xffbfefd0, mail_ctx = (nil), end_offset = 4448ULL, move_diff = 30LL, extra_space = 4294971774ULL, first_seq = 1U, last_seq = 163U), line 422 in "mbox-sync-rewrite.c" [6] mbox_sync_do(sync_ctx = 0xffbfefd0, flags = -4198952), line 920 in "mbox-sync.c" [7] mbox_sync(mbox = 0xc99e0, flags = MBOX_SYNC_UNDIRTY), line 1873 in "mbox-sync.c" [8] mbox_storage_sync_init(box = 0xc99e0, flags = MAILBOX_SYNC_FLAG_FULL_READ), line 1957 in "mbox-sync.c" [9] mailbox_sync_init(box = 0xc99e0, flags = MAILBOX_SYNC_FLAG_FULL_READ), line 406 in "mail-storage.c" [10] imap_sync_nonselected(box = 0xc99e0, flags = MAILBOX_SYNC_FLAG_FULL_READ), line 196 in "imap-sync.c" [11] _cmd_select_full(cmd = 0xc39e4, readonly = 0), line 39 in "cmd-select.c" [12] cmd_select(cmd = 0xc39e4), line 92 in "cmd-select.c" [13] client_handle_input(cmd = 0xc39e4), line 335 in "client.c" [14] client_handle_input(cmd = 0xc39e4), line 389 in "client.c" [15] _client_input(context = 0xc39a0), line 432 in "client.c" [16] io_loop_handler_run(ioloop = 0xb9f08), line 199 in "ioloop-poll.c" [17] io_loop_run(ioloop = 0xb9f08), line 326 in "ioloop.c" [18] main(argc = -4195453, argv = 0xb0800, envp = 0xb1be4), line 290 in "main.c"
And in case it helps, a dump from frame [5] which is the last bit before the crash:
(dbx) frame 5 Current function is mbox_sync_rewrite 422 i_panic("mbox %s: seq=%u uid=%u uid_broken=%d " (dbx) dump first_nonexpunged = 255U move_diff = 30LL ret = 0 mails = 0xcd810 idx = 0 padding_per_mail = 20U first_nonexpunged_idx = 0 expunged_space = 0 sync_ctx = 0xffbfefd0 extra_space = 4294971774ULL mail_ctx = (nil) dest_offset = 0 count = 2U last_seq = 163U orig_prev_msg_uid = 1359U next_move_diff = 10ULL end_offset = 4448ULL __PRETTY_FUNCTION__ = "mbox_sync_rewrite" start_offset = 0 offset = 4294971774ULL first_seq = 1U next_end_offset = 52ULL
If these happen frequently, I could also send a debug patch that writes the broken mbox headers to some temp file. That with the core file would provide enough information to figure out what exactly is the problem.
This is still an option, if it would help.
-Brian Hayden Internet Services University of MN
participants (2)
-
bhayden＠umn.edu
-
Timo Sirainen