Connect. Communicate. Collaborate. Securely.

Home » Kerio User Forums » Kerio Connect » Timeout accessing the Drafts folder. You may not even be aware this is happening.
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
First, let me say we're a new Kerio customer. And while overall we're happy with the server, I can't say the same for Kerio's support. It's almost nonexistent & they take days to reply if at all. This is why I've turned to this forum for your help.

We installed Kerio about 4 months ago. Everything seems to work nicely. But upon closer examination we have a problem that can become very serious under load.

There's about 50 macs (10.5 & 10.4) connecting, & we're running the latest Kerio server on a very basic Centos5.2 install (no SELinux, antivirus, etc.). File permissions are consistent & seem appropriate.

Everything seemed to be working normally. But one day I had the Activity Viewer open while using Mail.app & I noticed 2 connections to the server:
Communicating with server [Drafts] Fetching; 
Updating cache directory Received 1 of 48 headers.
The first connection keeps trying until it eventually times out. Meanwhile the 2nd connection just sits there idle waiting for the 1st connection to finish. It times out in about 90 seconds or so.

I ran IMAP in debug & could see a lot of entries for my connection.
[04/Feb/2009 15:48:45][3907] {imaps} Peek FETCH executed on message 00000998 in folder ~adam<_a.t_>OurCompany.com/Drafts

[04/Feb/2009 15:48:45][3907] {imaps} Update: 0 expunges, 0 flags, 49 exists, 0 recent, 1 expunges waiting

[04/Feb/2009 15:48:45][3907] {imaps} Sent 1 fetch responses

[04/Feb/2009 15:48:45][3907] {imaps} Command 601118.26 FETCH 49:* (INTERNALDATE UID RFC822.SIZE FLAGS 
BODY.PEEK[HEADER.FIELDS (date subject from to cc message-id in-reply-to references x-priority 
x-mail-rss-source-name x-uniform-type-identifier x-universally-unique-identifier x-apple-mail-todo-message-id 
x-apple-mail-todo-id received-spf x-spam-status x-spam-flag content-type)])

This last line repeats nearly 400 times a second until it eventually times out. Over 90 seconds, times X users, explains the periodic unusually high load on our server.

The only thing that changes is the command ID. For example, one line says "Command 601692.26", the next "Command 601693.26", then "Command 601695.26", etc.

I tried deleting all the *.fld files in the Drafts folder as recommended in the Kerio forums. The first time mail.app connects to the Drafts folder it works normally. But shortly thereafter the problem reoccurs.

If anyone has any suggestions or is experieincing this problem, I'd really appreciated your feedback. Sorry for the long post, & thanks in advance.
  •  
Pavel Dobry (Kerio)

Messages: 5245
Karma: 251
Send a private message to this user
Looks like possible bug in Apple Mail. It is not normal to send such amount of requests to the server. I would recommend following steps:

1. create new account in Apple Mail to exclude possible corruption of Apple Mail database
2. switch account to IMAP (with no SSL) and get network trace (eg. with sudo tcpdump -i en0 -s 0 "tcp port 143") so we can analyze what the Apple Mail is trying to do.
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
Thank you very much for the suggestion. When I get in to work tomorrow I'll give it try. Thanks again!
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
Sorry for the delay--we had a WAN outage yesterday that had us scrambling. Much better today : )

I took your suggestion & interrogated the transactions. I can see what's happening and I think this is a Kerio issue.

LOG FROM WIRESHARK 
some of the descriptions are truncated
------------------
259	621.871030	<user>	KERIO	IMAP	Request: 84.9 SELECT Drafts
260	621.871439	KERIO	<user>	IMAP	Response: 84.9 OK [READ-WRITE] SELECT completed\r\n * FLAGS (\Deleted \Seen \Answered \Draft \Flagged $MDNSent $Forwarded $AutoJunk $AutoNotJunk $Junk $NotJunk)

262	621.872819	<user>	KERIO	IMAP	Request: 85.9 FETCH 1:52 (FLAGS UID)
264	621.873641	KERIO	<user>	IMAP	Response: 85.9 OK FETCH completed\r\n

