dovecot - Apr 2007 - 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 at 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.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20070513/13180128/attachment.bin>

On May 13 2007, Timo Sirainen wrote:
>On Mon, 2007-04-23 at 13:40 -0500, bhayden at 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