Very annoying IMAP problem (cyrus + Outlook)

[Denis BUCHER]

Strange but it doesn't appear in the transaction logs.

Anyway, we think we solved the problem by deleting messages marked as 
being deleted ! ("Expunge" AFAIK ?)

I'll keep you posted in case of new information/discoveries/solutions

Denis

Wesley Craig a écrit :
> On 01 Sep 2008, at 14:50, Denis BUCHER wrote:
>> What should I do next to solve my problem ?
> 
> There are actually a couple of places cyrus might give the fatal error 
> "word too long".  The prot routines should be recording the interactions 
> before passing the data up to the imap layer where the parsing error 
> occurs.  Are there any long lines in your telemetry?  The bad line 
> should directly proceed "* BYE Fatal error: word too long" in the 
> telemetry (if I'm reading imapd's fatal() routine correctly).
> 
> AFAIK, there's nothing to be done other than adjusting the MAXWORD 
> and/or MAXQUOTED limits.  That means upgrading or recompiling the old 
> version that you're on.
> 
> :wes
> 
>> Denis BUCHER a écrit :
>>> David Carter a écrit :
>>>> On Fri, 22 Aug 2008, Denis BUCHER wrote:
>>>>> As far as I understand, the cause of the problem is : * "Outlook is
>>>>> sending either a token or quoted string that is longer than 8K bytes."
>>>> Your problem is a mailbox which contains several thousand messages.
>>>> Possibly several thousand messages which Outlook hasn't seen 
>>>> previously.
>>>>
>>>> Outlook tries to construct a single IMAP command of the form:
>>>>
>>>>  UID FETCH uid,uid,uid,... <some set of fields>
>>>>
>>>> where the list of UIDs is larger than 8 KBytes in size.
>>>
>>> Ok that's what I have :
>>>
>>> a) Logs are present
>>> # ls -l /var/lib/imap/log/dbucher
>>> total 2508
>>> -rw------- 1 cyrus mail 355147 Aug 22 14:43 20235
>>> -rw------- 1 cyrus mail   5327 Aug 22 14:43 25058
>>> -rw------- 1 cyrus mail  10654 Aug 22 14:54 25415
>>> -rw------- 1 cyrus mail 355241 Aug 22 15:24 25416
>>> -rw------- 1 cyrus mail 355537 Aug 22 15:03 25417
>>> -rw------- 1 cyrus mail 355147 Aug 22 14:48 25576
>>> -rw------- 1 cyrus mail   5327 Aug 22 14:59 26381
>>> -rw------- 1 cyrus mail   5327 Aug 22 15:04 26763
>>> -rw------- 1 cyrus mail 355443 Aug 22 15:15 26765
>>> -rw------- 1 cyrus mail   5327 Aug 22 15:09 27095
>>> -rw------- 1 cyrus mail   5327 Aug 22 15:14 27752
>>> -rw------- 1 cyrus mail 360146 Aug 22 15:19 28135
>>> -rw------- 1 cyrus mail   5327 Aug 22 15:24 28463
>>> -rw------- 1 cyrus mail   5327 Aug 22 15:29 29125
>>> -rw------- 1 cyrus mail 355147 Aug 22 15:29 29127
>>>
>>> b) That's the UID FETCH :
>>> # grep "UID FETCH" *
>>> 20235:<1219408982<jbf7 UID FETCH 7136:* (UID FLAGS RFC822.SIZE
>>> BODY.PEEK[HEADER] INTERNALDATE)
>>> 20235:<1219408982<eke2 UID FETCH 1:7135 (UID FLAGS)
>>> 25416:<1219411440<kb1u UID FETCH 7136:* (UID FLAGS RFC822.SIZE
>>> BODY.PEEK[HEADER] INTERNALDATE)
>>> 25416:<1219411440<qv47 UID FETCH 1:7135 (UID FLAGS)
>>> 25417:<1219409521<1ozq UID FETCH 7136:* (UID FLAGS RFC822.SIZE
>>> BODY.PEEK[HEADER] INTERNALDATE)
>>> 25417:<1219409521<h7ki UID FETCH 1:7135 (UID FLAGS)
>>> 25576:<1219409287<ukf6 UID FETCH 7136:* (UID FLAGS RFC822.SIZE
>>> BODY.PEEK[HEADER] INTERNALDATE)
>>> 25576:<1219409287<9vks UID FETCH 1:7135 (UID FLAGS)
>>> 26765:<1219410214<y8b2 UID FETCH 7136:* (UID FLAGS RFC822.SIZE
>>> BODY.PEEK[HEADER] INTERNALDATE)
>>> 26765:<1219410214<b685 UID FETCH 1:7135 (UID FLAGS)
>>> 28135:<1219411131<7bfi UID FETCH 7136:* (UID FLAGS RFC822.SIZE
>>> BODY.PEEK[HEADER] INTERNALDATE)
>>> 28135:<1219411131<dkkx UID FETCH 1:7135 (UID FLAGS)
>>> 29127:<1219411745<4g4y UID FETCH 7136:* (UID FLAGS RFC822.SIZE
>>> BODY.PEEK[HEADER] INTERNALDATE)
>>> 29127:<1219411745<cos6 UID FETCH 1:7135 (UID FLAGS)
>>>
>>> c) Most sessions in the logs seem to finish correctly :
>>> ...
>>> <1219411787<DONE
>>> ZZZZ LOGOUT
>>>> 1219411787>5mk6 OK Completed
>>> * BYE LOGOUT received
>>> ZZZZ OK Completed
>>>
>>> d) But not all :
>>> ==> 30887 <==
>>>> 1219413279>91rc OK Completed
>>> <1219413279<6leo IDLE
>>>> 1219413279>+ idling
>>> <1219413343<DONE
>>>> 1219413343>6leo OK Completed
>>> <1219413343<351h UID STORE 7136 +FLAGS (\Deleted \Seen)
>>>> 1219413343>* 7136 FETCH (FLAGS (\Deleted \Seen) UID 7136)
>>> 351h OK Completed
>>> <1219413343<dpau IDLE
>>>> 1219413343>+ idling
>>> [end of file]
>>>
>>> e) And there are many "Fatal error: word too long" but not with same
>>> number...
>>> Aug 22 14:43:03 atlantic imaps[25050]: Fatal error: word too long
>>> Aug 22 14:48:08 atlantic imaps[25063]: Fatal error: word too long
>>> Aug 22 14:53:24 atlantic imaps[17518]: Fatal error: word too long
>>> Aug 22 14:58:28 atlantic imaps[26379]: Fatal error: word too long
>>> Aug 22 15:03:34 atlantic imaps[26776]: Fatal error: word too long
>>> Aug 22 15:08:40 atlantic imaps[27118]: Fatal error: word too long
>>> Aug 22 15:13:45 atlantic imaps[27749]: Fatal error: word too long
>>> Aug 22 15:18:51 atlantic imaps[27174]: Fatal error: word too long
>>> Aug 22 15:24:01 atlantic imaps[28464]: Fatal error: word too long
>>> Aug 22 15:29:06 atlantic imaps[29123]: Fatal error: word too long
>>>
>>> Normally the watched account having had "Fatal error", I should find a
>>> fatal error in the transactions logs ? Or is nothing written in case of
>>> a Fatal error ? (Which I hope not ;-)
> 


Denis Bucher

-- 

Denis Bucher   Horus Digital Solutions sàrl  Each problem has a solution
___________________________________________________________________________
    Tél. +41-22-8000625     Fax: +41-22-8000622      www.hsolutions.ch