266	621.881812	<user>	KERIO	IMAP	Request: 86.9 APPEND Drafts (\Seen \Draft $NotJunk) "20-Feb-2009 10:49:16 -0600" {4501+}
267	621.881908	<user>	KERIO	IMAP	Request: X-Uniform-Type-Identifier: com.apple.mail-draft
268	621.881914	<user>	KERIO	IMAP	Request: ace; -webkit-line-break: =
269	621.881917	<user>	KERIO	IMAP	Request:  sans-serif;=3D"" font-size:=3D"" 11px;=3D"" =
272	621.882818	<user>	KERIO	IMAP	Request: erted-space">&nbsp;</span><a =
273	621.883764	KERIO	<user>	IMAP	Response: 86.9 OK [APPENDUID 1233785626 3567] APPEND completed\r\n	* 53 EXISTS

275	621.886988	<user>	KERIO	IMAP	Request: 87.9 UID FETCH 3567 (BODYSTRUCTURE BODY.PEEK[])
276	621.887760	KERIO	<user>	IMAP	Response: * 53 FETCH (UID 3567 BODYSTRUCTURE ("text" "html" ("charset" "US-ASCII") NIL NIL "quoted-printable" 3845 59 NIL NIL NIL) BODY[] {4501}
277	621.887877	KERIO	<user>	IMAP	Response: : none; -webkit-text-size-adjust: =
278	621.887987	KERIO	<user>	IMAP	Response: bsp-mode: space; -webkit-line-break: =
280	621.888310	KERIO	<user>	IMAP	Response: 87.9 OK UID FETCH completed\r\n	ottom-style: dotted; =

282	621.894433	<user>	KERIO	IMAP	Request: 88.9 UID STORE 3566 +FLAGS.SILENT (\Seen \Deleted)
283	621.895262	KERIO	<user>	IMAP	Response: 88.9 OK UID STORE completed

285	621.895630	<user>	KERIO	IMAP	Request: 89.9 FETCH 53:* (INTERNALDATE UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from to cc message-id in-reply-to references x-priority x-mail-rss-source-name x-uniform-type-identifier x-universally-unique-identifier x-apple-mail-todo-message-id x-apple-mail-todo-id received-spf x-spam-status x-spam-flag content-type)])
286	621.896395	KERIO	<user>	IMAP	Response: 89.9 OK FETCH completed\r\n	* 52 FETCH (UID 3567 RFC822.SIZE 4501 INTERNALDATE "20-Feb-2009 10:49:16 -0600" BODY[HEADER.FIELDS ("date" "subject" "from" "to" "cc" "message-id" "in-reply-to" "references" "x-priority" "x-mail-rss-source-name" "x-uniform-type-identifier" "x-universally-unique-identifier" "x-apple-mail-todo-message-id" "x-apple-mail-todo-id" "received-spf" "x-spam-status" "x-spam-flag" "content-type")] {377}

288	621.897046	<user>	KERIO	IMAP	Request: 90.9 FETCH 53:* (INTERNALDATE UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from to cc message-id in-reply-to references x-priority x-mail-rss-source-name x-uniform-type-identifier x-universally-unique-identifier x-apple-mail-todo-message-id x-apple-mail-todo-id received-spf x-spam-status x-spam-flag content-type)])
289	621.897847	KERIO	<user>	IMAP	Response: 90.9 OK FETCH completed\r\n	* 52 FETCH (UID 3567 RFC822.SIZE 4501 INTERNALDATE "20-Feb-2009 10:49:16 -0600" BODY[HEADER.FIELDS ("date" "subject" "from" "to" "cc" "message-id" "in-reply-to" "references" "x-priority" "x-mail-rss-source-name" "x-uniform-type-identifier" "x-universally-unique-identifier" "x-apple-mail-todo-message-id" "x-apple-mail-todo-id" "received-spf" "x-spam-status" "x-spam-flag" "content-type")] {377}

<repeats until timeout>

###


KERIO IMAP LOG
--------------

    [20/Feb/2009 10:48:46][14857] {imaps} Command 79.9 APPEND Drafts (\Seen \Draft $NotJunk) "20-Feb-2009 10:48:46 -0600" {4488+}
    [20/Feb/2009 10:48:46][14857] {imaps} Update: 0 expunges, 0 flags, 53 exists, 0 recent, 0 expunges waiting
    [20/Feb/2009 10:48:46][14857] {imaps} 79.9 OK [APPENDUID 1233785626 3566] APPEND completed
    [20/Feb/2009 10:48:46][14857] {imaps} Command 80.9 UID FETCH 3566 (BODYSTRUCTURE BODY.PEEK[])
    [20/Feb/2009 10:48:46][14857] {imaps} Sent 1 fetch responses


1   [20/Feb/2009 10:49:16][14857] {imaps} Command 84.9 SELECT Drafts
2   [20/Feb/2009 10:49:16][14857] {imaps} Command 85.9 FETCH 1:52 (FLAGS UID)
3   [20/Feb/2009 10:49:16][14857] {imaps} Sent 52 fetch responses
4   [20/Feb/2009 10:49:16][14857] {imaps} Command 86.9 APPEND Drafts (\Seen \Draft $NotJunk) "20-Feb-2009 10:49:16 -0600" {4501+}
5   [20/Feb/2009 10:49:16][14857] {imaps} Update: 0 expunges, 0 flags, 53 exists, 0 recent, 0 expunges waiting
6   [20/Feb/2009 10:49:16][14857] {imaps} 86.9 OK [APPENDUID 1233785626 3567] APPEND completed
7   [20/Feb/2009 10:49:16][14857] {imaps} Command 87.9 UID FETCH 3567 (BODYSTRUCTURE BODY.PEEK[])
8   [20/Feb/2009 10:49:16][14857] {imaps} Sent 1 fetch responses
9   [20/Feb/2009 10:49:16][14857] {imaps} Command 88.9 UID STORE 3566 +FLAGS.SILENT (\Seen \Deleted)
10  [20/Feb/2009 10:49:16][14857] {imaps} Some messages were deleted, invoking folder expunge.
11  [20/Feb/2009 10:49:16][14857] {imaps} Command 89.9 FETCH 53:* (INTERNALDATE UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from to cc message-id in-reply-to references x-priority x-mail-rss-source-name x-uniform-type-identifier x-universally-unique-identifier x-apple-mail-todo-message-id x-apple-mail-todo-id received-spf x-spam-status x-spam-flag content-type)])
12  [20/Feb/2009 10:49:16][14857] {imaps} Peek FETCH executed on message 00000def in folder ~me<_a.t_>our-company.com/Drafts
13  [20/Feb/2009 10:49:16][14857] {imaps} Update: 0 expunges, 0 flags, 53 exists, 0 recent, 1 expunges waiting
14  [20/Feb/2009 10:49:16][14857] {imaps} Sent 1 fetch responses
15  [20/Feb/2009 10:49:16][14857] {imaps} Command 90.9 FETCH 53:* (INTERNALDATE UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from to cc message-id in-reply-to references x-priority x-mail-rss-source-name x-uniform-type-identifier x-universally-unique-identifier x-apple-mail-todo-message-id x-apple-mail-todo-id received-spf x-spam-status x-spam-flag content-type)])
16  [20/Feb/2009 10:49:16][14857] {imaps} Peek FETCH executed on message 00000def in folder ~me<_a.t_>our-company.com/Drafts
17  [20/Feb/2009 10:49:16][14857] {imaps} Update: 0 expunges, 0 flags, 53 exists, 0 recent, 1 expunges waiting
18  [20/Feb/2009 10:49:16][14857] {imaps} Sent 1 fetch responses

