[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