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=<EurP9wPmVgCBu/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=22811, session=<mSXT9wPmWgCBu/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=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=<JKbQ9wPmVwCBu/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=22814, session=<USLS9wPmWQCBu/Qf> 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=<KyHU9wPmWwCBu/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=22827, session=<kxTY9wPmXACBu/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=22828, session=<CXXg9wPmXQCBu/Qf> 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 <Address 0x2c1e out of bounds>) 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 <Address 0x2c1e 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 = 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 <login_client_connected>, failure_callback = 0x418f30 <login_client_failed>} 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 = </etc/pki/tls/certs/example.pem ssl_key = </etc/pki/tls/private/example-key.pem userdb { driver = passwd } protocol imap { mail_max_userip_connections = 30 mail_plugins = listescape quota imap_quota } protocol pop3 { mail_max_userip_connections = 10 pop3_uidl_format = %08Xu%08Xv }

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