Panic: file istream.c: line 167 with 2.2.13 + istream.c/.h from dovecot-2-2-dffc6dd2be0d
Hi,
Getting following panics with traces: Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Cached message size smaller than expected (1782 < 1872) Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Maildir filename has wrong S value, renamed the file from /path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S to /path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1872:2,S Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Corrupted index cache file /path/cencored/Maildir/dovecot.index.cache: Broken physical size for mail UID 5758 Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: read(/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S) failed: Invalid argument Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: read(/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S) failed: Invalid argument (uid=5758) Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Cached message size smaller than expected (1781 < 1869) Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Maildir filename has wrong S value, renamed the file from /path/cencored/Maildir/cur/1201767850.29173.host.cencored.fi,S=1781:2,S to /path/cencored/Maildir/cur/1201767850.29173.host.cencored.fi,S=1869:2,S Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Corrupted index cache file /path/cencored/Maildir/dovecot.index.cache: Broken physical size for mail UID 5767 Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: read(/path/cencored/Maildir/cur/1201767850.29173.host.cencored.fi,S=1781:2,S) failed: Invalid argument Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: read(/path/cencored/Maildir/cur/1201767850.29173.host.cencored.fi,S=1781:2,S) failed: Invalid argument (uid=5767) Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Cached message size smaller than expected (9252 < 9346) Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Maildir filename has wrong S value, renamed the file from /path/cencored/Maildir/cur/1205131753.12346.host.cencored.fi,S=9252:2,RS to /path/cencored/Maildir/cur/1205131753.12346.host.cencored.fi,S=9346:2,RS Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Corrupted index cache file /path/cencored/Maildir/dovecot.index.cache: Broken physical size for mail UID 6296 Jul 6 08:11:52 dovecot: imap(user@domain.tld): Panic: file istream.c: line 167 (i_stream_read): assertion failed: (old_size <= _stream->pos - _stream->skip) Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0 [0x575c1f] -> /usr/lib/dovecot/libdovecot.so.0 [0x575c9d] -> /usr/lib/dovecot/libdovecot.so.0 [0x575514] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x13b) [0x57f99b] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x2b) [0x57fbfb] -> /usr/lib/dovecot/libdovecot.so.0 [0x565b5e] -> /usr/lib/dovecot/libdovecot.so.0 [0x567469] -> /usr/lib/dovecot/libdovecot.so.0(message_parser_parse_next_block+0x43) [0x565cd3] -> /usr/lib/dovecot/libdovecot.so.0(message_parser_parse_body+0x2c) [0x565e4c] -> /usr/lib/dovecot/libdovecot-storage.so.0 [0x944dd2] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_mail_get_parts+0x6a) [0x945c7a] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_get_parts+0x16) [0x91ad76] -> /usr/lib/dovecot/libdovecot-storage.so.0 [0x94aa7c] -> /usr/lib/dovecot/libdovecot-storage.so.0 [0x94ba89] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_storage_search_next_nonblo Jul 6 08:11:52 dovecot: imap(user@domain.tld): Fatal: master: service(imap): child 31268 killed with signal 6 (core dumps disabled)
These can of course be fixed with maildir-size-fix.pl and deleting dovecot index files, but there are thousands like these. Dovecot 1.2 didn't have any issues with these old maildirs transfered over from courierimap.
Best Regards, Toni Mattila
On 6.7.2014, at 12.07, Toni Mattila toni@solu.fi wrote:
Getting following panics with traces: Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Cached message size smaller than expected (1782 < 1872) Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Maildir filename has wrong S value, renamed the file from /path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S to /path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1872:2,S Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: Corrupted index cache file /path/cencored/Maildir/dovecot.index.cache: Broken physical size for mail UID 5758 Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: read(/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S) failed: Invalid argument Jul 6 08:11:52 dovecot: imap(user@domain.tld): Error: read(/path/cencored/Maildir/cur/1201713258.3136.host.cencored.fi,S=1782:2,S) failed: Invalid argument (uid=5758)
This is intended.
Jul 6 08:11:52 dovecot: imap(user@domain.tld): Panic: file istream.c: line 167 (i_stream_read): assertion failed: (old_size <= _stream->pos - _stream->skip)
This isn't intended, but I can't seem to be able to reproduce the crash. What's your doveconf -n output?
These can of course be fixed with maildir-size-fix.pl and deleting dovecot index files, but there are thousands like these. Dovecot 1.2 didn't have any issues with these old maildirs transfered over from courierimap.
maildir_broken_filename_sizes=yes restores the old behavior.
Hi,
On 6.7.2014 20:23, Timo Sirainen wrote:
Jul 6 08:11:52 dovecot: imap(user@domain.tld): Panic: file istream.c: line 167 (i_stream_read): assertion failed: (old_size <= _stream->pos - _stream->skip) This isn't intended, but I can't seem to be able to reproduce the crash. What's your doveconf -n output?
auth_mechanisms = plain apop auth_verbose = yes auth_verbose_passwords = plain:5 default_client_limit = 5000 default_process_limit = 1000 default_vsz_limit = 384 M disable_plaintext_auth = no first_valid_uid = 89 imap_idle_notify_interval = 6 mins mail_location = maildir:~/Maildir mail_plugins = " mail_log notify" mailbox_list_index = yes managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave duplicate mbox_write_locks = fcntl namespace inbox { inbox = yes location = mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { auto = subscribe special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Spam { auto = subscribe special_use = \Junk } mailbox Trash { auto = subscribe special_use = \Trash } prefix = INBOX. separator = . } passdb { driver = vpopmail } plugin { mail_log_events = mailbox_delete mailbox_rename sieve = ~/.dovecot.sieve sieve_dir = ~/sieve sieve_max_script_size = 5M } pop3_client_workarounds = outlook-no-nuls oe-ns-eoh pop3_uidl_format = %f protocols = imap pop3 lmtp sieve service imap-login { inet_listener imap { address = 0.0.0.0 port = 143 } inet_listener imaps { address = 0.0.0.0 port = 993 } } service managesieve-login { inet_listener sieve { address = 0.0.0.0 port = 4190 } service_count = 1 } service managesieve { process_limit = 1024 } service pop3-login { inet_listener pop3 { address = 0.0.0.0 port = 110 } inet_listener pop3s { address = 0.0.0.0 port = 995 } } ssl_cert =
These can of course be fixed with maildir-size-fix.pl and deleting dovecot index files, but there are thousands like these. Dovecot 1.2 didn't have any issues with these old maildirs transfered over from courierimap. maildir_broken_filename_sizes=yes restores the old behavior.
Ok will try that too.
I have now enabled coredumps just to see if I can get more info. This 32bit Centos 5.
Thanks, Toni
Hi,
Here is gdb backtrace for the crash.
#0 0x00f69402 in __kernel_vsyscall ()
No symbol table info available.
#1 0x0070af30 in raise () from /lib/i686/nosegneg/libc.so.6
No symbol table info available.
#2 0x0070c911 in abort () from /lib/i686/nosegneg/libc.so.6
No symbol table info available.
#3 0x00575c14 in default_fatal_finish (type=<value optimized out>,
status=0) at failures.c:193
backtrace = 0x86ae100 "/usr/lib/dovecot/libdovecot.so.0
[0x575c1f] -> /usr/lib/dovecot/libdovecot.so.0 [0x575c9d] ->
/usr/lib/dovecot/libdovecot.so.0 [0x575514] ->
/usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x13b) [0x57"...
#4 0x00575c9d in i_internal_fatal_handler (ctx=0xbfbc1c94,
format=0x5a2784 "file %s: line %d (%s): assertion failed: (%s)",
args=0xbfbc1cb4 "\f?Z") at failures.c:657
status = 0
#5 0x00575514 in i_panic (format=0x5a2784 "file %s: line %d (%s):
assertion failed: (%s)") at failures.c:267
ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0}
args = 0xbfbc1cb4 "\f?Z"
#6 0x0057f99b in i_stream_read (stream=0x86ea960) at istream.c:170
_stream = (struct istream_private *) 0x86ea928
old_size = 8192
ret = -2
__FUNCTION__ = "i_stream_read"
#7 0x0057fbfb in i_stream_read_data (stream=0x86ea960,
data_r=0xbfbc1d64, size_r=0xbfbc1d60, threshold=8192) at istream.c:536
ret = 8191
read_more = false
__FUNCTION__ = "i_stream_read_data"
#8 0x00564927 in message_parse_header_next (ctx=0x86f1770,
hdr_r=0xbfbc1da4) at message-header-parser.c:89
msg = (
const unsigned char *) 0x871de58 "References:
1397041424.77339.YahooMailNeo@web161206.mail.bf1.yahoo.com
1397041447.45218.YahooMailNeo@web161202.mail.bf1.yahoo.com
1397041471.51235.YahooMailNeo@web161205.mail.bf1.yahoo.com <1397"...
i = <value optimized out>
size = 8192
startpos = 8191
colon_pos = 10
parse_size = 8191
ret = 1
continued = false
continues = <value optimized out>
crlf_newline = <value optimized out>
__FUNCTION__ = "message_parse_header_next"
#9 0x00565414 in message_parse_header (input=0x86ea960, hdr_size=0x0,
flags=MESSAGE_HEADER_PARSER_FLAG_CLEAN_ONELINE, callback=0x94ae40
Panic: file istream.c: line 167 (i_stream_read): assertion failed: (old_size <= _stream->pos - _stream->skip)
Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0 [0x575c1f] -> /usr/lib/dovecot/libdovecot.so.0 [0x575c9d] -> /usr/lib/dovecot/libdovecot.so.0 [0x575514] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x13b) [0x57f99b] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x2b) [0x57fbfb] -> /usr/lib/dovecot/libdovecot.so.0(message_parse_header_next+0x87) [0x564927] -> /usr/lib/dovecot/libdovecot.so.0(message_parse_header+0x54) [0x565414] -> /usr/lib/dovecot/libdovecot-storage.so.0 [0x94a9c8] -> /usr/lib/dovecot/libdovecot-storage.so.0 [0x94ba89] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_storage_search_next_nonblock+0xde) [0x94c5fe] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_search_next_nonblock+0x3e) [0x9222ee] -> dovecot/imap [0x8062b40] -> dovecot/imap [0x8063214] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0xbe) [0x58822e] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x97) [0x Fatal: master: service(imap): child 6201 killed with signal 6 (core dumped)
Thanks, Toni
Should be fixed by http://hg.dovecot.org/dovecot-2.2/rev/1a38a85d952e
On 7.7.2014, at 12.47, Toni Mattila toni@solu.fi wrote:
Hi,
Here is gdb backtrace for the crash. #0 0x00f69402 in __kernel_vsyscall () No symbol table info available. #1 0x0070af30 in raise () from /lib/i686/nosegneg/libc.so.6 No symbol table info available. #2 0x0070c911 in abort () from /lib/i686/nosegneg/libc.so.6 No symbol table info available. #3 0x00575c14 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:193 backtrace = 0x86ae100 "/usr/lib/dovecot/libdovecot.so.0 [0x575c1f] -> /usr/lib/dovecot/libdovecot.so.0 [0x575c9d] -> /usr/lib/dovecot/libdovecot.so.0 [0x575514] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x13b) [0x57"... #4 0x00575c9d in i_internal_fatal_handler (ctx=0xbfbc1c94, format=0x5a2784 "file %s: line %d (%s): assertion failed: (%s)", args=0xbfbc1cb4 "\f?Z") at failures.c:657 status = 0 #5 0x00575514 in i_panic (format=0x5a2784 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:267 ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0} args = 0xbfbc1cb4 "\f?Z" #6 0x0057f99b in i_stream_read (stream=0x86ea960) at istream.c:170 _stream = (struct istream_private *) 0x86ea928 old_size = 8192 ret = -2 __FUNCTION__ = "i_stream_read" #7 0x0057fbfb in i_stream_read_data (stream=0x86ea960, data_r=0xbfbc1d64, size_r=0xbfbc1d60, threshold=8192) at istream.c:536 ret = 8191 read_more = false __FUNCTION__ = "i_stream_read_data" #8 0x00564927 in message_parse_header_next (ctx=0x86f1770, hdr_r=0xbfbc1da4) at message-header-parser.c:89 msg = ( const unsigned char *) 0x871de58 "References: 1397041424.77339.YahooMailNeo@web161206.mail.bf1.yahoo.com 1397041447.45218.YahooMailNeo@web161202.mail.bf1.yahoo.com 1397041471.51235.YahooMailNeo@web161205.mail.bf1.yahoo.com <1397"... i = <value optimized out> size = 8192 startpos = 8191 colon_pos = 10 parse_size = 8191 ret = 1 continued = false continues = <value optimized out> crlf_newline = <value optimized out> __FUNCTION__ = "message_parse_header_next" #9 0x00565414 in message_parse_header (input=0x86ea960, hdr_size=0x0, flags=MESSAGE_HEADER_PARSER_FLAG_CLEAN_ONELINE, callback=0x94ae40
, context=0xbfbc1e0c) at message-header-parser.c:393 hdr_ctx = (struct message_header_parser_ctx *) 0x86f1770 hdr = (struct message_header_line *) 0x0 ret = <value optimized out> __FUNCTION__ = "message_parse_header" #10 0x0094a9c8 in search_match_once (ctx=0x86ee338) at index-search.c:697 ret = <value optimized out> #11 0x0094ba89 in search_more (ctx=0x86ee338, mail_r=0xbfbc1f28) at index-search.c:1401 imail = <value optimized out> ret = <value optimized out> #12 0x0094c5fe in index_storage_search_next_nonblock (_ctx=0x86ee338, mail_r=0xbfbc1f94, tryagain_r=0xbfbc1f9b) at index-search.c:1677 ctx = (struct index_search_context *) 0x0 mail = <value optimized out> mailp = <value optimized out> seq = <value optimized out> ret = <value optimized out> #13 0x009222ee in mailbox_search_next_nonblock (ctx=0x86ee338, mail_r=0xbfbc1f94, tryagain_r=0xbfbc1f9b) at mail-storage.c:1796 box = (struct mailbox *) 0x6 #14 0x08062b40 in cmd_search_more (cmd=0x86cc438) at imap-search.c:443 ctx = (struct imap_search_context *) 0x86cc500 opts = SEARCH_RETURN_ALL mail = (struct mail *) 0x0 sync_flags = <value optimized out> end_time = {tv_sec = 6135364, tv_usec = 141343184} id = 8050 id_min = 8050 id_max = 8050 time_msecs = <value optimized out> tryagain = <value optimized out> lost_data = <value optimized out> __FUNCTION__ = "cmd_search_more" #15 0x08063214 in cmd_search_more_callback (cmd=0x86cc438) at imap-search.c:527 client = (struct client *) 0x86cb9d0 finished = <value optimized out> #16 0x0058822e in io_loop_handle_timeouts (ioloop=0x86b6498) at ioloop.c:410 timeout = <value optimized out> _data_stack_cur_id = 2 #17 0x005896e7 in io_loop_handler_run_internal (ioloop=0x86b6498) at ioloop-epoll.c:193 ctx = (struct ioloop_handler_context *) 0x86b7610 event = <value optimized out> list = <value optimized out> io = <value optimized out> tv = {tv_sec = 0, tv_usec = 0} msecs = 0 ret = 0 i = <value optimized out> j = <value optimized out> call = <value optimized out> __FUNCTION__ = "io_loop_handler_run_internal" #18 0x00587e1e in io_loop_handler_run (ioloop=0x86b6498) at ioloop.c:488 No locals. #19 0x00587ea8 in io_loop_run (ioloop=0x86b6498) at ioloop.c:465 __FUNCTION__ = "io_loop_run" #20 0x0052e42d in master_service_run (service=0x86b63c0, callback=0x8066000 ) at master-service.c:566 No locals. #21 0x08065e9f in main (argc=Cannot access memory at address 0x0 ) at main.c:400 login_set = {auth_socket_path = 0x86ae038 "P?j\b", postlogin_socket_path = 0x0, postlogin_timeout_secs = 60, callback = 0x80660c0 , failure_callback = 0x8066060 , request_auth_token = 1} service_flags = <value optimized out> storage_service_flags = MAIL_STORAGE_SERVICE_FLAG_DISALLOW_ROOT username = 0x0 c = <value optimized out> set_roots = {0x806daa0, 0x0} Panic: file istream.c: line 167 (i_stream_read): assertion failed: (old_size <= _stream->pos - _stream->skip)
Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0 [0x575c1f] -> /usr/lib/dovecot/libdovecot.so.0 [0x575c9d] -> /usr/lib/dovecot/libdovecot.so.0 [0x575514] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x13b) [0x57f99b] -> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x2b) [0x57fbfb] -> /usr/lib/dovecot/libdovecot.so.0(message_parse_header_next+0x87) [0x564927] -> /usr/lib/dovecot/libdovecot.so.0(message_parse_header+0x54) [0x565414] -> /usr/lib/dovecot/libdovecot-storage.so.0 [0x94a9c8] -> /usr/lib/dovecot/libdovecot-storage.so.0 [0x94ba89] -> /usr/lib/dovecot/libdovecot-storage.so.0(index_storage_search_next_nonblock+0xde) [0x94c5fe] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_search_next_nonblock+0x3e) [0x9222ee] -> dovecot/imap [0x8062b40] -> dovecot/imap [0x8063214] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handle_timeouts+0xbe) [0x58822e] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x97) [0x Fatal: master: service(imap): child 6201 killed with signal 6 (core dumped)
Thanks, Toni
Hei,
On 7.7.2014 13:16, Timo Sirainen wrote:
Should be fixed by http://hg.dovecot.org/dovecot-2.2/rev/1a38a85d952e
Cheers for the quick fix. I have that now running on production and will report back soon.
Thanks, Toni
Hi,
On 7.7.2014 13:16, Timo Sirainen wrote:
Should be fixed by http://hg.dovecot.org/dovecot-2.2/rev/1a38a85d952e
Nope. Still happens:
(gdb) bt
#0 0x00568402 in __kernel_vsyscall ()
#1 0x0070af30 in raise () from /lib/i686/nosegneg/libc.so.6
#2 0x0070c911 in abort () from /lib/i686/nosegneg/libc.so.6
#3 0x00d13c14 in default_fatal_finish (type=<value optimized out>,
status=0) at failures.c:193
#4 0x00d13c9d in i_internal_fatal_handler (ctx=0xbf824104,
format=0xd40784 "file %s: line %d (%s): assertion failed: (%s)",
args=0xbf824124 "\f��") at failures.c:657
#5 0x00d13514 in i_panic (format=0xd40784 "file %s: line %d (%s):
assertion failed: (%s)") at failures.c:267
#6 0x00d1d99b in i_stream_read (stream=0x85c7d20) at istream.c:170
#7 0x00d1dbfb in i_stream_read_data (stream=0x85c7d20,
data_r=0xbf824264, size_r=0xbf824268, threshold=31) at istream.c:538
#8 0x00d03b5e in message_parser_read_more (ctx=0x85dc020,
block_r=0xbf82425c, full_r=0xbf8241db) at message-parser.c:128
#9 0x00d05469 in parse_next_body_to_boundary (ctx=0x85dc020,
block_r=0xbf82425c) at message-parser.c:361
#10 0x00d03cd3 in message_parser_parse_next_block (ctx=0x85dc020,
block_r=0xbf82425c) at message-parser.c:1015
#11 0x00d03e4c in message_parser_parse_body (ctx=0x85dc020,
hdr_callback=0, context=0x0) at message-parser.c:1079
#12 0x0026fdd2 in index_mail_parse_body (mail=0x85da810,
field=MAIL_CACHE_FLAGS) at index-mail.c:914
#13 0x00270c7a in index_mail_get_parts (_mail=0x85da810,
parts_r=0xbf824358) at index-mail.c:285
#14 0x00245d76 in mail_get_parts (mail=0x85da810, parts_r=0xbf824358) at
mail.c:114
#15 0x00275a7c in search_match_once (ctx=0x85cbc28) at index-search.c:745
#16 0x00276a89 in search_more (ctx=0x85cbc28, mail_r=0xbf824458) at
index-search.c:1401
#17 0x002775fe in index_storage_search_next_nonblock (_ctx=0x85cbc28,
mail_r=0xbf8244c4, tryagain_r=0xbf8244cb) at index-search.c:1677
#18 0x0024d2ee in mailbox_search_next_nonblock (ctx=0x85cbc28,
mail_r=0xbf8244c4, tryagain_r=0xbf8244cb) at mail-storage.c:1796
#19 0x08062b40 in cmd_search_more (cmd=0x85ac430) at imap-search.c:443
#20 0x08063079 in imap_search_start (ctx=0x85ac4e8, sargs=0x85d9000,
sort_program=0x0) at imap-search.c:610
#21 0x08056d86 in cmd_search (cmd=0x85ac430) at cmd-search.c:48
#22 0x0805c953 in command_exec (cmd=0x85ac430) at imap-commands.c:158
#23 0x0805b69f in client_command_input (cmd=0x85ac430) at imap-client.c:778
#24 0x0805b751 in client_command_input (cmd=0x85ac430) at imap-client.c:839
#25 0x0805b913 in client_handle_input (client=0x85ab9c8) at
imap-client.c:877
#26 0x0805bd71 in client_input (client=0x85ab9c8) at imap-client.c:931
#27 0x00d25d88 in io_loop_call_io (io=0x85ac3b0) at ioloop.c:441
#28 0x00d2775f in io_loop_handler_run_internal (ioloop=0x8596490) at
ioloop-epoll.c:220
#29 0x00d25e2e in io_loop_handler_run (ioloop=0x8596490) at ioloop.c:488
#30 0x00d25eb8 in io_loop_run (ioloop=0x8596490) at ioloop.c:465
#31 0x00ccc42d in master_service_run (service=0x85963b8,
callback=0x8066000
(gdb) f 6
#6 0x00d1d99b in i_stream_read (stream=0x85c7d20) at istream.c:170
170 i_assert(_stream->skip != _stream->pos);
(gdb) p *_stream
$1 = {m = {refcount = 2, name = 0x0, error = 0x85cc0a8 "Cached message
size smaller than expected (3082265 < 3082342)", close = 0xd1e1e0
(gdb) p *_stream.parent.real_stream
$2 = {m = {refcount = 1, name = 0x85c7c70
"/cencored/Maildir/cur/1303455370.23018.cencored.fi,S=3082265:2,RS",
error = 0x0, close = 0xd217d0
Thanks, Toni
Hi,
Any further ideas on this one or suggestions how to provide more info?
Thanks, Toni
On 7.7.2014 14:35, Toni Mattila wrote:
Hi,
On 7.7.2014 13:16, Timo Sirainen wrote:
Should be fixed by http://hg.dovecot.org/dovecot-2.2/rev/1a38a85d952e
Nope. Still happens: (gdb) bt #0 0x00568402 in __kernel_vsyscall () #1 0x0070af30 in raise () from /lib/i686/nosegneg/libc.so.6 #2 0x0070c911 in abort () from /lib/i686/nosegneg/libc.so.6 #3 0x00d13c14 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:193 #4 0x00d13c9d in i_internal_fatal_handler (ctx=0xbf824104, format=0xd40784 "file %s: line %d (%s): assertion failed: (%s)", args=0xbf824124 "\f��") at failures.c:657 #5 0x00d13514 in i_panic (format=0xd40784 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:267 #6 0x00d1d99b in i_stream_read (stream=0x85c7d20) at istream.c:170 #7 0x00d1dbfb in i_stream_read_data (stream=0x85c7d20, data_r=0xbf824264, size_r=0xbf824268, threshold=31) at istream.c:538 #8 0x00d03b5e in message_parser_read_more (ctx=0x85dc020, block_r=0xbf82425c, full_r=0xbf8241db) at message-parser.c:128 #9 0x00d05469 in parse_next_body_to_boundary (ctx=0x85dc020, block_r=0xbf82425c) at message-parser.c:361 #10 0x00d03cd3 in message_parser_parse_next_block (ctx=0x85dc020, block_r=0xbf82425c) at message-parser.c:1015 #11 0x00d03e4c in message_parser_parse_body (ctx=0x85dc020, hdr_callback=0, context=0x0) at message-parser.c:1079 #12 0x0026fdd2 in index_mail_parse_body (mail=0x85da810, field=MAIL_CACHE_FLAGS) at index-mail.c:914 #13 0x00270c7a in index_mail_get_parts (_mail=0x85da810, parts_r=0xbf824358) at index-mail.c:285 #14 0x00245d76 in mail_get_parts (mail=0x85da810, parts_r=0xbf824358) at mail.c:114 #15 0x00275a7c in search_match_once (ctx=0x85cbc28) at index-search.c:745 #16 0x00276a89 in search_more (ctx=0x85cbc28, mail_r=0xbf824458) at index-search.c:1401 #17 0x002775fe in index_storage_search_next_nonblock (_ctx=0x85cbc28, mail_r=0xbf8244c4, tryagain_r=0xbf8244cb) at index-search.c:1677 #18 0x0024d2ee in mailbox_search_next_nonblock (ctx=0x85cbc28, mail_r=0xbf8244c4, tryagain_r=0xbf8244cb) at mail-storage.c:1796 #19 0x08062b40 in cmd_search_more (cmd=0x85ac430) at imap-search.c:443 #20 0x08063079 in imap_search_start (ctx=0x85ac4e8, sargs=0x85d9000, sort_program=0x0) at imap-search.c:610 #21 0x08056d86 in cmd_search (cmd=0x85ac430) at cmd-search.c:48 #22 0x0805c953 in command_exec (cmd=0x85ac430) at imap-commands.c:158 #23 0x0805b69f in client_command_input (cmd=0x85ac430) at imap-client.c:778 #24 0x0805b751 in client_command_input (cmd=0x85ac430) at imap-client.c:839 #25 0x0805b913 in client_handle_input (client=0x85ab9c8) at imap-client.c:877 #26 0x0805bd71 in client_input (client=0x85ab9c8) at imap-client.c:931 #27 0x00d25d88 in io_loop_call_io (io=0x85ac3b0) at ioloop.c:441 #28 0x00d2775f in io_loop_handler_run_internal (ioloop=0x8596490) at ioloop-epoll.c:220 #29 0x00d25e2e in io_loop_handler_run (ioloop=0x8596490) at ioloop.c:488 #30 0x00d25eb8 in io_loop_run (ioloop=0x8596490) at ioloop.c:465 #31 0x00ccc42d in master_service_run (service=0x85963b8, callback=0x8066000
) at master-service.c:566 #32 0x08065e9f in main (argc=Cannot access memory at address 0x0 ) at main.c:400 (gdb) f 6 #6 0x00d1d99b in i_stream_read (stream=0x85c7d20) at istream.c:170 170 i_assert(_stream->skip != _stream->pos); (gdb) p *_stream $1 = {m = {refcount = 2, name = 0x0, error = 0x85cc0a8 "Cached message size smaller than expected (3082265 < 3082342)", close = 0xd1e1e0
, destroy = 0xd1e400 , set_max_buffer_size = 0xd1e140 , destroy_callbacks = {arr = {buffer = 0x85cc070, element_size = 8}, v = 0x85cc070, v_modifiable = 0x85cc070}}, read = 0x26bf10 , seek = 0xd1cee0 , sync = 0, stat = 0xd1d140 , get_size = 0xd1cf10 , switch_ioloop = 0, istream = {v_offset = 0, stream_errno = 22, mmaped = 0, blocking = 1, closed = 0, readable_fd = 0, seekable = 1, eof = 0, real_stream = 0x85c7ce8}, fd = 16, abs_start_offset = 0, statbuf = {st_dev = 2050, __pad1 = 0, __st_ino = 45313747, st_mode = 33152, st_nlink = 1, st_uid = 89, st_gid = 89, st_rdev = 0, __pad2 = 0, st_size = 3082342, st_blksize = 4096, st_blocks = 6032, st_atim = {tv_sec = 1334256398, tv_nsec = 0}, st_mtim = {tv_sec = 1303455370, tv_nsec = 0}, st_ctim = {tv_sec = 1334256398, tv_nsec = 0}, st_ino = 45313747}, io = 0x0, buffer = 0x863cb30 "\nALUNAAC2DQAAtw0AALgNAAC5DQAAug0AALsNAAC8DQAAvQ0AAL4NAAC/DQAAwA0AAMENAADCDQAA\nww0AAMQNAADFDQAAxg0AAMcNAADIDQAAyQ0AAMoNAADLDQAAzA0AAM0NAADODQAAzw0AANANAADR\nDQAA0g0AANMNAADUDQAA1Q0AANYNAADXDQAA2A0AANkNA"..., w_buffer = 0x0, buffer_size = 0, max_buffer_size = 8192, init_buffer_size = 8192, skip = 0, pos = 0, try_alloc_limit = 0, parent = 0x8600988, parent_start_offset = 0, parent_expected_offset = 3077052, access_counter = 1136, line_str = 0x0, line_crlf = 0, return_nolf_line = 0, stream_size_passthrough = 1}
(gdb) p *_stream.parent.real_stream $2 = {m = {refcount = 1, name = 0x85c7c70 "/cencored/Maildir/cur/1303455370.23018.cencored.fi,S=3082265:2,RS", error = 0x0, close = 0xd217d0
, destroy = 0xd1e400 , set_max_buffer_size = 0xd1e140 , destroy_callbacks = {arr = {buffer = 0x0, element_size = 0}, v = 0x0, v_modifiable = 0x0}}, read = 0xd213f0 , seek = 0xd212c0 , sync = 0xd21000 , stat = 0xd21200 , get_size = 0xd1cf10 , switch_ioloop = 0, istream = { v_offset = 3077052, stream_errno = 0, mmaped = 0, blocking = 1, closed = 0, readable_fd = 1, seekable = 1, eof = 0, real_stream = 0x8600950}, fd = 16, abs_start_offset = 0, statbuf = {st_dev = 2050, __pad1 = 0, __st_ino = 45313747, st_mode = 33152, st_nlink = 1, st_uid = 89, st_gid = 89, st_rdev = 0, __pad2 = 0, st_size = 3082342, st_blksize = 4096, st_blocks = 6032, st_atim = {tv_sec = 1334256398, tv_nsec = 0}, st_mtim = {tv_sec = 1303455370, tv_nsec = 0}, st_ctim = {tv_sec = 1334256398, tv_nsec = 0}, st_ino = 45313747}, io = 0x0, buffer = 0x863cb30 "\nALUNAAC2DQAAtw0AALgNAAC5DQAAug0AALsNAAC8DQAAvQ0AAL4NAAC/DQAAwA0AAMENAADCDQAA\nww0AAMQNAADFDQAAxg0AAMcNAADIDQAAyQ0AAMoNAADLDQAAzA0AAM0NAADODQAAzw0AANANAADR\nDQAA0g0AANMNAADUDQAA1Q0AANYNAADXDQAA2A0AANkNA"..., w_buffer = 0x863cb30 "\nALUNAAC2DQAAtw0AALgNAAC5DQAAug0AALsNAAC8DQAAvQ0AAL4NAAC/DQAAwA0AAMENAADCDQAA\nww0AAMQNAADFDQAAxg0AAMcNAADIDQAAyQ0AAMoNAADLDQAAzA0AAM0NAADODQAAzw0AANANAADR\nDQAA0g0AANMNAADUDQAA1Q0AANYNAADXDQAA2A0AANkNA"...,
buffer_size = 8192, max_buffer_size = 8192, init_buffer_size = 8192, skip = 0, pos = 5290, try_alloc_limit = 0, parent = 0x0, parent_start_offset = 0, parent_expected_offset = 0, access_counter = 1136, line_str = 0x0, line_crlf = 0, return_nolf_line = 0, stream_size_passthrough = 0}
On 22 Jul 2014, at 09:20, Toni Mattila toni@solu.fi wrote:
Any further ideas on this one or suggestions how to provide more info?
I still can't reproduce. And I don't understand how it could get into that state. Can you still easily reproduce it with some specific mail? If so, could you send the mail to me (maybe with all the actual sensitive content replaced with 'x' letters or something)?
Thanks, Toni
On 7.7.2014 14:35, Toni Mattila wrote:
Hi,
On 7.7.2014 13:16, Timo Sirainen wrote:
Should be fixed by http://hg.dovecot.org/dovecot-2.2/rev/1a38a85d952e
Nope. Still happens: (gdb) bt #0 0x00568402 in __kernel_vsyscall () #1 0x0070af30 in raise () from /lib/i686/nosegneg/libc.so.6 #2 0x0070c911 in abort () from /lib/i686/nosegneg/libc.so.6 #3 0x00d13c14 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:193 #4 0x00d13c9d in i_internal_fatal_handler (ctx=0xbf824104, format=0xd40784 "file %s: line %d (%s): assertion failed: (%s)", args=0xbf824124 "\f��") at failures.c:657 #5 0x00d13514 in i_panic (format=0xd40784 "file %s: line %d (%s): assertion failed: (%s)") at failures.c:267 #6 0x00d1d99b in i_stream_read (stream=0x85c7d20) at istream.c:170 #7 0x00d1dbfb in i_stream_read_data (stream=0x85c7d20, data_r=0xbf824264, size_r=0xbf824268, threshold=31) at istream.c:538 #8 0x00d03b5e in message_parser_read_more (ctx=0x85dc020, block_r=0xbf82425c, full_r=0xbf8241db) at message-parser.c:128 #9 0x00d05469 in parse_next_body_to_boundary (ctx=0x85dc020, block_r=0xbf82425c) at message-parser.c:361 #10 0x00d03cd3 in message_parser_parse_next_block (ctx=0x85dc020, block_r=0xbf82425c) at message-parser.c:1015 #11 0x00d03e4c in message_parser_parse_body (ctx=0x85dc020, hdr_callback=0, context=0x0) at message-parser.c:1079 #12 0x0026fdd2 in index_mail_parse_body (mail=0x85da810, field=MAIL_CACHE_FLAGS) at index-mail.c:914 #13 0x00270c7a in index_mail_get_parts (_mail=0x85da810, parts_r=0xbf824358) at index-mail.c:285 #14 0x00245d76 in mail_get_parts (mail=0x85da810, parts_r=0xbf824358) at mail.c:114 #15 0x00275a7c in search_match_once (ctx=0x85cbc28) at index-search.c:745 #16 0x00276a89 in search_more (ctx=0x85cbc28, mail_r=0xbf824458) at index-search.c:1401 #17 0x002775fe in index_storage_search_next_nonblock (_ctx=0x85cbc28, mail_r=0xbf8244c4, tryagain_r=0xbf8244cb) at index-search.c:1677 #18 0x0024d2ee in mailbox_search_next_nonblock (ctx=0x85cbc28, mail_r=0xbf8244c4, tryagain_r=0xbf8244cb) at mail-storage.c:1796 #19 0x08062b40 in cmd_search_more (cmd=0x85ac430) at imap-search.c:443 #20 0x08063079 in imap_search_start (ctx=0x85ac4e8, sargs=0x85d9000, sort_program=0x0) at imap-search.c:610 #21 0x08056d86 in cmd_search (cmd=0x85ac430) at cmd-search.c:48 #22 0x0805c953 in command_exec (cmd=0x85ac430) at imap-commands.c:158 #23 0x0805b69f in client_command_input (cmd=0x85ac430) at imap-client.c:778 #24 0x0805b751 in client_command_input (cmd=0x85ac430) at imap-client.c:839 #25 0x0805b913 in client_handle_input (client=0x85ab9c8) at imap-client.c:877 #26 0x0805bd71 in client_input (client=0x85ab9c8) at imap-client.c:931 #27 0x00d25d88 in io_loop_call_io (io=0x85ac3b0) at ioloop.c:441 #28 0x00d2775f in io_loop_handler_run_internal (ioloop=0x8596490) at ioloop-epoll.c:220 #29 0x00d25e2e in io_loop_handler_run (ioloop=0x8596490) at ioloop.c:488 #30 0x00d25eb8 in io_loop_run (ioloop=0x8596490) at ioloop.c:465 #31 0x00ccc42d in master_service_run (service=0x85963b8, callback=0x8066000
) at master-service.c:566 #32 0x08065e9f in main (argc=Cannot access memory at address 0x0 ) at main.c:400 (gdb) f 6 #6 0x00d1d99b in i_stream_read (stream=0x85c7d20) at istream.c:170 170 i_assert(_stream->skip != _stream->pos); (gdb) p *_stream $1 = {m = {refcount = 2, name = 0x0, error = 0x85cc0a8 "Cached message size smaller than expected (3082265 < 3082342)", close = 0xd1e1e0
, destroy = 0xd1e400 , set_max_buffer_size = 0xd1e140 , destroy_callbacks = {arr = {buffer = 0x85cc070, element_size = 8}, v = 0x85cc070, v_modifiable = 0x85cc070}}, read = 0x26bf10 , seek = 0xd1cee0 , sync = 0, stat = 0xd1d140 , get_size = 0xd1cf10 , switch_ioloop = 0, istream = {v_offset = 0, stream_errno = 22, mmaped = 0, blocking = 1, closed = 0, readable_fd = 0, seekable = 1, eof = 0, real_stream = 0x85c7ce8}, fd = 16, abs_start_offset = 0, statbuf = {st_dev = 2050, __pad1 = 0, __st_ino = 45313747, st_mode = 33152, st_nlink = 1, st_uid = 89, st_gid = 89, st_rdev = 0, __pad2 = 0, st_size = 3082342, st_blksize = 4096, st_blocks = 6032, st_atim = {tv_sec = 1334256398, tv_nsec = 0}, st_mtim = {tv_sec = 1303455370, tv_nsec = 0}, st_ctim = {tv_sec = 1334256398, tv_nsec = 0}, st_ino = 45313747}, io = 0x0, buffer = 0x863cb30 "\nALUNAAC2DQAAtw0AALgNAAC5DQAAug0AALsNAAC8DQAAvQ0AAL4NAAC/DQAAwA0AAMENAADCDQAA\nww0AAMQNAADFDQAAxg0AAMcNAADIDQAAyQ0AAMoNAADLDQAAzA0AAM0NAADODQAAzw0AANANAADR\nDQAA0g0AANMNAADUDQAA1Q0AANYNAADXDQAA2A0AANkNA"..., w_buffer = 0x0, buffer_size = 0, max_buffer_size = 8192, init_buffer_size = 8192, skip = 0, pos = 0, try_alloc_limit = 0, parent = 0x8600988, parent_start_offset = 0, parent_expected_offset = 3077052, access_counter = 1136, line_str = 0x0, line_crlf = 0, return_nolf_line = 0, stream_size_passthrough = 1}
(gdb) p *_stream.parent.real_stream $2 = {m = {refcount = 1, name = 0x85c7c70 "/cencored/Maildir/cur/1303455370.23018.cencored.fi,S=3082265:2,RS", error = 0x0, close = 0xd217d0
, destroy = 0xd1e400 , set_max_buffer_size = 0xd1e140 , destroy_callbacks = {arr = {buffer = 0x0, element_size = 0}, v = 0x0, v_modifiable = 0x0}}, read = 0xd213f0 , seek = 0xd212c0 , sync = 0xd21000 , stat = 0xd21200 , get_size = 0xd1cf10 , switch_ioloop = 0, istream = { v_offset = 3077052, stream_errno = 0, mmaped = 0, blocking = 1, closed = 0, readable_fd = 1, seekable = 1, eof = 0, real_stream = 0x8600950}, fd = 16, abs_start_offset = 0, statbuf = {st_dev = 2050, __pad1 = 0, __st_ino = 45313747, st_mode = 33152, st_nlink = 1, st_uid = 89, st_gid = 89, st_rdev = 0, __pad2 = 0, st_size = 3082342, st_blksize = 4096, st_blocks = 6032, st_atim = {tv_sec = 1334256398, tv_nsec = 0}, st_mtim = {tv_sec = 1303455370, tv_nsec = 0}, st_ctim = {tv_sec = 1334256398, tv_nsec = 0}, st_ino = 45313747}, io = 0x0, buffer = 0x863cb30 "\nALUNAAC2DQAAtw0AALgNAAC5DQAAug0AALsNAAC8DQAAvQ0AAL4NAAC/DQAAwA0AAMENAADCDQAA\nww0AAMQNAADFDQAAxg0AAMcNAADIDQAAyQ0AAMoNAADLDQAAzA0AAM0NAADODQAAzw0AANANAADR\nDQAA0g0AANMNAADUDQAA1Q0AANYNAADXDQAA2A0AANkNA"..., w_buffer = 0x863cb30 "\nALUNAAC2DQAAtw0AALgNAAC5DQAAug0AALsNAAC8DQAAvQ0AAL4NAAC/DQAAwA0AAMENAADCDQAA\nww0AAMQNAADFDQAAxg0AAMcNAADIDQAAyQ0AAMoNAADLDQAAzA0AAM0NAADODQAAzw0AANANAADR\nDQAA0g0AANMNAADUDQAA1Q0AANYNAADXDQAA2A0AANkNA"...,
buffer_size = 8192, max_buffer_size = 8192, init_buffer_size = 8192, skip = 0, pos = 5290, try_alloc_limit = 0, parent = 0x0, parent_start_offset = 0, parent_expected_offset = 0, access_counter = 1136, line_str = 0x0, line_crlf = 0, return_nolf_line = 0, stream_size_passthrough = 0}
Hi,
On 20.8.2014 16:58, Timo Sirainen wrote:
I still can't reproduce. And I don't understand how it could get into that state. Can you still easily reproduce it with some specific mail? If so, could you send the mail to me (maybe with all the actual sensitive content replaced with 'x' letters or something)?
It still happens for users 1-2 times a day. I think it's due to that "Error: Maildir filename has wrong S value, renamed the file from" is only ran for first occurance.
So for some users that only have few broken sizes in maildir filenames they won't even notice it as after few crashes the mailbox is ok.
When only that first filename is renamed and index fixed for that one mail and user uses search it then crashes as some of the other mails have smaller on disk size than S=/index has.
The crashes also go away when index files are removed and that fix-maildir.pl ran from your site for that particular user.
Thanks, Toni
participants (2)
-
Timo Sirainen
-
Toni Mattila