Crash in service imap with version 2.2.13

Urban Loesch bind at enas.net
Tue Jul 1 15:03:11 UTC 2014


Hi,

I did some more debugging and now I can reproduce the crash with one of the affected mailboxes:

I made a test with telnet:

...
telnet localhost 143
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
* OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready.
L LOGIN "user at domain.net" "secretpassword"
L OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT
MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN
CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE COMPRESS=DEFLATE QUOTA] Logged in
00000003 STATUS INBOX (MESSAGES RECENT UNSEEN UIDNEXT UIDVALIDITY)
* STATUS INBOX (MESSAGES 3 RECENT 0 UIDNEXT 10255 UIDVALIDITY 1309600294 UNSEEN 0)
00000003 OK Status completed.
00000004 NOOP
00000004 OK NOOP completed.
00000005 EXAMINE INBOX
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS ()] Read-only mailbox.
* 3 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1309600294] UIDs valid
* OK [UIDNEXT 10255] Predicted next UID
00000005 OK [READ-ONLY] Examine completed (0.001 secs).
00000006 UID THREAD REFERENCES US-ASCII ALL
Connection closed by foreign host.

...

As you can see dovecots segfaults one the imap command "00000006 UID THREAD REFERENCES US-ASCII ALL".

during this session I made an strace, too:

