dovecot - Sep 2009 - Some issues in Dovecot 1.2.5 after upgrade from 1.0.15

We upgraded from Dovecot 1.0.15 to 1.2.5 last night, on Solaris 10 using
mboxes, mostly without issues.

However I had to trash the index/cache files (too many folders were
showing corruption issues which is especially bad for Prayer Webmail
".prayer" folders that store preferences; Prayer sees a disconnection
as
the folder being missing!).

I've had one imap process panic in mailbox sync (as I mentioned above,
the index files have been newly created in 1.2.5):
> Sep 30 09:57:10 imap-login: Info: Login: user=<xxxxxxxx>,
method=PLAIN, rip=134.225.xx.xx, lip=134.225.16.6
> Sep 30 09:57:10 imap-login: Info: Login: user=<xxxxxxxx>,
method=PLAIN, rip=134.225.xx.xx, lip=134.225.16.6
> Sep 30 09:57:11 IMAP 25384 xxxxxxxx 134.225.xx.xx : Panic: file
mail-index-sync-update.c: line 933 (mail_index_sync_map): assertion failed:
(map->hdr.indexid == index->indexid || map->hdr.indexid == 0)
> Sep 30 09:57:11 dovecot: Error: child 25384 (imap) killed with signal 6
(core dumped)
This looks like it was the user's first connection since the upgrade, as
well. Here's the backtrace:
> #0  0xff21fe78 in _libc_kill () from /usr/lib/libc.so.1
> (gdb) bt
> #0  0xff21fe78 in _libc_kill () from /usr/lib/libc.so.1
> #1  0xff1b5a3c in abort () from /usr/lib/libc.so.1
> #2  0xbe258 in default_fatal_finish (type=LOG_TYPE_PANIC, status=0) at
failures.c:160
> #3  0xbeb14 in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0,
fmt=0x0, args=0xffbee758) at failures.c:440
> #4  0xbe414 in i_panic (format=0xec7f0 "file %s: line %d (%s):
assertion failed: (%s)") at failures.c:207
> #5  0x98a00 in mail_index_sync_map (_map=0x1263e4,
type=MAIL_INDEX_SYNC_HANDLER_HEAD, force=false) at mail-index-sync-update.c:802
> #6  0x8c618 in mail_index_map (index=0x1263a8,
type=MAIL_INDEX_SYNC_HANDLER_HEAD) at mail-index-map.c:934
> #7  0x89e30 in mail_index_refresh (index=0x0) at mail-index.c:551
> #8  0x62bec in mbox_sync_header_refresh (mbox=0x1272d8) at mbox-sync.c:1586
> #9  0x62d28 in mbox_sync_has_changed_full (mbox=0x1272d8, leave_dirty=true,
empty_r=0xffbeeab7) at mbox-sync.c:1644
> #10 0x62cb4 in mbox_sync_has_changed (mbox=0xffffffff, leave_dirty=true) at
mbox-sync.c:1611
> #11 0x63428 in mbox_sync_int (mbox=0x1272d8, flags=0, lock_id=0xffbeee04)
at mbox-sync.c:1701
> #12 0x634f4 in mbox_sync (mbox=0x1272d8, flags=0) at mbox-sync.c:1894
> #13 0x63674 in mbox_storage_sync_init (box=0x1272d8, flags=65) at
mbox-sync.c:1936
> #14 0x7ebf4 in mailbox_sync_init (box=0x1272d8, flags=65) at
mail-storage.c:562
> #15 0x7ecb8 in mailbox_sync (box=0x1272d8, flags=65, status_items=239,
status_r=0xffbeefd0) at mail-storage.c:593
> #16 0x29fc0 in select_open (ctx=0x11ebf0, mailbox=0x1 <Address 0x1 out
of bounds>, readonly=false) at cmd-select.c:273
> #17 0x2a294 in cmd_select_full (cmd=0x11eb60, readonly=false) at
cmd-select.c:382
> #18 0x2a3d0 in cmd_select (cmd=0x11eb60) at cmd-select.c:389
> #19 0x2d064 in client_command_input (cmd=0x11eb60) at client.c:611
> #20 0x2cf08 in client_command_input (cmd=0x11eb60) at client.c:660
> #21 0x2d0ec in client_handle_next_command (client=0x11e8d8,
remove_io_r=0xffbef2b7) at client.c:701
> #22 0x2d1e0 in client_handle_input (client=0x11e8d8) at client.c:713
> #23 0x2d318 in client_input (client=0x11e8d8) at client.c:752
> #24 0xc7ea4 in io_loop_handler_run (ioloop=0x11b370) at ioloop-poll.c:203
> #25 0xc7694 in io_loop_run (ioloop=0x11b370) at ioloop.c:335
> #26 0x36e34 in main (argc=1119232, argv=0xffbef4fc, envp=0xffbef50c) at
main.c:327
I'm also seeing some other errors, e.g. :
> Sep 30 10:37:06 auth(default): Error: Master request 15820.607 not found
> Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal 11
(core not dumped) (latest ip=134.225.1.46)
> Sep 30 10:51:38 dovecot: Error: child 11162 (login) killed with signal 11
(core not dumped) (latest ip=134.225.1.46)
> Sep 30 10:54:03 imap-login: Warning: Error sending handshake to auth
server: Transport endpoint is not connected
How do I get the login (presumably imap-login) processes to dump core
(or do I need to insert gdbhelper)?

