[horde] Horde 5beta5 activesync problem with plain messages

Jan Schneider jan at horde.org
Tue Sep 25 13:16:23 UTC 2012


Zitat von Tomi Orava <Tomi.Orava at ncircle.nullnet.fi>:

> Quoting Jan Schneider <jan at horde.org>:
>
>> Zitat von 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:
>>>
>>> 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
>>
>> You probably hit this bug:  
>> https://bugzilla.cyrusimap.org/show_bug.cgi?id=3718
>
> Yes, that was the case as you and Leena Heino pointed out.
> Now, it seems that the cyrus imapd is not dying anymore, but Horde activesync
> is still not too happy about my imapd replies:
>
> ie: activesync logs simply:
>
> 2012-09-25T14:31:30+03:00 ERR: IMAP error reported by server.
>
>
> while the cyrus imapd log says:
>
> <1348572690<2 ENABLE QRESYNC<1348572690<
>> 1348572690>* ENABLED CONDSTORE QRESYNC
> 2 OK Completed
> <1348572690<3 NAMESPACE
>> 1348572690>* NAMESPACE (("INBOX." ".")) (("user." ".")) (("" "."))
> 3 OK Completed
> <1348572690<4 SELECT INBOX (QRESYNC (917787116 18667  
> 38730,38733:38736,38738,39179:39312,39314:39337,39383:39388))<1348572690<
>> 1348572690>* 650 EXISTS
> * 0 RECENT
> * FLAGS (\Answered \Flagged \Draft \Deleted \Seen $MDNSent NonJunk  
> Junk $Forwarded $Label3 $Label1 $Label2 $Label4 $Label5 Old)
> * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen  
> $MDNSent NonJunk Junk $Forwarded $Label3 $Label1 $Label2 $Label4  
> $Label5 Old \*)] Ok
> * OK [UNSEEN 568] Ok
> * OK [UIDVALIDITY 917787116] Ok
> * OK [UIDNEXT 39390] Ok
> * OK [HIGHESTMODSEQ 18668] Ok
> * OK [URLMECH INTERNAL] Ok
> 4 OK [READ-WRITE] Completed
> <1348572690<5 UID STORE 39354 (UNCHANGEDSINCE 18668) +FLAGS.SILENT \seen
>> 1348572690>* 619 FETCH (FLAGS (\Seen NonJunk) UID 39354 MODSEQ (18669))
> 5 OK Completed
> <1348572690<6 UID FETCH 1:* UID (CHANGEDSINCE 18657)
>> 1348572690>* 619 FETCH (UID 39354 MODSEQ (18669))
> * 644 FETCH (UID 39383 MODSEQ (18658))
> * 645 FETCH (UID 39384 MODSEQ (18661))
> * 646 FETCH (UID 39385 MODSEQ (18660))
> * 647 FETCH (UID 39386 MODSEQ (18662))
> * 648 FETCH (UID 39387 MODSEQ (18663))
> * 649 FETCH (UID 39388 MODSEQ (18667))
> * 650 FETCH (UID 39389 MODSEQ (18668))
> 6 OK Completed (0.000 sec)
> <1348572690<7 UID FETCH 39354,39383:39388 UID (CHANGEDSINCE  
> 18657)<1348572690<
>> 1348572690>* 619 FETCH (UID 39354 MODSEQ (18669))
> * 644 FETCH (UID 39383 MODSEQ (18658))
> * 645 FETCH (UID 39384 MODSEQ (18661))
> * 646 FETCH (UID 39385 MODSEQ (18660))
> * 647 FETCH (UID 39386 MODSEQ (18662))
> * 648 FETCH (UID 39387 MODSEQ (18663))
> * 649 FETCH (UID 39388 MODSEQ (18667))
> 7 OK Completed (0.000 sec)
> <1348572690<8 UID FETCH 39389 (FLAGS) (CHANGEDSINCE 18657)<1348572690<
>> 1348572690>* 650 FETCH (FLAGS () UID 39389 MODSEQ (18668))
> 8 OK Completed (0.000 sec)
> <1348572690<9 UID FETCH 1:* () (VANISHED CHANGEDSINCE 18657)<1348572690<
>> 1348572690>9 BAD Invalid UID Fetch attribute

This has been fixed already since.

> <1348572690<10 LOGOUT<1348572690<
>> 1348572690>* BYE LOGOUT received
> 10 OK Completed
>
> To me it looks like activesync doesn't like the fact that I've deleted a mail
> by using a different imap client.
>
> Tomi Orava


-- 
Jan Schneider
The Horde Project
http://www.horde.org/



More information about the horde mailing list