Hello,
I have been seeing an issue with Dovecot 2.2.5 (which is the current version packaged by cPanel). This is happening with any action that tries to access the mailbox index via IMAP. This log and debug information comes from a force-resync attempt, however, the same errors are logged when the user tries to open the mailbox or move a message to it. (User, domain, and IPs in log have been changed for privacy reasons).
System is a CentOS 5.10 (x64) VPS under Virtuozzo 4.0, and is not OOMing or hitting any container limits. User is connecting from multiple devices on the same IP, most of which are Apple Mail & iOS. Other users with only Apple Mail & iOS devices are also experiencing the same errors.
Log:
Nov 19 15:55:33 host dovecot: imap-login: Login: user=user@domain.com, method=PLAIN, rip=1.2.3.4, lip=5.6.7.8, mpid=13887, TLS, session= Nov 19 15:55:33 host dovecot: imap: Debug: Loading modules from directory: /usr/lib64/dovecot Nov 19 15:55:33 host dovecot: imap: Debug: Module loaded: /usr/lib64/dovecot/lib01_acl_plugin.so Nov 19 15:55:33 host dovecot: imap: Debug: Module loaded: /usr/lib64/dovecot/lib10_quota_plugin.so Nov 19 15:55:33 host dovecot: imap: Debug: Module loaded: /usr/lib64/dovecot/lib11_imap_quota_plugin.so Nov 19 15:55:33 host dovecot: imap: Debug: Added userdb setting: mail=maildir:/home/username/mail/domain.com/user Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: Effective uid=504, gid=502, home=/home/username/mail/domain.com/user Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: acl: No acl_shared_dict setting - shared mailbox listing is disabled Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: Quota root: name= backend=maildir args= Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: Quota rule: root= mailbox=INBOX.Trash ignored Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: Quota grace: root= bytes=0 (10%) Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: Namespace : type=private, prefix=INBOX., sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/username/mail/domain.com/user Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: maildir++: root=/home/username/mail/domain.com/user, index=, indexpvt=, control=, inbox=/home/username/mail/domain.com/user, alt= Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: acl: initializing backend with data: vfile Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: acl: acl username = user@domain.com Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: acl: owner = 1 Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: acl vfile: Global ACL directory: (none) Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: Namespace : type=private, prefix=, sep=, inbox=no, hidden=yes, list=no, subscriptions=no location=fail::LAYOUT=none Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt= Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: acl vfile: file /home/username/mail/domain.com/user/.TrainSpam/dovecot-acl not found Nov 19 15:55:33 host dovecot: imap(user@domain.com): Debug: acl vfile: file /home/username/mail/domain.com/user/.Spam/dovecot-acl not found Nov 19 15:55:35 host dovecot: imap(user@domain.com): Error: broken sync positions in index file /home/username/mail/domain.com/user/.Spam/dovecot.index Nov 19 15:55:35 host dovecot: imap(user@domain.com): Warning: fscking index file /home/username/mail/domain.com/user/.Spam/dovecot.index Nov 19 15:55:35 host dovecot: imap(user@domain.com): Error: Fixed index file /home/username/mail/domain.com/user/.Spam/dovecot.index: log_file_tail_offset 3988 -> 3868 Nov 19 15:55:35 host dovecot: imap(user@domain.com): Panic: file mail-transaction-log.c: line 350 (mail_transaction_log_set_mailbox_sync_pos): assertion failed: (file_offset >= log->head->saved_tail_offset) Nov 19 15:55:35 host dovecot: imap(user@domain.com): Error: Raw backtrace: /usr/lib64/dovecot/libdovecot.so.0 [0x2b07be142400] -> /usr/lib64/dovecot/libdovecot.so.0 [0x2b07be142456] -> /usr/lib64/dovecot/libdovecot.so.0 [0x2b07be141df3] -> /usr/lib64/dovecot/libdovecot-storage.so.0 [0x2b07bdea066b] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_sync_commit+0x89) [0x2b07bde97ed9] -> /usr/lib64/dovecot/libdovecot-storage.so.0 [0x2b07bde25e4d] -> /usr/lib64/dovecot/libdovecot-storage.so.0(maildir_transaction_save_commit_pre+0x856) [0x2b07bde22186] -> /usr/lib64/dovecot/libdovecot-storage.so.0 [0x2b07bde81cc8] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_transaction_commit_full+0x86) [0x2b07bde8f466] -> /usr/lib64/dovecot/libdovecot-storage.so.0(index_transaction_commit+0xa5) [0x2b07bde820a5] -> /usr/lib64/dovecot/lib10_quota_plugin.so [0x2b07bef5252b] -> /usr/lib64/dovecot/lib01_acl_plugin.so [0x2b07bed40f77] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mailbox_transaction_commit_ge Nov 19 15:55:35 host dovecot: imap(user@domain.com): Fatal: master: service(imap): child 13887 killed with signal 6 (core dumped)
Debug:
Core was generated by `dovecot/imap'. Program terminated with signal 6, Aborted. #0 0x00002b07be3e0265 in raise () from /lib64/libc.so.6 (gdb) bt full #0 0x00002b07be3e0265 in raise () from /lib64/libc.so.6 No symbol table info available. #1 0x00002b07be3e1d10 in abort () from /lib64/libc.so.6 No symbol table info available. #2 0x00002b07be14240d in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:191 backtrace = 0x1773c798 "/usr/lib64/dovecot/libdovecot.so.0 [0x2b07be142400] -> /usr/lib64/dovecot/libdovecot.so.0 [0x2b07be142456] -> /usr/lib64/dovecot/libdovecot.so.0 [0x2b07be141df3] -> /usr/lib64/dovecot/libdovecot-stora"... #3 0x00002b07be142456 in i_internal_fatal_handler (ctx=0x7fff3c65f120, format=<value optimized out>, args=<value optimized out>) at failures.c:652 status = 0 #4 0x00002b07be141df3 in i_panic (format=0x363f
) at failures.c:263 ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0} args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7fff3c65f1f0, reg_save_area = 0x7fff3c65f130}} #5 0x00002b07bdea066b in mail_transaction_log_set_mailbox_sync_pos (log=<value optimized out>, file_seq=<value optimized out>, file_offset=<value optimized out>) at mail-transaction-log.c:350 __FUNCTION__ = "mail_transaction_log_set_mailbox_sync_pos" #6 0x00002b07bde97ed9 in mail_index_sync_update_mailbox_offset (_ctx=0x1776e588) at mail-index-sync.c:751 seq = 4 offset = 3868 #7 mail_index_sync_commit (_ctx=0x1776e588) at mail-index-sync.c:795 ctx = 0x17787570 index = 0x17770cf0 next_uid = <value optimized out> want_rotate = <value optimized out> index_undeleted = false delete_index = false ret = <value optimized out> #8 0x00002b07bde25e4d in maildir_sync_index_finish (ctx=0x1776e570, success=<value optimized out>) at maildir-sync-index.c:331 mbox = 0x1776ea30 time_diff = <value optimized out> ret = 0 #9 0x00002b07bde22186 in maildir_transaction_save_commit_pre (_ctx=0x177800e0) at maildir-save.c:1029 ctx = <value optimized out> _t = 0x17779bc0 sync_flags = <value optimized out> ret = 0 __FUNCTION__ = "maildir_transaction_save_commit_pre" #10 0x00002b07bde81cc8 in index_transaction_index_commit (index_trans=0x17779cb0, result_r=0x7fff3c65f470) at index-transaction.c:51 t = 0x17779bc0 pvt_sync_ctx = 0x0 ret = 0 __FUNCTION__ = "index_transaction_index_commit" #11 0x00002b07bde8f466 in mail_index_transaction_commit_full (_t=0x7fff3c65f498, result_r=0x7fff3c65f470) at mail-index-transaction.c:262 t = 0x17779cb0 index = 0x17770cf0 index_undeleted = false #12 0x00002b07bde820a5 in index_transaction_commit (t=0x17779bc0, changes_r=0x7fff3c65f5a0) at index-transaction.c:194 box = 0x1776ea30 itrans = 0x0 result = {log_file_seq = 0, log_file_offset = 0, commit_size = 0, ignored_modseq_changes = 0} ret = 0 #13 0x00002b07bef5252b in quota_mailbox_transaction_commit (ctx=0x17779bc0, changes_r=0x7fff3c65f5a0) at quota-storage.c:134 qt = 0x1777a890 #14 0x00002b07bed40f77 in acl_transaction_commit (ctx=0x17779bc0, changes_r=0x7fff3c65f5a0) at acl-mailbox.c:451 abox = 0x1776f048 ret = <value optimized out> #15 0x00002b07bde53975 in mailbox_transaction_commit_get_changes (_t=<value optimized out>, changes_r=0x7fff3c65f5a0) at mail-storage.c:1847 _data_stack_cur_id = 4 t = 0x17779bc0 save_count = 1 ret = <value optimized out> __FUNCTION__ = "mailbox_transaction_commit_get_changes" #16 0x000000000040c0d3 in cmd_copy_full () No symbol table info available. #17 0x000000000040c39b in cmd_copy () No symbol table info available. #18 0x0000000000414d97 in command_exec () No symbol table info available. #19 0x0000000000413b9b in client_command_input () No symbol table info available. #20 0x0000000000413c5f in client_command_input () No symbol table info available. #21 0x0000000000413e0f in client_handle_input () No symbol table info available. #22 0x0000000000414212 in client_input () No symbol table info available. #23 0x00002b07be150f16 in io_loop_call_io (io=0x1775c450) at ioloop.c:387 ioloop = 0x17744720 t_id = 2 #24 0x00002b07be15238d in io_loop_handler_run (ioloop=<value optimized out>) at ioloop-epoll.c:215 ctx = <value optimized out> event = 0x17746210 list = 0x1775c4a0 io = 0x363f tv = {tv_sec = 1799, tv_usec = 999752} events_count = <value optimized out> msecs = <value optimized out> ret = 1 i = 0 call = false __FUNCTION__ = "io_loop_handler_run" #25 0x00002b07be150ebd in io_loop_run (ioloop=0x17744720) at ioloop.c:406 No locals. #26 0x00002b07be107223 in master_service_run (service=0x177445b0, callback=0x363f) at master-service.c:566 No locals. #27 0x000000000041d437 in main () No symbol table info available.# dovecot -n # 2.2.5: /etc/dovecot/dovecot.conf # OS: Linux 2.6.18-028stab101.1 x86_64 CentOS release 5.10 (Final) auth_cache_size = 2 k auth_mechanisms = plain login auth_username_chars = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789!#$-=?^_{}~./@+%" disable_plaintext_auth = no lock_method = dotlock mail_debug = yes mailbox_idle_check_interval = 15 secs mmap_disable = yes namespace { inbox = yes location = prefix = INBOX. type = private } passdb { args = /usr/local/cpanel/bin/dovecot-wrap driver = checkpassword } plugin { acl = vfile quota = maildir quota_rule = INBOX.Trash:ignore } protocols = imap pop3 service auth { unix_listener auth-client { mode = 0666 } } service imap-login { client_limit = 500 inet_listener imap { address = * } inet_listener imaps { address = * } process_limit = 100 process_min_avail = 2 service_count = 1 vsz_limit = 64 M } service imap { process_limit = 512 vsz_limit = 256 M } service managesieve-login { client_limit = 500 process_limit = 100 process_min_avail = 2 service_count = 1 vsz_limit = 64 M } service managesieve { process_limit = 512 vsz_limit = 256 M } service pop3-login { client_limit = 500 inet_listener pop3 { address = * } inet_listener pop3s { address = * } process_limit = 100 process_min_avail = 2 service_count = 1 vsz_limit = 64 M } service pop3 { process_limit = 512 vsz_limit = 256 M } ssl_cert =
Any help with this would be greatly appreciated!
cheers,
-- Rob