[Dovecot] error in 1.1.2
Ive been getting a LOT of these errors since 1.1.2: So far ive seen this with 1800 customers, and we're getting active complaints about errors in imap clients. When I check the users log I always see this error.. This always happens with COPY commands in Squirrelmail.
Sep 2 20:09:35 userimap4.xs4all.nl dovecot: IMAP(xxxxxxx): rename(/var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache) failed: No such file or directory Sep 2 20:09:35 userimap4.xs4all.nl dovecot: IMAP(xxxxxxx): rename(/var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache) failed: No such file or directory Sep 2 20:09:35 userimap4.xs4all.nl dovecot: IMAP(xxxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache: No such file or directory Sep 2 20:09:35 userimap4.xs4all.nl dovecot: IMAP(xxxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache: No such file or directory Sep 1 20:14:06 userimap4.xs4all.nl dovecot: IMAP(xxxxxxx): rename(/var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache) failed: No such file or directory Sep 1 20:14:06 userimap4.xs4all.nl dovecot: IMAP(xxxxxxx): rename(/var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache) failed: No such file or directory Sep 1 20:14:06 userimap4.xs4all.nl dovecot: IMAP(xxxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache: No such file or directory Sep 1 20:14:06 userimap4.xs4all.nl dovecot: IMAP(xxxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/j/jd/xxxxxxx/.Inveztor/dovecot.index.cache: No such file or directory
FreeBSD 6.2, NFS storage for everything. Any idea?
Cor
On Mon, 2008-09-08 at 17:40 +0200, Cor Bosman wrote:
Ive been getting a LOT of these errors since 1.1.2:
What version did you use before?
So far ive seen this with 1800 customers, and we're getting active complaints about errors in imap clients. When I check the users log I always see this error.. This always happens with COPY commands in Squirrelmail.
*always*? Does the patch here help: http://dovecot.org/list/dovecot/2006-December/018145.html
But even then, errors in cache file handling are ignored and they shouldn't be visible to clients. What error exactly do the clients see? Does the COPY command fail with NO? Does anything else get logged besides these rename/file_dotlock_replace lines?
Ive been getting a LOT of these errors since 1.1.2:
What version did you use before?
I used 1.1-rc4 -> 1.1.1 -> 1.1.2
So far ive seen this with 1800 customers, and we're getting active complaints about errors in imap clients. When I check the users log I always see this error.. This always happens with COPY commands in Squirrelmail.
*always*? Does the patch here help:
I phrased it wrong. All complaints are exactly the same, but it of course doesnt happen with every COPY, else our customers would be unable to use imap :)
They all paste some squirrelmail error with a dutch message basically saying: connection dropped by imap server: Query: COPY 983,987 "Trash" It's always a COPY command they're pasting.
They often say it took a while to get the error, and some people are suggesting it's only with large emails. So it could be a PHP timeout related bug, although im not positive.
I dont think it's a coincidence that every single person that complaints has that set of errors in the dovecot error log. Over the past week ive found 1800 seperate users, and thats still only a fraction of our total user base.
http://dovecot.org/list/dovecot/2006-December/018145.html
But even then, errors in cache file handling are ignored and they shouldn't be visible to clients. What error exactly do the clients see? Does the COPY command fail with NO? Does anything else get logged besides these rename/file_dotlock_replace lines?
I dont know exactly what the clients see. It looks like php loses the connection to the imap server. Ive been trying to find a customer that can repeat this consistently so I can turn rawlog on. I dont see any dovecot crashes though.
I'll add that patch to 1 or 2 servers and see if the errors disappear on those servers.
Cor
On Sep 8, 2008, at 11:28 PM, Cor Bosman wrote:
They often say it took a while to get the error, and some people are suggesting it's only with large emails. So it could be a PHP timeout related bug, although im not positive.
I dont think it's a coincidence that every single person that
complaints has that set of errors in the dovecot error log. Over the past week
ive found 1800 seperate users, and thats still only a fraction of our total
user base.
If copying a single mail takes longer than the dotlocking timeout,
another process may have overridden the lock file and caused errors.
And since it took so long, maybe PHP or something timed out.
This should help figuring out if the problem is due to timeouts: http://hg.dovecot.org/dovecot-1.1/rev/241097889792
They often say it took a while to get the error, and some people are suggesting it's only with large emails. So it could be a PHP timeout related bug, although im not positive.
I dont think it's a coincidence that every single person that
complaints has that set of errors in the dovecot error log. Over the past week
ive found 1800 seperate users, and thats still only a fraction of our total
user base.If copying a single mail takes longer than the dotlocking timeout,
another process may have overridden the lock file and caused errors.
And since it took so long, maybe PHP or something timed out.This should help figuring out if the problem is due to timeouts: http://hg.dovecot.org/dovecot-1.1/rev/241097889792
FYI, im getting the same problem on local FS if i use dotlocking. Ive switched one server back to local FS indexes and im still getting this error. So far it looks like the error disappears if I switch to fcntl (and mmap/fsync back to normal)
Sep 9 10:54:17 userimap1 dovecot: IMAP(xxxxxx): rename(/usr/local/var/dovecot-index/m/ms/xxxxxx/.INBOX/dovecot.index.cache.lock, /usr/local/var/dovecot-index/m/ms/xxxxxx/.INBOX/dovecot.index.cache) failed: No such file or directory Sep 9 10:54:17 userimap1 dovecot: IMAP(xxxxxx): file_dotlock_replace() failed with index cache file /usr/local/var/dovecot-index/m/ms/xxxxxx/.INBOX/dovecot.index.cache: No such file or directory
It's still possible that 2 processes hit the same lockfile, but at least it's not possibe that 2 different machines do.
I'll do the following, unless you say different.
- keep one server on local indexes with fcntl
- set one server up with the previous patch you sent me
- set one server up with timeout patch
- upgrade one server to 1.1.3.
Where is this dotlocking timeout configured anyways?
Cor
If copying a single mail takes longer than the dotlocking timeout,
another process may have overridden the lock file and caused errors.
And since it took so long, maybe PHP or something timed out.This should help figuring out if the problem is due to timeouts: http://hg.dovecot.org/dovecot-1.1/rev/241097889792
Ive got this patch running on a server, but im not seeing any additional log entries. Here's one that just came by on the server that I added your last patch to.
Sep 9 15:39:07 userimap3.xs4all.nl dovecot: IMAP(xxxxxx): rename(/var/spool/mail/dovecot-control/indexes/a/an/xxxxxx/.Vergadering Plenair/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/a/an/xxxxxx/.Vergadering Plenair/dovecot.index.cache) failed: No such file or directory Sep 9 15:39:07 userimap3.xs4all.nl dovecot: IMAP(xxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/a/an/xxxxxx/.Vergadering Plenair/dovecot.index.cache: No such file or directory
I see no difference on 1.1.3, i still get errors. And the patch you sent me in your first reply also doesnt change things.
Only thing that seems to work is just moving away from dotlock/nfs, but im not sure that fixes the actual error people are reporting. I just dont see the error log entry anymore (obviously).
Cor
Oops, I do see a logline, just not in the error log. Weird.
Sep 9 16:42:54 userimap3.xs4all.nl dovecot: IMAP(xxxxxxx): rename(/var/spool/mail/dovecot-control/indexes/d/dr/xxxxxxx/.Trash/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/d/dr/xxxxxxx/.Trash/dovecot.index.cache) failed: No such file or directory Sep 9 16:42:54 userimap3.xs4all.nl dovecot: IMAP(xxxxxxx): Our dotlock file /var/spool/mail/dovecot-control/indexes/d/dr/xxxxxxx/.Trash/dovecot.index.cache.lock was deleted (kept it 61 secs) Sep 9 16:42:54 userimap3.xs4all.nl dovecot: IMAP(xxxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/d/dr/xxxxxxx/.Trash/dovecot.index.cache: No such file or directory
This is from the full log file...
Cor
On Tue, 2008-09-09 at 17:16 +0200, Cor Bosman wrote:
Oops, I do see a logline, just not in the error log. Weird.
Sep 9 16:42:54 userimap3.xs4all.nl dovecot: IMAP(xxxxxxx): rename(/var/spool/mail/dovecot-control/indexes/d/dr/xxxxxxx/.Trash/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/d/dr/xxxxxxx/.Trash/dovecot.index.cache) failed: No such file or directory Sep 9 16:42:54 userimap3.xs4all.nl dovecot: IMAP(xxxxxxx): Our dotlock file /var/spool/mail/dovecot-control/indexes/d/dr/xxxxxxx/.Trash/dovecot.index.cache.lock was deleted (kept it 61 secs) Sep 9 16:42:54 userimap3.xs4all.nl dovecot: IMAP(xxxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/d/dr/xxxxxxx/.Trash/dovecot.index.cache: No such file or directory
60 seconds is also when Dovecot decides the dotlock file is stale. So I guess the cache file compression is taking longer than that. Hmm. I hadn't thought about that before, since it was supposed to happen rarely enough. But I guess during the compression other processes shouldn't be stuck waiting for it. I'll have to think about something - probably make the lock timeout only a couple of seconds and after that just fail to update it.
But the cache compression really shouldn't take that long unless you're really really running out of disk I/O. I wonder if there's some problems with the locking / NFS caching. You do have mail_nfs_*=yes, right?
60 seconds is also when Dovecot decides the dotlock file is stale. So I guess the cache file compression is taking longer than that. Hmm. I hadn't thought about that before, since it was supposed to happen rarely enough. But I guess during the compression other processes shouldn't be stuck waiting for it. I'll have to think about something - probably make the lock timeout only a couple of seconds and after that just fail to update it.
But the cache compression really shouldn't take that long unless you're really really running out of disk I/O. I wonder if there's some problems with the locking / NFS caching. You do have mail_nfs_*=yes, right?
# grep nfs dovecot.conf mail_nfs_storage = yes mail_nfs_index = yes
What exactly is being compressed? We have 500MB mailspace, and plenty of users have that kind of space actually in use.
I dont think the storage servers are slow in any way. Else we'd be seeing this much more. As i said, so far it's less than 1% of our users that I can find with that cache error, but most of those do say they have a lot of large files. So maybe it's something with lots of emails, and the need to update a large portion of the cache? It probably needs to go over the wire twice right? Once to read, once to write?
One thing is, we dont use deliver, so whenever dovecot hits the user's email it most likely will have to re-index all new email.
Cor
On Tue, 2008-09-09 at 17:31 +0200, Cor Bosman wrote:
60 seconds is also when Dovecot decides the dotlock file is stale. So I guess the cache file compression is taking longer than that. Hmm. I hadn't thought about that before, since it was supposed to happen rarely enough. But I guess during the compression other processes shouldn't be stuck waiting for it. I'll have to think about something - probably make the lock timeout only a couple of seconds and after that just fail to update it.
Did a couple of changes:
http://hg.dovecot.org/dovecot-1.1/rev/898e3810c014 http://hg.dovecot.org/dovecot-1.1/rev/e3c5acf92b53
But the cache compression really shouldn't take that long unless you're really really running out of disk I/O. I wonder if there's some problems with the locking / NFS caching. You do have mail_nfs_*=yes, right?
# grep nfs dovecot.conf mail_nfs_storage = yes mail_nfs_index = yes
What exactly is being compressed? We have 500MB mailspace, and plenty of users have that kind of space actually in use.
Basically deleted space is removed from dovecot.index.cache by recreating the file and leaving out the deleted parts.
I dont think the storage servers are slow in any way. Else we'd be seeing this much more. As i said, so far it's less than 1% of our users that I can find with that cache error, but most of those do say they have a lot of large files. So maybe it's something with lots of emails, and the need to update a large portion of the cache? It probably needs to go over the wire twice right? Once to read, once to write?
You could check how large the dovecot.index.cache file is for those users. Normally it's something like 10-20% of the mailbox size, but it really depends on the emails.
One thing is, we dont use deliver, so whenever dovecot hits the user's email it most likely will have to re-index all new email.
There's no "reindexing". It just sees a new mail and adds it to the index. Not a problem in any way.
Did a couple of changes:
http://hg.dovecot.org/dovecot-1.1/rev/898e3810c014 http://hg.dovecot.org/dovecot-1.1/rev/e3c5acf92b53
Ok, will add them.
You could check how large the dovecot.index.cache file is for those users. Normally it's something like 10-20% of the mailbox size, but it really depends on the emails.
Of all the errors ive seen today, most cache files are < 100k. I only see 5 with a file larger than 1 MB.
Cor
Oh, now im getting assert failed with those 2 patches applied..
Sep 9 18:33:59 userimap3 dovecot: Panic: IMAP(xxxxx): file mail-cache.c: line 572 (mail_cache_lock): assertion failed: ((ret <= 0 && !cache->locked) || (ret > 0 && cache->locked))
Cor
- Cor Bosman cor@xs4all.nl:
Oh, now im getting assert failed with those 2 patches applied..
Sep 9 18:33:59 userimap3 dovecot: Panic: IMAP(xxxxx): file mail-cache.c: line 572 (mail_cache_lock): assertion failed: ((ret <= 0 && !cache->locked) || (ret > 0 && cache->locked))
Same here.
-- Ralf Hildebrandt (Ralf.Hildebrandt@charite.de) snickebo@charite.de Postfix - Einrichtung, Betrieb und Wartung Tel. +49 (0)30-450 570-155 http://www.arschkrebs.de I'm looking for a job PowerPoint & Windows. Office and NT - I might like'em more after my lobotomy
After applying the recent patches:
- root root@postamt.charite.de:
GNU gdb 6.8-debian Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "i486-linux-gnu"... Reading symbols from /lib/i686/cmov/libdl.so.2...Reading symbols from /usr/lib/debug/lib/i686/cmov/libdl-2.7.so...done. done. Loaded symbols for /lib/i686/cmov/libdl.so.2 Reading symbols from /lib/i686/cmov/libc.so.6...Reading symbols from /usr/lib/debug/lib/i686/cmov/libc-2.7.so...done. done. Loaded symbols for /lib/i686/cmov/libc.so.6 Reading symbols from /lib/ld-linux.so.2...Reading symbols from /usr/lib/debug/lib/ld-2.7.so...done. done. Loaded symbols for /lib/ld-linux.so.2 Reading symbols from /usr/local/lib/dovecot/imap/lib10_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib10_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_trash_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_trash_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_fts_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_fts_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so Reading symbols from /lib/libgcc_s.so.1...done. Loaded symbols for /lib/libgcc_s.so.1 Core was generated by `/usr/local/libexec/dovecot/imap'. Program terminated with signal 6, Aborted. [New process 31810] #0 0xb7f1d424 in __kernel_vsyscall () #0 0xb7f1d424 in __kernel_vsyscall () No symbol table info available. #1 0xb7dde640 in raise () from /lib/i686/cmov/libc.so.6 No symbol table info available. #2 0xb7de0018 in abort () from /lib/i686/cmov/libc.so.6 No symbol table info available. #3 0x080d65f5 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:150 backtrace = 0x8143978 "/usr/local/libexec/dovecot/imap [0x80d65e1] -> /usr/local/libexec/dovecot/imap [0x80d6662] -> /usr/local/libexec/dovecot/imap [0x80d5ff9] -> /usr/local/libexec/dovecot/imap(mail_cache_lock+0x26a) [0x8"... #4 0x080d6662 in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0x80ea22c "file %s: line %d (%s): assertion failed: (%s)", args=0xbff37214 "60\017\b<\002") at failures.c:430 No locals. #5 0x080d5ff9 in i_panic ( format=0x80ea22c "file %s: line %d (%s): assertion failed: (%s)") at failures.c:197 No locals. #6 0x080a8a1a in mail_cache_lock (cache=0x8158310, require_same_reset_id=false) at mail-cache.c:572 ext = <value optimized out> iview = (struct mail_index_view *) 0x0 reset_id = 1204552485 i = 0 ret = 0 __PRETTY_FUNCTION__ = "mail_cache_lock" #7 0x080a9b70 in mail_cache_header_fields_update (cache=0x8158310) at mail-cache-fields.c:490 ret = <value optimized out> #8 0x080a7764 in mail_cache_view_close (view=0x81703c8) at mail-cache.c:671 __PRETTY_FUNCTION__ = "mail_cache_view_close" #9 0x080a3194 in index_transaction_free (t=0x8170fc0) at index-transaction.c:24 No locals. #10 0x080a3280 in index_transaction_finish_commit (t=0x8170fc0, log_file_seq_r=0xbff37338, log_file_offset_r=0xbff37330) at index-transaction.c:48 ret = <value optimized out> __PRETTY_FUNCTION__ = "index_transaction_finish_commit" #11 0x0807480f in maildir_transaction_commit (t=0x815ad28, log_file_seq_r=0xbff37338, log_file_offset_r=0xbff37330) at maildir-transaction.c:29 mt = (struct maildir_transaction_context *) 0x8170fc0 ret = <value optimized out> #12 0x080a30ee in index_transaction_commit (_t=0x8170fc0, uid_validity_r=0xbff37454, first_saved_uid_r=0xbff37450, last_saved_uid_r=0xbff3744c) at index-transaction.c:105 itrans = (struct mail_index_transaction *) 0x0 seq = 0 offset = 0 #13 0xb7d9d7e4 in mail_log_transaction_commit (t=0x8170fc0, uid_validity_r=0xbff37454, first_saved_uid_r=0xbff37450, last_saved_uid_r=0xbff3744c) at mail-log-plugin.c:420 lt = (struct mail_log_transaction_context *) 0x0 #14 0xb7daf60f in quota_mailbox_transaction_commit (ctx=0x8170fc0, uid_validity_r=0xbff37454, first_saved_uid_r=0xbff37450, last_saved_uid_r=0xbff3744c) at quota-storage.c:95 qt = (struct quota_transaction_context *) 0x8170f38 #15 0xb7da2e94 in fts_transaction_commit (t=0x8170fc0, uid_validity_r=0xbff37454, first_saved_uid_r=0xbff37450, last_saved_uid_r=0xbff3744c) at fts-storage.c:707 box = (struct mailbox *) 0x8156e58 ft = (struct fts_transaction_context *) 0x815a860 ret = <value optimized out> #16 0x080a4f06 in mailbox_transaction_commit (t=0xbff37494) at mail-storage.c:675 uidvalidity = 0 uid1 = 0 uid2 = 0 #17 0x08068beb in imap_sort (cmd=0x814f5f0, charset=0x8153788 "ISO-8859-1", args=0x816fa10, sort_program=0xbff374dc) at imap-sort.c:103 client = (struct client *) 0x814f3a8 wanted_headers = {0x0, 0x0} wanted_fields = <value optimized out> search_ctx = (struct mail_search_context *) 0x0 t = (struct mailbox_transaction_context *) 0x0 headers_ctx = (struct mailbox_header_lookup_ctx *) 0x0 mail = (struct mail *) 0x0 str = (string_t *) 0x81430f8 written = true ret = 0 #18 0x0806118c in cmd_sort (cmd=0x814f5f0) at cmd-sort.c:139 client = (struct client *) 0x814f3a8 sargs = (struct mail_search_arg *) 0x0 sorting = {MAIL_SORT_ARRIVAL, MAIL_SORT_END, 1386138, 5, 135591408, 135591408, 135608040, 3220403480, 134618590} args = (const struct imap_arg *) 0x8153688 args_count = <value optimized out> pool = (pool_t) 0x816f9f8 error = <value optimized out> charset = 0x8153788 "ISO-8859-1" #19 0x080627dc in client_command_input (cmd=0x814f5f0) at client.c:580 client = (struct client *) 0x814f3a8 command = <value optimized out> __PRETTY_FUNCTION__ = "client_command_input" #20 0x0806286f in client_command_input (cmd=0x814f5f0) at client.c:629 client = (struct client *) 0x814f3a8 command = (struct command *) 0x7c42 __PRETTY_FUNCTION__ = "client_command_input" #21 0x08062e6d in client_handle_input (client=<value optimized out>) at client.c:670 _data_stack_cur_id = 3 ret = <value optimized out> remove_io = <value optimized out> handled_commands = false #22 0x0806337e in client_input (client=0x814f3a8) at client.c:725 cmd = <value optimized out> output = (struct ostream *) 0x814f52c bytes = <value optimized out> __PRETTY_FUNCTION__ = "client_input" #23 0x080de070 in io_loop_handler_run (ioloop=0x814b9b0) at ioloop-epoll.c:203 ctx = (struct ioloop_handler_context *) 0x814baa8 event = (const struct epoll_event *) 0x814bae8 list = (struct io_list *) 0x814c5c0 io = (struct io_file *) 0x814f588 tv = {tv_sec = 4, tv_usec = 994051} t_id = 2 msecs = <value optimized out> ret = 1 i = 0 j = 0 call = <value optimized out> #24 0x080dd4e0 in io_loop_run (ioloop=0x814b9b0) at ioloop.c:320 No locals. #25 0x0806b4ea in main (argc=) at main.c:293 No locals.
- root root@postamt.charite.de:
GNU gdb 6.8-debian Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "i486-linux-gnu"... Reading symbols from /lib/i686/cmov/libdl.so.2...Reading symbols from /usr/lib/debug/lib/i686/cmov/libdl-2.7.so...done. done. Loaded symbols for /lib/i686/cmov/libdl.so.2 Reading symbols from /lib/i686/cmov/libc.so.6...Reading symbols from /usr/lib/debug/lib/i686/cmov/libc-2.7.so...done. done. Loaded symbols for /lib/i686/cmov/libc.so.6 Reading symbols from /lib/ld-linux.so.2...Reading symbols from /usr/lib/debug/lib/ld-2.7.so...done. done. Loaded symbols for /lib/ld-linux.so.2 Reading symbols from /usr/local/lib/dovecot/imap/lib10_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib10_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_trash_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_trash_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_fts_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_fts_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so Reading symbols from /lib/libgcc_s.so.1...done. Loaded symbols for /lib/libgcc_s.so.1 Core was generated by `/usr/local/libexec/dovecot/imap'. Program terminated with signal 6, Aborted. [New process 32052] #0 0xb7f40424 in __kernel_vsyscall () #0 0xb7f40424 in __kernel_vsyscall () No symbol table info available. #1 0xb7e01640 in raise () from /lib/i686/cmov/libc.so.6 No symbol table info available. #2 0xb7e03018 in abort () from /lib/i686/cmov/libc.so.6 No symbol table info available. #3 0x080d65f5 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:150 backtrace = 0x8ccf3c8 "/usr/local/libexec/dovecot/imap [0x80d65e1] -> /usr/local/libexec/dovecot/imap [0x80d6662] -> /usr/local/libexec/dovecot/imap [0x80d5ff9] -> /usr/local/libexec/dovecot/imap(mail_cache_lock+0x26a) [0x8"... #4 0x080d6662 in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0x80ea22c "file %s: line %d (%s): assertion failed: (%s)", args=0xbf959484 "60\017\b<\002") at failures.c:430 No locals. #5 0x080d5ff9 in i_panic ( format=0x80ea22c "file %s: line %d (%s): assertion failed: (%s)") at failures.c:197 No locals. #6 0x080a8a1a in mail_cache_lock (cache=0x8d01d10, require_same_reset_id=false) at mail-cache.c:572 ext = <value optimized out> iview = (struct mail_index_view *) 0x0 reset_id = 1167818280 i = 0 ret = 0 __PRETTY_FUNCTION__ = "mail_cache_lock" #7 0x080ab0c3 in mail_cache_transaction_lock (ctx=0x8d043a8) at mail-cache-transaction.c:201 cache = (struct mail_cache *) 0x8d01d10 ret = <value optimized out> __PRETTY_FUNCTION__ = "mail_cache_transaction_lock" #8 0x080ac6aa in mail_cache_transaction_commit (_ctx=0x8d04148) at mail-cache-transaction.c:716 ctx = (struct mail_cache_transaction_ctx *) 0x8d043a8 cache = (struct mail_cache *) 0x8d01d10 ret = <value optimized out> #9 0x080b3c46 in mail_index_transaction_commit_v (t=0x8d03ef0, log_file_seq_r=0xbf959688, log_file_offset_r=0xbf959680) at mail-index-transaction.c:581 ret = <value optimized out> __PRETTY_FUNCTION__ = "mail_index_transaction_commit_v" #10 0x080a3250 in index_transaction_finish_commit (t=0x8d01ec8, log_file_seq_r=0xbf959688, log_file_offset_r=0xbf959680) at index-transaction.c:38 ret = <value optimized out> __PRETTY_FUNCTION__ = "index_transaction_finish_commit" #11 0x0807480f in maildir_transaction_commit (t=0x8d03ef0, log_file_seq_r=0xbf959688, log_file_offset_r=0xbf959680) at maildir-transaction.c:29 mt = (struct maildir_transaction_context *) 0x8d01ec8 ret = <value optimized out> #12 0x080a30ee in index_transaction_commit (_t=0x8d01ec8, uid_validity_r=0xbf9597d0, first_saved_uid_r=0xbf9597cc, last_saved_uid_r=0xbf9597c8) at index-transaction.c:105 itrans = (struct mail_index_transaction *) 0x0 seq = 4 offset = 148017744 #13 0xb7dc07e4 in mail_log_transaction_commit (t=0x8d01ec8, uid_validity_r=0xbf9597d0, first_saved_uid_r=0xbf9597cc, last_saved_uid_r=0xbf9597c8) at mail-log-plugin.c:420 lt = (struct mail_log_transaction_context *) 0x0 #14 0xb7dd260f in quota_mailbox_transaction_commit (ctx=0x8d01ec8, uid_validity_r=0xbf9597d0, first_saved_uid_r=0xbf9597cc, last_saved_uid_r=0xbf9597c8) at quota-storage.c:95 qt = (struct quota_transaction_context *) 0x8d046f0 #15 0xb7dc5e94 in fts_transaction_commit (t=0x8d01ec8, uid_validity_r=0xbf9597d0, first_saved_uid_r=0xbf9597cc, last_saved_uid_r=0xbf9597c8) at fts-storage.c:707 box = (struct mailbox *) 0x8d290c8 ft = (struct fts_transaction_context *) 0x8d01c08 ret = <value optimized out> #16 0x0805cca2 in cmd_append_continue_parsing (cmd=0x8cdb5f0) at cmd-append.c:252 uid2 = <value optimized out> msg = <value optimized out> sync_flags = <value optimized out> imap_flags = <value optimized out> uid_validity = <value optimized out> uid1 = <value optimized out> client = (struct client *) 0x8cdb3a8 ctx = (struct cmd_append_context *) 0x8cdb638 args = (const struct imap_arg *) 0x8d047b8 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> nonsync = <value optimized out> __PRETTY_FUNCTION__ = "cmd_append_continue_parsing" #17 0x0805d361 in client_input_append (cmd=0x8cdb5f0) at cmd-append.c:79 client = (struct client *) 0x8cdb3a8 output = (struct ostream *) 0x8cdb52c finished = <value optimized out> __PRETTY_FUNCTION__ = "client_input_append" #18 0x080de070 in io_loop_handler_run (ioloop=0x8cd79b0) at ioloop-epoll.c:203 ctx = (struct ioloop_handler_context *) 0x8cd7aa8 event = (const struct epoll_event *) 0x8cd7ae8 list = (struct io_list *) 0x8cd85c0 io = (struct io_file *) 0x8cdb588 tv = {tv_sec = 4, tv_usec = 793558} t_id = 2 msecs = <value optimized out> ret = 1 i = 0 j = 0 call = <value optimized out> #19 0x080dd4e0 in io_loop_run (ioloop=0x8cd79b0) at ioloop.c:320 No locals. #20 0x0806b4ea in main (argc=) at main.c:293 No locals.
- root root@postamt.charite.de:
GNU gdb 6.8-debian Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "i486-linux-gnu"... Reading symbols from /lib/i686/cmov/libdl.so.2...Reading symbols from /usr/lib/debug/lib/i686/cmov/libdl-2.7.so...done. done. Loaded symbols for /lib/i686/cmov/libdl.so.2 Reading symbols from /lib/i686/cmov/libc.so.6...Reading symbols from /usr/lib/debug/lib/i686/cmov/libc-2.7.so...done. done. Loaded symbols for /lib/i686/cmov/libc.so.6 Reading symbols from /lib/ld-linux.so.2...Reading symbols from /usr/lib/debug/lib/ld-2.7.so...done. done. Loaded symbols for /lib/ld-linux.so.2 Reading symbols from /usr/local/lib/dovecot/imap/lib10_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib10_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_trash_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_trash_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_fts_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_fts_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so Reading symbols from /lib/libgcc_s.so.1...done. Loaded symbols for /lib/libgcc_s.so.1 Core was generated by `/usr/local/libexec/dovecot/imap'. Program terminated with signal 6, Aborted. [New process 7887] #0 0xb7f49424 in __kernel_vsyscall () #0 0xb7f49424 in __kernel_vsyscall () No symbol table info available. #1 0xb7e0a640 in raise () from /lib/i686/cmov/libc.so.6 No symbol table info available. #2 0xb7e0c018 in abort () from /lib/i686/cmov/libc.so.6 No symbol table info available. #3 0x080d65f5 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:150 backtrace = 0x8ffb548 "/usr/local/libexec/dovecot/imap [0x80d65e1] -> /usr/local/libexec/dovecot/imap [0x80d6662] -> /usr/local/libexec/dovecot/imap [0x80d5ff9] -> /usr/local/libexec/dovecot/imap(mail_cache_lock+0x26a) [0x8"... #4 0x080d6662 in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0x80ea22c "file %s: line %d (%s): assertion failed: (%s)", args=0xbfa62464 "60\017\b<\002") at failures.c:430 No locals. #5 0x080d5ff9 in i_panic ( format=0x80ea22c "file %s: line %d (%s): assertion failed: (%s)") at failures.c:197 No locals. #6 0x080a8a1a in mail_cache_lock (cache=0x901d398, require_same_reset_id=false) at mail-cache.c:572 ext = <value optimized out> iview = (struct mail_index_view *) 0x0 reset_id = 1204318466 i = 0 ret = 0 __PRETTY_FUNCTION__ = "mail_cache_lock" #7 0x080ab0c3 in mail_cache_transaction_lock (ctx=0x9021e18) at mail-cache-transaction.c:201 cache = (struct mail_cache *) 0x901d398 ret = <value optimized out> __PRETTY_FUNCTION__ = "mail_cache_transaction_lock" #8 0x080ac6aa in mail_cache_transaction_commit (_ctx=0x9020b60) at mail-cache-transaction.c:716 ctx = (struct mail_cache_transaction_ctx *) 0x9021e18 cache = (struct mail_cache *) 0x901d398 ret = <value optimized out> #9 0x080b3c46 in mail_index_transaction_commit_v (t=0x9020908, log_file_seq_r=0xbfa62668, log_file_offset_r=0xbfa62660) at mail-index-transaction.c:581 ret = <value optimized out> __PRETTY_FUNCTION__ = "mail_index_transaction_commit_v" #10 0x080a3250 in index_transaction_finish_commit (t=0x9020b78, log_file_seq_r=0xbfa62668, log_file_offset_r=0xbfa62660) at index-transaction.c:38 ret = <value optimized out> __PRETTY_FUNCTION__ = "index_transaction_finish_commit" #11 0x0807480f in maildir_transaction_commit (t=0x9020908, log_file_seq_r=0xbfa62668, log_file_offset_r=0xbfa62660) at maildir-transaction.c:29 mt = (struct maildir_transaction_context *) 0x9020b78 ret = <value optimized out> #12 0x080a30ee in index_transaction_commit (_t=0x9020b78, uid_validity_r=0xbfa62784, first_saved_uid_r=0xbfa62780, last_saved_uid_r=0xbfa6277c) at index-transaction.c:105 itrans = (struct mail_index_transaction *) 0x0 seq = 4 offset = 151056352 #13 0xb7dc97e4 in mail_log_transaction_commit (t=0x9020b78, uid_validity_r=0xbfa62784, first_saved_uid_r=0xbfa62780, last_saved_uid_r=0xbfa6277c) at mail-log-plugin.c:420 lt = (struct mail_log_transaction_context *) 0x0 #14 0xb7ddb60f in quota_mailbox_transaction_commit (ctx=0x9020b78, uid_validity_r=0xbfa62784, first_saved_uid_r=0xbfa62780, last_saved_uid_r=0xbfa6277c) at quota-storage.c:95 qt = (struct quota_transaction_context *) 0x9022150 #15 0xb7dcee94 in fts_transaction_commit (t=0x9020b78, uid_validity_r=0xbfa62784, first_saved_uid_r=0xbfa62780, last_saved_uid_r=0xbfa6277c) at fts-storage.c:707 box = (struct mailbox *) 0x900ee58 ft = (struct fts_transaction_context *) 0x901fdd8 ret = <value optimized out> #16 0x080a4f06 in mailbox_transaction_commit (t=0xbfa627c4) at mail-storage.c:675 uidvalidity = 0 uid1 = 0 uid2 = 0 #17 0x08068beb in imap_sort (cmd=0x90075f0, charset=0x900b788 "ISO-8859-1", args=0x9020128, sort_program=0xbfa6280c) at imap-sort.c:103 client = (struct client *) 0x90073a8 wanted_headers = {0x0, 0x0} wanted_fields = <value optimized out> search_ctx = (struct mail_search_context *) 0x0 t = (struct mailbox_transaction_context *) 0x0 headers_ctx = (struct mailbox_header_lookup_ctx *) 0x0 mail = (struct mail *) 0x0 str = (string_t *) 0x8ffb0f8 written = false ret = 0 #18 0x0806118c in cmd_sort (cmd=0x90075f0) at cmd-sort.c:139 client = (struct client *) 0x90073a8 sargs = (struct mail_search_arg *) 0x0 sorting = {MAIL_SORT_ARRIVAL, MAIL_SORT_END, 42786, 5, 151025136, 151025136, 151041768, 3215337544, 134618590} args = (const struct imap_arg *) 0x900b688 args_count = <value optimized out> pool = (pool_t) 0x9020110 error = <value optimized out> charset = 0x900b788 "ISO-8859-1" #19 0x080627dc in client_command_input (cmd=0x90075f0) at client.c:580 client = (struct client *) 0x90073a8 command = <value optimized out> __PRETTY_FUNCTION__ = "client_command_input" #20 0x0806286f in client_command_input (cmd=0x90075f0) at client.c:629 client = (struct client *) 0x90073a8 command = (struct command *) 0x1ecf __PRETTY_FUNCTION__ = "client_command_input" #21 0x08062e6d in client_handle_input (client=<value optimized out>) at client.c:670 _data_stack_cur_id = 3 ret = <value optimized out> remove_io = <value optimized out> handled_commands = false #22 0x0806337e in client_input (client=0x90073a8) at client.c:725 cmd = <value optimized out> output = (struct ostream *) 0x900752c bytes = <value optimized out> __PRETTY_FUNCTION__ = "client_input" #23 0x080de070 in io_loop_handler_run (ioloop=0x90039b0) at ioloop-epoll.c:203 ctx = (struct ioloop_handler_context *) 0x9003aa8 event = (const struct epoll_event *) 0x9003ae8 list = (struct io_list *) 0x90045c0 io = (struct io_file *) 0x9007588 tv = {tv_sec = 2, tv_usec = 562323} t_id = 2 msecs = <value optimized out> ret = 1 i = 0 j = 0 call = <value optimized out> #24 0x080dd4e0 in io_loop_run (ioloop=0x90039b0) at ioloop.c:320 No locals. #25 0x0806b4ea in main (argc=) at main.c:293 No locals.
- root root@postamt.charite.de:
GNU gdb 6.8-debian Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "i486-linux-gnu"... Reading symbols from /lib/i686/cmov/libdl.so.2...Reading symbols from /usr/lib/debug/lib/i686/cmov/libdl-2.7.so...done. done. Loaded symbols for /lib/i686/cmov/libdl.so.2 Reading symbols from /lib/i686/cmov/libc.so.6...Reading symbols from /usr/lib/debug/lib/i686/cmov/libc-2.7.so...done. done. Loaded symbols for /lib/i686/cmov/libc.so.6 Reading symbols from /lib/ld-linux.so.2...Reading symbols from /usr/lib/debug/lib/ld-2.7.so...done. done. Loaded symbols for /lib/ld-linux.so.2 Reading symbols from /usr/local/lib/dovecot/imap/lib10_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib10_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_trash_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_trash_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_fts_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_fts_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib20_mail_log_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib21_fts_squat_plugin.so Reading symbols from /lib/libgcc_s.so.1...done. Loaded symbols for /lib/libgcc_s.so.1 Core was generated by `/usr/local/libexec/dovecot/imap'. Program terminated with signal 6, Aborted. [New process 15937] #0 0xb7f9c424 in __kernel_vsyscall () #0 0xb7f9c424 in __kernel_vsyscall () No symbol table info available. #1 0xb7e5d640 in raise () from /lib/i686/cmov/libc.so.6 No symbol table info available. #2 0xb7e5f018 in abort () from /lib/i686/cmov/libc.so.6 No symbol table info available. #3 0x080d65f5 in default_fatal_finish (type=<value optimized out>, status=0) at failures.c:150 backtrace = 0x9900390 "/usr/local/libexec/dovecot/imap [0x80d65e1] -> /usr/local/libexec/dovecot/imap [0x80d6662] -> /usr/local/libexec/dovecot/imap [0x80d5ff9] -> /usr/local/libexec/dovecot/imap(mail_cache_lock+0x26a) [0x8"... #4 0x080d6662 in i_internal_fatal_handler (type=LOG_TYPE_PANIC, status=0, fmt=0x80ea22c "file %s: line %d (%s): assertion failed: (%s)", args=0xbfcb7fb4 "60\017\b<\002") at failures.c:430 No locals. #5 0x080d5ff9 in i_panic ( format=0x80ea22c "file %s: line %d (%s): assertion failed: (%s)") at failures.c:197 No locals. #6 0x080a8a1a in mail_cache_lock (cache=0x9914450, require_same_reset_id=false) at mail-cache.c:572 ext = <value optimized out> iview = (struct mail_index_view *) 0x0 reset_id = 1204304370 i = 0 ret = 0 __PRETTY_FUNCTION__ = "mail_cache_lock" #7 0x080a9b70 in mail_cache_header_fields_update (cache=0x9914450) at mail-cache-fields.c:490 ret = <value optimized out> #8 0x080a7764 in mail_cache_view_close (view=0x993fc88) at mail-cache.c:671 __PRETTY_FUNCTION__ = "mail_cache_view_close" #9 0x080a3194 in index_transaction_free (t=0x992e870) at index-transaction.c:24 No locals. #10 0x080a3280 in index_transaction_finish_commit (t=0x992e870, log_file_seq_r=0xbfcb80d8, log_file_offset_r=0xbfcb80d0) at index-transaction.c:48 ret = <value optimized out> __PRETTY_FUNCTION__ = "index_transaction_finish_commit" #11 0x0807480f in maildir_transaction_commit (t=0x992e600, log_file_seq_r=0xbfcb80d8, log_file_offset_r=0xbfcb80d0) at maildir-transaction.c:29 mt = (struct maildir_transaction_context *) 0x992e870 ret = <value optimized out> #12 0x080a30ee in index_transaction_commit (_t=0x992e870, uid_validity_r=0xbfcb81f4, first_saved_uid_r=0xbfcb81f0, last_saved_uid_r=0xbfcb81ec) at index-transaction.c:105 itrans = (struct mail_index_transaction *) 0x0 seq = 0 offset = 0 #13 0xb7e1c7e4 in mail_log_transaction_commit (t=0x992e870, uid_validity_r=0xbfcb81f4, first_saved_uid_r=0xbfcb81f0, last_saved_uid_r=0xbfcb81ec) at mail-log-plugin.c:420 lt = (struct mail_log_transaction_context *) 0x0 #14 0xb7e2e60f in quota_mailbox_transaction_commit (ctx=0x992e870, uid_validity_r=0xbfcb81f4, first_saved_uid_r=0xbfcb81f0, last_saved_uid_r=0xbfcb81ec) at quota-storage.c:95 qt = (struct quota_transaction_context *) 0x9940040 #15 0xb7e21e94 in fts_transaction_commit (t=0x992e870, uid_validity_r=0xbfcb81f4, first_saved_uid_r=0xbfcb81f0, last_saved_uid_r=0xbfcb81ec) at fts-storage.c:707 box = (struct mailbox *) 0x9912e50 ft = (struct fts_transaction_context *) 0x992e9f8 ret = <value optimized out> #16 0x080a4f06 in mailbox_transaction_commit (t=0x990c68c) at mail-storage.c:675 uidvalidity = 0 uid1 = 0 uid2 = 0 #17 0x08064aa5 in imap_fetch_deinit (ctx=0x990c680) at imap-fetch.c:405 i = <value optimized out> #18 0x0805e085 in cmd_fetch_finish (ctx=0x0) at cmd-fetch.c:74 cmd = (struct client_command_context *) 0x990c5f0 ok_message = 0x80ea5ea "OK Fetch completed." #19 0x0805e3a5 in cmd_fetch (cmd=0x990c5f0) at cmd-fetch.c:163 ctx = (struct imap_fetch_context *) 0x990c680 args = (const struct imap_arg *) 0x9910668 search_arg = (struct mail_search_arg *) 0x990c638 messageset = <value optimized out> ret = <value optimized out> #20 0x080627dc in client_command_input (cmd=0x990c5f0) at client.c:580 client = (struct client *) 0x990c3a8 command = <value optimized out> __PRETTY_FUNCTION__ = "client_command_input" #21 0x0806286f in client_command_input (cmd=0x990c5f0) at client.c:629 client = (struct client *) 0x990c3a8 command = (struct command *) 0x3e41 __PRETTY_FUNCTION__ = "client_command_input" #22 0x08062e6d in client_handle_input (client=<value optimized out>) at client.c:670 _data_stack_cur_id = 3 ret = <value optimized out> remove_io = <value optimized out> handled_commands = false #23 0x0806337e in client_input (client=0x990c3a8) at client.c:725 cmd = <value optimized out> output = (struct ostream *) 0x990c52c bytes = <value optimized out> __PRETTY_FUNCTION__ = "client_input" #24 0x080de070 in io_loop_handler_run (ioloop=0x99089b0) at ioloop-epoll.c:203 ctx = (struct ioloop_handler_context *) 0x9908aa8 event = (const struct epoll_event *) 0x9908ae8 list = (struct io_list *) 0x99095c0 io = (struct io_file *) 0x990c588 tv = {tv_sec = 4, tv_usec = 935200} t_id = 2 msecs = <value optimized out> ret = 1 i = 0 j = 0 call = <value optimized out> #25 0x080dd4e0 in io_loop_run (ioloop=0x99089b0) at ioloop.c:320 No locals. #26 0x0806b4ea in main (argc=) at main.c:293 No locals.
- Cor Bosman cor@xs4all.nl:
Oh, now im getting assert failed with those 2 patches applied..
Sep 9 18:33:59 userimap3 dovecot: Panic: IMAP(xxxxx): file mail-cache.c: line 572 (mail_cache_lock): assertion failed: ((ret <= 0 && !cache->locked) || (ret > 0 && cache->locked))
Cor
-- Ralf Hildebrandt (i.A. des IT-Zentrums) Ralf.Hildebrandt@charite.de Charite - Universitätsmedizin Berlin Tel. +49 (0)30-450 570-155 Gemeinsame Einrichtung von FU- und HU-Berlin Fax. +49 (0)30-450 570-962 IT-Zentrum Standort CBF I'm looking for a job!
On Sep 9, 2008, at 7:35 PM, Cor Bosman wrote:
Oh, now im getting assert failed with those 2 patches applied..
Sep 9 18:33:59 userimap3 dovecot: Panic: IMAP(xxxxx): file mail- cache.c: line 572 (mail_cache_lock): assertion failed: ((ret <= 0
&& !cache->locked) || (ret > 0 && cache->locked))
Sorry, this helps: http://hg.dovecot.org/dovecot-1.1/rev/5835adeb6359
Now im seeing these:
Sep 9 19:28:25 userimap3 dovecot: IMAP(xxxxx): file_dotlock_create() failed with index cache file /var/spool/mail/dovecot-control/indexes/u/ul/xxxxx/.Collega Coaching/dovecot.index.cache: Resource temporarily unavailable
Is that any better?
Cor
On Tue, 2008-09-09 at 20:20 +0200, Cor Bosman wrote:
Now im seeing these:
Sep 9 19:28:25 userimap3 dovecot: IMAP(xxxxx): file_dotlock_create() failed with index cache file /var/spool/mail/dovecot-control/indexes/u/ul/xxxxx/.Collega Coaching/dovecot.index.cache: Resource temporarily unavailable
Is that any better?
Yes, although the error message could be changed to "locking timed out". But at least now the error shouldn't be visible to clients (other than small slowdowns due to the 2 second lock wait).
Anyway, the real problem is one of:
a) Dovecot is really locking dovecot.index.cache file for a long time for some reason and other processes are timing out because of it.
b) Some process is crashing and leaving stale dovecot.index.cache.lock files lying around. But that'd have to be a .lock from another server, because on the same server Dovecot checks to see if the PID exists and if not it'll just override the lock immediately.
c) NFS caching problems: the .lock file was deleted by server1 but server2 didn't see that, so it keeps assuming that the file exists long after it was really gone.
On Tue, 2008-09-09 at 21:26 +0300, Timo Sirainen wrote:
On Tue, 2008-09-09 at 20:20 +0200, Cor Bosman wrote:
Now im seeing these:
Sep 9 19:28:25 userimap3 dovecot: IMAP(xxxxx): file_dotlock_create() failed with index cache file /var/spool/mail/dovecot-control/indexes/u/ul/xxxxx/.Collega Coaching/dovecot.index.cache: Resource temporarily unavailable
Is that any better?
Yes, although the error message could be changed to "locking timed out". But at least now the error shouldn't be visible to clients (other than small slowdowns due to the 2 second lock wait).
Anyway, the real problem is one of:
Oh, right, local fs has the same problem, but not with fcntl. That's kind of weird. Then pretty much none of my ideas are valid. It rather sounds like the lock_method=dotlock handling code would be broken. But I just tried and can't reproduce this problem..
Can you reproduce it with imaptest (using a test account so it won't break your mails :)? http://imapwiki.org/ImapTest
Yes, although the error message could be changed to "locking timed out". But at least now the error shouldn't be visible to clients (other than small slowdowns due to the 2 second lock wait).
Anyway, the real problem is one of:
a) Dovecot is really locking dovecot.index.cache file for a long time for some reason and other processes are timing out because of it.
Almost all cache files are very small. There is no reason this should take a long time. Unless there's something weird in the cache building code that keeps it in a never ending state.
b) Some process is crashing and leaving stale dovecot.index.cache.lock files lying around. But that'd have to be a .lock from another server, because on the same server Dovecot checks to see if the PID exists and if not it'll just override the lock immediately.
That could be more likely. We have 30 servers operating on this spool, so if some of them have crashing processes that keep a .lock on a different server, that may cause issues right? Could even be from some old dovecot version? I checked last weeks logs, and i had almost no crashes. About 100 'killed with signal' log lines, out of a few zillion log entries.
im doing a find now on dovecot.index.cache.lock files on our nfs indexes dir.
c) NFS caching problems: the .lock file was deleted by server1 but server2 didn't see that, so it keeps assuming that the file exists long after it was really gone.
But what about this... im also seeing the same problem if I keep nfs=yes and dotlock on a local filesystem instead of NFS. That should exclude any multiple-nfs server issues right? Or will doing nfs=yes on a local FS give weird results?
I should just move everything to Linux..
Cor
On Tue, 2008-09-09 at 20:39 +0200, Cor Bosman wrote:
b) Some process is crashing and leaving stale dovecot.index.cache.lock files lying around. But that'd have to be a .lock from another server, because on the same server Dovecot checks to see if the PID exists and if not it'll just override the lock immediately.
That could be more likely. We have 30 servers operating on this spool, so if some of them have crashing processes that keep a .lock on a different server, that may cause issues right? Could even be from some old dovecot version? I checked last weeks logs, and i had almost no crashes. About 100 'killed with signal' log lines, out of a few zillion log entries.
im doing a find now on dovecot.index.cache.lock files on our nfs indexes dir.
The old code was overriding the .cache.lock files if their mtime was older than 1 minute. The new code is overriding them after 5 minutes. So unless the processes keep crasing all the time it shouldn't be the problem.
c) NFS caching problems: the .lock file was deleted by server1 but server2 didn't see that, so it keeps assuming that the file exists long after it was really gone.
But what about this... im also seeing the same problem if I keep nfs=yes and dotlock on a local filesystem instead of NFS. That should exclude any multiple-nfs server issues right? Or will doing nfs=yes on a local FS give weird results?
Should work fine.
I should just move everything to Linux..
I just tested on my kvm FreeBSD 7.0 installation. I can't reproduce it there either with "imaptest logout=0".
But yes, Linux's NFS client implementation works better with Dovecot than FreeBSD's, since FreeBSD's NFS caches can't be flushed reliably.
I just tested on my kvm FreeBSD 7.0 installation. I can't reproduce it there either with "imaptest logout=0".
Neither can i..
As a test I set 1 server up with local FS again, but with NFS=yes and mmap/fsync etc as if it's nfs index, and im getting the same errors.
So it doesnt seem related to our NSF server.
Cor
On Tue, 2008-09-09 at 23:07 +0200, Cor Bosman wrote:
I just tested on my kvm FreeBSD 7.0 installation. I can't reproduce it there either with "imaptest logout=0".
Neither can i..
As a test I set 1 server up with local FS again, but with NFS=yes and mmap/fsync etc as if it's nfs index, and im getting the same errors.
So you can reproduce it easily with imaptest? Could you post your dovecot -n output so I could see if I can reproduce it on my FreeBSD installation?
Neither can i..
As a test I set 1 server up with local FS again, but with NFS=yes and mmap/fsync etc as if it's nfs index, and im getting the same errors.
So you can reproduce it easily with imaptest? Could you post your dovecot -n output so I could see if I can reproduce it on my FreeBSD installation?
No, i cant reproduce it at all with imaptest, thats why i said 'neither can i'. I get enough of em from customers that i can wait for it though. But i can never predict who gets one. Ive been trying to find a customer that can reproduce it, but so far no luck. Our helpdesk has called some people and they say it usually works fine again if they try again, but then sometimes a day later they get the same problem on a different mail. It usually happens when they delete a file and it gets copied to the trash.
Any specific commands I should try with imaptest?
Still need dovecot -n?
Cor
On Wed, 2008-09-10 at 09:42 +0200, Cor Bosman wrote:
Neither can i..
As a test I set 1 server up with local FS again, but with NFS=yes and mmap/fsync etc as if it's nfs index, and im getting the same errors.
So you can reproduce it easily with imaptest? Could you post your dovecot -n output so I could see if I can reproduce it on my FreeBSD installation?
No, i cant reproduce it at all with imaptest, thats why i said 'neither can i'.
Yes, but the next sentence said you got the errors with a test server. :)
I get enough of em from customers that i can wait for it though. But i can never predict who gets one. Ive been trying to find a customer that can reproduce it, but so far no luck. Our helpdesk has called some people and they say it usually works fine again if they try again, but then sometimes a day later they get the same problem on a different mail. It usually happens when they delete a file and it gets copied to the trash.
Any specific commands I should try with imaptest?
Since it's copying related, try running two instances of imaptest where one copies messages and another runs on the destination box:
./imaptest logout=0 copy=100 copybox=Trash ./imaptest box=Trash append=0
Still need dovecot -n?
I guess it could still show something useful. :)
./imaptest logout=0 copy=100 copybox=Trash ./imaptest box=Trash append=0
Ok, running those 2 now.
Still need dovecot -n?
I guess it could still show something useful. :)
# 1.1.2: /usr/local/etc/dovecot.conf base_dir: /var/run/dovecot/ ssl_ca_file: /etc/ssl/certs/verisign.pem ssl_cert_file: /etc/ssl/certs/userimap.pem ssl_key_file: /etc/ssl/private/userimap.pem disable_plaintext_auth: no login_dir: /var/run/dovecot//login login_executable: /usr/local/libexec/dovecot/imap-login login_greeting: XS4ALL User-IMAP ready. login_process_size: 512 login_processes_count: 32 login_max_processes_count: 1024 max_mail_processes: 1024 mail_max_userip_connections: 32 first_valid_uid: 20 mail_location: maildir:%Nu:INBOX=%Nu:INDEX=/var/spool/mail/dovecot-control/indexes/%1u/%2u/%u:CONTROL=/var/spool/mail/dovecot-control/%1u/%2u/%u/INBOX mailbox_idle_check_interval: 60 mmap_disable: yes mail_nfs_storage: yes mail_nfs_index: yes lock_method: dotlock maildir_stat_dirs: yes mbox_read_locks: dotlock_try mbox_write_locks: dotlock_try mail_executable: /usr/local/libexec/dovecot/rawlog /usr/local/libexec/dovecot/imap mail_process_size: 512 mail_plugins: imap_quota quota imap_capability: IMAP4rev1 SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ IDLE CHILDREN NAMESPACE LOGIN-REFERRALS QUOTA imap_client_workarounds: outlook-idle delay-newmail namespace: type: private separator: / location: maildir:%Nu:INDEX=/var/spool/mail/dovecot-control/indexes/%1u/%2u/%u:INBOX=%Nu:CONTROL=/var/spool/mail/dovecot-control/%1u/%2u/%u/INBOX inbox: yes list: yes subscriptions: yes namespace: type: private separator: / prefix: home/ location: mbox:~/mail/:INDEX=/var/spool/mail/dovecot-control/indexes/%1u/%2u/%u hidden: yes subscriptions: yes auth default: cache_size: 1024 passdb: driver: passwd-file args: /usr/local/etc/dovecot.masterusers passdb: driver: pam args: cache_key=%u%r dovecot userdb: driver: passwd plugin: quota: fs
on 9-10-2008 11:55 AM Cor Bosman spake the following:
./imaptest logout=0 copy=100 copybox=Trash ./imaptest box=Trash append=0
Ok, running those 2 now.
Still need dovecot -n? I guess it could still show something useful. :)
# 1.1.2: /usr/local/etc/dovecot.conf base_dir: /var/run/dovecot/ ssl_ca_file: /etc/ssl/certs/verisign.pem ssl_cert_file: /etc/ssl/certs/userimap.pem ssl_key_file: /etc/ssl/private/userimap.pem disable_plaintext_auth: no
login_dir: /var/run/dovecot//login Is the // above a typo?
-- MailScanner is like deodorant... You hope everybody uses it, and you notice quickly if they don't!!!!
Since it's copying related, try running two instances of imaptest where one copies messages and another runs on the destination box:
./imaptest logout=0 copy=100 copybox=Trash ./imaptest box=Trash append=0
It took about 1.5 hours, but I got 1..running the above 2 tests at the same time.
Sep 10 22:06:41 imap dovecot: IMAP(scorpio): rename(/var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache) failed: No such file or directory Sep 10 22:06:41 imap dovecot: IMAP(scorpio): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache: No such file or directory
Thats on an unpatched server.. default 1.1.2 code. It seems to be a very rare occurance.
Cor
On Wed, 2008-09-10 at 22:49 +0200, Cor Bosman wrote:
Since it's copying related, try running two instances of imaptest where one copies messages and another runs on the destination box:
./imaptest logout=0 copy=100 copybox=Trash ./imaptest box=Trash append=0
It took about 1.5 hours, but I got 1..running the above 2 tests at the same time.
Sep 10 22:06:41 imap dovecot: IMAP(scorpio): rename(/var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache) failed: No such file or directory Sep 10 22:06:41 imap dovecot: IMAP(scorpio): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache: No such file or directory
Thats on an unpatched server.. default 1.1.2 code. It seems to be a very rare occurance.
Looks like I managed to reproduce it in about 5 minutes with the original cache timeouts. imaptest reported that several commands were hanging for over 60 seconds then. I'll try to figure out if this can be prevented.
On Thu, 2008-09-11 at 11:11 +0300, Timo Sirainen wrote:
Sep 10 22:06:41 imap dovecot: IMAP(scorpio): rename(/var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache) failed: No such file or directory Sep 10 22:06:41 imap dovecot: IMAP(scorpio): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache: No such file or directory
Thats on an unpatched server.. default 1.1.2 code. It seems to be a very rare occurance.
Looks like I managed to reproduce it in about 5 minutes with the original cache timeouts. imaptest reported that several commands were hanging for over 60 seconds then. I'll try to figure out if this can be prevented.
This should fix it: http://hg.dovecot.org/dovecot-1.1/rev/7772018e917c
I'll still do some small tweaks for the cache locking code.
Sep 10 22:06:41 imap dovecot: IMAP(scorpio): rename(/var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache) failed: No such file or directory Sep 10 22:06:41 imap dovecot: IMAP(scorpio): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache: No such file or directory
Thats on an unpatched server.. default 1.1.2 code. It seems to be a very rare occurance.
Looks like I managed to reproduce it in about 5 minutes with the original cache timeouts. imaptest reported that several commands were hanging for over 60 seconds then. I'll try to figure out if this can be prevented.
This should fix it: http://hg.dovecot.org/dovecot-1.1/rev/7772018e917c
This is completely seperate from your previous patches?
Cor
On Thu, 2008-09-11 at 17:00 +0200, Cor Bosman wrote:
Sep 10 22:06:41 imap dovecot: IMAP(scorpio): rename(/var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache) failed: No such file or directory Sep 10 22:06:41 imap dovecot: IMAP(scorpio): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/s/sc/scorpio/.Trash/dovecot.index.cache: No such file or directory
Thats on an unpatched server.. default 1.1.2 code. It seems to be a very rare occurance.
Looks like I managed to reproduce it in about 5 minutes with the original cache timeouts. imaptest reported that several commands were hanging for over 60 seconds then. I'll try to figure out if this can be prevented.
This should fix it: http://hg.dovecot.org/dovecot-1.1/rev/7772018e917c
This is completely seperate from your previous patches?
Conceptually at least, but I don't know if it applies cleanly without them.
I've been following this thread: the bug is related with copying mail across NFS in combination with cache locking, right? Cor uses FBSD; but is this a bug that might impact other platforms as well?
Cheers,
Jan
----- Original Message ----- From: "Cor Bosman" cor@xs4all.nl To: "Dovecot Mailing List" dovecot@dovecot.org Cc: "Cor Bosman" cor@xs4all.nl Sent: Thursday, September 11, 2008 5:48 PM Subject: Re: [Dovecot] error in 1.1.2
Conceptually at least, but I don't know if it applies cleanly without them.
Cool! Ive just applied all patches you gave me to our production source, and i'll sync it to a few servers to try it out and see :)
Cor
On Sep 11, 2008, at 9:00 PM, Jan van den Berg wrote:
I've been following this thread: the bug is related with copying
mail across NFS in combination with cache locking, right? Cor uses FBSD; but is this a bug that might impact other platforms
as well?
The main bug here was that with lock_method=dotlock when cache file
was being compressed, it could have tried to lock the cache file
again, seeing that the .lock file already exists (created by itself)
and waiting for it until timeout and then overriding it and causing
the compression to fail. The OS or filesystem didn't matter.
I've been following this thread: the bug is related with copying
mail across NFS in combination with cache locking, right? Cor uses FBSD; but is this a bug that might impact other platforms
as well?The main bug here was that with lock_method=dotlock when cache file
was being compressed, it could have tried to lock the cache file
again, seeing that the .lock file already exists (created by itself)
and waiting for it until timeout and then overriding it and causing
the compression to fail. The OS or filesystem didn't matter.
After I applied the patches the errors disappeared. No problems anymore. Thanks Timo.
Cor
Ive been able to grab the dovecot.rawlog output of a few people with this problem.. basically this is what I see with all of them:
Sep 10 13:43:13 userimap7.xs4all.nl dovecot: IMAP(xxxxxx): rename(/var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache) failed: No such file or directory Sep 10 13:43:13 userimap7.xs4all.nl dovecot: IMAP(xxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache: No such file or directory
da56 UID COPY 11078 "Junk E-mail"
And I see no result in the .out file, so the client waits for a result, doesnt get it, and times out.
I can also absolutely verify that if I take the NFS server out of the equation completely I still get this problem.
Cor
On 9/10/2008 8:10 AM, Cor Bosman wrote:
Ive been able to grab the dovecot.rawlog output of a few people with this problem.. basically this is what I see with all of them:
Sep 10 13:43:13 userimap7.xs4all.nl dovecot: IMAP(xxxxxx): rename(/var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache) failed: No such file or directory Sep 10 13:43:13 userimap7.xs4all.nl dovecot: IMAP(xxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache: No such file or directory
da56 UID COPY 11078 "Junk E-mail"
So this is Outlook and its Junk Email Filters auto-copying these messages...
--
Best regards,
Charles
On 9/10/2008 8:18 AM, Cor Bosman wrote:
da56 UID COPY 11078 "Junk E-mail"
So this is Outlook and its Junk Email Filters auto-copying these messages...
Nah, thats coincidental, the target folder doesnt seem to matter.
Ok, but what about the client - is this outlook specific?
--
Best regards,
Charles
On Wed, 2008-09-10 at 14:10 +0200, Cor Bosman wrote:
Ive been able to grab the dovecot.rawlog output of a few people with this problem.. basically this is what I see with all of them:
Sep 10 13:43:13 userimap7.xs4all.nl dovecot: IMAP(xxxxxx): rename(/var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache) failed: No such file or directory Sep 10 13:43:13 userimap7.xs4all.nl dovecot: IMAP(xxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache: No such file or directory
da56 UID COPY 11078 "Junk E-mail"
And I see no result in the .out file, so the client waits for a result, doesnt get it, and times out.
I can also absolutely verify that if I take the NFS server out of the equation completely I still get this problem.
The above is without my patches I guess? Otherwise it should have waited only 2 seconds?
Sep 10 13:43:13 userimap7.xs4all.nl dovecot: IMAP(xxxxxx): rename(/var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache.lock, /var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache) failed: No such file or directory Sep 10 13:43:13 userimap7.xs4all.nl dovecot: IMAP(xxxxxx): file_dotlock_replace() failed with index cache file /var/spool/mail/dovecot-control/indexes/c/co/xxxxxx/.Junk E-mail/dovecot.index.cache: No such file or directory
da56 UID COPY 11078 "Junk E-mail"
And I see no result in the .out file, so the client waits for a result, doesnt get it, and times out.
I can also absolutely verify that if I take the NFS server out of the equation completely I still get this problem.
The above is without my patches I guess? Otherwise it should have waited only 2 seconds?
Yes, not running your patches. Should I just apply them to all our servers?
Cor
participants (6)
-
Charles Marcus
-
Cor Bosman
-
Jan van den Berg
-
Ralf Hildebrandt
-
Scott Silva
-
Timo Sirainen