...
16:01:30.589383 epoll_wait(11, {{EPOLLIN, {u32=15105616, u64=15105616}}}, 5, 1793648) = 1
16:01:42.604817 read(7, "00000003 STATUS INBOX (MESSAGES "..., 8192) = 68
16:01:42.604997 open("/proc/meminfo", O_RDONLY) = 4
16:01:42.605180 fstat(4, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
16:01:42.605453 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f07e45df000
16:01:42.605732 read(4, "MemTotal:        8388608 kB\nMemF"..., 1024) = 1024
16:01:42.605840 close(4)                = 0
16:01:42.605866 munmap(0x7f07e45df000, 4096) = 0
16:01:42.605965 stat("/home/vmail/domain.net/user/mailboxes/INBOX/dbox-Mails", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
16:01:42.606013 stat("/home/dovecotindex/domain.net/user/mailboxes/INBOX", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
16:01:42.606050 stat("/home/dovecotindex/domain.net/user/mailboxes/INBOX", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
16:01:42.606093 stat("/home/vmail/domain.net/user/mailboxes/INBOX", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
16:01:42.606134 open("/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index.log", O_RDWR|O_APPEND) = 4
16:01:42.606164 fstat(4, {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:42.606195 brk(0xea7000)           = 0xea7000
16:01:42.606222 pread(4, "\1\2(\0$\352\16N{\0\0\0z\0\0\0\304\200\0\0\t\362\261S\0\0\0\0\0\0\0\0"..., 3984, 0) = 3984
16:01:42.606263 open("/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index", O_RDWR) = 12
16:01:42.606290 fstat(12, {st_mode=S_IFREG|0600, st_size=516, ...}) = 0
16:01:42.606321 pread(12, "\7\2x\0(\1\0\0,\0\0\0\1\0\0\0$\352\16N\0\0\0\0&\352\16N\5(\0\0"..., 8192, 0) = 516
16:01:42.606369 fstat(4, {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:42.606476 stat("/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:42.606510 fstat(4, {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:42.606544 stat("/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:42.606576 fstat(4, {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:42.606648 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0
16:01:42.606674 write(7, "* STATUS INBOX (MESSAGES 3 RECEN"..., 115) = 115
16:01:42.606699 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0
16:01:42.606798 epoll_wait(11, {}, 5, 5000) = 0
16:01:47.609442 epoll_wait(11, {{EPOLLIN, {u32=15105616, u64=15105616}}}, 5, 5000) = 1
16:01:48.193526 read(7, "00000004 NOOP\r\n", 8124) = 15
16:01:48.193707 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0
16:01:48.193745 write(7, "00000004 OK NOOP completed.\r\n", 29) = 29
16:01:48.193940 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0
16:01:48.194084 epoll_wait(11, {}, 5, 4415) = 0
16:01:52.609478 close(12)               = 0
16:01:52.609543 close(4)                = 0
16:01:52.609618 epoll_wait(11, {{EPOLLIN, {u32=15105616, u64=15105616}}}, 5, 1795584) = 1
16:01:52.685853 read(7, "00000005 EXAMINE INBOX\r\n", 8109) = 24
16:01:52.686081 brk(0xea5000)           = 0xea5000
16:01:52.686282 stat("/home/vmail/domain.net/user/mailboxes/INBOX/dbox-Mails", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
16:01:52.686557 stat("/home/dovecotindex/domain.net/user/mailboxes/INBOX", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
16:01:52.686611 stat("/home/dovecotindex/domain.net/user/mailboxes/INBOX", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
16:01:52.686654 stat("/home/vmail/domain.net/user/mailboxes/INBOX", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
16:01:52.686691 open("/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index.log", O_RDWR|O_APPEND) = 4
16:01:52.686720 fstat(4, {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:52.686750 pread(4, "\1\2(\0$\352\16N{\0\0\0z\0\0\0\304\200\0\0\t\362\261S\0\0\0\0\0\0\0\0"..., 3984, 0) = 3984
16:01:52.686786 open("/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index", O_RDWR) = 12
16:01:52.686821 fstat(12, {st_mode=S_IFREG|0600, st_size=516, ...}) = 0
16:01:52.686850 pread(12, "\7\2x\0(\1\0\0,\0\0\0\1\0\0\0$\352\16N\0\0\0\0&\352\16N\5(\0\0"..., 8192, 0) = 516
16:01:52.686887 fstat(4, {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:52.686968 stat("/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index.log", {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:52.687002 fstat(4, {st_mode=S_IFREG|0600, st_size=3984, ...}) = 0
16:01:52.687056 setsockopt(7, SOL_TCP, TCP_CORK, [1], 4) = 0
16:01:52.687079 write(7, "* FLAGS (\\Answered \\Flagged \\Del"..., 261) = 261
16:01:52.687105 setsockopt(7, SOL_TCP, TCP_CORK, [0], 4) = 0
16:01:52.687207 epoll_wait(11, {{EPOLLIN, {u32=15105616, u64=15105616}}}, 5, 1800000) = 1
16:02:04.438436 read(7, "00000006 UID THREAD REFERENCES U"..., 8085) = 45
16:02:04.438728 open("/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index.thread", O_RDWR) = 13
16:02:04.438808 fstat(13, {st_mode=S_IFREG|0600, st_size=136, ...}) = 0
16:02:04.438921 pread(13, "\1\0\0\0&\352\16N\200\200\200\276\242M\0\1 \343z\1\0\0\0a\0\235\204\246\373\2\0\0"..., 8192, 0) = 136
...

Deleting the "/home/dovecotindex/domain.net/user/mailboxes/INBOX/dovecot.index.thread" file resolves the problem, but I'm not shure if
this is the correct solution. I mean, if I have to delete all "dovecot.index.thread" files on my servers after upgrading to Dovecot 2.2.13
and I can't say if the problem comes back.

Are there some changes between version 2.1.15 and 2.2.13 which affects the dovecot indexes?
I can't find nothing in the wiki to this.

As I just said, the probkem only happens with Horde Webmail.

Thanks
Urban


Am 24.06.2014 10:40, schrieb Urban Loesch:
> 
> Hi,
> 
> yesterday  I upgraded to version 2.2.13 under Debian Squeeze.
> 
> Since today morning sometimes my logfile shows the folling error:
> 
> ..
> Jun 24 10:14:16 mailstore dovecot: imap(user at domain.net pid:23434 session:<jf6yi5D8TADD/vzh>): Fatal: master: service(imap): child 23434 killed with
> signal 11 (core dumped)
> ...
> 
> The kernel error log shows:
> ...
> Jun 24 10:14:16 mailstore kernel: [13959701.899726] imap[23434]: segfault at 1012acec0 ip 00007f7dd89b5e52 sp 00007ffffd33d9b0 error 4 in
> libdovecot-storage.so.0.0.0[7f7dd88ed000+10d000]
> ...
> 
> This seems only to happen in conjunction with Horde Webmail. Other IMAP clients aren't affected.
> 
> I made a backtrace:
> 
> -----> start backtrace <-----
> Core was generated by `dovecot/imap'.
> Program terminated with signal 11, Segmentation fault.
> #0  mail_index_strmap_uid_exists (ctx=0x7ffffd33d9f0, uid=8442) at mail-index-strmap.c:395
> 395	mail-index-strmap.c: No such file or directory.
> 	in mail-index-strmap.c
> (gdb) bt full
> #0  mail_index_strmap_uid_exists (ctx=0x7ffffd33d9f0, uid=8442) at mail-index-strmap.c:395
>         rec = 0x1012acec0
> #1  0x00007f7dd89b79ab in mail_index_strmap_view_renumber (_sync=<value optimized out>) at mail-index-strmap.c:842
>         ctx = {view = 0x12b2d80, input = 0x0, end_offset = 0, highest_str_idx = 0, uid_lookup_seq = 0, lost_expunged_uid = 0, data = 0x0, end = 0x0,
> str_idx_base = 0x0, rec = {uid = 0, ref_index = 0, str_idx = 0}, next_ref_index = 0,
>           rec_size = 0, too_large_uids = 0}
>         str_idx = 0
>         count = 1
>         ret = <value optimized out>
>         prev_uid = 8442
>         i = 0
>         dest = 0
>         count2 = <value optimized out>
> #2  mail_index_strmap_write (_sync=<value optimized out>) at mail-index-strmap.c:1189
>         ret = <value optimized out>
> #3  mail_index_strmap_view_sync_commit (_sync=<value optimized out>) at mail-index-strmap.c:1236
>         sync = <value optimized out>
>         view = <value optimized out>
> #4  0x00007f7dd899fc23 in mail_thread_index_map_build (box=<value optimized out>, args=<value optimized out>, ctx_r=<value optimized out>) at
> index-thread.c:332
>         last_uid = 8442
>         search_ctx = <value optimized out>
>         mail = <value optimized out>
>         seq1 = 0
>         tbox = 0x12af2e0
>         headers_ctx = 0x12b7e50
>         search_args = <value optimized out>
>         seq2 = <value optimized out>
>         wanted_headers = {0x7f7dd89d8542 "message-id", 0x7f7dd89d9f96 "in-reply-to", 0x7f7dd89d9fa2 "references", 0x0}
> #5  mail_thread_init (box=<value optimized out>, args=<value optimized out>, ctx_r=<value optimized out>) at index-thread.c:569
>         tbox = 0x12af2e0
>         ctx = 0x12afc10
>         search_ctx = 0x12b2b20
>         ret = <value optimized out>
>         __FUNCTION__ = "mail_thread_init"
> #6  0x0000000000414ef3 in imap_thread (cmd=0x12a7eb0) at cmd-thread.c:90
>         ctx = <value optimized out>
>         str = 0x12afbd0
> #7  cmd_thread (cmd=0x12a7eb0) at cmd-thread.c:281
>         client = 0x12a72b0
>         thread_type = MAIL_THREAD_REFERENCES
>         sargs = 0x12b04a0
>         args = 0x128faf8
>         charset = 0x128fc18 "US-ASCII"
>         str = 0x128fc08 "REFERENCES"
>         ret = <value optimized out>
> #8  0x00000000004181fd in command_exec (cmd=0x12a7eb0) at imap-commands.c:158
>         hook = 0x128d110
>         ret = <value optimized out>
> #9  0x00000000004172e0 in client_command_input (cmd=0x12a7eb0) at imap-client.c:778
>         client = 0x12a72b0
>         command = <value optimized out>
>         __FUNCTION__ = "client_command_input"
> #10 0x0000000000417376 in client_command_input (cmd=0x12a7eb0) at imap-client.c:839
>         client = 0x12a72b0
>         command = 0x12acd00
>         __FUNCTION__ = "client_command_input"
> #11 0x000000000041765d in client_handle_next_command (client=0x12a72b0) at imap-client.c:877
> No locals.
> #12 client_handle_input (client=0x12a72b0) at imap-client.c:889
>         _data_stack_cur_id = 3
>         ret = 80
>         remove_io = <value optimized out>
>         handled_commands = false
> ---Type <return> to continue, or q <return> to quit---
>         __FUNCTION__ = "client_handle_input"
> #13 0x00000000004179ef in client_input (client=0x12a72b0) at imap-client.c:931
>         cmd = <value optimized out>
>         output = 0x12a7cf0
>         bytes = <value optimized out>
>         __FUNCTION__ = "client_input"
> #14 0x00007f7dd869808e in io_loop_call_io (io=0x12a7dc0) at ioloop.c:441
>         ioloop = 0x128c760
>         t_id = 2
>         __FUNCTION__ = "io_loop_call_io"
> #15 0x00007f7dd869923f in io_loop_handler_run_internal (ioloop=<value optimized out>) at ioloop-epoll.c:220
>         ctx = 0x128d3f0
>         event = 0x128e260
>         list = 0x128ee50
>         io = 0x12acde0
>         tv = {tv_sec = 4, tv_usec = 996567}
>         msecs = <value optimized out>
>         ret = 1
>         i = 0
>         call = false
>         __FUNCTION__ = "io_loop_handler_run_internal"
> #16 0x00007f7dd8698119 in io_loop_handler_run (ioloop=0x12acde0) at ioloop.c:488
> No locals.
> #17 0x00007f7dd86981a8 in io_loop_run (ioloop=0x128c760) at ioloop.c:465
>         __FUNCTION__ = "io_loop_run"
> #18 0x00007f7dd8645153 in master_service_run (service=0x128c5f0, callback=0x20fa) at master-service.c:566
> No locals.
> #19 0x0000000000420f87 in main (argc=1, argv=0x128c3a0) at main.c:410
>         set_roots = {0x428fc0, 0x0}
>         login_set = {auth_socket_path = 0x1284050 "\210@(\001", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, callback = 0x421180
> <login_client_connected>, failure_callback = 0x421120 <login_client_failed>,
>           request_auth_token = 1}
>         service_flags = <value optimized out>
>         storage_service_flags = MAIL_STORAGE_SERVICE_FLAG_DISALLOW_ROOT
>         username = 0x0
>         c = <value optimized out>
> 
> -----> end backtrace <-----
> 
> Have you any idea how I can solve this?
> 
> Many thanks
> Urban Loesch
> 
> doveconf -n:
> 
> ...
> # 2.2.13 (38cd37cea8b1): /etc/dovecot/dovecot.conf
> # OS: Linux 3.4.67-vs2.3.3.9-rol-em64t-efigpt x86_64 Debian 6.0.9 ext4
> auth_cache_negative_ttl = 0
> auth_cache_size = 80 M
> auth_cache_ttl = 1 weeks
> auth_mechanisms = plain login
> auth_verbose = yes
> default_client_limit = 2000
> deliver_log_format = msgid=%m: %$ %p %w
> disable_plaintext_auth = no
> login_trusted_networks = INTERNAL_IPS
> mail_gid = mailstore
> mail_location = mdbox:/home/vmail/%d/%n:INDEX=/home/dovecotindex/%d/%n
> mail_log_prefix = "%s(%u pid:%p session:<%{session}>): "
> mail_plugins = " quota mail_log notify zlib"
> mail_uid = mailstore
> mailbox_idle_check_interval = 1 mins
> managesieve_notify_capability = mailto
> managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags
> copy include variables body enotify environment mailbox date ihave duplicate imapflags notify
> mdbox_rotate_size = 10 M
> namespace inbox {
>   inbox = yes
>   location =
>   mailbox Drafts {
>     special_use = \Drafts
>   }
>   mailbox Junk {
>     special_use = \Junk
>   }
>   mailbox Sent {
>     special_use = \Sent
>   }
>   mailbox "Sent Items" {
>     special_use = \Sent
>   }
>   mailbox "Sent Messages" {
>     special_use = \Sent
>   }
>   mailbox Trash {
>     special_use = \Trash
>   }
>   prefix =
>   separator = /
>   type = private
> }
> passdb {
>   args = /etc/dovecot/dovecot-sql-account.conf
>   driver = sql
> }
> plugin {
>   mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename flag_change save mailbox_create append
>   mail_log_fields = uid box msgid size from
>   mail_log_group_events = no
>   quota = dict:Storage used::file:%h/dovecot-quota
>   quota_rule2 = Trash:storage=+100M
>   quota_warning = storage=95%% quota-warning 95 %u
>   quota_warning2 = storage=80%% quota-warning 80 %u
>   sieve = ~/.dovecot.sieve
>   sieve_dir = ~/sieve
>   sieve_extensions = +notify +imapflags
>   sieve_max_redirects = 15
>   zlib_save = gz
>   zlib_save_level = 9
> }
> protocols = imap pop3 lmtp sieve
> service auth-worker {
>   service_count = 0
>   vsz_limit = 512 M
> }
> service auth {
>   unix_listener auth-userdb {
>     group = mailstore
>     mode = 0660
>     user = root
>   }
> }
> service imap-login {
>   inet_listener imap {
>     port = 143
>   }
>   process_limit = 256
>   process_min_avail = 50
>   service_count = 1
> }
> service imap {
>   process_limit = 2048
>   process_min_avail = 50
>   service_count = 1
>   vsz_limit = 512 M
> }
> service lmtp {
>   inet_listener lmtp {
>     address = *
>     port = 24
>   }
>   unix_listener /var/spool/postfix/private/dovecot-lmtp {
>     group = postfix
>     mode = 0666
>     user = postfix
>   }
> }
> service pop3-login {
>   inet_listener pop3 {
>     port = 110
>   }
>   process_limit = 256
>   process_min_avail = 25
>   service_count = 1
> }
> service pop3 {
>   process_limit = 256
>   process_min_avail = 25
>   service_count = 1
> }
> service quota-warning {
>   executable = script /usr/local/rol/dovecot/quota-warning.sh
>   unix_listener quota-warning {
>     user = mailstore
>   }
>   user = mailstore
> }
> ssl = no
> ssl_cert = </etc/dovecot/ssl/dovecot.pem
> ssl_key = </etc/dovecot/ssl/dovecot.key
> userdb {
>   args = /etc/dovecot/dovecot-sql-account.conf
>   driver = sql
> }
> protocol lmtp {
>   mail_fsync = optimized
>   mail_plugins = " quota mail_log notify zlib sieve zlib"
> }
> protocol imap {
>   imap_client_workarounds = tb-extra-mailbox-sep
>   imap_id_log = *
>   imap_logout_format = bytes=%i/%o session=<%{session}>
>   mail_max_userip_connections = 40
>   mail_plugins = " quota mail_log notify zlib imap_quota imap_zlib"
> }
> protocol pop3 {
>   mail_plugins = " quota mail_log notify zlib"
>   pop3_logout_format = bytes_sent=%o top=%t/%p, retr=%r/%b, del=%d/%m, size=%s uidl_hash=%u session=<%{session}>
> }
> 
> ....
> 


More information about the dovecot mailing list