[Dovecot] Index cache errors worse with 2.2.x
Hi!
I am getting "Cached message size smaller than expected" errors since dovecot-2.1.x. Until now, I thought that those errors don't do any harm, I assumed that the cache will just be rebuilt after the error had been detected.
However, since dovecot 2.2.x (I tried 2.2.7 and 2.2.10), the errors sometimes seem to actually cause mail access to fail.
With dovecot-2.1.1, only the first two messages were logged, since using 2.2.7 and 2.2.10, the "read ... failed: Invalid argument" sometimes appear: -------------------- 8< -------------------- May 7 17:03:52 samba dovecot: imap(xyz): Error: Cached message size smaller than expected (2246 < 2247) May 7 17:03:52 samba dovecot: imap(xyz): Error: Corrupted index cache file /home/xyz/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 11277 May 7 17:03:52 samba dovecot: imap(xyz): Error: read(/var/mail/xyz) failed: Invalid argument May 7 17:03:52 samba dovecot: imap(xyz): Error: read(/var/mail/xyz) failed: Invalid argument (uid=11277) -------------------- 8< --------------------
I am using dovecot on RHEL6 with mbox mailboxes. Message size differences are always 1 byte.
Any hints would be appreciated!
Cheers, --leo
P.S.: Those errors occur some times a day and affect different users.. (Upgrade 2.1.1 -> 2.2.7 was on 2013-11-22, 2.2.10 was installed on 2014-01-20.)
# for f in maillog* ; do echo -n "$f: "; grep "dovecot:.*Error: read.*failed.*Invalid arg" $f | wc -l; done maillog: 31 maillog-20130801: 0 maillog-20130901: 1 maillog-20131001: 0 maillog-20131101: 0 maillog-20131201: 30 maillog-20140101: 92 maillog-20140201: 110 maillog-20140301: 99 maillog-20140401: 133 maillog-20140501: 100
# for f in maillog* ; do echo -n "$f: "; grep "dovecot:.*Error: Cached message size smaller than expected" $f | wc -l; done maillog: 99 maillog-20130801: 465 maillog-20130901: 484 maillog-20131001: 512 maillog-20131101: 460 maillog-20131201: 520 maillog-20140101: 402 maillog-20140201: 400 maillog-20140301: 355 maillog-20140401: 481 maillog-20140501: 434
-- e-mail ::: Leo.Bergolth (at) wu.ac.at fax ::: +43-1-31336-906050 location ::: IT-Services | Vienna University of Economics | Austria
On 5/7/2014 4:38 PM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
I am getting "Cached message size smaller than expected" errors since dovecot-2.1.x.
Please provide enough info for someone to actually be able to attempt to help you.
At a bare minimum, you should *always* (not just for dovecot) provide at least the OS/ver and dovecot config (doveconf -n output).
Also, the further from 'default' settings your setup is, the more important it is to provide a description of your environment (ie, is this a single server or a member of a cluster? are you using NFS? etc)...
--
Best regards,
Charles
On 05/08/2014 11:44 AM, Charles Marcus wrote:
On 5/7/2014 4:38 PM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
I am getting "Cached message size smaller than expected" errors since dovecot-2.1.x.
Please provide enough info for someone to actually be able to attempt to help you.
At a bare minimum, you should *always* (not just for dovecot) provide at least the OS/ver and dovecot config (doveconf -n output).
See the doveconf output below.
Also, the further from 'default' settings your setup is, the more important it is to provide a description of your environment (ie, is this a single server or a member of a cluster? are you using NFS? etc)...
I am using a single server, mbox, local disks (/home and /var is XFS on HP SmartArray).
I tried dovecot 2.2.7, 2.2.10 and 2.2.12. All of them produce tha same errors. ("Cached message size smaller than expected", sometimes followed by "read... Invalid argument".)
2.1.1 seems to only produce "Cached message size smaller than expected" without the read errors.
Cheers, --leo
-------------------- 8< -------------------- # 2.2.12: /etc/dovecot/dovecot.conf # OS: Linux 2.6.32-431.3.1.el6.x86_64 x86_64 CentOS release 6.5 (Final) auth_mechanisms = plain login auth_verbose = yes default_vsz_limit = 512 M first_valid_uid = 100 imap_client_workarounds = tb-extra-mailbox-sep login_trusted_networks = 172.23.60.0/24 mail_location = mbox:~/mail:INBOX=/var/mail/%u mail_plugins = " mail_log notify" mail_privileged_group = mail 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 mbox_write_locks = fcntl namespace inbox { inbox = yes location = mbox:~/mail:INBOX=/var/mail/%u mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = separator = / type = private } passdb { driver = pam } plugin { mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size } protocols = imap pop3 service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0666 user = postfix } } service imap-postlogin { executable = script-login -d /usr/local/sbin/dovecot-post-login.pl } service imap { executable = imap imap-postlogin } ssl = required ssl_cert =
-- e-mail ::: Leo.Bergolth (at) wu.ac.at fax ::: +43-1-31336-906050 location ::: IT-Services | Vienna University of Economics | Austria
On 5/8/2014 5:59 AM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
I am using a single server, mbox, local disks (/home and /var is XFS on HP SmartArray).
Hmmm... could be an mbox specific issue (I seem to recall issues in the past that ended up being mbox related, and I think Timo doesn't give mbox as much attention as maildir and dbox).
Also, possibly a kernel issue - you are on a very old one (I know the argument, but I disagree with and have never 'gotten' it). 2.6.32 is 6.5 years old.
Also, did you change default_vsz_limit for a good reason (one should never change defaults unless there is a very specific reason for your setup)? Not that I think that could be causing this particular issue though...
--
Best regards,
Charles
Am 08.05.2014 13:36, schrieb Charles Marcus:
On 5/8/2014 5:59 AM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
I am using a single server, mbox, local disks (/home and /var is XFS on HP SmartArray).
Hmmm... could be an mbox specific issue (I seem to recall issues in the past that ended up being mbox related,
I think it might probably be the same issue that had already been described one year ago for 2.2.0: http://thread.gmane.org/gmane.mail.imap.dovecot/71636 (Although in my case, the "Cached message size smaller than expected" difference is always 1 byte.)
and I think Timo doesn't give mbox as much attention as maildir and dbox).
Too bad. Unfortunately it's not easy to switch for me. :-( Is mbox really such an uncommon scenario with dovecot? AFAIK it's the default config shipped with most linux distros..
Also, possibly a kernel issue - you are on a very old one (I know the argument, but I disagree with and have never 'gotten' it). 2.6.32 is 6.5 years old.
Hmm - I think that's very unlikely a kernel issue. It's a Redhat EL 6 kernel so that kernel is actively maintained and very widely used.
Also, did you change default_vsz_limit for a good reason
Yes. I suppose. ;-) However, I don't remember that reason now. :-) Maybe I read some recommendation about that? Maybe about large mailboxes?
Cheers, --leo
e-mail ::: Leo.Bergolth (at) wu.ac.at fax ::: +43-1-31336-906050 location ::: IT-Services | Vienna University of Economics | Austria
Le 8 mai 2014 à 11:59, Alexander 'Leo' Bergolth a écrit :
[...] I am using a single server, mbox, local disks (/home and /var is XFS on HP SmartArray).
I tried dovecot 2.2.7, 2.2.10 and 2.2.12. All of them produce tha same errors. ("Cached message size smaller than expected", sometimes followed by "read... Invalid argument".)
2.1.1 seems to only produce "Cached message size smaller than expected" without the read errors.
Cheers, --leo
[...] mbox_write_locks = fcntl [...]
Hello Alexander,
Your error messages seem to be related to the user's INBOX. On the other hand, your config doesn't make appear lda nor lmtp (or I missed it, in which case, well... sorry). Who puts the incoming messages into the mboxes?
Axel
On 05/13/2014 12:43 PM, Axel Luttgens wrote:
Le 8 mai 2014 à 11:59, Alexander 'Leo' Bergolth a écrit :
[...] I am using a single server, mbox, local disks (/home and /var is XFS on HP SmartArray).
I tried dovecot 2.2.7, 2.2.10 and 2.2.12. All of them produce tha same errors. ("Cached message size smaller than expected", sometimes followed by "read... Invalid argument".)
2.1.1 seems to only produce "Cached message size smaller than expected" without the read errors.
Cheers, --leo
[...] mbox_write_locks = fcntl [...]
Hello Alexander,
Your error messages seem to be related to the user's INBOX.
They appear with different users and are not always related to inboxes. I've also encountered those messages with other mailboxes, like /home/$USER/mail/Trash.
"doveadm force-resync" doesn't fix them.
On the other hand, your config doesn't make appear lda nor lmtp (or I missed it, in which case, well... sorry). Who puts the incoming messages into the mboxes?
Mail is delivered via maildrop (maildrop-2.5.0-13.el6.x86_64).
I don't think that it is a mailbox lock problem between LDA and dovecot, since
- the errors occur with mailboxes other than INBOX
- there is no mail delivery logged between the last imap logout and the error:
-------------------- 8< --------------------
May 13 10:16:46 samba dovecot: imap-login: Login: user=<USERX>, method=PLAIN, rip=172.23.60.1, lip=172.23.60.3, mpid=6875, secured, session=<leNZr0P5NQCsFzwB>
May 13 10:18:06 samba dovecot: imap(USERX): Disconnected: Logged out in=507 out=4607
May 13 10:19:56 samba dovecot: imap-login: Login: user=<USERX>, method=PLAIN, rip=172.23.60.1, lip=172.23.60.3, mpid=7686, secured, session=<NAaoukP5OQCsFzwB>
May 13 10:37:05 samba dovecot: imap-login: Login: user=<USERX>, method=PLAIN, rip=172.23.60.1, lip=172.23.60.3, mpid=12234, secured, session=<tQX990P5aACsFzwB>
May 13 10:38:04 samba dovecot: imap-login: Login: user=<USERX>, method=PLAIN, rip=172.23.60.1, lip=172.23.60.3, mpid=12483, secured, session=
However I do often see multiple imap logins before the errors. Maybe it's a dovecot internal cache locking issue?
Cheers, --leo
e-mail ::: Leo.Bergolth (at) wu.ac.at
fax ::: +43-1-31336-906050
location ::: IT-Services | Vienna University of Economics | Austria
On 05/08/2014 11:59 AM, Alexander 'Leo' Bergolth wrote:
On 05/08/2014 11:44 AM, Charles Marcus wrote:
On 5/7/2014 4:38 PM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
I am getting "Cached message size smaller than expected" errors since dovecot-2.1.x.
I tried dovecot 2.2.7, 2.2.10 and 2.2.12. All of them produce tha same errors. ("Cached message size smaller than expected", sometimes followed by "read... Invalid argument".)
This really drives me to despair! :-( Timo please help!
I also tried dovecot-2.2.13 and even downgraded to dovecot-2.1.17 now. (Did a doveadm -v force-resync -u $user "*" for all users after changing versions.) I can also see somehow similar problems on another box that uses (the rather old) dovecot 2.1.1.
I tried to add dotlock to mbox_write_locks since according to the source, the LDA (maildrop) seems to try dotlock before fcntl. I also changed fcntl to dotlock for locking index files. (lock_method = dotlock) The only processes that access a users mailboxes are dovecot (imap and pop) and maildrop (LDA).
The only non-standard setup I can identify is that I am using an imap-postlogin script that dynamically adds some additional namespaces via environment variables for some users that have access to shared mailboxes. But I doubt wether this can have an influence on the index.cache errors.
I'd greatly appreciate your help!
Thanks, --leo
maillogs,dovecot config and additional information can be found at: http://leo.kloburg.at/tmp/dovecot-index/
2.2.13 Errors: -------------------- 8< -------------------- May 19 05:51:15 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (75357 < 75358) May 19 05:51:15 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 70929 May 19 05:51:15 samba dovecot: imap(USER1): Error: copy: i_stream_read() failed: Invalid argument May 19 05:51:15 samba dovecot: imap(USER1): Error: mail parser: read(/var/mail/USER1, box=Trash) failed: Invalid argument May 19 07:23:59 samba dovecot: imap(USER2): Error: Cached message size smaller than expected (75357 < 75358) May 19 07:23:59 samba dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 18322 May 19 07:23:59 samba dovecot: imap(USER2): Error: read(/var/mail/USER2) failed: Cached message size smaller than expected (75357 < 75358) (FETCH BODY[] for mailbox INBOX UID 18322) May 19 07:48:11 samba dovecot: imap(USER3): Error: Cached message size smaller than expected (13510 < 13511) May 19 07:48:11 samba dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 952 May 19 07:48:11 samba dovecot: imap(USER3): Error: read(/var/mail/USER3) failed: Cached message size smaller than expected (13510 < 13511) (FETCH BODY[2] for mailbox INBOX UID 952) May 19 07:58:45 samba dovecot: imap(USER4): Error: Cached message size smaller than expected (1892192 < 1892193) May 19 07:58:45 samba dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 20561 May 19 07:58:45 samba dovecot: imap(USER4): Error: copy: i_stream_read() failed: Invalid argument May 19 07:58:45 samba dovecot: imap(USER4): Error: mail parser: read(/var/mail/USER4, box=Stab) failed: Invalid argument May 19 08:58:44 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (185239 < 185240) May 19 08:58:44 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 70934 May 19 08:58:44 samba dovecot: imap(USER1): Error: read(/var/mail/USER1) failed: Cached message size smaller than expected (185239 < 185240) (FETCH BODY[] for mailbox INBOX UID 70934) May 19 09:00:00 samba dovecot: imap(USER2): Error: Cached message size smaller than expected (185239 < 185240) May 19 09:00:00 samba dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 18324 May 19 09:00:00 samba dovecot: imap(USER2): Error: copy: i_stream_read() failed: Invalid argument May 19 09:00:00 samba dovecot: imap(USER2): Error: mail parser: read(/var/mail/USER2, box=Trash) failed: Invalid argument May 19 09:56:47 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (1829385 < 1829386) May 19 09:56:47 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 70938 May 19 09:56:47 samba dovecot: imap(USER1): Error: copy: i_stream_read() failed: Invalid argument May 19 09:56:47 samba dovecot: imap(USER1): Error: mail parser: read(/var/mail/USER1, box=Trash) failed: Invalid argument May 19 10:11:48 samba dovecot: imap(USER5): Error: Cached message size smaller than expected (75357 < 75358) May 19 10:11:48 samba dovecot: imap(USER5): Error: Corrupted index cache file /home/USER5/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 24136 May 19 10:11:48 samba dovecot: imap(USER5): Error: read(/var/mail/USER5) failed: Cached message size smaller than expected (75357 < 75358) (FETCH BODY[] for mailbox INBOX UID 24136) -------------------- 8< --------------------
2.1.17 Errors: -------------------- 8< -------------------- May 22 12:36:29 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (63266 < 63267) May 22 12:36:29 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 71075 May 22 12:38:01 samba dovecot: imap(USER2): Error: Cached message size smaller than expected (221845 < 221846) May 22 12:38:01 samba dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 2871 May 22 12:38:01 samba dovecot: imap(USER2): Error: read(/var/mail/USER2) failed: Input/output error (FETCH for mailbox INBOX UID 2871) May 22 12:38:02 samba dovecot: imap(USER2): Error: Cached message size smaller than expected (221845 < 221846) May 22 12:38:02 samba dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 2871 May 22 12:56:02 samba dovecot: imap(USER3): Error: Cached message size smaller than expected (57091 < 57092) May 22 12:56:02 samba dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 18358 May 22 12:56:02 samba dovecot: imap(USER3): Error: read(/var/mail/USER3) failed: Input/output error (FETCH for mailbox INBOX UID 18358) May 22 12:56:11 samba dovecot: imap(USER3): Error: Cached message size smaller than expected (57091 < 57092) May 22 12:56:11 samba dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 18358 May 22 12:56:11 samba dovecot: imap(USER3): Error: read(/var/mail/USER3) failed: Input/output error (FETCH for mailbox INBOX UID 18358) May 22 13:21:26 samba dovecot: imap(USER4): Error: Cached message size smaller than expected (57091 < 57092) May 22 13:21:26 samba dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 11275 May 22 13:21:26 samba dovecot: imap(USER4): Error: read(/var/mail/USER4) failed: Input/output error (FETCH for mailbox INBOX UID 11275) May 22 14:03:02 samba dovecot: imap(USER5): Error: Cached message size smaller than expected (16034 < 16035) May 22 14:03:02 samba dovecot: imap(USER5): Error: Corrupted index cache file /home/USER5/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 11394 May 22 14:03:02 samba dovecot: imap(USER5): Error: read(/var/mail/USER5) failed: Input/output error (uid=11394) May 22 14:35:49 samba dovecot: imap(USER6): Error: Cached message size smaller than expected (10925 < 10926) May 22 14:35:49 samba dovecot: imap(USER6): Error: Corrupted index cache file /home/USER6/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 23149 May 22 14:43:08 samba dovecot: imap(USER1): Error: Cached message size smaller than expected (616708 < 616709) May 22 14:43:08 samba dovecot: imap(USER1): Error: Corrupted index cache file /home/USER1/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 71078 May 22 14:43:08 samba dovecot: imap(USER1): Error: read(/var/mail/USER1) failed: Input/output error (FETCH for mailbox INBOX UID 71078) May 22 14:51:52 samba dovecot: imap(USER5): Error: Cached message size smaller than expected (10924 < 10925) May 22 14:51:52 samba dovecot: imap(USER5): Error: Corrupted index cache file /home/USER5/mail/.imap/INBOX/dovecot.index.cache: Broken physical size for mail UID 11499 May 22 14:51:52 samba dovecot: imap(USER5): Error: read(/var/mail/USER5) failed: Input/output error (uid=11499) -------------------- 8< --------------------
2.1.1 on another box: -------------------- 8< -------------------- Mar 4 20:32:44 strike dovecot: imap(USER1): Error: Log synchronization error at seq=1,offset=2656 for /home/USER1/mail/.imap/Drafts/dovecot.index: Extension header update points outside header size Mar 4 20:32:44 strike dovecot: imap(USER1): Error: Log synchronization error at seq=1,offset=2744 for /home/USER1/mail/.imap/Drafts/dovecot.index: Extension header update points outside header size Mar 4 20:32:44 strike dovecot: imap(USER1): Error: Log synchronization error at seq=1,offset=2832 for /home/USER1/mail/.imap/Drafts/dovecot.index: Extension header update points outside header size Mar 10 07:27:00 strike dovecot: imap(USER2): Error: Cached message size larger than expected (10369 > 10337) Mar 10 07:27:00 strike dovecot: imap(USER2): Error: Corrupted index cache file /home/USER2/mail/.imap/Sent/dovecot.index.cache: Broken physical size for mail UID 606 Mar 10 07:27:00 strike dovecot: imap(USER2): Error: read(/home/USER2/mail/Sent) failed: Input/output error (FETCH for mailbox Sent UID 606) Mar 11 10:45:21 strike dovecot: imap(USER3): Error: Cached message size larger than expected (1066719 > 1065140) Mar 11 10:45:21 strike dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/Drafts/dovecot.index.cache: Broken physical size for mail UID 458 Mar 11 10:45:21 strike dovecot: imap(USER3): Error: Cached message size larger than expected (1066719 > 1065140) Mar 11 10:45:21 strike dovecot: imap(USER3): Error: Corrupted index cache file /home/USER3/mail/.imap/Drafts/dovecot.index.cache: Broken physical size for mail UID 458 Mar 11 10:45:21 strike dovecot: imap(USER3): Error: copy: i_stream_read() failed: Input/output error Mar 17 19:47:29 strike dovecot: imap(USER4): Error: Cached message size larger than expected (4093 > 3364) Mar 17 19:47:29 strike dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/Drafts/dovecot.index.cache: Broken physical size for mail UID 20089 Mar 17 19:47:29 strike dovecot: imap(USER4): Error: Cached message size larger than expected (4093 > 3364) Mar 17 19:47:29 strike dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/Drafts/dovecot.index.cache: Broken physical size for mail UID 20089 Mar 17 19:47:29 strike dovecot: imap(USER4): Error: copy: i_stream_read() failed: Input/output error Apr 2 18:06:39 strike dovecot: imap(USER5): Error: Log synchronization error at seq=1,offset=30176 for /home/USER5/mail/.imap/virus/dovecot.index: Extension header update points outside header size Apr 16 18:49:26 strike dovecot: imap(USER4): Error: FETCH [] for mailbox Drafts UID 20428 got too little data: 9936 vs 10490 Apr 16 18:49:26 strike dovecot: imap(USER4): Error: Corrupted index cache file /home/USER4/mail/.imap/Drafts/dovecot.index.cache: Broken virtual size for mail UID 20428 Apr 28 16:04:56 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=3900 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size Apr 28 16:04:56 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=3988 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size Apr 28 16:04:56 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=4076 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size Apr 28 16:04:59 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=4164 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size Apr 28 16:05:34 strike dovecot: imap(USER6): Error: Log synchronization error at seq=1,offset=4340 for /home/USER6/mail/.imap/Berni/dovecot.index: Extension header update points outside header size May 12 13:34:52 strike dovecot: imap(USER4): Error: Log synchronization error at seq=2,offset=240 for /home/USER4/mail/.imap/Junk/dovecot.index: Extension header update points outside header size May 12 21:59:29 strike dovecot: imap(USER5): Error: Log synchronization error at seq=1,offset=30264 for /home/USER5/mail/.imap/virus/dovecot.index: Extension header update points outside header size -------------------- 8< --------------------
-------------------- 8< -------------------- # 2.2.12: /etc/dovecot/dovecot.conf # OS: Linux 2.6.32-431.3.1.el6.x86_64 x86_64 CentOS release 6.5 (Final) auth_mechanisms = plain login auth_verbose = yes default_vsz_limit = 512 M first_valid_uid = 100 imap_client_workarounds = tb-extra-mailbox-sep login_trusted_networks = 172.23.60.0/24 mail_location = mbox:~/mail:INBOX=/var/mail/%u mail_plugins = " mail_log notify" mail_privileged_group = mail 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 mbox_write_locks = fcntl namespace inbox { inbox = yes location = mbox:~/mail:INBOX=/var/mail/%u mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = separator = / type = private } passdb { driver = pam } plugin { mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size } protocols = imap pop3 service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0666 user = postfix } } service imap-postlogin { executable = script-login -d /usr/local/sbin/dovecot-post-login.pl } service imap { executable = imap imap-postlogin } ssl = required ssl_cert =
--
e-mail ::: Leo.Bergolth (at) wu.ac.at
fax ::: +43-1-31336-906050
location ::: IT-Services | Vienna University of Economics | Austria
On 23.5.2014, at 2.54, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
On 05/08/2014 11:59 AM, Alexander 'Leo' Bergolth wrote:
On 05/08/2014 11:44 AM, Charles Marcus wrote:
On 5/7/2014 4:38 PM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
I am getting "Cached message size smaller than expected" errors since dovecot-2.1.x.
I tried dovecot 2.2.7, 2.2.10 and 2.2.12. All of them produce tha same errors. ("Cached message size smaller than expected", sometimes followed by "read... Invalid argument".)
This really drives me to despair! :-( Timo please help!
I highly recommend switching away from mbox format. This of course should be fixed, but mbox code is currently pretty low priority on my list of things to fix.
On 23.05.2014 22:03, Timo Sirainen wrote:
On 5/7/2014 4:38 PM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
I am getting "Cached message size smaller than expected" errors since dovecot-2.1.x.
I tried dovecot 2.2.7, 2.2.10 and 2.2.12. All of them produce tha same errors. ("Cached message size smaller than expected", sometimes followed by "read... Invalid argument".)
This really drives me to despair! :-( Timo please help!
I highly recommend switching away from mbox format. This of course should be fixed, but mbox code is currently pretty low priority on my list of things to fix.
I'd understand and support that if we were talking about some esoteric unusual mailbox format.
However, mbox is still standard for many distributions and is used in a huge number of small-scale mailserver installations.
Dovecots documentation doesn't mention that mbox support is broken. Quite contrary even the homepage states: "while still supporting the standard mbox and Maildir formats". The mbox Wiki page says that mbox is standard on usual Unix systems and praises dovecots indexing: "the mbox format is typically thought of as a slow format. However with Dovecot's indexing this isn't true."
Timo, I really appreciate your work on dovecot. I am successfully using dovecot (and mbox) for more then 10 years now and I still believe that it is the number one choice.
However, I think this misleading information should really be replaced with big fat warnings about broken mbox support. Moreover the linux distributions should be warned to not ship mbox mail delivery configurations by default.
I'll consider switching to another mailbox format but such a migration is not a snap decision, it has to be well considered. I cannot switch overnight and thus it's really frustrating having to accept a broken mail system for the meantime. Deprecation warnings would have helped here.
Cheers, --leo
e-mail ::: Leo.Bergolth (at) wu.ac.at fax ::: +43-1-31336-906050 location ::: IT-Services | Vienna University of Economics | Austria
Le 23 mai 2014 à 11:54, Alexander 'Leo' Bergolth a écrit :
[...]
I tried to add dotlock to mbox_write_locks since according to the source, the LDA (maildrop) seems to try dotlock before fcntl.
Hello Alexander,
I don't know very much about maildrop, but isn't this configurable, perhaps thru maildroprc or such? I'm asking, because guessing about such matters may be somewhat audacious...
I also changed fcntl to dotlock for locking index files. (lock_method = dotlock)
Such a change shouldn't be needed (and could even lead to inefficiencies), since only Dovecot software is supposed to handle those index files. Or could it be that you have some concerns with XFS's locking capabilities?
The only processes that access a users mailboxes are dovecot (imap and pop) and maildrop (LDA).
It could be interesting to see a raw message as delivered by maildrop under your mail system. Could you try something along these lines?
- prepare a user's environment:
- create a test user
- send him some messages, access his mboxes thru pop, imap..., move, delete some messages...
- do not access that user's account anymore
- send a short message to that user, perhaps one with some frills (i.e. a bit more complicated than just plain ASCII)
- do a cat on that user's inbox (or, probably better, a hexdump -C)
The only non-standard setup I can identify is that I am using an imap-postlogin script that dynamically adds some additional namespaces via environment variables for some users that have access to shared mailboxes. But I doubt wether this can have an influence on the index.cache errors.
Who knows? ;-)
Now, those errors seem to occur only with IMAP, never with POP. More precisely, within imap processes. Is this really the case? If yes, this could provide a hint.
Again, as far as I can tell, the cache-related error messages seem to occur only with INBOX, never with another mailbox.
On the other hand, the error messages related to "invalid arguments" either do not specify a mailbox, or specify a non-INBOX mailbox (e.g., "Trash", "A_TO_DO", "A_ZV-Zahlungsvorschlag"...). And the most precise of those message mention "mail parser: read(" or "copy: i_stream_read() failed".
Putting all these pieces together might perhaps lead someone more knowledgeable to an explanation...
HTH, Axel
On 05/07/2014 10:38 PM, Alexander 'Leo' Bergolth wrote:
I am getting "Cached message size smaller than expected" errors since dovecot-2.1.x. Until now, I thought that those errors don't do any harm, I assumed that the cache will just be rebuilt after the error had been detected.
However, since dovecot 2.2.x (I tried 2.2.7 and 2.2.10), the errors sometimes seem to actually cause mail access to fail.
dovecot 2.2.12 and 2.2.13 also show the same errors:
-------------------- 8< --------------------
May 13 10:38:07 samba dovecot: imap-login: Login: user=<xxx>, method=PLAIN, rip=172.23.60.1, lip=172.23.60.3, mpid=12503, secured, session=
As before, message size difference is always 1 byte.
Is there any debug mode that could be used to collect more information without flooding the server?
Cheers, --leo
e-mail ::: Leo.Bergolth (at) wu.ac.at
fax ::: +43-1-31336-906050
location ::: IT-Services | Vienna University of Economics | Austria
On 5/13/2014 5:46 AM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
May 13 10:38:08 samba dovecot: imap(xxx): Disconnected: Internal error occurred. Refer to server log for more information. [2014-05-13 10:38:07] in=794 out=264037
So... what does server log show?
--
Best regards,
Charles
On 05/13/2014 01:03 PM, Charles Marcus wrote:
On 5/13/2014 5:46 AM, Alexander 'Leo' Bergolth leo@strike.wu.ac.at wrote:
May 13 10:38:08 samba dovecot: imap(xxx): Disconnected: Internal error occurred. Refer to server log for more information. [2014-05-13 10:38:07] in=794 out=264037
So... what does server log show?
That's it. (The previous lines are all that gets logged.)
--leo
e-mail ::: Leo.Bergolth (at) wu.ac.at fax ::: +43-1-31336-906050 location ::: IT-Services | Vienna University of Economics | Austria
participants (4)
-
Alexander 'Leo' Bergolth
-
Axel Luttgens
-
Charles Marcus
-
Timo Sirainen