Re: [Dovecot] litte problems upgrade from 1.0.x to 1.1.1
Hi,
Dovecot does not use mail messages to store folder meta-data as far as I know so I highly doubt this message was created by Dovecot (does Dovecot even send out messages except when going over quota?). Also notice the date of 2006-09-18, which is almost two years in the past. The message was probably created by some client and was somehow (willingly) ignored or flagged as deleted. Could be that upgrading Dovecot to 1.1 made the message visible again for whatever reason. and Anyway, this is most certainly not a Dovecot-internal message.
this case is really suspicious to me. don't hang on the old date 2006-09-18. I can recreate it with dovecot 1.1.1 running on my machine. I create completly new mbox, write to it and when i view mbox in console i see just this mail. After deleting (pop3) this mail with our webmailer or OutLook Express etc. I see this internal message with current date. I do not belive in Clients that put internal mesages by pop3-protocol, but what should it be else? pop/imapserver is dovecot 1.1.1 And why this case just happens by updateing from 1.0.x to 1.1.1 and not during further updates from 1.0.x to 1.0.x+1 ? If you say this is not dovecot related i have to accept this but i am a little bit doubtful...
Unfortunately i have now a more annoying error in imap processing. Sometimes it happens that dovecot seems to be out of sync. My Log says:
Jul 7 11:22:44 servername dovecot: IMAP(loginname): Next message unexpectedly lost from 156756352 Jul 7 11:22:44 servername dovecot: child 21652 (imap) killed with signal 11
Jul 4 13:41:09 servername dovecot: imap-login: Login: user=<loginname>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured Jul 4 13:41:10 servername dovecot: IMAP(loginname): Next message unexpectedly lost from 156715931 Jul 4 13:41:10 servername dovecot: IMAP(loginname): Disconnected: Logged out bytes=459/3359
Jul 4 13:41:32 servername dovecot: imap-login: Login: user=<loginname>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured Jul 4 13:41:32 servername dovecot: IMAP(loginname): Next message unexpectedly lost from 156715931 Jul 4 13:41:32 servername dovecot: IMAP(loginname): Next message unexpectedly lost from 156715931 Jul 4 13:41:32 servername dovecot: Panic: IMAP(loginname): file message-parser.c: line 770 (message_parser_parse_next_block): assertion failed: (ctx->input->eof || ctx->input->closed || ctx->input->stream_errno != 0 || ctx->broken) Jul 4 13:41:32 dd10636 dovecot: IMAP(loginname): Raw backtrace: imap [0x80c2cf0] -> imap [0x80c2d4a] -> imap [0x80c265c] -> imap(message_parser_parse_body+0) [0x80bbfa0] -> imap(index_mail_cache_parse_continue+0x22) [0x8087172] -> imap(mbox_save_continue+0x9c) [0x807054c] -> imap(mail_storage_copy+0xe4) [0x8091684 ] -> /usr/lib/dovecot/imap/lib20_mail_log_plugin.so [0xb7f5ed1a] -> imap(cmd_copy+0x1d2) [0x805a1c2] -> imap [0x805edfc] -> imap [0x805eea5] -> imap [0x805f65 5] -> imap(client_input+0x5e) [0x805f86e] -> imap(io_loop_handler_run+0x100) [0x80ca590] -> imap(io_loop_run+0x28) [0x80c9738] -> imap(main+0x46b) [0x806736b] -> /lib/libc.so.6(__libc_start_main+0xdc) [0xb7e4887c] -> imap [0x8059211] Jul 4 13:41:32 dd10636 dovecot: child 10768 (imap) killed with signal 6
Hmm, if we got more errors with 1.1.1 on our servers we have to downgrade to 1.0.15 and stop installing new version and wait for 1.1.x alltogether we have ~2000 servers, but most of them are running still 1.0.x
This is my configure-line, dovecot is packaged by my self
./configure
--prefix=/usr
--sysconfdir=/etc
--localstatedir=/var
--mandir=/usr/share/man
--with-ssl=openssl
--with-storages=mbox,maildir,raw
--with-pam
--with-passwd
This is my dovecot.conf
## Dovecot configuration file #protocols = imap imaps pop3 pop3s protocols = imap imaps pop3 pop3s ssl_disable = no ssl_cert_file = "/path/*.domainname.crt" ssl_key_file = "/path/*.domainname.com.key" ssl_ca_file = "/path/*.domainname.com.bundle.crt" disable_plaintext_auth = no syslog_facility = mail login_user = dovecot login_process_per_connection = no login_processes_count = 1 login_greeting = domainname.com mailserver ready. login_log_format_elements = user=<%u> method=%m rip=%r lip=%l %c login_log_format = %$: %s max_mail_processes = 100 verbose_proctitle = yes auth_verbose = yes mail_location = mbox:~/mail:INBOX=/var/spool/mail/%u #default_mail_env = mbox:~/mail:INBOX=/var/spool/mail/%u mail_cache_min_mail_count = 30 mmap_disable=no mail_debug=no lock_method = flock mbox_read_locks = dotlock mbox_write_locks = dotlock fcntl mbox_dirty_syncs = yes mbox_very_dirty_syncs = yes mbox_lazy_writes = no
## ## IMAP specific settings ##
protocol imap { login_executable = /usr/libexec/dovecot/imap-login imap_client_workarounds = outlook-idle netscape-eoh tb-extra-mailbox-sep delay-newmail mail_plugins = mail_log }
## ## POP3 specific settings ##
protocol pop3 { ssl_disable = no login_executable = /usr/libexec/dovecot/pop3-login mail_executable = /usr/libexec/dovecot/pop3 pop3_no_flag_updates = no pop3_uidl_format = %08Xu%08Xv pop3_client_workarounds = oe-ns-eoh outlook-no-nuls }
System is suse 10.1
Thank you Andre
On Jul 7, 2008, at 3:33 PM, Andre Hübner wrote:
Dovecot does not use mail messages to store folder meta-data as far
as I know so I highly doubt this message was created by Dovecot (does Dovecot
even send out messages except when going over quota?). Also notice the date of 2006-09-18, which is almost two years in the past. The message was
probably created by some client and was somehow (willingly) ignored or
flagged as deleted. Could be that upgrading Dovecot to 1.1 made the message
visible again for whatever reason. and Anyway, this is most certainly not a Dovecot-internal message.this case is really suspicious to me. don't hang on the old date
2006-09-18. I can recreate it with dovecot 1.1.1 running on my
machine. I create completly new mbox, write to it and when i view mbox in
console i see just this mail. After deleting (pop3) this mail with
our webmailer or OutLook Express etc. I see this internal message
with current date.
Right. Dovecot creates such a "DO NOT DELETE" mail just as UW-IMAP/
Pine does. It's created when all messages from the mbox get deleted,
so that UIDVALIDITY and NEXT-UID fields can be stored (without relying
on them staying in index files).
But these messages should be ignored by Dovecot. If the first message
of the mailbox has X-IMAP: header, it's skipped. I've really no idea
why these would only now be visible with v1.1. Perhaps v1.0 had
written buggy headers and v1.1 is more strict? I don't really know..
Can you reproduce this in any way (so that the client even sees it)?
unately i have now a more annoying error in imap processing.
Sometimes it happens that dovecot seems to be out of sync. My Log says:Jul 7 11:22:44 servername dovecot: IMAP(loginname): Next message
unexpectedly lost from 156756352
Looks like some kind of a locking problem.
Jul 7 11:22:44 servername dovecot: child 21652 (imap) killed with
signal 11
Can you get a gdb backtrace from this crash? See http://dovecot.org/bugreport.html
Jul 4 13:41:32 servername dovecot: IMAP(loginname): Next message
unexpectedly lost from 156715931 Jul 4 13:41:32 servername dovecot: Panic: IMAP(loginname): file
message-parser.c: line 770 (message_parser_parse_next_block):
assertion failed: (ctx->input->eof || ctx->input->closed || ctx->input->stream_errno != 0 || ctx->broken)
Probably related to the message changing unexpectedly..
lock_method = flock
See if it makes any difference to change this to fcntl.
mbox_read_locks = dotlock mbox_write_locks = dotlock fcntl
How do you deliver new mails to the mbox?
mbox_lazy_writes = no
Why? This makes performance worse.
System is suse 10.1
What filesystem?
Hi,
thanks for your mail :)
Right. Dovecot creates such a "DO NOT DELETE" mail just as UW-IMAP/ Pine does. It's created when all messages from the mbox get deleted, so that UIDVALIDITY and NEXT-UID fields can be stored (without relying on them staying in index files).
But these messages should be ignored by Dovecot. If the first message of the mailbox has X-IMAP: header, it's skipped. I've really no idea why these would only now be visible with v1.1. Perhaps v1.0 had written buggy headers and v1.1 is more strict? I don't really know.. Can you reproduce this in any way (so that the client even sees it)?
no, unfortunately not. i tried to copy internal mesages to newly created mboxes and played a little bit but could not reproduce this behavior. ok, its annoying but explainable to users. as long it is a one time feature i can live with it... ;)
interesting is that those old internal-message (mbox created 2006|2007 etc.) is still unchanged in empty mbox even when it was deliverd a thousend times...
more problematical is my still occuring issue with kills/craches in imap-section.
Looks like some kind of a locking problem.
it appears directly when reading some messages using imap-protokoll. a lot of mesages are ok but one is creating this line in maillog
Jul 14 15:38:48 servername dovecot: IMAP(loginname): Next message unexpectedly lost from 6693538
this happens on all my dovecot 1.1.1 servers with some messages in imap-server.
Can you get a gdb backtrace from this crash? See http://dovecot.org/bugreport.html
hmm, unfortunately not. i edited dovecot.conf for debuginfo which is written in maillog. but i do not find any coredump. :(
this is dovecot -n
# 1.1.1: /etc/dovecot.conf protocols: imap imaps pop3 pop3s ssl_ca_file: /path/path/*.myservername.com.bundle.crt ssl_cert_file: /path/path/*.myservername.com.crt ssl_key_file: /path/path/*.myservername.com.key disable_plaintext_auth: no login_dir: /var/run/dovecot/login login_executable(default): /usr/libexec/dovecot/imap-login login_executable(imap): /usr/libexec/dovecot/imap-login login_executable(pop3): /usr/libexec/dovecot/pop3-login login_greeting: myservername.com mailserver ready. login_process_per_connection: no login_processes_count: 1 max_mail_processes: 100 verbose_proctitle: yes mail_location: mbox:~/mail:INBOX=/var/spool/mail/%u mail_cache_min_mail_count: 30 mail_debug: yes mbox_read_locks: dotlock mbox_very_dirty_syncs: yes mail_drop_priv_before_exec: yes mail_executable(default): /usr/libexec/dovecot/imap mail_executable(imap): /usr/libexec/dovecot/imap mail_executable(pop3): /usr/libexec/dovecot/pop3 mail_plugins(default): mail_log mail_plugins(imap): mail_log mail_plugins(pop3): mail_plugin_dir(default): /usr/lib/dovecot/imap mail_plugin_dir(imap): /usr/lib/dovecot/imap mail_plugin_dir(pop3): /usr/lib/dovecot/pop3 imap_client_workarounds(default): outlook-idle netscape-eoh tb-extra-mailbox-sep delay-newmail imap_client_workarounds(imap): outlook-idle netscape-eoh tb-extra-mailbox-sep delay-newmail imap_client_workarounds(pop3): pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): oe-ns-eoh outlook-no-nuls auth default: verbose: yes passdb: driver: shadow userdb: driver: passwd
Jul 4 13:41:32 servername dovecot: IMAP(loginname): Next message unexpectedly lost from 156715931 Jul 4 13:41:32 servername dovecot: Panic: IMAP(loginname): file message-parser.c: line 770 (message_parser_parse_next_block): assertion failed: (ctx->input->eof || ctx->input->closed || ctx->input->stream_errno != 0 || ctx->broken)
Probably related to the message changing unexpectedly..
it happens every day. current example, this is a complete sequenz:
Jul 14 16:08:31 servername dovecot: imap-login: Login: user=<thisuser>, method=PLAIN, rip=85.13.133.104, lip=85.13.133.104, secured Jul 14 16:08:31 servername dovecot: IMAP(thisuser): Loading modules from directory: /usr/lib/dovecot/imap Jul 14 16:08:31 servername dovecot: IMAP(thisuser): Module loaded: /usr/lib/dovecot/imap/lib20_mail_log_plugin.so Jul 14 16:08:31 servername dovecot: IMAP(thisuser): Effective uid=504, gid=501, home=/home/popuser/thisuser Jul 14 16:08:31 servername dovecot: IMAP(thisuser): mbox: data=/home/popuser/thisuser/mail:INBOX=/var/spool/mail/thisuser Jul 14 16:08:31 servername dovecot: IMAP(thisuser): fs: root=/home/popuser/thisuser/mail, index=, control=, inbox=/var/spool/mail/thisuser Jul 14 16:08:31 servername dovecot: IMAP(thisuser): Next message unexpectedly lost from 6693538 Jul 14 16:08:31 servername dovecot: IMAP(thisuser): Next message unexpectedly lost from 6693538 Jul 14 16:08:31 servername dovecot: Panic: IMAP(thisuser): file message-parser.c: line 770 (message_parser_parse_next_block): assertion failed: (ctx->input->eof || ctx->input->closed || ctx->input->stream_errno != 0 || ctx->broken) Jul 14 16:08:31 servername dovecot: IMAP(thisuser): Raw backtrace: imap [0x80c2cf0] -> imap [0x80c2d4a] -> imap [0x80c265c] -> imap(message_parser_parse_body+0) [0x80bbfa0] -> imap(index_mail_cache_parse_continue+0x22) [0x8087172] -> imap [0x8070441] -> imap(mbox_save_continue+0x2d) [0x80704dd] -> imap(mail_storage_co py+0xe4) [0x8091684] -> /usr/lib/dovecot/imap/lib20_mail_log_plugin.so [0xb7f65d1a] -> imap(cmd_copy+0x1d2) [0x805a1c2] -> imap [0x805edfc] -> imap [0x805eea5 ] -> imap [0x805f655] -> imap(client_input+0x5e) [0x805f86e] -> imap(io_loop_handler_run+0x100) [0x80ca590] -> imap(io_loop_run+0x28) [0x80c9738] -> imap(main +0x46b) [0x806736b] -> /lib/libc.so.6(__libc_start_main+0xdc) [0xb7e4f87c] -> imap [0x8059211] Jul 14 16:08:31 servername dovecot: child 7162 (imap) killed with signal 6
lock_method = flock
See if it makes any difference to change this to fcntl. changed to fcntl, no difference.
How do you deliver new mails to the mbox? mails that arrive will be deliverd by procmail, relevant line in /etc/postfix/main.cf is:
mailbox_command = /usr/bin/procmail :)
mbox_lazy_writes = no
Why? This makes performance worse. hmm, may be a kind of historical relict by my forerunner, now it is changed. thanks.
System is suse 10.1
What filesystem? we use xfs
hmm, what can i do now? i wonder why no coredump is created to be more helpful for debugging. i did follow the bugreport.html Hope there is some further help, dovecot is a great software which we want to use further on.
Thank you Andre
Hi,
Can you get a gdb backtrace from this crash? See http://dovecot.org/bugreport.html
additional to my last mail now a cordump was created
this is dovecot -n
# 1.1.1: /etc/dovecot.conf protocols: imap imaps pop3 pop3s ssl_ca_file: /path/path/*.myservername.com.bundle.crt ssl_cert_file: /path/path/*.myservername.com.crt ssl_key_file: /path/path/*.myservername.com.key disable_plaintext_auth: no login_dir: /var/run/dovecot/login login_executable(default): /usr/libexec/dovecot/imap-login login_executable(imap): /usr/libexec/dovecot/imap-login login_executable(pop3): /usr/libexec/dovecot/pop3-login login_greeting: myservername.com mailserver ready. login_process_per_connection: no login_processes_count: 1 max_mail_processes: 100 verbose_proctitle: yes mail_location: mbox:~/mail:INBOX=/var/spool/mail/%u mail_cache_min_mail_count: 30 mail_debug: yes mbox_read_locks: dotlock mbox_very_dirty_syncs: yes mail_drop_priv_before_exec: yes mail_executable(default): /usr/libexec/dovecot/imap mail_executable(imap): /usr/libexec/dovecot/imap mail_executable(pop3): /usr/libexec/dovecot/pop3 mail_plugins(default): mail_log mail_plugins(imap): mail_log mail_plugins(pop3): mail_plugin_dir(default): /usr/lib/dovecot/imap mail_plugin_dir(imap): /usr/lib/dovecot/imap mail_plugin_dir(pop3): /usr/lib/dovecot/pop3 imap_client_workarounds(default): outlook-idle netscape-eoh tb-extra-mailbox-sep delay-newmail imap_client_workarounds(imap): outlook-idle netscape-eoh tb-extra-mailbox-sep delay-newmail imap_client_workarounds(pop3): pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): oe-ns-eoh outlook-no-nuls auth default: verbose: yes passdb: driver: shadow userdb: driver: passwd
lines in log:
Jul 16 08:45:55 servername dovecot: IMAP(user): Loading modules from directory: /usr/lib/dovecot/imap Jul 16 08:45:55 servername dovecot: imap-login: Login: user=<user>, method=PLAIN, rip=85.13.133.104, lip=85.13.133.104, secured Jul 16 08:45:55 servername dovecot: IMAP(user): Module loaded: /usr/lib/dovecot/imap/lib20_mail_log_plugin.so Jul 16 08:45:55 servername dovecot: IMAP(user): Effective uid=504, gid=501, home=/home/popuser/user Jul 16 08:45:55 servername dovecot: IMAP(user): mbox: data=/home/popuser/user/mail:INBOX=/var/spool/mail/user Jul 16 08:45:55 servername dovecot: IMAP(user): fs: root=/home/popuser/user/mail, index=, control=, inbox=/var/spool/mail/user Jul 16 08:45:55 servername dovecot: IMAP(user): Next message unexpectedly lost from 6693538 Jul 16 08:45:55 servername dovecot: IMAP(user): Next message unexpectedly lost from 6693538 Jul 16 08:45:55 servername dovecot: Panic: IMAP(user): file message-parser.c: line 770 (message_parser_parse_next_block): assertion failed: (ctx->input->eof || ctx->input->closed || ctx->input->stream_errno != 0 || ctx->broken) Jul 16 08:45:55 servername dovecot: IMAP(user): Raw backtrace: imap [0x80c2cf0] -> imap [0x80c2d4a] -> imap [0x80c265c] -> imap(message_parser_parse_body+0) [0x80bbfa0] -> imap(index_mail_cache_parse_continue+0x22) [0x8087172] -> imap(mbox_save_continue+0x9c) [0x807054c] -> imap(mail_storage_copy+0xe4) [0x8091684] -> /usr/lib/dovecot/imap/lib20_mail_log_plugin.so [0xb7f88d1a] -> imap(cmd_copy+0x1d2) [0x805a1c2] -> imap [0x805edfc] -> imap [0x805eea5] -> imap [0x805f655 ] -> imap(client_input+0x5e) [0x805f86e] -> imap(io_loop_handler_run+0x100) [0x80ca590] -> imap(io_loop_run+0x28) [0x80c9738] -> imap(main+0x46b) [0x806736b] -> /lib/libc.so.6(__libc_start_main+0xdc) [0xb7e7287c] -> imap [0x8059211] Jul 16 08:45:55 servername dovecot: child 26263 (imap) killed with signal 6
gdb output:
gdb /usr/libexec/dovecot/imap /home/popuser/user/core GNU gdb 6.4 Copyright 2005 Free Software Foundation, Inc. GDB is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Type "show copying" to see the conditions. There is absolutely no warranty for GDB. Type "show warranty" for details. This GDB was configured as "i586-suse-linux"...Using host libthread_db library "/lib/libthread_db.so.1".
warning: exec file is newer than core file. Core was generated by `imap [user 85.13.133.104]'. Program terminated with signal 6, Aborted.
warning: Can't read pathname for load map: Eingabe-/Ausgabefehler.
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /usr/lib/dovecot/imap/lib20_mail_log_plugin.so...done.
Loaded symbols for /usr/lib/dovecot/imap/lib20_mail_log_plugin.so
Reading symbols from /lib/libnss_files.so.2...done.
Loaded symbols for /lib/libnss_files.so.2
Reading symbols from /lib/libgcc_s.so.1...done.
Loaded symbols for /lib/libgcc_s.so.1
#0 0xffffe410 in __kernel_vsyscall ()
(gdb) bt full
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7e857d0 in raise () from /lib/libc.so.6
No symbol table info available.
#2 0xb7e86ea3 in abort () from /lib/libc.so.6
No symbol table info available.
#3 0x080c2cfd in fd_debug_verify_leaks (first_fd=135383096, last_fd=0) at
fd-close-on-exec.c:32
addr = {family = 11517, u = {ip6 = {in6_u = {u6_addr8 =
"AM\016\bx\005\017\bÌ_\r\bý\v\b", u6_addr16 = {19777, 2062, 1400, 2063,
24524, 2061, 48579,
2059}, u6_addr32 = {135155009, 135202168, 135094220, 134987203}}},
ip4 = {s_addr = 135155009}}}
raddr = {family = 0, u = {ip6 = {in6_u = {u6_addr8 =
"\001\000\000\000\000\000\000\0008È\021\b\230H¯¿", u6_addr16 = {1, 0, 0, 0,
51256, 2065, 18584,
49071}, u6_addr32 = {1, 0, 135383096, 3215935640}}}, ip4 = {s_addr
= 1}}}
port = <value optimized out>
rport = <value optimized out>
st = {st_dev = 0, __pad1 = 0, __st_ino = 0, st_mode = 0, st_nlink =
0, st_uid = 0, st_gid = 0, st_rdev = 0, __pad2 = 0, st_size = 0, st_blksize
= 0,
st_blocks = 0, st_atim = {tv_sec = 0, tv_nsec = 0}, st_mtim = {tv_sec = 0,
tv_nsec = 0}, st_ctim = {tv_sec = 0, tv_nsec = 0}, st_ino = 0}
old_errno = <value optimized out>
#4 0x080c2d4a in fd_debug_verify_leaks (first_fd=0, last_fd=4) at
fd-close-on-exec.c:44
sa = {sun_family = 0,
sun_path =
"\210\t\017\btH¯¿E\000\000\000ÈG¯¿¶\025\f\b;\f\017\bäG¯¿@H¯¿Øvú·B\a\005\b\224\226g\000\224\002\000\001\000\000\000\000\030H¯¿\224\002\000\000èG¯¿
", '\0'
##############
i see you did a lot of patches, hope this helps :) Thank you Andre
On Mon, 2008-07-21 at 11:59 +0200, Andre Hübner wrote:
Jul 16 08:45:55 servername dovecot: Panic: IMAP(user): file message-parser.c: line 770 (message_parser_parse_next_block): assertion failed: (ctx->input->eof || ctx->input->closed || ctx->input->stream_errno != 0 || ctx->broken)
Line 770.
#6 0x080bbfa0 in message_parser_parse_header (ctx=0xbfaf4920, hdr_size=0xbfaf4920, callback=0, context=0x19) at message-parser.c:798
Line 798.
This backtrace is from a different crash I suppose?
Servus,
Jul 16 08:45:55 servername dovecot: Panic: IMAP(user): file message-parser.c: line 770 (message_parser_parse_next_block): assertion failed: (ctx->input->eof || ctx->input->closed || ctx->input->stream_errno != 0 || ctx->broken)
Line 770.
#6 0x080bbfa0 in message_parser_parse_header (ctx=0xbfaf4920, hdr_size=0xbfaf4920, callback=0, context=0x19) at message-parser.c:798
Line 798.
This backtrace is from a different crash I suppose?
Nope, all data in this mail today at 11:59 am are the same crash
- core-dump was created exactly at this time --> Jul 16 08:45:55 servername dovecot: child 26263 (imap) killed with signal 6
- user in mailog which produced the error and location of coredump ist correct. i do not know why this output of different lines, but its the same crash.
Thank you Andre
participants (2)
-
Andre Hübner
-
Timo Sirainen