[horde] Horde 5beta5 activesync problem with plain messages

Mon Sep 24 22:07:06 UTC 2012

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:

2012-09-25T01:00:48+03:00 INFO: Request being handled for device: SEC155335ACE18C3 Supporting protocol version: 12.1
2012-09-25T01:00:48+03:00 INFO: [SEC155335ACE18C3] Handling SYNC command.
2012-09-25T01:00:48+03:00 DEBUG: [SEC155335ACE18C3] Checking policykey for device: 0 user: foouser
2012-09-25T01:00:48+03:00 DEBUG: Policykey: 0 verified.
2012-09-25T01:00:48+03:00 DEBUG: I  <Synchronize>
2012-09-25T01:00:48+03:00 DEBUG: I   <Folders>
2012-09-25T01:00:48+03:00 DEBUG: I    <Folder>
2012-09-25T01:00:48+03:00 DEBUG: I     <SyncKey>
2012-09-25T01:00:48+03:00 DEBUG: I      {5060cb17-be20-4b8c-98fe-7e24c0a8090a}15
2012-09-25T01:00:48+03:00 DEBUG: I     </SyncKey>
2012-09-25T01:00:48+03:00 DEBUG: I     <FolderId>
2012-09-25T01:00:48+03:00 DEBUG: I      INBOX
2012-09-25T01:00:48+03:00 INFO: [SEC155335ACE18C3] Folder server id: INBOX
2012-09-25T01:00:48+03:00 DEBUG: I     </FolderId>
2012-09-25T01:00:48+03:00 DEBUG: I     <DeletesAsMoves/>
2012-09-25T01:00:48+03:00 DEBUG: I     <GetChanges/>
2012-09-25T01:00:48+03:00 ERR: Unmatched content:
2012-09-25T01:00:48+03:00 ERR: Array
(
    [1] => 1
    [2] => GetChanges
    [4] => 0
)

2012-09-25T01:00:48+03:00 DEBUG: I     <WindowSize>
2012-09-25T01:00:48+03:00 ERR: Unmatched content:
2012-09-25T01:00:48+03:00 ERR: Array
(
    [1] => 1
    [2] => WindowSize
    [4] => 1
)

2012-09-25T01:00:48+03:00 DEBUG: I      50
2012-09-25T01:00:48+03:00 DEBUG: I     </WindowSize>
2012-09-25T01:00:48+03:00 DEBUG: I     <Options>
2012-09-25T01:00:48+03:00 DEBUG: I      <FilterType>
2012-09-25T01:00:48+03:00 DEBUG: I       5
2012-09-25T01:00:48+03:00 DEBUG: I      </FilterType>
2012-09-25T01:00:48+03:00 DEBUG: I      <AirSyncBase:BodyPreference>
2012-09-25T01:00:48+03:00 DEBUG: I       <AirSyncBase:Type>
2012-09-25T01:00:48+03:00 DEBUG: I        2
2012-09-25T01:00:48+03:00 DEBUG: I       </AirSyncBase:Type>
2012-09-25T01:00:48+03:00 DEBUG: I      </AirSyncBase:BodyPreference>
2012-09-25T01:00:48+03:00 DEBUG: I      <AirSyncBase:BodyPreference>
2012-09-25T01:00:48+03:00 DEBUG: I       <AirSyncBase:Type>
2012-09-25T01:00:48+03:00 DEBUG: I        4
2012-09-25T01:00:48+03:00 DEBUG: I       </AirSyncBase:Type>
2012-09-25T01:00:48+03:00 DEBUG: I      </AirSyncBase:BodyPreference>
2012-09-25T01:00:48+03:00 DEBUG: I     </Options>
2012-09-25T01:00:48+03:00 DEBUG: I    </Folder>
2012-09-25T01:00:48+03:00 DEBUG: I   </Folders>
2012-09-25T01:00:48+03:00 DEBUG: I  </Synchronize>
2012-09-25T01:00:48+03:00 DEBUG: Have syncable collections
2012-09-25T01:00:48+03:00 DEBUG: All synckeys confirmed. Continuing with SYNC
2012-09-25T01:00:48+03:00 DEBUG: O  <Synchronize>
2012-09-25T01:00:48+03:00 DEBUG: O   <Status>
2012-09-25T01:00:48+03:00 DEBUG: O    1
2012-09-25T01:00:48+03:00 DEBUG: O   <Status/>
2012-09-25T01:00:48+03:00 DEBUG: [12586] Initializing state for collection: INBOX, synckey: {5060cb17-be20-4b8c-98fe-7e24c0a8090a}15
2012-09-25T01:00:48+03:00 DEBUG: [12586] Loading state for synckey {5060cb17-be20-4b8c-98fe-7e24c0a8090a}15
2012-09-25T01:00:48+03:00 DEBUG: [12586] Initializing message diff engine for INBOX
2012-09-25T01:00:48+03:00 DEBUG: Horde_ActiveSync_Driver_Horde::getServerChanges(INBOX, 1348523281, 1348524048, 1346104848, 0)
2012-09-25T01:00:48+03:00 DEBUG: IMAP status: Array
(
    [highestmodseq] => 0
    [uidnext] => 39350
    [uidvalidity] => 917787116
)

2012-09-25T01:00:48+03:00 DEBUG: [12586] Found 0 message changes in INBOX.

The imap sw in question is cyrus imap 2.4.16 (just updated it) and it works
otherwise well for horde itself and thunderbird etc.

Tomi Orava