[horde] Horde 5beta5 activesync problem with plain messages

Michael J Rubinsky mrubinsk at horde.org
Mon Sep 24 22:47:21 UTC 2012 

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.



> 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


-- 
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 6062 bytes
Desc: S/MIME Cryptographic Signature
URL: <http://lists.horde.org/archives/horde/attachments/20120924/82fb801d/attachment.bin>

More information about the horde mailing list