dovecot - May 2009 - "Broken mailbox list" with virtual plugin

Hi,

I'm using the virtual plugin for a virtual inbox (with dovecot 1.2, r8980),
whose dovecot-virtual file looks as follows:

  INBOX
  INBOX/Lists
  INBOX/Bulk
  INBOX/MaybeSpam
  Folders/TODO
    all

Everything seems to work fine, but I get the following error in my logfiles:

  IMAP(matthijs): virtual /home/matthijs/Mail/virtual/INBOX: Broken mailbox list

Some investigation of the source code tells me that this error means that
there was corrupt data in the index. In particular, the ext_data read from the
index was not long enough to contain all mailbox names. Adding some debug code
confirms this:

ext_size: 187
ext_data: \b0\5\0\0\5\0\0\0E\0\0\0\17\20w\9c\1\0\0\0\5\0\0\0\e9\af\e4I\92\1\0
          \0\e7\2\0\0\0\0\0\0\7\0\0\0\b\0\0\0\e8\af\e4IO\3\0\0\5c\5\0\0\0\0\0
          \0\8\0\0\0\a\0\0\0\ed\af\e4I\e6\0\0\0j\1\0\0\0\0\0\0\9\0\0\0\f\0\0
          \0\3a\b0\e4I1\0\0\0e\0\0\0\0\0\0\0E\0\0\0\c\0\0\0\eb\af\e4I\c8\0\0
          \0e\0\0\0\0\0\0\0INBOXINBOX/ListsINBOX/BulkINBOX/MaybeSpamFolders/TO
ext_hdr: change_counter=1456 mailbox_count=5 highest_mailbox_id=69
search_args_crc32=2625052695
mailbox: id=1 name_len=5 uid_validity=1239724009 next_uid=402 higest_modseq=743
mailbox name: INBOX
mailbox: id=7 name_len=11 uid_validity=1239724008 next_uid=847
higest_modseq=1372
mailbox name: INBOX/Lists
mailbox: id=8 name_len=10 uid_validity=1239724013 next_uid=230 higest_modseq=362
mailbox name: INBOX/Bulk
mailbox: id=9 name_len=15 uid_validity=1239724090 next_uid=49 higest_modseq=101
mailbox name: INBOX/MaybeSpam
mailbox: id=69 name_len=12 uid_validity=1239724011 next_uid=200
higest_modseq=101
virtual /home/matthijs/Mail/virtual/INBOX: Broken mailbox list

As you can see in the ext_data dump, the last mailbox name (Folders/TODO) is
cut short. I'm not so sure what caused this error.

I've just tried removing the index files, which seems to fix the error
message. The index file gets recreated and my debug statements show proper
output. Another solution is adding an extra file to the folder
list, in which case the index will get fixed as well.

Perhaps it would be good to recreate the index file when this error is found,
instead of complaining?

Also, from the code (virtual_sync_ext_header_read in
src/virtual/virtual-sync.c) it seems that the last mailbox should be skipped
because of this error, but the mailbox works fine. I'm probably not looking
closely enough :-)

I haven't been able to reliably break the index file with some quick testing
(reconnecting, restarting and modifying the mailbox list), but I did manage to
break it once (by removing a mailbox from halfway the list, and then adding it
again). I couldn't reproduce that, though, since removing a mailbox
doesn't
always seem to recreate the index for some reason...

I've also just upgraded to the latest version, so if this is a bug fixed
between r8980 and r9018, then you'll probably not hear from me again :-)

I hope all this info helps a bit, I'm available for further debugging and
testing (also on IRC, nick is blathijs).

Gr.

Matthijs
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: Digital signature
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20090506/e0e70ca7/attachment-0002.bin>

Hi,

I just noticed another error in the log, something somewhat more serious:

Panic: file virtual-sync.c: line 524: unreached
Raw backtrace: 
  imap [0x80efa61]
  -> imap [0x80efae2]
  -> imap [0x80ef469]
  -> /usr/lib/dovecot/modules/imap/lib20_virtual_plugin.so [0xb7e5f762]
  ->
/usr/lib/dovecot/modules/imap/lib20_virtual_plugin.so(virtual_storage_sync_init+0x122d)
[0xb7e60cbd]
  -> imap(mailbox_sync+0x32) [0x80b4ad2]
  -> imap(cmd_close+0x9a) [0x8060b7a]
  -> imap [0x806717c]
  -> imap [0x8067219]
  -> imap(client_handle_input+0x1d) [0x806785d]
  -> imap(client_input+0x63) [0x8067d13]
  -> imap(io_loop_handler_run+0xe0) [0x80f8660]
  -> imap(io_loop_run+0x20) [0x80f7af0]
  -> imap(main+0x5e5) [0x8070635]
  -> /lib/libc.so.6(__libc_start_main+0xe5) [0xb7e7b455]
  -> imap [0x805fc61]
child 17088 (imap) killed with signal 6 (core dumps disabled)

I'm not quite sure what I was doing when this error occured, I don't
think I
did anything in particular. I did remove a mailbox from the virtual list (that
I put there for debugging), but that was some time before this error ocurred
IIRC.

Gr.

Matthijs
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: Digital signature
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20090506/9d10836e/attachment-0002.bin>

On Wed, 2009-05-06 at 11:06 +0200, Matthijs Kooijman
wrote:
> virtual /home/matthijs/Mail/virtual/INBOX: Broken mailbox list
..
> I've just tried removing the index files, which seems to fix the error
> message. The index file gets recreated and my debug statements show proper
> output. Another solution is adding an extra file to the folder
> list, in which case the index will get fixed as well.
> 
> Perhaps it would be good to recreate the index file when this error is
found,
> instead of complaining?
That's what it should have done. I just tested and it did successfully
update the index file without complaining about anything again. Anyway I
added some more checks to the code now.
> Also, from the code (virtual_sync_ext_header_read in
> src/virtual/virtual-sync.c) it seems that the last mailbox should be
skipped
> because of this error, but the mailbox works fine. I'm probably not
looking
> closely enough :-)
It then handles it the same way as newly seen mailboxes. Gives a new
mailbox ID and syncs it from the beginning.
> I haven't been able to reliably break the index file with some quick
testing
> (reconnecting, restarting and modifying the mailbox list), but I did manage
to
> break it once (by removing a mailbox from halfway the list, and then adding
it
> again). I couldn't reproduce that, though, since removing a mailbox
doesn't
> always seem to recreate the index for some reason...
I tried stress testing by having it open "*" mailboxes and then
randomly
creating and deleting them. Didn't seem to cause broken virtual index
file.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20090517/114e2400/attachment-0002.bin>