[horde] Horde 5beta5 activesync problem with plain messages

[Tomi Orava]

On 09/25/2012 01:47 AM, Michael J Rubinsky wrote:
> 
> Quoting Tomi Orava <Tomi.Orava at ncircle.nullnet.fi>:
> 
>> On 09/25/2012 12:40 AM, mrubinsk at horde.org wrote:
>>> Quoting Tomi Orava <Tomi.Orava at ncircle.nullnet.fi>>
>>>> Hi,
>>>>
>>>> Has anyone else noticed a similar problem where the latest 5.0.0beta5 horde is completely ignoring all the imap mailbox mails that are NOT html messages ? I've been playing with a Samsung Galaxy S3 mobile phone and it's completely missing all the plain non-html mails from its inbox that is synced from the horde via activesync v12.01.
>>>>
>>>> After enabling quite a lot of debug, it seems that the problem lies on the horde end and the activesync driver really is having problems in delivering plain messages to the client:
>>>>
>>>> A working html mail is processed like:
>>>>
>>>> 2012-09-25T00:05:30+03:00 DEBUG: Polling Horde_ActiveSync_Driver_Horde::_getMailFolders()
>>>> 2012-09-25T00:05:30+03:00 DEBUG: Sending HTML Message.
>>>> 2012-09-25T00:05:30+03:00 DEBUG: O     <Commands>
>>>> 2012-09-25T00:05:30+03:00 DEBUG: O      <Add>
>>>> 2012-09-25T00:05:30+03:00 DEBUG: O       <ServerEntryId>
>>>> 2012-09-25T00:05:30+03:00 DEBUG: O        38730
>>>> 2012-09-25T00:05:30+03:00 DEBUG: O       <ServerEntryId/>
>>>> 2012-09-25T00:05:30+03:00 DEBUG: O       <Data>
>>>> 2012-09-25T00:05:30+03:00 DEBUG: O        <POOMMAIL:To>
>>>> <snip>
>>>>
>>>> However, a plain mail only gets:
>>>>
>>>> 2012-09-25T00:05:30+03:00 DEBUG: Horde::getMessage(INBOX, 38733)
>>>> 2012-09-25T00:05:30+03:00 ERR: Mail server closed the connection unexpectedly.
>>>> 2012-09-25T00:05:30+03:00 ERR: Unknown backend error skipping message: Mail server closed the connection unexpectedly.
>>>> 2012-09-25T00:05:30+03:00 DEBUG: Updating state during change
>>>>
>>>>
>>>> An example of a "plain mail" is here:
>>>>
>>>> From: monit at foobar.foo.com
>>>> To: root at foobar.foo.com
>>>> Subject: monit alert --  PID changed apache
>>>> Date: Mon, 24 Sep 2012 21:00:53 GMT
>>>> X-Mailer: monit 5.3.2
>>>> Mime-Version: 1.0
>>>> Content-Type: text/plain; charset="iso-8859-1"
>>>> Content-Transfer-Encoding: 8bit
>>>> Message-id: <1348520453.981209251 at foobar.foo.com>
>>>>
>>>> PID changed Service apache
>>>>
>>>>     Date:        Tue, 25 Sep 2012 00:00:53
>>>>     Action:      alert
>>>>     Host:        foobar.foo.com
>>>>     Description: process PID changed from 31106 to 32123
>>>>
>>>> Your faithful employee,
>>>> Monit
>>>>
>>>> ---------------------------------------
>>>>
>>>> It's pretty much what you get by running:
>>>>
>>>> echo -e "To: root\nSubject: test\n\nfoobar test"
>>>>
>>>>
>>>> Tomi Orava
>>>>
>>>> -- 
>>>> Horde mailing list
>>>> Frequently Asked Questions: http://horde.org/faq/
>>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>>>
>>> This error means that the IMAP server died, not the activesync server.  It could be a bug in the IMAP server unable to respond to the requests we are sending it.  An IMAP server log would be .ore helpful than the AS log. FWIW  I receive plain text messages with no issues on 5 different test devices.
>>
>> Ok, I'm unable to see anything useful via cyrus imap logs and or horde raw imap logs.
>> Perhaps, the couple of "Unmatched content" comments are really related:
> 
> No, those are completely expected, unrelated, and harmless.
> 
> The error messages in your log:
> 
>>>> 2012-09-25T00:05:30+03:00 ERR: Mail server closed the connection unexpectedly.
>>>> 2012-09-25T00:05:30+03:00 ERR: Unknown backend error skipping message: Mail server closed the connection unexpectedly.
> 
> indicate the IMAP server has closed the connection unexpectedly.

And finally I can also see it from the cyrus end. This seems to cause the death of the imap process:

7 OK Completed (0.000 secs 373 calls)
<1348545548<8 UID FETCH 39371 (BODYSTRUCTURE FLAGS)
>1348545548>* 637 FETCH (FLAGS (NonJunk) UID 39371 BODYSTRUCTURE ("TEXT" "PLAIN" ("CHARSET" "us-ascii") NIL NIL "7BIT" 15 1 NIL NIL NIL NIL))
8 OK Completed (0.000 sec)
<1348545548<9 UID FETCH 39371 (ENVELOPE)<1348545548<
>1348545548>* 637 FETCH (UID 39371 ENVELOPE ("Tue, 25 Sep 2012 06:58:50 +0300 (EEST)" "test12" (("foouser" NIL "foouser" "ncircle.nullnet.fi")) (("foouser" NIL "foouser" "ncircle.nullnet.fi")) (("foouser" NIL "foouser" "ncircle.nullnet.fi")) ((NIL NIL "foouser" "ncircle.nullnet.fi")) NIL NIL NIL "<20120925035850.96C4E2041EDA at ncircle.nullnet.fi>"))
9 OK Completed (0.000 sec)
<1348545548<10 UID FETCH 39371 (BINARY.PEEK[1] BINARY.SIZE[1])

Hmm, I quess my cyrus setup has been working too long without any problems ...

Thanks,
Tomi Orava