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@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@domain.net pid:23434 session:
): 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
, failure_callback = 0x421120 , 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 = 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}> }
....