Dovecot -n output (%J is a local hash function and we don't use the lda;
my start-up script sets the fd limit to 4096 once Dovecot has started):
> # 1.2.5: /opt/RDGdovect/etc/dovecot.conf
> Warning: fd limit 2048 is lower than what Dovecot can use under full load
(more than 4352). Either grow the limit or change login_max_processes_count and
max_mail_processes settings
> # OS: SunOS 5.8 sun4u  ufs
> base_dir: /opt/RDGdovect/var/run/
> log_path: /opt/RDGdovect/var/log/dovecot.log
> info_log_path: /opt/RDGdovect/var/log/dovecot.log
> protocols: imap imaps pop3 pop3s
> listen(default): 134.225.16.6:143
> listen(imap): 134.225.16.6:143
> listen(pop3): 134.225.16.6:110
> ssl_listen(default): 134.225.16.6:993
> ssl_listen(imap): 134.225.16.6:993
> ssl_listen(pop3): 134.225.16.6:995
> ssl_cert_file(default): /opt/RDGdovect/ssl/imap.reading.ac.uk.crt.pem
> ssl_cert_file(imap): /opt/RDGdovect/ssl/imap.reading.ac.uk.crt.pem
> ssl_cert_file(pop3): /opt/RDGdovect/ssl/pop.reading.ac.uk.crt.pem
> ssl_key_file(default): /opt/RDGdovect/ssl/imap.reading.ac.uk.key.pem
> ssl_key_file(imap): /opt/RDGdovect/ssl/imap.reading.ac.uk.key.pem
> ssl_key_file(pop3): /opt/RDGdovect/ssl/pop.reading.ac.uk.key.pem
> disable_plaintext_auth: no
> shutdown_clients: no
> login_dir: /opt/RDGdovect/var/run/login
> login_executable(default): /opt/RDGdovect/libexec/dovecot/imap-login
> login_executable(imap): /opt/RDGdovect/libexec/dovecot/imap-login
> login_executable(pop3): /opt/RDGdovect/libexec/dovecot/pop3-login
> login_greeting(default): University of Reading IMAP ready.
> login_greeting(imap): University of Reading IMAP ready.
> login_greeting(pop3): University of Reading POP3 ready.
> login_process_per_connection: no
> max_mail_processes: 4096
> verbose_proctitle: yes
> mail_location:
mbox:/export/folders/%13.h/mail/:INBOX=/export/mail/%13.h/INBOX:INDEX=/export/indexes/%13.h
> mail_nfs_storage: yes
> mbox_very_dirty_syncs: yes
> mail_drop_priv_before_exec: yes
> mail_executable(default): /opt/RDGdovect/libexec/dovecot/imap
> mail_executable(imap): /opt/RDGdovect/libexec/dovecot/imap
> mail_executable(pop3): /opt/RDGdovect/libexec/dovecot/pop3
> mail_plugins(default): zlib mail_log
> mail_plugins(imap): zlib mail_log
> mail_plugins(pop3):
> mail_plugin_dir(default): /opt/RDGdovect/libexec/plugins
> mail_plugin_dir(imap): /opt/RDGdovect/libexec/plugins
> mail_plugin_dir(pop3): /opt/RDGdovect/lib/dovecot/pop3
> mail_log_prefix: %Us %p %u %r :
> imap_client_workarounds(default): delay-newmail
> imap_client_workarounds(imap): delay-newmail
> imap_client_workarounds(pop3):
> pop3_reuse_xuidl(default): no
> pop3_reuse_xuidl(imap): no
> pop3_reuse_xuidl(pop3): yes
> pop3_uidl_format(default): %08Xu%08Xv
> pop3_uidl_format(imap): %08Xu%08Xv
> pop3_uidl_format(pop3): %08Xv%08Xu
> pop3_client_workarounds(default):
> pop3_client_workarounds(imap):
> pop3_client_workarounds(pop3): outlook-no-nuls
> namespace:
>   type: private
>   separator: /
>   inbox: yes
>   list: yes
>   subscriptions: yes
> namespace:
>   type: private
>   separator: /
>   prefix: mail/
>   hidden: yes
>   list: no
>   subscriptions: yes
> namespace:
>   type: private
>   separator: /
>   prefix: ~/mail/
>   hidden: yes
>   list: no
>   subscriptions: yes
> namespace:
>   type: private
>   separator: /
>   prefix: ~%u/mail/
>   hidden: yes
>   list: no
>   subscriptions: yes
> lda:
>   postmaster_address: postmaster at example.com
> auth default:
>   mechanisms: plain login
>   username_format: %Lu
>   verbose: yes
>   passdb:
>     driver: passwd-file
>     args: /export/mailconfig/%Ju/%u/migrating
>     deny: yes
>   passdb:
>     driver: passwd-file
>     args: /export/mailconfig/%Ju/%u/proxy.%Ls
>   passdb:
>     driver: ldap
>     args: /opt/RDGdovect/etc/dovecot-ldap.conf
>   userdb:
>     driver: passwd-file
>     args: /opt/RDGdovect/etc/userdb
Best Wishes,
Chris