<repeats until timeout>

###


TELNET IMAP
-----------
telnet KERIO 143
Trying KERIO...
Connected to KERIO.
Escape character is '^]'.
* OK Kerio MailServer 6.6.2 IMAP4rev1 server ready
1 LOGIN me mypassword
1 OK LOGIN completed
2 SELECT Drafts
* FLAGS (\Deleted \Seen \Answered \Draft \Flagged $MDNSent $Forwarded $AutoJunk $AutoNotJunk $Junk $NotJunk)
* 52 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1233785626] UID validity
* OK [UIDNEXT 3568] Predicted next UID
* OK [PERMANENTFLAGS (\Deleted \Seen \Answered \Draft \Flagged $MDNSent $Forwarded $AutoJunk $AutoNotJunk $Junk $NotJunk)] Permanent flags
2 OK [READ-WRITE] SELECT completed
3 FETCH 53:* (INTERNALDATE UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from to cc message-id in-reply-to references x-priority x-mail-rss-source-name x-uniform-type-identifier x-universally-unique-identifier)])
* 52 FETCH (UID 3567 RFC822.SIZE 4501 INTERNALDATE "20-Feb-2009 10:49:16 -0600" BODY[HEADER.FIELDS ("date" "subject" "from" "to" "cc" "message-id" "in-reply-to" "references" "x-priority" "x-mail-rss-source-name" "x-uniform-type-identifier" "x-universally-unique-identifier")] {332}
X-Uniform-Type-Identifier: com.apple.mail-draft
From: me <me<_a.t_>our-company.com>
To: me <me<_a.t_>our-company.com>
X-Universally-Unique-Identifier: 7f54b12f-cadb-4cdb-84e6-82b7f1644da4
Subject: kerio-draft-test
Message-Id: <A2FDD7B6-EEDF-4C03-A492-176A046F0387<_a.t_>our-company.com>
Date: Fri, 20 Feb 2009 10:49:16 -0600

 FLAGS (\Seen \Draft $NotJunk))
