[horde] Horde 5beta5 activesync problem with plain messages
Tomi Orava
Tomi.Orava at ncircle.nullnet.fi
Tue Sep 25 11:38:00 UTC 2012
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
<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
More information about the horde
mailing list