-- 
--+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+-
Christopher Wakelin,                           c.d.wakelin at reading.ac.uk
IT Services Centre, The University of Reading,  Tel: +44 (0)118 378 8439
Whiteknights, Reading, RG6 2AF, UK              Fax: +44 (0)118 975 3094

On Wed, 2009-09-30 at 11:06 +0100, Chris Wakelin wrote:
> > Sep 30 09:57:11 IMAP 25384 xxxxxxxx 134.225.xx.xx : Panic: file
mail-index-sync-update.c: line 933 (mail_index_sync_map): assertion failed:
(map->hdr.indexid == index->indexid || map->hdr.indexid == 0)
..
> > #5  0x98a00 in mail_index_sync_map (_map=0x1263e4,
type=MAIL_INDEX_SYNC_HANDLER_HEAD, force=false) at mail-index-sync-update.c:802
Could you also do:

fr 5
p *index
p *map
> > Sep 30 10:37:06 auth(default): Error: Master request 15820.607 not
found
Either timed out for some reason or some other strange bug..
> > Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal
11 (core not dumped) (latest ip=134.225.1.46)
..
> How do I get the login (presumably imap-login) processes to dump core
With Linux this would be enough:

login_executable = .../imap-login -D

With Solaris you'll also have to somehow make setuid binaries dump core.
http://publib.boulder.ibm.com/httpserv/ihsdiag/coredumps.html says you
could do:

coreadm -e global-setid -e proc-setid -e global

Perhaps with those global core dumps it wouldn't even be necessary to
add the -D parameter. Anyway the -D's point was to make
the /var/run/dovecot/login/ directory writable to it, so it could write
core dump there.
> (or do I need to insert gdbhelper)?
I'm not really sure anymore if that even works (anymore). :)
-------------- 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/20090930/953f0147/attachment-0002.bin>

On Wed, 2009-09-30 at 11:06 +0100, Chris Wakelin wrote:
> > Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal
11 (core not dumped) (latest ip=134.225.1.46)
..
> >   passdb:
> >     driver: passwd-file
> >     args: /export/mailconfig/%Ju/%u/proxy.%Ls
You're using proxying also? Apparently there's something wrong there,
perhaps with master user logins or something.. I haven't yet found out
what exactly it is, but these should fix the crashes and log more
information:

http://hg.dovecot.org/dovecot-1.2/rev/b1293abca645
http://hg.dovecot.org/dovecot-1.2/rev/c8e24c1b8468

-------------- 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/20090930/cfc6ff3a/attachment-0002.bin>

