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}>
> }
>
> ....
>