[horde] Horde 5beta5 activesync problem with plain messages
Tomi Orava
Tomi.Orava at ncircle.nullnet.fi
Tue Sep 25 20:13:03 UTC 2012
Quoting Jan Schneider <jan at horde.org>:
> 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.
Yes, this seems to be true. I have now switched from pear
installation to GIT installation and indeed both my activesync
test devices seem to working just fine.
Thanks a lot for your help!
Tomi Orava
>
>> <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/
>
> --
> Horde mailing list
> Frequently Asked Questions: http://horde.org/faq/
> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
More information about the horde
mailing list