Rob Dosogne
2013-Nov-20 03:14 UTC
[Dovecot] Dovecot 2.2.5: Panic: file mail-transaction-log.c: line 350 (mail_transaction_log_set_mailbox_sync_pos)
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 at domain.com>, method=PLAIN, rip=1.2.3.4, lip=5.6.7.8,
mpid=13887, TLS, session=<A+FrZpDr/wAYzVli>
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 at domain.com): Debug: Effective
uid=504, gid=502, home=/home/username/mail/domain.com/user
Nov 19 15:55:33 host dovecot: imap(user at domain.com): Debug: acl: No
acl_shared_dict setting - shared mailbox listing is disabled
Nov 19 15:55:33 host dovecot: imap(user at domain.com): Debug: Quota
root: name= backend=maildir argsNov 19 15:55:33 host dovecot: imap(user at
domain.com): Debug: Quota
rule: root= mailbox=INBOX.Trash ignored
Nov 19 15:55:33 host dovecot: imap(user at domain.com): Debug: Quota
grace: root= bytes=0 (10%)
Nov 19 15:55:33 host dovecot: imap(user at 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 at domain.com): Debug: maildir++:
root=/home/username/mail/domain.com/user, index=, indexpvt=, control=,
inbox=/home/username/mail/domain.com/user, altNov 19 15:55:33 host dovecot:
imap(user at domain.com): Debug: acl:
initializing backend with data: vfile
Nov 19 15:55:33 host dovecot: imap(user at domain.com): Debug: acl: acl
username = user at domain.com
Nov 19 15:55:33 host dovecot: imap(user at domain.com): Debug: acl: owner = 1
Nov 19 15:55:33 host dovecot: imap(user at domain.com): Debug: acl vfile:
Global ACL directory: (none)
Nov 19 15:55:33 host dovecot: imap(user at 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 at domain.com): Debug: none:
root=, index=, indexpvt=, control=, inbox=, altNov 19 15:55:33 host dovecot:
imap(user at 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 at 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 at 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 at domain.com): Warning: fscking
index file /home/username/mail/domain.com/user/.Spam/dovecot.index
Nov 19 15:55:35 host dovecot: imap(user at 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 at 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 at 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 at 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 <Address 0x363f out
of bounds>) 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 = </etc/dovecot/ssl/dovecot.crt
ssl_cipher_list = ALL:!ADH:RC4+RSA:+HIGH:+MEDIUM:-LOW:-SSLv2:-EXP
ssl_key = </etc/dovecot/ssl/dovecot.key
userdb {
driver = prefetch
}
userdb {
args = /usr/local/cpanel/bin/dovecot-wrap
driver = checkpassword
}
verbose_proctitle = yes
protocol imap {
imap_idle_notify_interval = 15 mins
imap_logout_format = in=%i, out=%o, bytes=%i/%o
mail_max_userip_connections = 100
mail_plugins = acl quota imap_quota
}
protocol pop3 {
mail_max_userip_connections = 100
mail_plugins = quota
pop3_logout_format = top=%t/%p, retr=%r/%b, del=%d/%m, size=%s, bytes=%i/%o
pop3_uidl_format = UID%u-%v
}
protocol lda {
postmaster_address = postmaster at example.com
}
Any help with this would be greatly appreciated!
cheers,
--
Rob
Apparently Analagous Threads
Wisdom of the Ancients