3 OK FETCH completed
4 FETCH 53:* all
* 52 FETCH (RFC822.SIZE 4501 INTERNALDATE "20-Feb-2009 10:49:16 -0600" ENVELOPE ("Fri, 20 Feb 2009 10:49:16 -0600" "kerio-draft-test" (("me" NIL "me" "our-company.com")) (("me" NIL "me" "our-company.com")) (("me" NIL "me" "our-company.com")) (("me" NIL "me" "our-company.com")) NIL NIL NIL "<A2FDD7B6-EEDF-4C03-A492-176A046F0387<_a.t_>our-company.com>") FLAGS (\Seen \Draft $NotJunk))
4 OK FETCH completed
5 LOGOUT
* BYE logging out
5 OK LOGOUT completed


It looks like Mail.app asks Kerio for the number of messages in Drafts. Kerio replies, 53. Mail.app appends the changes which Kerio saves, creating a new message id 3567 (& it becomes the 54th message). Mail.app then requests the old message (id 3566, the 53rd message) be deleted. Kerio says it's deleted but the log says it's waiting to expunge (but I'm pretty sure it actually has already been deleted--or at least I don't see it anymore).

Anyway, Mail.app requests this new message again (which is now message #53) but Kerio says it's the 52nd message or it's actually returning the 52nd message. (You can see this in the WireShark log lines 285-289, & in the telnet log request 3 & 4.) In either case, Mail.app is not getting what it expects & therefore requests it again...& again...& again.

Your thoughts? TIA!
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
I've had a little more time to think about this & it must be a Mail.app bug.

I was not aware that a ranged fetch request--even if the starting value is beyond the actual count--will always return the last message if the ending range is an asterisk (eg., there's 52 messages but you request "FETCH 67:*" then message 52 is returned). I confirmed this behavior on a Cyrus IMAP server.

Since this is consistent IMAP behavior it must be Mail.app that's handling the replies incorrectly.

I hoped this was a Kerio bug because I know it would be quickly fixed. With Apple, it could take years. Meanwhile our server is getting hammered Sad
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
I noticed kerio's pdobry posted in Apple's forum about this exact symptom only it was happening with the iPhone.

So I decided to run Mail.app via IMAP against Kerio & Cyrus. When a new email is created, Mail.app will auto-save the changes every few minutes. Mail does this by creating (appending) a new message & deleting the previous draft. It does this each time it saves the draft.

The problem appears to be the way Kerio handles the deleted file.

In IMAP, a message is not deleted as you might expect. To delete a message, you first set it's \Deleted flag. Then you must execute the Expunge command or issue a Close command. Only then is the message actually deleted. But until either command is issued, the message remains in place.

When the draft is saved in Cyrus, it's handled as you would expect. If you have 10 drafts, add another one, & flag 1 for deletion, you have 11 drafts. (Remember, a message flagged for deletion is not actually deleted until Expunge or Close is issued.)

For some reason, Kerio it is reporting back that the draft really has been deleted (even though it's not). So in Kerio, it says there's 10 drafts even though there's really 11.

The problem is Mail.app asks for the 11th file, Kerio returns the 10th file. Mail.app must see this is the 10th file, so it asks again for the 11th file. And this just continues to loop over & over until it timesout.

pdobry, can you comment on this? TIA!!!
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
Would someone please test this? It's quick & easy for us to reproduce for all our Mail.app users.

Simply open Mail.app & make sure the Activity Window is open. Create a new message & save it as a draft. Make a change & save it. Make a change & save it. When the error occurs, the Activity Window displays messages like "Communicating with server [Drafts] Fetching; and, Updating cache directory Received 1 of 10 headers."

Thanks!
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
Seriously?!? No one has literally 15 seconds to test this?

Don't mean to be a whiner but this "bug" hammers our servers & since we have a typical setup (& since this looks like a Kerio issue), I suspect you're also experiencing this problem.

Most any feedback is appreciated.
  •  
My IT Indy

Messages: 1262
Karma: 40
Send a private message to this user
I tried to replicate it and couldn't do it.

-
My IT Indy
Kerio Certified Reseller and Hosted Provider
http://www.myitindy.com
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
HoosierMac wrote on Tue, 16 June 2009 11:05

I tried to replicate it and couldn't do it.

That helps. So thanks, HoosierMac!

Were you using Mail.app & what OS is your mail server?

Thanks again.
  •  
My IT Indy

Messages: 1262
Karma: 40
Send a private message to this user
I'm using mail.app on 10.5.7 and the OS is Leopard Server 10.5.6. KMS 6.7.0p1. I actually tested it against a CentOS 5.3 server running KMS 6.7.0p1 as well.

-
My IT Indy
Kerio Certified Reseller and Hosted Provider
http://www.myitindy.com
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
HoosierMac wrote on Tue, 16 June 2009 11:24

I'm using mail.app on 10.5.7 and the OS is Leopard Server 10.5.6. KMS 6.7.0p1. I actually tested it against a CentOS 5.3 server running KMS 6.7.0p1 as well.


This is a Kerio bug.

I just setup 2 new client computers connecting to a new Mac with a just-downloaded-and-installed-Kerio 6.7.0 patch 1--same bug! This must be happening to a lot of people because I watch the IMAP commands & replies & see exactly where the problem is.

I installed a brand new 6.7.0p1 on a new Mac (10.5.7). Created my account in Kerio Admin then opened Mail.app (v3.6) & setup a local account. Created a new email, saved it. Made a change, saved it. BAM! Same bug.

So I grabbed another Mac (10.5.6), set up Mail.app (v3.5) to connect to the new Kerio server. Same bug.

Grabbed another Mac (10.5., set up Mail.app (v3.6). Same bug.

Grabbed an old Mac running 10.3.9 & Mail.app v1.3.11. This version does not exhibit this bug because each time Mail.app deletes the old version it issues an explicit EXPUNGE command so the everything is fine.
  •  
stewie

Messages: 106
Karma: 0
Send a private message to this user
HoosierMac wrote on Tue, 16 June 2009 11:24

I'm using mail.app on 10.5.7 and the OS is Leopard Server 10.5.6. KMS 6.7.0p1. I actually tested it against a CentOS 5.3 server running KMS 6.7.0p1 as well.


Sorry, HoosierMac, I meant to respond to you. I know you're very technical so try a tcpdump & watch for yourself.

Be sure your account is set to save Drafts on the server, otherwise Mail.app will never talk to Kerio to save the message.

After a new message, save, edit, save, You'll see Mail set the delete flag & Kerio actually deletes the message, but it's not suppose to.

This behavior is completely reproducible every single time.

I really appreciate your help, HoosierMac!
  •  
Pavel Dobry (Kerio)

Messages: 5245
Karma: 251
Send a private message to this user
Can you post the ticket ID from our tech support? I would like to review it.

Did you try to disable IMAP auto-expunge on the server? I'm surprised you didn't get this advice while resolving the issue with tech support.
stewie

Messages: 106
Karma: 0
Send a private message to this user
#OVS-652899

After waiting a week for a reply, I turned to the forums for assistance.
Previous Topic: upload from website to calander
Next Topic: Feature Request-Resource Room Update
Goto Forum:
  


Disclaimer:
Kerio discussion forums are intended for open communication between forum members and may contain information and material posted by members which may be useful in learning about Kerio products. The discussion forums are not intended to provide technical support for any specific product. Any information implied or expressed in the discussion forums is that of the posting member. Kerio is in no way responsible for the information posted in the forums, or its accuracy. Kerio employees may participate in the discussions, but their postings do not represent an offical position of the company on any issues raised or discussed. Kerio reserves the right to monitor and maintain the forums to promote free and accurate exchange of information.

Current Time: Sat Sep 23 05:54:13 CEST 2017

Total time taken to generate the page: 0.00524 seconds
.:: Contact :: Home ::.
Powered by: FUDforum 3.0.4.