Timo Sirainen wrote:
> On Wed, 2009-09-30 at 11:06 +0100, Chris Wakelin wrote:
>>> Sep 30 09:57:11 IMAP 25384 xxxxxxxx 134.225.xx.xx : Panic: file
mail-index-sync-update.c: line 933 (mail_index_sync_map): assertion failed:
(map->hdr.indexid == index->indexid || map->hdr.indexid == 0)
> ..
>>> #5  0x98a00 in mail_index_sync_map (_map=0x1263e4,
type=MAIL_INDEX_SYNC_HANDLER_HEAD, force=false) at mail-index-sync-update.c:802
> 
> Could you also do:
> 
> fr 5
> p *index
> p *map
OK:
> (gdb) fr 5
> #5  0x98a00 in mail_index_sync_map (_map=0x1263e4,
type=MAIL_INDEX_SYNC_HANDLER_HEAD, force=false) at mail-index-sync-update.c:802
> 802                     return 0;
> (gdb) p *index
> $1 = {dir = 0x1264f8
"/export/indexes/a/120/xxxxxxxx/.imap/INBOX", prefix = 0x11add0
"dovecot.index", cache = 0x127930, log = 0x1271f0, fsync_mask = 0,
>   mode = 384, gid = -1, gid_origin = 0x1278b8
"/export/mail/a/120/xxxxxxxx/INBOX", extension_pool = 0x126540,
extensions = {arr = {buffer = 0x126558,
>       element_size = 36}, v = 0x126558, v_modifiable = 0x126558},
sync_lost_handlers = {arr = {buffer = 0x11b578, element_size = 4}, v = 0x11b578,
>     v_modifiable = 0x11b578}, filepath = 0x1278e8
"/export/indexes/a/120/xxxxxxxx/.imap/INBOX/dovecot.index", fd = -1,
map = 0x127ac0,
>   indexid = 1254301030, inconsistency_id = 0, last_read_log_file_seq = 0,
last_read_log_file_head_offset = 0, last_read_log_file_tail_offset = 0,
>   last_read_stat = {st_dev = 0, st_pad1 = {0, 0, 0}, st_ino = 0, st_mode =
0, st_nlink = 0, st_uid = 0, st_gid = 0, st_rdev = 0, st_pad2 = {0, 0},
>     st_size = 0, st_atim = {tv_sec = 0, tv_nsec = 0}, st_mtim = {tv_sec =
0, tv_nsec = 0}, st_ctim = {tv_sec = 0, tv_nsec = 0}, st_blksize = 0,
>     st_blocks = 0, st_fstype = '\000' <repeats 15 times>,
st_pad4 = {0, 0, 0, 0, 0, 0, 0, 0}}, fsck_log_head_file_seq = 0,
fsck_log_head_file_offset = 0,
>   lock_type = 3, shared_lock_count = 0, excl_lock_count = 0,
lock_id_counter = 2, lock_method = FILE_LOCK_METHOD_FCNTL, file_lock = 0x0,
dotlock = 0x0,
>   keywords_pool = 0x126948, keywords = {arr = {buffer = 0x11b5c8,
element_size = 4}, v = 0x11b5c8, v_modifiable = 0x11b5c8}, keywords_hash =
0x126b88,
>   keywords_ext_id = 0, modseq_ext_id = 1, module_contexts = {arr = {buffer
= 0x11b5a0, element_size = 4}, v = 0x11b5a0, v_modifiable = 0x11b5a0},
>   error = 0x0, nodiskspace = 0, index_lock_timeout = 0, opened = 1,
log_locked = 0, mmap_disable = 0, fsync_disable = 0, use_excl_dotlocks = 1,
>   nfs_flush = 0, readonly = 0, mapping = 1, syncing = 0, need_recreate = 0,
index_min_write = 1, modseqs_enabled = 0, initial_create = 0,
>   initial_mapped = 1}
> (gdb) p *map
> $2 = {index = 0x1263a8, refcount = 2, hdr = {major_version = 7
'\a', minor_version = 2 '\002', base_header_size = 120,
header_size = 120, record_size = 8,
>     compat_flags = 0 '\000', unused = "\000\000", indexid
= 1254301031, flags = 0, uid_validity = 0, next_uid = 1, messages_count = 0,
>     unused_old_recent_messages_count = 0, seen_messages_count = 0,
deleted_messages_count = 0, first_recent_uid = 1, first_unseen_uid_lowwater = 0,
>     first_deleted_uid_lowwater = 0, log_file_seq = 2, log_file_tail_offset
= 0, log_file_head_offset = 40, sync_size = 0, sync_stamp = 0, day_stamp = 0,
>     day_first_uid = {0, 0, 0, 0, 0, 0, 0, 0}}, hdr_base = 0x127fc0,
hdr_copy_buf = 0x11b640, extension_pool = 0x0, extensions = {arr = {buffer =
0x0,
>       element_size = 0}, v = 0x0, v_modifiable = 0x0}, ext_id_map = {arr =
{buffer = 0x0, element_size = 0}, v = 0x0, v_modifiable = 0x0},
>   keyword_idx_map = {arr = {buffer = 0x0, element_size = 0}, v = 0x0,
v_modifiable = 0x0}, rec_map = 0x127b78, write_base_header = 0, write_ext_header
= 0,
>   write_atomic = 0}
I was wrong about it being Solaris 10; the mail server is still on
Solaris 8 (with the latest and last patch cluster installed) and Dovecot
was compiled with gcc 3.3.2.

