- dovecot - dovecot.org

[Dovecot] dovecot 2 beta4 errors & core dumps
by de Lafond Guillaume 07 Jun '10

07 Jun '10

Hi, While running imaptest with "clients=50 seed=123 msgs=100000000 random secs=600", I got errors : "Error: user(a)domain.com[55]: Unexpected BYE: * BYE IMAP session state is inconsistent, please relogin.". dovecot.log : Apr 03 10:23:47 imap(user(a)domain.com): Panic: file index- transaction.c: line 145 (index_transaction_rollback): assertion failed: (box->transaction_count > 0 || box->view->transactions == 0) Apr 03 10:23:47 imap(user(a)domain.com): Error: Raw backtrace: /usr/ local/dovecot2/lib/dovecot/libdovecot.so.0 [0xb7e9adc1] -> /usr/local/ dovecot2/lib/dovecot/libdovecot.so.0 [0xb7e9ae3f] -> /usr/local/ dovecot2/lib/dovecot/libdovecot.so.0(i_error+0) [0xb7e9b0f8] -> /usr/ local/dovecot2/lib/dovecot/libdovecot-storage.so.0 [0xb7f3e9c2] -> / usr/local/dovecot2/lib/dovecot/lib10_quota_plugin.so [0xb7cdaaea] -> / usr/local/dovecot2/lib/dovecot/libdovecot-storage.so. 0(mailbox_transaction_rollback+0x20) [0xb7ef03f0] -> /usr/local/ dovecot2/lib/dovecot/lib10_quota_plugin.so [0xb7cda323] -> /usr/local/ dovecot2/lib/dovecot/lib10_quota_plugin.so [0xb7cda4df] -> /usr/local/ dovecot2/lib/dovecot/libdovecot-storage.so.0(maildir_sync_index+0x897) [0xb7f52bb7] -> /usr/local/dovecot2/lib/dovecot/libdovecot-storage.so. 0(maildir_transaction_save_commit_pre+0x710) [0xb7f50f70] -> /usr/ local/dovecot2/lib/dovecot/libdovecot-storage.so.0 [0xb7f3ee27] -> / usr/local/dovecot2/lib/dovecot/libdovecot-storage.so. 0(mail_index_transaction_commit_full+0x85) [0xb7f08ee5] -> /usr/local/ dovecot2/lib/dovecot/libdovecot-storage.so.0(index_transaction_commit +0x83) [0xb7f3ea53] -> /usr/local/dovecot2/lib/dovecot/ lib10_quota_plugin.so [0xb7cdab81] -> /usr/local/dovecot2/lib/dovecot/ libdovecot-storage.so.0(mailbox_transaction_commit_get_changes+0x42) [0xb7ef0c72] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND] [0x804eab2] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND] [0x804e8cb] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND] [0x804ed02] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND] (cmd_append+0x1d9) [0x804f069] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND] [0x80562dc] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND] [0x8056379] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND] (client_handle_input+0x2d) [0x80564ed] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND](client_input+0x5f) [0x8056f0f] -> / usr/local/dovecot2/lib/dovecot/libdovecot.so.0(io_loop_handler_run +0xf5) [0xb7ea7425] -> /usr/local/dovecot2/lib/dovecot/libdovecot.so. 0(io_loop_run+0x30) [0xb7ea6470] -> /usr/local/dovecot2/lib/dovecot/ libdovecot.so.0(master_service_run+0x2a) [0xb7e93eaa] -> dovecot/imap [user(a)domain.com 10.0.0.5 APPEND](main+0x2ad) [0x805f9ed] -> /lib/i686/cmov/libc.so. 6(__libc_start_main+0xe5) [0xb7d0f455] Apr 03 10:23:47 master: Error: service(imap): child 27371 killed with signal 6 (core dumped) Apr 03 10:23:50 imap(user(a)domain.com): Error: dotlock /var/mail/d/ domain.com/user/Maildir/dovecot-uidlist.lock was immediately deleted under us Apr 03 10:23:50 imap(user(a)domain.com): Error: dotlock /var/mail/d/ domain.com/user/Maildir/dovecot-uidlist.lock was immediately deleted under us Apr 03 10:23:50 imap(user(a)domain.com): Warning: Our dotlock file /var/ mail/d/domain.com/user/Maildir/dovecot-uidlist.lock was deleted (locked 0 secs ago, touched 0 secs ago) Apr 03 10:23:50 imap(user(a)domain.com): Warning: Our dotlock file /var/ mail/d/domain.com/user/Maildir/dovecot-uidlist.lock was deleted (locked 0 secs ago, touched 0 secs ago) Apr 03 10:23:50 imap(user(a)domain.com): Error: Log synchronization error at seq=2,offset=8188 for /var/mail/dovecot_indexes/d/domain.com/ user/.INBOX/dovecot.index: Append with UID 32, but next_uid = 33 Apr 03 10:23:50 imap(user(a)domain.com): Warning: fscking index file / var/mail/dovecot_indexes/d/domain.com/user/.INBOX/dovecot.index Apr 03 10:23:50 imap(user(a)domain.com): Error: Log synchronization error at seq=2,offset=8188 for /var/mail/dovecot_indexes/d/domain.com/ user/.INBOX/dovecot.index: Append with UID 32, but next_uid = 33 Apr 03 10:23:50 imap(user(a)domain.com): Warning: fscking index file / var/mail/dovecot_indexes/d/domain.com/user/.INBOX/dovecot.index Apr 03 10:23:50 imap(user(a)domain.com): Warning: Our dotlock file /var/ mail/d/domain.com/user/Maildir/dovecot-uidlist.lock was overridden (locked 0 secs ago, touched 0 secs ago) Apr 03 10:23:50 imap(user(a)domain.com): Error: dotlock /var/mail/d/ domain.com/user/Maildir/dovecot-uidlist.lock was immediately recreated under us Apr 03 10:23:50 imap(user(a)domain.com): Error: Log synchronization error at seq=2,offset=8188 for /var/mail/dovecot_indexes/d/domain.com/ user/.INBOX/dovecot.index: Append with UID 32, but next_uid = 33 Apr 03 10:23:50 imap(user(a)domain.com): Warning: fscking index file / var/mail/dovecot_indexes/d/domain.com/user/.INBOX/dovecot.index The backtrace : Core was generated by `dovecot/imap'. Program terminated with signal 6, Aborted. [New process 27371] #0 0xb7f85424 in __kernel_vsyscall () (gdb) bt full #0 0xb7f85424 in __kernel_vsyscall () No symbol table info available. #1 0xb7d24640 in raise () from /lib/i686/cmov/libc.so.6 No symbol table info available. #2 0xb7d26018 in abort () from /lib/i686/cmov/libc.so.6 No symbol table info available. #3 0xb7e9add5 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:164 backtrace = 0x80643d0 "/usr/local/dovecot2/lib/dovecot/libdovecot.so. 0 [0xb7e9adc1] -> /usr/local/dovecot2/lib/dovecot/libdovecot.so.0 [0xb7e9ae3f] -> /usr/local/dovecot2/lib/dovecot/libdovecot.so.0(i_error +0) [0xb7e9b0f8] "... #4 0xb7e9ae3f in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0xb7f6f1c4 "file %s: line %d (%s): assertion failed: (%s)", args=0xbfffda44 "\2228??\221") at failures.c:592 No locals. #5 0xb7e9b0f8 in i_panic (format=0xb7f6f1c4 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:230 No locals. #6 0xb7f3e9c2 in index_transaction_rollback (t=0x80b2a90) at index- transaction.c:144 box = (struct mailbox *) 0x808d340 itrans = (struct mail_index_transaction *) 0x0 __FUNCTION__ = "index_transaction_rollback" #7 0xb7cdaaea in quota_mailbox_transaction_rollback (ctx=0x80b2a90) at quota-storage.c:112 qt = (struct quota_transaction_context *) 0x80a9628 #8 0xb7ef03f0 in mailbox_transaction_rollback (_t=0x808d780) at mail- storage.c:1155 t = (struct mailbox_transaction_context *) 0x6aeb #9 0xb7cda323 in quota_mailbox_sync_cleanup (qbox=0x808d6c0) at quota- storage.c:246 No locals. #10 0xb7cda4df in quota_mailbox_sync_notify (box=0x808d340, uid=0, sync_type=<value optimized out>) at quota-storage.c:274 qbox = (struct quota_mailbox *) 0x808d6c0 i = <value optimized out> count = <value optimized out> size = <value optimized out> #11 0xb7f52bb7 in maildir_sync_index (ctx=0x80b45a0, partial=true) at maildir-sync-index.c:631 mbox = (struct maildir_mailbox *) 0x808d340 view = (struct mail_index_view *) 0x80a9270 view2 = (struct mail_index_view *) 0x0 iter = (struct maildir_uidlist_iter_ctx *) 0x0 trans = (struct mail_index_transaction *) 0x80b42c8 hdr = (const struct mail_index_header *) 0x80a85f8 empty_hdr = {major_version = 0 '\0', minor_version = 0 '\0', base_header_size = 0, header_size = 0, record_size = 576, compat_flags = 8 '\b', unused = "???", indexid = 3084301177, flags = 3085242720, uid_validity = 28, next_uid = 3085743644, messages_count = 134956776, unused_old_recent_messages_count = 576, seen_messages_count = 3221216296, deleted_messages_count = 3085530619, first_recent_uid = 3085747040, first_unseen_uid_lowwater = 0, first_deleted_uid_lowwater = 0, log_file_seq = 576, log_file_tail_offset = 28, log_file_head_offset = 1, sync_size = 13256344077235912704, sync_stamp = 3085747040, day_stamp = 134956776, day_first_uid = {3221216328, 3085530784, 3085747040, 3085781192, 3086502160, 3085743644, 4294967295, 3086618612}} rec = <value optimized out> seq = 0 seq2 = 0 uid = 29 prev_uid = 29 uflags = 0 filename = 0x80aee58 "1270283027.M108835P27367.test- mail,S=1837,W=1881:2," uid_validity = 1270283075 next_uid = <value optimized out> hdr_next_uid = 30 first_recent_uid = 30 first_uid = 1 changes = 4 ret = 0 time_before_sync = 1270283027 expunged_guid_128 = "?????o\216\bl\236?\000?8=\216" expunged = false full_rescan = false __FUNCTION__ = "maildir_sync_index" #12 0xb7f50f70 in maildir_transaction_save_commit_pre (_ctx=0x80ada00) at maildir-save.c:765 _t = (struct mailbox_transaction_context *) 0x80a9d38 last_mf = <value optimized out> sync_flags = <value optimized out> ret = <value optimized out> __FUNCTION__ = "maildir_transaction_save_commit_pre" #13 0xb7f3ee27 in index_transaction_index_commit (index_trans=0x80aa258, result_r=0xbfffddcc) at index-transaction.c:27 it = (struct index_transaction_context *) 0x80a9d38 ibox = (struct index_mailbox_context *) 0x808d558 ret = <value optimized out> __FUNCTION__ = "index_transaction_index_commit" #14 0xb7f08ee5 in mail_index_transaction_commit_full (_t=0xbfffdde8, result_r=0xbfffddcc) at mail-index-transaction.c:237 t = (struct mail_index_transaction *) 0x80aa258 index = (struct mail_index *) 0x806e708 index_undeleted = false #15 0xb7f3ea53 in index_transaction_commit (t=0x80a9d38, changes_r=0xbfffde8c) at index-transaction.c:123 box = (struct mailbox *) 0x808d340 itrans = (struct mail_index_transaction *) 0x0 result = {log_file_seq = 0, log_file_offset = 0, commit_size = 0, ignored_uid_changes = 0, ignored_modseq_changes = 0} ret = <value optimized out> __FUNCTION__ = "index_transaction_commit" #16 0xb7cdab81 in quota_mailbox_transaction_commit (ctx=0x80a9d38, changes_r=0xbfffde8c) at quota-storage.c:94 qt = (struct quota_transaction_context *) 0x80aa628 #17 0xb7ef0c72 in mailbox_transaction_commit_get_changes (_t=0x80893c8, changes_r=0xbfffde8c) at mail-storage.c:1143 _data_stack_cur_id = 4 t = (struct mailbox_transaction_context *) 0x80a9d38 ret = <value optimized out> #18 0x0804eab2 in cmd_append_continue_parsing (cmd=0x8089328) at cmd- append.c:265 sync_flags = <value optimized out> imap_flags = <value optimized out> changes = {pool = 0x80b3308, uid_validity = 0, saved_uids = {arr = {buffer = 0x80b3320, element_size = 8}, v = 0x80b3320, v_modifiable = 0x80b3320}, ignored_uid_changes = 0, ignored_modseq_changes = 0} msg = <value optimized out> client = (struct client *) 0x8084318 ctx = (struct cmd_append_context *) 0x80893b8 args = (const struct imap_arg *) 0x80ab218 flags_list = <value optimized out> flags = <value optimized out> keywords_list = <value optimized out> keywords = <value optimized out> internal_date_str = <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> __FUNCTION__ = "cmd_append_continue_parsing" #19 0x0804e8cb in cmd_append_continue_message (cmd=0x8089328) at cmd- append.c:446 client = (struct client *) 0x8084318 ctx = (struct cmd_append_context *) 0x80893b8 size = 0 ret = <value optimized out> #20 0x0804ed02 in cmd_append_continue_parsing (cmd=0x8089328) at cmd- append.c:379 client = (struct client *) 0x8084318 ctx = (struct cmd_append_context *) 0x80893b8 args = (const struct imap_arg *) 0x80ab218 flags_list = (const struct imap_arg *) 0x0 flags = 0 keywords_list = (const char * const *) 0x80ab1e0 keywords = (struct mail_keywords *) 0x0 internal_date_str = 0x0 internal_date = -1 ret = 0 timezone_offset = 0 save_count = <value optimized out> nonsync = true __FUNCTION__ = "cmd_append_continue_parsing" #21 0x0804f069 in cmd_append (cmd=0x8089328) at cmd-append.c:540 client = (struct client *) 0x8084318 ctx = (struct cmd_append_context *) 0x80893b8 mailbox = 0x808abd8 "INBOX" #22 0x080562dc in client_command_input (cmd=0x8089328) at imap- client.c:647 client = (struct client *) 0x8084318 command = <value optimized out> __FUNCTION__ = "client_command_input" #23 0x08056379 in client_command_input (cmd=0x8089328) at imap- client.c:697 client = (struct client *) 0x8084318 command = <value optimized out> __FUNCTION__ = "client_command_input" #24 0x080564ed in client_handle_input (client=0x8084318) at imap- client.c:738 _data_stack_cur_id = 3 ret = false remove_io = <value optimized out> handled_commands = false __FUNCTION__ = "client_handle_input" #25 0x08056f0f in client_input (client=0x8084318) at imap-client.c:789 cmd = <value optimized out> output = (struct ostream *) 0x8083054 bytes = <value optimized out> __FUNCTION__ = "client_input" #26 0xb7ea7425 in io_loop_handler_run (ioloop=0x806c358) at ioloop- epoll.c:208 ctx = (struct ioloop_handler_context *) 0x806c478 event = (const struct epoll_event *) 0x806c4b8 list = (struct io_list *) 0x80830d8 io = (struct io_file *) 0x80830b0 tv = {tv_sec = 1799, tv_usec = 999126} t_id = 2 msecs = <value optimized out> ret = 1 i = 0 j = 0 call = <value optimized out> #27 0xb7ea6470 in io_loop_run (ioloop=0x806c358) at ioloop.c:350 No locals. #28 0xb7e93eaa in master_service_run (service=0x806c2a8, callback=0x805faa0 <client_connected>) at master-service.c:486 No locals. #29 0x0805f9ed in main (argc=Cannot access memory at address 0x0 ) at main.c:323 service_flags = <value optimized out> storage_service_flags = <value optimized out> postlogin_socket_path = 0x0 username = 0x0 c = <value optimized out> set_roots = {0x8062760, 0x0} (gdb) I don't have errors with clients=1 seed=123 msgs=100000000 random secs=600. -- Guillaume de Lafond Aqua Ray

2 1

[Dovecot] mangled user_attrs from LDAP
by markham breitbach 07 Jun '10

07 Jun '10

I have setup dovecot to allow users to login using their email address or uid and have found a strange behaviour when the user logs in using the email address for a "username". I am using OpenLDAP for a backend data store with a rather customized schema. This behaviour occurs for both POP3 and IMAP logins. For some users it works as expected, but for others the pass_attrs->user does not get mapped back to the uid, but remains the mailLocalAddress (dovecot-ldap.conf is attached at the end of this post). Here is an excerpt from the logs for a working and a malfunctioning user. In both cases the users were logged directly into the pop3 port (ie. telnet <mailserver> 110) and used the fully qualified email address as the user (ie. foo(a)ex.tld) Jun 02 13:23:19 pop3-login: Info: Login: user=<foo>, method=PLAIN, rip=64.247.129.10, lip=64.247.129.10, secured Jun 02 13:23:19 POP3(foo): Info: Loading modules from directory: /usr/local/lib/dovecot/pop3 Jun 02 13:23:19 POP3(foo): Info: Module loaded: /usr/local/lib/dovecot/pop3/lib10_quota_plugin.so Jun 02 13:23:19 POP3(foo): Info: Effective uid=14921, gid=2000, home=/nonexistent Jun 02 13:23:19 POP3(foo): Info: Quota root: name=User quota backend=maildir args= Jun 02 13:23:19 POP3(foo): Info: Quota rule: root=User quota mailbox=* bytes=0 messages=0 Jun 02 13:23:19 POP3(foo): Info: maildir: data=/var/mail/foo Jun 02 13:23:19 POP3(foo): Info: maildir++: root=/var/mail/foo, index=, control=, inbox=/var/mail/foo Jun 02 13:23:19 POP3(foo): Info: Namespace : Using permissions from /var/mail/foo: mode=0700 gid=-1 Jun 02 16:54:06 pop3-login: Info: Login: user=<bobs>, method=PLAIN, rip=199.247.84.12, lip=64.247.129.4 Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: Loading modules from directory: /usr/local/lib/dovecot/pop3 Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: Module loaded: /usr/local/lib/dovecot/pop3/lib10_quota_plugin.so Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: Effective uid=38538, gid=2000, home=/nonexistent Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: Quota root: name=User quota backend=maildir args= Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: Quota rule: root=User quota mailbox=* bytes=524288000 messages=0 Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: Quota rule: root=User quota mailbox=Trash bytes=52428800 messages=0 Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: Quota rule: root=User quota mailbox=Deleted Messages bytes=52428800 messages=0 Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: maildir: data=/var/mail/bob_smith(a)example.tld Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: maildir++: root=/var/mail/bob_smith(a)example.tld, index=, control=, inbox=/var/mail/bob_smith(a)example.tld Jun 02 16:54:06 POP3(bob_smith(a)example.tld): Info: Namespace : Using permissions from /var/mail/bob_smith(a)example.tld: mode=0700 gid=-1 Jun 02 16:54:10 POP3(bob_smith(a)example.tld): Info: Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 After much searching for anything different between these records, some tcpdumps showed that the problem occured when LDAP returned the attributes in a different order than they are requested in. In this sample, you can see the request for uid,homeDirectory,uidNumber,gidNumber,mailQuota and the values are returned in the order gidNumber, uid, uidNumber, homeDirectory. There is no mailQuota set for this user. 16:54:06.145597 IP mail.xxxxx.com.62929 > closest-ldap.ldap: P 14:261(247) ack 15 win 33304 <nop,nop,timestamp 1521221146 267819447> 0x0000: 4500 012b fd4d 4000 4006 b87a 40f7 8104 E..+.M@.@..z@... 0x0010: 40f7 8112 f5d1 0185 41e1 8b7d 5aea 01d9 @.......A..}Z... 0x0020: 8018 8218 8522 0000 0101 080a 5aab fe1a ....."......Z... 0x0030: 0ff6 99b7 3081 f402 0120 6381 ee04 0b64 ....0.....c....d 0x0040: 633d 322c 6463 3d73 7369 0a01 020a 0100 c=2,dc=ssi...... 0x0050: 0201 0002 0100 0101 00a0 8198 a317 040d ................ 0x0060: 6163 636f 756e 7473 7461 7475 7304 0661 accountstatus..a 0x0070: 6374 6976 65a3 1c04 1265 6d61 696c 6163 ctive....emailac 0x0080: 636f 756e 7453 7461 7475 7304 0661 6374 countStatus..act 0x0090: 6976 65a1 5fa3 2704 0375 6964 0420 626f ive._.'..uid..bo 0x00a0: 625f 6d61 6364 6f6e 616c 6440 6772 6561 b_xxxxxxxxx@xxxx 0x00b0: 7473 6c61 7665 6865 6c69 2e63 6f6d a334 xxxxxxxxxx.com.4 0x00c0: 0410 6d61 696c 4c6f 6361 6c41 6464 7265 ..mailLocalAddre 0x00d0: 7373 0420 626f 625f 6d61 6364 6f6e 616c ss..bob_xxxxxxxx 0x00e0: 6440 6772 6561 7473 6c61 7665 6865 6c69 x@xxxxxxxxxxxxxx 0x00f0: 2e63 6f6d 3035 0403 7569 6404 0d68 6f6d .com05..uid..hom 0x0100: 6544 6972 6563 746f 7279 0409 7569 644e eDirectory..uidN 0x0110: 756d 6265 7204 0967 6964 4e75 6d62 6572 umber..gidNumber 0x0120: 0409 6d61 696c 5175 6f74 61 ..mailQuota 16:54:06.147464 IP closest-ldap.ldap > mail.xxxxx.com.62929: P 15:142(127) ack 261 win 32942 <nop,nop,timestamp 267819449 1521221146> 0x0000: 4500 00b3 bb91 4000 4006 faae 40f7 8112 E.....@.@...@... 0x0010: 40f7 8104 0185 f5d1 5aea 01d9 41e1 8c74 @.......Z...A..t 0x0020: 8018 80ae b708 0000 0101 080a 0ff6 99b9 ................ 0x0030: 5aab fe1a 307d 0201 2064 7804 1663 6e3d Z...0}...dx..cn= 0x0040: 6773 6862 6f62 6d2c 6463 3d32 2c64 633d xxxbobx,dc=2,dc= 0x0050: 7373 6930 5e30 1304 0967 6964 4e75 6d62 ssi0^0...gidNumb 0x0060: 6572 3106 0404 3230 3030 3010 0403 7569 er1...20000...ui 0x0070: 6431 0904 0767 7368 626f 626d 3014 0409 d1...xxxbobx0... 0x0080: 7569 644e 756d 6265 7231 0704 0533 3835 uidNumber1...385 0x0090: 3338 301f 040d 686f 6d65 4469 7265 6374 380...homeDirect 0x00a0: 6f72 7931 0e04 0c2f 6e6f 6e65 7869 7374 ory1.../nonexist 0x00b0: 656e 74 ent I will spare you the packet dump, but in the cases where the login works correctly, LDAP returns the values in the same order that they are requested in. This behaviour has been found with both OpenLDAP: slapd 2.3.39 and OpenLDAP: slapd 2.4.17, and is consistent with standard LDAP behaviour (ie, there is no guaranteed ordering in the LDAP database). A brief look at the code, seems to indicate that the values are being pulled from the LDAP return struct in a step-wise manner, which could certainly put them out of sync with the request if it is assumed that they will always be returned in the same order....This is just based on a quick review of the code though, and not any detailed tracing. Here is the obligatory dovecot -n: # 1.2.11: /usr/local/etc/dovecot.conf # OS: FreeBSD 6.4-RELEASE-p7 i386 nullfs log_path: /var/log/dovecot.log info_log_path: /var/log/dovecot-info.log protocols: pop3 pop3s imap imaps disable_plaintext_auth: no login_dir: /usr/local/var/run/dovecot/login login_executable(default): /usr/local/libexec/dovecot/imap-login login_executable(imap): /usr/local/libexec/dovecot/imap-login login_executable(pop3): /usr/local/libexec/dovecot/pop3-login first_valid_uid: 0 mail_location: maildir:/var/mail/%u mail_debug: yes mail_executable(default): /usr/local/libexec/dovecot/imap mail_executable(imap): /usr/local/libexec/dovecot/imap mail_executable(pop3): /usr/local/libexec/dovecot/pop3 mail_plugins(default): quota imap_quota mail_plugins(imap): quota imap_quota mail_plugins(pop3): quota mail_plugin_dir(default): /usr/local/lib/dovecot/imap mail_plugin_dir(imap): /usr/local/lib/dovecot/imap mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3 pop3_uidl_format(default): %08Xu%08Xv pop3_uidl_format(imap): %08Xu%08Xv pop3_uidl_format(pop3): %v.%u lda: postmaster_address: postmaster(a)ssimicro.com mail_plugins: quota log_path: info_log_path: auth default: passdb: driver: ldap args: /usr/local/etc/dovecot-ldap.conf userdb: driver: prefetch userdb: driver: ldap args: /usr/local/etc/dovecot-ldap.conf userdb: driver: passwd socket: type: listen master: path: /usr/local/var/run/dovecot/auth-master mode: 384 user: dovecot plugin: quota: maildir:User quota quota_rule: *:storage=500MB quota_rule2: Trash:storage=50MB quota_rule3: Deleted Messages:storage=50MB home: /tmp/thome and the dovecot-ldap.conf hosts = closest-ldap base = "dc=2,dc=ssi" scope = subtree auth_bind = yes pass_attrs = uid=user, homeDirectory=userdb_home,uidNumber=userdb_uid,gidNumber=userdb_gid,mailQuota=userdb_quota_rule=*:bytes=%$ user_attrs = mailQuota=quota_rule=*:bytes=%$, uidNumber=uid,gidNumber=gid pass_filter = (&(accountstatus=active)(emailaccountStatus=active)(|(uid=%u)(mailLocalAddress=%u)))

2 4

[Dovecot] Expunge Logging Patch
by James Devine 07 Jun '10

07 Jun '10

I have made some changes to the expunge logging as client->mailbox is set to NULL prior to one of the relevant calls. The change leaves mailbox in the function now and adds client. The modified patch to 1.2.11 is included.

1 0

[Dovecot] Ignoring the quota by the LDA?
by Holger Richter 07 Jun '10

07 Jun '10

Is it possible to configure dovecot in a manner that only the imap process respects the quota, and the local delivery ignores completely the quota? I think it should happen if I don't activate the quota plugin in the lda section but only in the imap section. protocol lda { ... # mail_plugins = ... } protocol imap { ... mail_plugins = quota imap_quota ... } Will it work or will it result in a big mess? I've the aim that a mail will never be rejected because the recipient is over his/her quota. Regards, Holger

3 4

Re: [Dovecot] Problems with the IMAP proxy after upgrading from dovecot 1.1.16 to 1.211
by Holger Richter 07 Jun '10

07 Jun '10

>> >> May 7 14:47:42 ttt dovecot: auth(default): >> >> worker-server(uid,yyy.yyy.yyy.yyy): Aborted: Lookup timed out >> >> May 7 14:47:42 ttt dovecot: auth-worker(default): mysql: Connected to >> >> lll.lll.lll.lll (imapauth) >> > >> > "Lookup timed out" really shouldn't be happening.. That sounds like >> > Dovecot's MySQL connections hangs after a while? You have some stateful >> > firewall between Dovecot and MySQL that drops idling connections and >> > afterwards starts dropping the connection's packets? >> >> Indeed, there is a firewall with stateful inspection between Dovecot >> and MySQL. > > Right, so the "Lookup timed out" works as intended. But I guess it > should automatically retry when that happens. There would still be that > 1 minute delay before that happens though. > >> The only workaround is a downgrade to Dovecot 1.1.20. > > Wonder what v1.1 does differently. I can't think of anything, really. > The main fundamental problem is still that mysql connection hangs and > the hang can't be detected/avoided. I think the right fix here would be > to change your firewall settings.. > >> I think my problem has to do with the changes in >> src/auth/auth-worker-server.c in changeset 8859. > > 8559:b0bc4519332f? Yep.

1 0

[Dovecot] Problems with the IMAP proxy after upgrading from dovecot 1.1.16 to 1.211
by Holger Richter 07 Jun '10

07 Jun '10

We have frequent timeout problems after upgrading our imap servers from dovecot 1.1.16 to dovecot 1.2.11. One server acts as proxy only, and the other one is the "real" imap server". The credentials for the proxy service are stored in a remote MYSQL database. There were no trouble with dovecot 1.1.16. But now, with the most recent version, we get frequent login failures. It seems dovecot reconnects too late to the MySQL database after a timeout, after sending the SQL query. Here's a piece of my log file: May 7 14:46:32 ttt dovecot: auth(default): new auth connection: pid=5136 May 7 14:46:42 ttt dovecot: auth(default): client in: AUTH^I1^IPLAIN^Iservice=imap^Isecured^Ilip=xxx.xxx.xxx.xxx^Irip=yyy.yyy.yyy.yyy^Ilport=sss^Irport=26480^Iresp=<hidden> May 7 14:46:42 ttt dovecot: auth-worker(default): sql(uid,yyy.yyy.yyy.yyy): query: SELECT NULL as password, destuser, host, 'zzz' as port, 'Y' as proxy, '0' as proxy_timeout, 'Y' as nopassword, 'Y' as nodelay from accounts where user ='uid'; May 7 14:47:42 ttt dovecot: auth(default): worker-server(uid,yyy.yyy.yyy.yyy): Aborted: Lookup timed out May 7 14:47:42 ttt dovecot: auth-worker(default): mysql: Connected to lll.lll.lll.lll (imapauth) May 7 14:47:44 ttt dovecot: auth(default): client out: FAIL^I1^Iuser=uid^Itemp May 7 14:47:49 ttt dovecot: imap-login: Disconnected (auth failed, 1 attempts): user=<uid>, method=PLAIN, rip=yyy.yyy.yyy.yyy, lip=xxx.xxx.xxx.xxx, TLS May 7 14:48:26 ttt dovecot: auth(default): new auth connection: pid=5159 May 7 14:48:47 ttt dovecot: auth(default): client in: AUTH^I1^IPLAIN^Iservice=imap^Isecured^Ilip=xxx.xxx.xxx.xxx^Irip=yyy.yyy.yyy.yyy^Ilport=sss^Irport=6243^Iresp=<hidden> May 7 14:48:47 ttt dovecot: auth-worker(default): sql(uid,yyy.yyy.yyy.yyy): query: SELECT NULL as password, destuser, host, 'zzz' as port, 'Y' as proxy, '0' as proxy_timeout, 'Y' as nopassword, 'Y' as nodelay from accounts where user ='uid'; May 7 14:48:47 ttt dovecot: auth(default): client out: OK^I1^Iuser=uid^Idestuser=luid^Ihost=mmm.mmm.mmm.mmm^Iport=zzz^Iproxy^Iproxy_timeout=0^Ipass=<hidden> May 7 14:48:47 ttt dovecot: imap-login: proxy(uid): started proxying to mmm.mmm.mmm.mmm:zzz/luid: user=<uid>, method=PLAIN, rip=yyy.yyy.yyy.yyy, lip=xxx.xxx.xxx.xxx, TLS May 7 14:48:48 ttt dovecot: imap-login: proxy(uid): disconnecting yyy.yyy.yyy.yyy As you can see, the second login attempt is always successful. Of course I've tried out various values (0, 60, 90, 300) for the proxy_timeout parameter - but without any success.

2 2

[Dovecot] authentification failure: double quotes in password
by Martin Ott 07 Jun '10

07 Jun '10

we use Passdb LDAP with authentication binds against an Active Directory Server. The problem with one of our users seems to be the usage of double quotes in his password, as the windows-login works: /var/log/dovecot-info.log auth(default): Info: ldap(testuser 77.22.xx.xxx): invalid credentials (given password: xxxxx"xxxxxxx) Which chars in passwords does the dovecot auth process not like? Is there something similar to auth_username_chars for passwords? thanks, martin

2 2

[Dovecot] Dovecot SSL/TLS on multiple interfaces ?
by Frank Bonnet 07 Jun '10

07 Jun '10

Hello I have a server which has two gigabits interfaces with different IP addresses and DNS names I would like to let IMAP(S) users access both. Is it possible to generate a SSL cert for each IP address on the same dovecot instance in the configuration file ? Thanks a lot

2 2

[Dovecot] How to autosubscribe Folder in dovecot
by mungalal2000＠indiatimes.com 07 Jun '10

07 Jun '10

Hi all, I have changed my imap server from courier to dovecot, Now i am facing problem to subscribe the existing mail folder after change of imap server by default they are showing in the unsubscribe folder list, is there any command or mechanism in dovecot to subscribe all the folder. i am using maildir format to store mail. Thanks & Regards. Munga (System Engginer) -- Click for exclusive coverage on the New Bajaj Pulsar 220 the fastest Indian bike http://www.zigwheels.com/Features/Bajaj-Pulsar-220-DTSi-Special-Coverage/Pu…

3 3

[Dovecot] raw backtrace in masses
by John Adams 06 Jun '10

06 Jun '10

Hi I've got huge amounts of May 3 15:47:37 host dovecot: [ID 583609 mail.error] IMAP(user): close(/home/user/Mail/R-Help.lock) failed: Disc quota exceeded May 3 15:47:37 host dovecot: [ID 583609 mail.error] IMAP(user): Raw backtrace: 0xb0e58 -> 0xb0894 -> 0x552b4 -> 0x55508 -> 0x55774 -> 0x55d9c -> 0x5759c -> 0x57ad0 -> 0x713cc -> 0x64284 -> 0x57be0 -> 0x71178 -> 0x6841c -> 0x76a38 -> 0x76a6c -> 0x25a08 -> 0x2afd4 -> 0x2bee4 -> 0x2bea0 -> 0x2c1f8 -> 0x2cb4c -> 0xb9450 -> 0xb8d00 -> 0x35294 -> 0x246e8 May 3 15:47:37 host dovecot: [ID 583609 mail.error] dovecot: child 3892 (imap) killed with signal 6 (core dumps disabled) May 3 15:47:49 host dovecot: [ID 583609 mail.error] IMAP(user): Raw backtrace: 0xb0e58 -> 0xb0894 -> 0x552b4 -> 0x55508 -> 0x55774 -> 0x55d9c -> 0x5759c -> 0x57ad0 -> 0x713cc -> 0x64284 -> 0x57be0 -> 0x71178 -> 0x6841c -> 0x76a38 -> 0x76a6c -> 0x25a08 -> 0x2afd4 -> 0x2bee4 -> 0x2bea0 -> 0x2c1f8 -> 0x2cb4c -> 0xb9450 -> 0xb8d00 -> 0x35294 -> 0x246e8 May 3 15:47:49 host dovecot: [ID 583609 mail.error] dovecot: child 4277 (imap) killed with signal 6 (core dumps disabled) The backtrace is always the same content. is this a disc quota problem? Dovecot is 1.2.11, managesieve patched. Thanks

3 9