New subject: [Dovecot] Dovecot 2.0, 2.1 and 2.2.5 core dump when Quota Plugin (FS) is enabled

10 Sep 2013


      Hi,
we are actually deploying a new IMAP-Server, targeting dovecot 2.1.17.
Unfortunately, our tests with imaptest did not succeed, were ending in
core dumps. We did this test:
./imaptest host=example.com port=143 user=strack pass=secret disconnect_quit  no_pipelining mbox=dovecot-crlf
That's what we get in dovecot's log:
Sep 10 11:17:04 imap-login: Info: Login: user=<strack>, method=PLAIN, rip=10.10.10.31, lip=10.10.10.21, mpid=22810, session=
Sep 10 11:17:04 imap-login: Info: Login: user=<strack>, method=PLAIN, rip=10.10.10.31, lip=10.10.10.21, mpid=22811, session=
Sep 10 11:17:04 imap-login: Info: Login: user=<strack>, method=PLAIN, rip=10.10.10.31, lip=10.10.10.21, mpid=22812, session=<1GbR9wPmWACBu/Qf>
Sep 10 11:17:04 imap-login: Info: Login: user=<strack>, method=PLAIN, rip=10.10.10.31, lip=10.10.10.21, mpid=22813, session=
Sep 10 11:17:04 imap-login: Info: Login: user=<strack>, method=PLAIN, rip=10.10.10.31, lip=10.10.10.21, mpid=22814, session=
Sep 10 11:17:04 imap(strack): Panic: file mbox-storage.c: line 712 (mbox_transaction_unlock): assertion failed: (mbox->box.transaction_count > 0 || mbox->mbox_lock_type == F_UNLCK)
Sep 10 11:17:04 imap(strack): Error: Raw backtrace: /usr/lib64/dovecot/libdovecot.so.0() [0x3c7824660a] -> /usr/lib64/dovecot/libdovecot.so.0() [0x3c78246656] -> /usr/lib64/dovecot/libdovecot.so.0() [0x3c78219eaa] -> /usr/lib64/dovecot/libdovecot-storage.so.0() [0x3c786600c0] -> /usr/lib/dovecot/lib10_quota_plugin.so(+0xb7e7) [0x7f113b5427e7] -> /usr/lib/dovecot/lib10_quota_plugin.so(+0xb218) [0x7f113b542218] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mbox_sync+0x88) [0x3c7865fea8] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mbox_transaction_save_commit_post+0x27) [0x3c78657c07] -> /usr/lib64/dovecot/libdovecot-storage.so.0() [0x3c786a5313] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_transaction_commit_full+0x9f) [0x3c786b3cdf] -> /usr/lib64/dovecot/libdovecot-storage.so.0(index_transaction_commit+0x8a) [0x3c786a4f5a] -> /usr/lib64/dovecot/libdovecot-storage.so.0() [0x3c78660121] -> /usr/lib/dovecot/lib10_quota_plugin.so(+0xb8af) [0x7f113b5428af] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mailbox_transaction_commit_get_changes+0x3e) [0x3c7867aa9e] -> dovecot/imap() [0x408b3a] -> dovecot/imap() [0x4088e4] -> dovecot/imap() [0x408d3c] -> dovecot/imap(cmd_append+0x139) [0x408f99] -> dovecot/imap(command_exec+0x3d) [0x41155d] -> dovecot/imap() [0x41046e] -> dovecot/imap() [0x41055a] -> dovecot/imap(client_handle_input+0x135) [0x410785] -> dovecot/imap(client_input+0x5f) [0x4110af] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x36) [0x3c78252c16] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x9f) [0x3c78253c9f] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x28) [0x3c78252bb8] -> /usr/lib64/dovecot/libdovecot.so.0(master_service_run+0x13) [0x3c7823e083] -> dovecot/imap(main+0x29d) [0x4195bd]
Sep 10 11:17:04 imap-login: Info: Login: user=<strack>, method=PLAIN, rip=10.10.10.31, lip=10.10.10.21, mpid=22826, session=
Sep 10 11:17:04 imap-login: Info: Login: user=<strack>, method=PLAIN, rip=10.10.10.31, lip=10.10.10.21, mpid=22827, session=
Sep 10 11:17:04 imap-login: Info: Login: user=<strack>, method=PLAIN, rip=10.10.10.31, lip=10.10.10.21, mpid=22828, session=
Sep 10 11:17:05 imap(strack): Fatal: master: service(imap): child 22806 killed with signal 6 (core dumped)
Sep 10 11:17:05 imap(strack): Info: Connection closed in=49 out=3832
Sep 10 11:17:05 imap(strack): Info: Connection closed in=49 out=3832
That's the backtrace of the coredump:
Loaded symbols for /lib64/libnss_files.so.2
Reading symbols from /lib64/libnss_sss.so.2...Reading symbols from /usr/lib/debug/lib64/libnss_sss.so.2.debug...done.
done.
Loaded symbols for /lib64/libnss_sss.so.2
Reading symbols from /lib64/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgcc_s.so.1
Core was generated by `dovecot/imap'.
Program terminated with signal 6, Aborted.
#0  0x0000003bc02328a5 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.107.el6_4.2.x86_64 keyutils-libs-1.4-4.el6.x86_64 krb5-libs-1.10.3-10.el6_4.4.x86_64 libcom_err-1.41.12-14.el6_4.2.x86_64 libgcc-4.4.7-3.el6.x86_64 libselinux-2.0.94-5.3.el6_4.1.x86_64 openssl-1.0.0-27.el6_4.2.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) bt
#0  0x0000003bc02328a5 in raise () from /lib64/libc.so.6
#1  0x0000003bc0234085 in abort () from /lib64/libc.so.6
#2  0x0000003c78246618 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:191
#3  0x0000003c78246656 in i_internal_fatal_handler (ctx=0x7fff1c87efa0, format=<value optimized out>, args=<value optimized out>) at failures.c:649
#4  0x0000003c78219eaa in i_panic (format=0x2c1e 
) at failures.c:263
#5  0x0000003c786600c0 in mbox_transaction_unlock (box=0x1a51270, lock_id=<value optimized out>) at mbox-storage.c:711
#6  0x00007f95c08c77e7 in quota_mailbox_transaction_rollback (ctx=0x1a589e0) at quota-storage.c:142
#7  0x00007f95c08c7218 in quota_mailbox_sync_notify (box=0x1a51270, uid=0, sync_type=0) at quota-storage.c:301
#8  0x0000003c7865fea8 in mbox_sync (mbox=0x1a51270, flags=<value optimized out>) at mbox-sync.c:2006
#9  0x0000003c78657c07 in mbox_transaction_save_commit_post (_ctx=0x1a53e20, result=<value optimized out>) at mbox-save.c:807
#10 0x0000003c786a5313 in index_transaction_index_commit (index_trans=0x1a5a530, result_r=0x7fff1c87f190) at index-transaction.c:50
#11 0x0000003c786b3cdf in mail_index_transaction_commit_full (_t=0x7fff1c87f1b8, result_r=0x7fff1c87f190) at mail-index-transaction.c:251
#12 0x0000003c786a4f5a in index_transaction_commit (t=<value optimized out>, changes_r=<value optimized out>) at index-transaction.c:132
#13 0x0000003c78660121 in mbox_transaction_commit (t=<value optimized out>, changes_r=<value optimized out>) at mbox-storage.c:729
#14 0x00007f95c08c78af in quota_mailbox_transaction_commit (ctx=0x1a5a390, changes_r=0x7fff1c87f260) at quota-storage.c:124
#15 0x0000003c7867aa9e in mailbox_transaction_commit_get_changes (_t=<value optimized out>, changes_r=0x7fff1c87f260) at mail-storage.c:1515
#16 0x0000000000408b3a in cmd_append_continue_parsing (cmd=0x1a4ea50) at cmd-append.c:284
#17 0x00000000004088e4 in cmd_append_continue_message (cmd=0x1a4ea50) at cmd-append.c:466
#18 0x0000000000408d3c in cmd_append_continue_parsing (cmd=0x1a4ea50) at cmd-append.c:399
#19 0x0000000000408f99 in cmd_append (cmd=0x1a4ea50) at cmd-append.c:519
#20 0x000000000041155d in command_exec (cmd=0x1a4ea50) at imap-commands.c:148
#21 0x000000000041046e in client_command_input (cmd=0x1a4ea50) at imap-client.c:684
#22 0x000000000041055a in client_command_input (cmd=0x1a4ea50) at imap-client.c:735
#23 0x0000000000410785 in client_handle_next_command (client=0x1a4e240) at imap-client.c:776
#24 client_handle_input (client=0x1a4e240) at imap-client.c:788
#25 0x00000000004110af in client_input (client=0x1a4e240) at imap-client.c:827
#26 0x0000003c78252c16 in io_loop_call_io (io=0x1a4cb70) at ioloop.c:379
#27 0x0000003c78253c9f in io_loop_handler_run (ioloop=<value optimized out>) at ioloop-epoll.c:213
#28 0x0000003c78252bb8 in io_loop_run (ioloop=0x1a35670) at ioloop.c:398
#29 0x0000003c7823e083 in master_service_run (service=0x1a35520, callback=<value optimized out>) at master-service.c:544
#30 0x00000000004195bd in main (argc=1, argv=0x1a35370) at main.c:389
That's the full backtrace of the coredump:
#0  0x0000003bc02328a5 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install
glibc-2.12-1.107.el6_4.2.x86_64 keyutils-libs-1.4-4.el6.x86_64
krb5-libs-1.10.3-10.el6_4.4.x86_64 libcom_err-1.41.12-14.el6_4.2.x86_64
libgcc-4.4.7-3.el6.x86_64 libselinux-2.0.94-5.3.el6_4.1.x86_64
openssl-1.0.0-27.el6_4.2.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) bt full
#0  0x0000003bc02328a5 in raise () from /lib64/libc.so.6
No symbol table info available.
#1  0x0000003bc0234085 in abort () from /lib64/libc.so.6
No symbol table info available.
#2  0x0000003c78246618 in default_fatal_finish (type=<value optimized
out>, status=0) at failures.c:191
backtrace = 0x1a2d3a8 "/usr/lib64/dovecot/libdovecot.so.0()
[0x3c7824660a] -> /usr/lib64/dovecot/libdovecot.so.0() [0x3c78246656]
-> /usr/lib64/dovecot/libdovecot.so.0() [0x3c78219eaa]
-> /usr/lib64/dovecot/libdovecot-stora"...
#3  0x0000003c78246656 in i_internal_fatal_handler (ctx=0x7fff1c87efa0,
format=<value optimized out>,
args=<value optimized out>) at failures.c:649
status = 0
#4  0x0000003c78219eaa in i_panic (format=0x2c1e 
) at failures.c:263
ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0}
args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area =
0x7fff1c87f070, reg_save_area = 0x7fff1c87efb0}}
#5  0x0000003c786600c0 in mbox_transaction_unlock (box=0x1a51270,
lock_id=<value optimized out>)
at mbox-storage.c:711
mbox = 0x1a51270
__FUNCTION__ = "mbox_transaction_unlock"
#6  0x00007f95c08c77e7 in quota_mailbox_transaction_rollback
(ctx=0x1a589e0) at quota-storage.c:142
qbox = 0x1a51858
qt = 0x1a66a90
#7  0x00007f95c08c7218 in quota_mailbox_sync_notify (box=0x1a51270,
uid=0, sync_type=0) at quota-storage.c:301
qbox = 0x1a51858
uids = <value optimized out>
sizep = <value optimized out>
i = <value optimized out>
count = <value optimized out>
size = <value optimized out>
#8  0x0000003c7865fea8 in mbox_sync (mbox=0x1a51270, flags=<value
optimized out>) at mbox-sync.c:2006
lock_id = 11
---Type <return> to continue, or q <return> to quit---
ret = 0
__FUNCTION__ = "mbox_sync"
#9  0x0000003c78657c07 in mbox_transaction_save_commit_post
(_ctx=0x1a53e20, result=<value optimized out>)
at mbox-save.c:807
ctx = 0x1a53e20
__FUNCTION__ = "mbox_transaction_save_commit_post"
#10 0x0000003c786a5313 in index_transaction_index_commit
(index_trans=0x1a5a530, result_r=0x7fff1c87f190)
at index-transaction.c:50
t = 0x1a5a390
ret = 0
__FUNCTION__ = "index_transaction_index_commit"
#11 0x0000003c786b3cdf in mail_index_transaction_commit_full
(_t=0x7fff1c87f1b8, result_r=0x7fff1c87f190)
at mail-index-transaction.c:251
t = 0x1a5a530
index = 0x1a4ccc0
index_undeleted = <value optimized out>
#12 0x0000003c786a4f5a in index_transaction_commit (t=<value optimized
out>, changes_r=<value optimized out>)
at index-transaction.c:132
box = 0x1a51270
itrans = 0x0
result = {log_file_seq = 17, log_file_offset = 6032, commit_size
= 196, ignored_modseq_changes = 0}
ret = <value optimized out>
#13 0x0000003c78660121 in mbox_transaction_commit (t=<value optimized
out>, changes_r=<value optimized out>)
at mbox-storage.c:729
mt = <value optimized out>
box = 0x1a51270
lock_id = 11
ret = <value optimized out>
#14 0x00007f95c08c78af in quota_mailbox_transaction_commit
(ctx=0x1a5a390, changes_r=0x7fff1c87f260)
---Type <return> to continue, or q <return> to quit---
at quota-storage.c:124
qbox = 0x1a51858
qt = 0x1a5a1e0
#15 0x0000003c7867aa9e in mailbox_transaction_commit_get_changes
(_t=<value optimized out>, changes_r=0x7fff1c87f260)
at mail-storage.c:1515
_data_stack_cur_id = 4
t = 0x1a5a390
ret = <value optimized out>
#16 0x0000000000408b3a in cmd_append_continue_parsing (cmd=0x1a4ea50) at
cmd-append.c:284
sync_flags = <value optimized out>
imap_flags = <value optimized out>
changes = {pool = 0x1a61fe0, uid_validity = 1268835246,
saved_uids = {arr = {buffer = 0x1a62000,
element_size = 8}, v = 0x1a62000, v_modifiable =
0x1a62000}, ignored_modseq_changes = 0,
changed = true, no_read_perm = false}
msg = <value optimized out>
client = 0x1a4e240
ctx = 0x1a4eb48
args = 0x1a59a98
flags_list = <value optimized out>
flags = <value optimized out>
keywords_list = <value optimized out>
keywords = <value optimized out>
internal_date_str = <value optimized out>
msg = <value optimized out>
internal_date = <value optimized out>
ret = <value optimized out>
timezone_offset = <value optimized out>
save_count = <value optimized out>
nonsync = <value optimized out>
---Type <return> to continue, or q <return> to quit---
fatal = <value optimized out>
__FUNCTION__ = "cmd_append_continue_parsing"
#17 0x00000000004088e4 in cmd_append_continue_message (cmd=0x1a4ea50) at
cmd-append.c:466
all_written = true
client = 0x1a4e240
ctx = 0x1a4eb48
size = 0
ret = <value optimized out>
#18 0x0000000000408d3c in cmd_append_continue_parsing (cmd=0x1a4ea50) at
cmd-append.c:399
client = 0x1a4e240
ctx = 0x1a4eb48
args = 0x1a59a98
flags_list = 0x0
flags = 0
keywords_list = 0x3c782426aa
keywords = 0x0
internal_date_str = <value optimized out>
msg = <value optimized out>
internal_date = -1
ret = 0
timezone_offset = 0
save_count = <value optimized out>
nonsync = true
fatal = <value optimized out>
__FUNCTION__ = "cmd_append_continue_parsing"
#19 0x0000000000408f99 in cmd_append (cmd=0x1a4ea50) at cmd-append.c:519
client = 0x1a4e240
ctx = 0x1a4eb48
mailbox = 0x1a38910 "INBOX"
---Type <return> to continue, or q <return> to quit---
#20 0x000000000041155d in command_exec (cmd=0x1a4ea50) at
imap-commands.c:148
hook = 0x1a36cd0
ret = <value optimized out>
#21 0x000000000041046e in client_command_input (cmd=0x1a4ea50) at
imap-client.c:684
client = 0x1a4e240
command = <value optimized out>
__FUNCTION__ = "client_command_input"
#22 0x000000000041055a in client_command_input (cmd=0x1a4ea50) at
imap-client.c:735
client = 0x1a4e240
command = <value optimized out>
__FUNCTION__ = "client_command_input"
#23 0x0000000000410785 in client_handle_next_command (client=0x1a4e240)
at imap-client.c:776
size = 1320
#24 client_handle_input (client=0x1a4e240) at imap-client.c:788
_data_stack_cur_id = 3
ret = false
remove_io = false
handled_commands = false
__FUNCTION__ = "client_handle_input"
#25 0x00000000004110af in client_input (client=0x1a4e240) at
imap-client.c:827
cmd = <value optimized out>
output = 0x1a4ca88
bytes = 1320
__FUNCTION__ = "client_input"
#26 0x0000003c78252c16 in io_loop_call_io (io=0x1a4cb70) at ioloop.c:379
ioloop = 0x1a35670
t_id = 2
#27 0x0000003c78253c9f in io_loop_handler_run (ioloop=<value optimized
out>) at ioloop-epoll.c:213
ctx = 0x1a359e0
---Type <return> to continue, or q <return> to quit---
events = <value optimized out>
event = 0x1a35a50
list = 0x1a4cbc0
io = <value optimized out>
tv = {tv_sec = 1799, tv_usec = 999319}
msecs = <value optimized out>
ret = 1
i = <value optimized out>
call = <value optimized out>
#28 0x0000003c78252bb8 in io_loop_run (ioloop=0x1a35670) at ioloop.c:398
No locals.
#29 0x0000003c7823e083 in master_service_run (service=0x1a35520,
callback=<value optimized out>)
at master-service.c:544
No locals.
#30 0x00000000004195bd in main (argc=1, argv=0x1a35370) at main.c:389
set_roots = {0x41c460, 0x0}
login_set = {auth_socket_path = 0x1a2d078
"/var/run/dovecot/auth-master", postlogin_socket_path = 0x0,
postlogin_timeout_secs = 60, callback = 0x419710
,
failure_callback = 0x418f30 }
service_flags = <value optimized out>
storage_service_flags = <value optimized out>
username = <value optimized out>
c = <value optimized out>
That's our configuration:
# 2.1.17: /etc/dovecot/dovecot.conf
# OS: Linux 2.6.32-358.18.1.el6.x86_64 x86_64 Red Hat Enterprise Linux
Server release 6.4 (Santiago) xfs
auth_debug = yes
auth_verbose = yes
debug_log_path = /var/log/dovecot/dovecot-debug.log
default_client_limit = 3000
default_process_limit = 8192
disable_plaintext_auth = no
log_path = /var/log/dovecot/dovecot.log
login_greeting = Server ready.
mail_debug = yes
mail_location = mbox:/var/spool/fhmrz_imap/%
u/dovecot-home:LAYOUT=maildir++:INBOX=/var/spool/mail/%
u:INDEX=/var/opt/index/%u/dovecot-indexes:CONTROL=/var/opt/index/%
u/dovecot-control
mail_plugin_dir = /usr/lib/dovecot
mail_plugins = listescape quota
mbox_write_locks = fcntl
namespace inbox {
inbox = yes
location =
mailbox Drafts {
special_use = \Drafts
}
mailbox Junk {
special_use = \Junk
}
mailbox Sent {
special_use = \Sent
}
mailbox "Sent Messages" {
special_use = \Sent
}
mailbox Trash {
special_use = \Trash
}
prefix =
separator = /
type = private
}
passdb {
driver = pam
}
plugin {
mail_log_events = delete undelete expunge copy mailbox_delete
mailbox_rename
mail_log_fields = uid box msgid size flags
quota = fs:User quota:user:noenforcing
quota_exceeded_message = Quota exceeded, please go to
http://www.timbuktu.edu/over_quota_help for instructions on how to fix
this.
}
protocols = imap pop3
service anvil {
client_limit = 16744
}
service auth {
client_limit = 16800
}
service imap-login {
inet_listener imap {
port = 143
}
inet_listener imaps {
port = 993
ssl = yes
}
process_limit = 8192
process_min_avail = 8
}
service imap {
process_limit = 16084
}
service pop3-login {
inet_listener pop3 {
port = 110
}
inet_listener pop3s {
port = 995
ssl = yes
}
}
service pop3 {
process_limit = 16084
}
ssl_cert = 
The problem occurs with dovecot-2.0.9 and dovecot-2.1.17 and also
dovecot-2.2.5!
From the stacktrace I could see that the problem origins from the quota
plugin. Thus, when I disabled the quota plugin the problem went away.
The problem did only occur on a high concurrency level on one
mbox/folder, running imaptest with only one user and 10 clients. When we
run imaptest in a more real-world fashion with several thousand of users
and clients=100, the error did not occur. Because of this I am not sure
how problematic this bug will be in a production environment? What do
you think?
Any help is greatly appreciated!
br
Harald Strack
--
Harald Strack, Dipl.Inf.(FH)
IT Development
ssystems
c/o berliner gazette
Danziger Str. 31
10435 Berlin
Tel:     +49 30 2023 6071 - 1
http://www.ssystems.de

[Dovecot] Dovecot 2.0, 2.1 and 2.2.5 core dump when Quota Plugin (FS) is enabled

Harald Strack

Timo Sirainen

tags

participants (2)