I've got a backup of the user's INBOX available, but I haven't been
able
to reproduce the crash on my test box (either with it put through
mboxcrypt.pl or without). I've seen no similar crashes (so far) either.
Let me know if you'd like me to send the anonymised version (4MB expands
to ~70MB).
> 
>>> Sep 30 10:37:06 auth(default): Error: Master request 15820.607 not
found
> 
> Either timed out for some reason or some other strange bug..
> 
>>> Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with
signal 11 (core not dumped) (latest ip=134.225.1.46)
> ..
>> How do I get the login (presumably imap-login) processes to dump core
> 
> With Linux this would be enough:
> 
> login_executable = .../imap-login -D
> 
> With Solaris you'll also have to somehow make setuid binaries dump
core.
> http://publib.boulder.ibm.com/httpserv/ihsdiag/coredumps.html says you
> could do:
> 
> coreadm -e global-setid -e proc-setid -e global
> 
> Perhaps with those global core dumps it wouldn't even be necessary to
> add the -D parameter. Anyway the -D's point was to make
> the /var/run/dovecot/login/ directory writable to it, so it could write
> core dump there.
> 
>> (or do I need to insert gdbhelper)?
> 
> I'm not really sure anymore if that even works (anymore). :)
...
>>>> Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with
signal 11 (core not dumped) (latest ip=134.225.1.46)
>> ..
>>>>   passdb:
>>>>     driver: passwd-file
>>>>     args: /export/mailconfig/%Ju/%u/proxy.%Ls
>> 
>> You're using proxying also? Apparently there's something wrong
there,
>> perhaps with master user logins or something.. I haven't yet found
out
>> what exactly it is, but these should fix the crashes and log more
>> information:
>> 
>> http://hg.dovecot.org/dovecot-1.2/rev/b1293abca645
>> http://hg.dovecot.org/dovecot-1.2/rev/c8e24c1b8468
>> 
Yes we're proxying to Exchange 2003 for those users that have a
proxy.imap or proxy.pop3 in their mailconfig directory (we migrated most
of our staff from Unix mailstore to Exchange without them noticing; all
the students, most functional accounts, and staff that have too much
mail are still on Unix).

I'll look at applying the patches this evening (there's probably no
point doing it on the test server as I guess it's triggered by load or
something odd in Exchange).

Strangely, though we haven't had any crashes since this morning:
> Sep 30 00:38:32 dovecot: Error: child 26387 (login) killed with signal 11
(core not dumped) (latest ip=134.225.1.46)
> Sep 30 00:55:02 dovecot: Error: child 9268 (login) killed with signal 11
(core not dumped) (ip=134.225.1.46)
> Sep 30 09:43:07 dovecot: Error: child 13660 (login) killed with signal 11
(core not dumped) (latest ip=134.225.1.46)
> Sep 30 10:51:27 dovecot: Error: child 29959 (login) killed with signal 11
(core not dumped) (latest ip=134.225.1.46)
> Sep 30 10:51:38 dovecot: Error: child 11162 (login) killed with signal 11
(core not dumped) (latest ip=134.225.1.46)
> Sep 30 11:18:05 dovecot: Error: child 23772 (login) killed with signal 11
(core not dumped) (latest ip=134.225.1.46)
> Sep 30 11:20:16 dovecot: Error: child 2120 (login) killed with signal 11
(core not dumped) (latest ip=134.225.1.46)
and all of them had latest ip=134.225.1.46, which is our Prayer Webmail
server and is used mostly by students (i.e. not people on Exchange).

Best Wishes,
Chris

-- 
--+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+-
Christopher Wakelin,                           c.d.wakelin at reading.ac.uk
IT Services Centre, The University of Reading,  Tel: +44 (0)118 378 8439
Whiteknights, Reading, RG6 2AF, UK              Fax: +44 (0)118 975 3094