[Dovecot] dovecot-1.1 + dovecot-sieve-1.1 deliver backtraces
Hi, I am trying dovecot-1.1 with dovecot-sieve-1.1. First, dovecot -n do not report about deliver settings. They are:
protocol lda { postmaster_address = postmaster@parkheights.dyndns.org hostname = parkheights.dyndns.org mail_plugins = cmusieve mail_plugin_dir = /usr/lib64/dovecot11/modules/lda sendmail_path = /usr/lib/sendmail auth_socket_path = /var/run/dovecot11/auth-master }
Then, $ sudo /usr/sbin/dovecot11 -n # 1.1.alpha1: /etc/dovecot11/dovecot11.conf base_dir: /var/run/dovecot11/ log_path: /tmp/dovecot11.log info_log_path: /tmp/dovecot11.debug protocols: imap imaps pop3 pop3s listen(default): *:143 listen(imap): *:143 listen(pop3): *:110 ssl_listen(default): *:993 ssl_listen(imap): *:993 ssl_listen(pop3): *:995 ssl_cert_file: /etc/ssl/parkheights.cert ssl_key_file: /etc/ssl/parkheights.key login_dir: /var/run/dovecot11/login login_executable(default): /usr/lib64/dovecot11/imap-login login_executable(imap): /usr/lib64/dovecot11/imap-login login_executable(pop3): /usr/lib64/dovecot11/pop3-login mail_extra_groups: mail mail_location: maildir:/var/spool/imap/%n/.imap mail_debug: yes mail_executable(default): /usr/lib64/dovecot11/imap mail_executable(imap): /usr/lib64/dovecot11/imap mail_executable(pop3): /usr/lib64/dovecot11/pop3 mail_plugin_dir(default): /usr/lib64/dovecot11/modules/imap mail_plugin_dir(imap): /usr/lib64/dovecot11/modules/imap mail_plugin_dir(pop3): /usr/lib64/dovecot11/modules/pop3 auth default: debug: yes debug_passwords: yes passdb: driver: passwd-file args: /etc/dovecot/dovecot.passwd userdb: driver: static args: uid=1927 gid=1927 home=/var/spool/imap/%n userdb: driver: passwd-file args: /etc/dovecot/dovecot.passwd socket: type: listen client: path: /var/spool/postfix/private/auth mode: 432 user: postfix group: postfix master: path: /var/run/dovecot11/auth-master mode: 384 user: vmail group: vmail
Couple of backtraces from /tmp/dovecot11.log are here. I will try to attach them as a textfile to this message, so that lines will not be wrapped, but I'm not sure that attachements are not stripped. So, please excuse me for duplication in this case.
dovecot: Jul 25 01:05:19 Error: IMAP(seriv): Corrupted index cache file /var/spool/imap/seriv/.imap/.community-lists-altlinux-org/dovecot.index.cache: Corrupted cach ed message_part data (physical_pos less than expected) deliver(seriv): Jul 25 04:17:26 Panic: seq = 1587, rec->uid = 0, first_new_seq = 1587, records = 1586 deliver(seriv): Jul 25 04:17:26 Error: Raw backtrace: /usr/lib64/dovecot11/deliver [0x46e045] -> /usr/lib64/dovecot11/deliver [0x46dd2c] -> /usr/lib64/dovecot11/deli ver [0x44de1e] -> /usr/lib64/dovecot11/deliver [0x44e687] -> /usr/lib64/dovecot11/deliver(index_transaction_finish_commit+0x28) [0x444488] -> /usr/lib64/dovecot11/de liver [0x41f53f] -> /usr/lib64/dovecot11/deliver(index_transaction_commit+0x38) [0x4442f8] -> /usr/lib64/dovecot11/deliver(mailbox_transaction_commit+0x11) [0x45f221 ] -> /usr/lib64/dovecot11/deliver(deliver_save+0x107) [0x414267] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab20987b] -> /usr/lib64/dovecot1 1/modules/lda/lib90_cmusieve_plugin.so(sieve_execute_bytecode+0x6b8) [0x2aaaab219dc8] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so(cmu_sieve_run+0x30 b) [0x2aaaab20a35b] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab208806] -> /usr/lib64/dovecot11/deliver(main+0xc4e) [0x41505e] -> /lib64/li bc.so.6(__libc_start_main+0xf4) [0x2aaaaaee5c14] -> /usr/lib64/dovecot11/deliver [0x413739] deliver(seriv): Jul 25 04:17:26 Panic: seq = 1587, rec->uid = 0, first_new_seq = 1587, records = 1586 deliver(seriv): Jul 25 04:17:26 Error: Raw backtrace: /usr/lib64/dovecot11/deliver [0x46e045] -> /usr/lib64/dovecot11/deliver [0x46dd2c] -> /usr/lib64/dovecot11/deli ver [0x44de1e] -> /usr/lib64/dovecot11/deliver [0x44e687] -> /usr/lib64/dovecot11/deliver(index_transaction_finish_commit+0x28) [0x444488] -> /usr/lib64/dovecot11/de liver [0x41f53f] -> /usr/lib64/dovecot11/deliver(index_transaction_commit+0x38) [0x4442f8] -> /usr/lib64/dovecot11/deliver(mailbox_transaction_commit+0x11) [0x45f221 ] -> /usr/lib64/dovecot11/deliver(deliver_save+0x107) [0x414267] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab20987b] -> /usr/lib64/dovecot1 1/modules/lda/lib90_cmusieve_plugin.so(sieve_execute_bytecode+0x6b8) [0x2aaaab219dc8] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so(cmu_sieve_run+0x30 b) [0x2aaaab20a35b] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab208806] -> /usr/lib64/dovecot11/deliver(main+0xc4e) [0x41505e] -> /lib64/li bc.so.6(__libc_start_main+0xf4) [0x2aaaaaee5c14] -> /usr/lib64/dovecot11/deliver [0x413739] dovecot: Jul 25 06:52:21 Error: IMAP(seriv): Corrupted index cache file /var/spool/imap/seriv/.imap/.sisyphus-lists-altlinux-org/dovecot.index.cache: Corrupted cache d message_part data (physical_pos less than expected)
-- With best regards, Sergey.
dovecot: Jul 25 01:05:19 Error: IMAP(seriv): Corrupted index cache file /var/spool/imap/seriv/.imap/.community-lists-altlinux-org/dovecot.index.cache: Corrupted cach ed message_part data (physical_pos less than expected) deliver(seriv): Jul 25 04:17:26 Panic: seq = 1587, rec->uid = 0, first_new_seq = 1587, records = 1586 deliver(seriv): Jul 25 04:17:26 Error: Raw backtrace: /usr/lib64/dovecot11/deliver [0x46e045] -> /usr/lib64/dovecot11/deliver [0x46dd2c] -> /usr/lib64/dovecot11/deli ver [0x44de1e] -> /usr/lib64/dovecot11/deliver [0x44e687] -> /usr/lib64/dovecot11/deliver(index_transaction_finish_commit+0x28) [0x444488] -> /usr/lib64/dovecot11/de liver [0x41f53f] -> /usr/lib64/dovecot11/deliver(index_transaction_commit+0x38) [0x4442f8] -> /usr/lib64/dovecot11/deliver(mailbox_transaction_commit+0x11) [0x45f221 ] -> /usr/lib64/dovecot11/deliver(deliver_save+0x107) [0x414267] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab20987b] -> /usr/lib64/dovecot1 1/modules/lda/lib90_cmusieve_plugin.so(sieve_execute_bytecode+0x6b8) [0x2aaaab219dc8] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so(cmu_sieve_run+0x30 b) [0x2aaaab20a35b] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab208806] -> /usr/lib64/dovecot11/deliver(main+0xc4e) [0x41505e] -> /lib64/li bc.so.6(__libc_start_main+0xf4) [0x2aaaaaee5c14] -> /usr/lib64/dovecot11/deliver [0x413739] deliver(seriv): Jul 25 04:17:26 Panic: seq = 1587, rec->uid = 0, first_new_seq = 1587, records = 1586 deliver(seriv): Jul 25 04:17:26 Error: Raw backtrace: /usr/lib64/dovecot11/deliver [0x46e045] -> /usr/lib64/dovecot11/deliver [0x46dd2c] -> /usr/lib64/dovecot11/deli ver [0x44de1e] -> /usr/lib64/dovecot11/deliver [0x44e687] -> /usr/lib64/dovecot11/deliver(index_transaction_finish_commit+0x28) [0x444488] -> /usr/lib64/dovecot11/de liver [0x41f53f] -> /usr/lib64/dovecot11/deliver(index_transaction_commit+0x38) [0x4442f8] -> /usr/lib64/dovecot11/deliver(mailbox_transaction_commit+0x11) [0x45f221 ] -> /usr/lib64/dovecot11/deliver(deliver_save+0x107) [0x414267] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab20987b] -> /usr/lib64/dovecot1 1/modules/lda/lib90_cmusieve_plugin.so(sieve_execute_bytecode+0x6b8) [0x2aaaab219dc8] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so(cmu_sieve_run+0x30 b) [0x2aaaab20a35b] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab208806] -> /usr/lib64/dovecot11/deliver(main+0xc4e) [0x41505e] -> /lib64/li bc.so.6(__libc_start_main+0xf4) [0x2aaaaaee5c14] -> /usr/lib64/dovecot11/deliver [0x413739] dovecot: Jul 25 06:52:21 Error: IMAP(seriv): Corrupted index cache file /var/spool/imap/seriv/.imap/.sisyphus-lists-altlinux-org/dovecot.index.cache: Corrupted cache d message_part data (physical_pos less than expected)
On 25.7.2007, at 17.18, Sergey wrote:
dovecot: Jul 25 01:05:19 Error: IMAP(seriv): Corrupted index cache
file /var/spool/imap/seriv/.imap/.community-lists-altlinux-org/ dovecot.index.cache: Corrupted cach ed message_part data (physical_pos less than expected)
Hmm. This is probably a new bug..
deliver(seriv): Jul 25 04:17:26 Panic: seq = 1587, rec->uid = 0, first_new_seq = 1587, records = 1586
But this crash is in mbox rewriting code which hasn't really changed
since v1.0.
Can you easily reproduce both of these? How? Are you using deliver
also with v1.0? Doesn't it crash?
Timo Sirainen wrote:
On 25.7.2007, at 17.18, Sergey wrote:
dovecot: Jul 25 01:05:19 Error: IMAP(seriv): Corrupted index cache file /var/spool/imap/seriv/.imap/.community-lists-altlinux-org/dovecot.index.cache:
Corrupted cach ed message_part data (physical_pos less than expected)
Hmm. This is probably a new bug..
deliver(seriv): Jul 25 04:17:26 Panic: seq = 1587, rec->uid = 0, first_new_seq = 1587, records = 1586
But this crash is in mbox rewriting code which hasn't really changed since v1.0.
Can you easily reproduce both of these? How? Are you using deliver also with v1.0? Doesn't it crash?
I have there 2 dovecots and 2 dovecot-sieve plugins installed in parallel. So, it may be just error in installing, so that some file confusion. My previous attempt, when I forgot to change in dovecot11.conf line '/usr/lib64/dovecot11/modules/lda' and it was pointing to lda of dovecot-1.0.2, has a very reproducible problem: deliver crashed at every message :-) Dovecot-1.0.2 has the same sieve script and works perfect. I had during last hours only 5 backtraces, with corresponding lines in postfix' log like the following:
Jul 25 08:11:12 mx01 postfix/qmgr[12199]: 5B8CF534C2E: from=sisyphus-bounces@lists.altlinux.org, size=5343, nrcpt=1 (queue active) Jul 25 08:11:12 mx01 postfix/pipe[14290]: 5B8CF534C2E: to=seriv@parkheights.dyndns.org, relay=dovecot11, delay=0.32, delays=0.29/0/0/0.03, dsn=5.3.0, status=bounced (Command died with signal 6: "/usr/lib64/dovecot11/deliver") Jul 25 08:11:12 mx01 postfix/cleanup[14198]: 9D88D534BD9: message-id=20070725121112.9D88D534BD9@mx01.menlo Jul 25 08:11:12 mx01 postfix/qmgr[12199]: 9D88D534BD9: from=<>, size=7080, nrcpt=1 (queue active) Jul 25 08:11:12 mx01 postfix/bounce[15778]: 5B8CF534C2E: sender non-delivery notification: 9D88D534BD9 Jul 25 08:11:12 mx01 postfix/qmgr[12199]: 5B8CF534C2E: removed
Total number of messages delivered by dovecot11-deliver are 240, so I'm not sure I can reproduce it quickly. I'll try to get coredumps of deliver.
Sergey.Sergey wrote:
Timo Sirainen wrote:
On 25.7.2007, at 17.18, Sergey wrote:
dovecot: Jul 25 01:05:19 Error: IMAP(seriv): Corrupted index cache file /var/spool/imap/seriv/.imap/.community-lists-altlinux-org/dovecot.index.cache:
Corrupted cach ed message_part data (physical_pos less than expected) Hmm. This is probably a new bug..
deliver(seriv): Jul 25 04:17:26 Panic: seq = 1587, rec->uid = 0, first_new_seq = 1587, records = 1586 But this crash is in mbox rewriting code which hasn't really changed since v1.0.
Can you easily reproduce both of these? How? Are you using deliver also with v1.0? Doesn't it crash?
I have there 2 dovecots and 2 dovecot-sieve plugins installed in parallel. So, it may be just error in installing, so that some file confusion. My previous attempt, when I forgot to change in dovecot11.conf line '/usr/lib64/dovecot11/modules/lda' and it was pointing to lda of dovecot-1.0.2, has a very reproducible problem: deliver crashed at every message :-) Dovecot-1.0.2 has the same sieve script and works perfect. I had during last hours only 5 backtraces, with corresponding lines in postfix' log like the following:
Jul 25 08:11:12 mx01 postfix/qmgr[12199]: 5B8CF534C2E: from=sisyphus-bounces@lists.altlinux.org, size=5343, nrcpt=1 (queue active) Jul 25 08:11:12 mx01 postfix/pipe[14290]: 5B8CF534C2E: to=seriv@parkheights.dyndns.org, relay=dovecot11, delay=0.32, delays=0.29/0/0/0.03, dsn=5.3.0, status=bounced (Command died with signal 6: "/usr/lib64/dovecot11/deliver") Jul 25 08:11:12 mx01 postfix/cleanup[14198]: 9D88D534BD9: message-id=20070725121112.9D88D534BD9@mx01.menlo Jul 25 08:11:12 mx01 postfix/qmgr[12199]: 9D88D534BD9: from=<>, size=7080, nrcpt=1 (queue active) Jul 25 08:11:12 mx01 postfix/bounce[15778]: 5B8CF534C2E: sender non-delivery notification: 9D88D534BD9 Jul 25 08:11:12 mx01 postfix/qmgr[12199]: 5B8CF534C2E: removed
Total number of messages delivered by dovecot11-deliver are 240, so I'm not sure I can reproduce it quickly. I'll try to get coredumps of deliver. I have 4 new backtraces logged into /tmp/dovecot.log. I have added line "mail_drop_priv_before_exec: yes" to dovecot11.conf, and verified that userdb, both static and from passwd file, returns user homes, and these homes are owned by user vmail specified in /etc/postfix/master.cf to run dovecot11 service. And can't find any core files written anywhere. What I'm missing? How to get coredumps of delivery agent?
I have read once more wiki pages about using dovecot delivery, and discovered that postfix configuration is missing a line
dovecot11_destination_recipient_limit = 1
May be, it's related to the problem? It looks like last cases of the problem occur at the time of bursts of mails arriving to postfix. I have added this line and will continue testing.
-- Sergey.
Sergey wrote:
Sergey wrote: [skip] I have added line "mail_drop_priv_before_exec: yes" to dovecot11.conf, and verified that userdb, both static and from passwd file, returns user homes, and these homes are owned by user vmail specified in /etc/postfix/master.cf to run dovecot11 service. And can't find any core files written anywhere. What I'm missing? How to get coredumps of delivery agent?
I have read once more wiki pages about using dovecot delivery, and discovered that postfix configuration is missing a line
dovecot11_destination_recipient_limit = 1
May be, it's related to the problem? It looks like last cases of the problem occur at the time of bursts of mails arriving to postfix. I have added this line and will continue testing.
Last night I put high load on the server, and got 250 backtraces in dovecot.log, So, destination_recipient_limit=1 did not help. I do not know how to get core files of delivery. So, I do not know how can I help with fixing this problem. Switched back to dovecot-1.0.2, got many messages like:
dovecot: Jul 27 06:36:16 Error: IMAP(seriv): Transaction log file /var/spool/imap/seriv/.imap/dovecot.index.log: marked corrupted dovecot: Jul 27 06:36:16 Error: IMAP(seriv): Corrupted transaction log file /var/spool/imap/seriv/.imap/dovecot.index.log: Recent counter wrong
Deleted all dovecot.index* in /var/spool/imap, and everything looks working well.
Sergey.I've tried dovecot-1.1-alpha3 (actually pulled from hg://hg.dovecot.org/dovecot changeset 6289:4a57baddc8b8) and dovecot-sieve from changeset 34:0367450c9382, and got problems:
$tail -2 /tmp/dovecot11.log deliver(seriv): Aug 13 17:21:17 Panic: file index-mail-headers.c: line 590 (index_mail_get_raw_headers): assertion failed: (ret != -1) deliver(seriv): Aug 13 17:21:17 Error: Raw backtrace: /usr/lib64/dovecot11/deliver [0x46e5f5] -> /usr/lib64/dovecot11/deliver [0x46e2dc] -> /usr/lib64/dovecot11/deliver [0x43f3da] -> /usr/lib64/dovecot11/deliver(index_mail_get_first_header+0x25) [0x43f675] -> /usr/lib64/dovecot11/deliver(deliver_get_return_address+0x1d) [0x41416d] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so(cmu_sieve_run+0x2ac) [0x2aaaab20a31c] -> /usr/lib64/dovecot11/modules/lda/lib90_cmusieve_plugin.so [0x2aaaab208806] -> /usr/lib64/dovecot11/deliver(main+0xc52) [0x4150f2] -> /lib64/libc.so.6(__libc_start_main+0xf4) [0x2aaaaaee5c14] -> /usr/lib64/dovecot11/deliver [0x4137d9]
$ sudo /usr/sbin/dovecot11 -n # 1.1.alpha3: /etc/dovecot11/dovecot11.conf base_dir: /var/run/dovecot11/ log_path: /tmp/dovecot11.log info_log_path: /tmp/dovecot11.debug protocols: imap imaps pop3 pop3s listen(default): *:143 listen(imap): *:143 listen(pop3): *:110 ssl_listen(default): *:993 ssl_listen(imap): *:993 ssl_listen(pop3): *:995 ssl_cert_file: /etc/ssl/parkheights.cert ssl_key_file: /etc/ssl/parkheights.key login_dir: /var/run/dovecot11/login login_executable(default): /usr/lib64/dovecot11/imap-login login_executable(imap): /usr/lib64/dovecot11/imap-login login_executable(pop3): /usr/lib64/dovecot11/pop3-login mail_extra_groups: mail mail_location: maildir:/var/spool/imap/%n/.imap mail_debug: yes mail_drop_priv_before_exec: yes mail_executable(default): /usr/lib64/dovecot11/imap mail_executable(imap): /usr/lib64/dovecot11/imap mail_executable(pop3): /usr/lib64/dovecot11/pop3 mail_plugin_dir(default): /usr/lib64/dovecot11/modules/imap mail_plugin_dir(imap): /usr/lib64/dovecot11/modules/imap mail_plugin_dir(pop3): /usr/lib64/dovecot11/modules/pop3 auth default: debug: yes debug_passwords: yes passdb: driver: passwd-file args: /etc/dovecot/dovecot.passwd userdb: driver: static args: uid=1927 gid=1927 home=/var/spool/imap/%n userdb: driver: passwd-file args: /etc/dovecot/dovecot.passwd socket: type: listen client: path: /var/spool/postfix/private/auth mode: 432 user: postfix group: postfix master: path: /var/run/dovecot11/auth-master mode: 384 user: vmail group: vmail
and the part of dovecot.conf corresponding to dovecot-sieve module is the following:
protocol lda { postmaster_address = postmaster@parkheights.dyndns.org hostname = parkheights.dyndns.org mail_plugins = cmusieve mail_plugin_dir = /usr/lib64/dovecot11/modules/lda sendmail_path = /usr/lib/sendmail auth_socket_path = /var/run/dovecot11/auth-master }
WBR,
Sergey Ivanov
participants (2)
-
Sergey
-
Timo Sirainen