[horde] ActiveSync e-Mail problem

Sat Jul 13 17:44:58 UTC 2013

Quoting lst_hoe02 at kwsoft.de:

> Zitat von lst_hoe02 at kwsoft.de:
>
>> Hello,
>>
>> testing the ActiveSync part we found the following problem with  
>> Cyrus 2.4.17 and iOS 6.1.3 (iPhone):
>>
>> The Account creation and events work fine, but e-Mail will only  
>> sync at startup with a somewhat random subset of the mails in the  
>> user mailbox. Further new mail will not show up on the Phone. The  
>> ActiveSync debug log show something like this:
>>
>> 2013-07-08T18:28:04+02:00 INFO: All synckeys confirmed. Continuing with SYNC
>> 2013-07-08T18:28:04+02:00 DEBUG: [4031] O  <Synchronize>
>> 2013-07-08T18:28:04+02:00 DEBUG: [4031] O   <Status>
>> 2013-07-08T18:28:04+02:00 DEBUG: [4031] O    1
>> 2013-07-08T18:28:04+02:00 DEBUG: [4031] O   </Status>
>> 2013-07-08T18:28:04+02:00 INFO: [4031] Initializing state for  
>> collection: INBOX, synckey: {51dac604-8df0-4fe1-bfaf-08dad5a44353}38
>> 2013-07-08T18:28:04+02:00 INFO: [4031] Loading state for synckey  
>> {51dac604-8df0-4fe1-bfaf-08dad5a44353}38
>> 2013-07-08T18:28:04+02:00 INFO: [4031] Initializing message diff  
>> engine for f1443163 (INBOX)
>> 2013-07-08T18:28:04+02:00 INFO: [4031]  
>> Horde_Core_ActiveSync_Driver::getServerChanges(INBOX, 1373300374,  
>> 1373300884, 1370881684, 0)
>> 2013-07-08T18:28:04+02:00 INFO: IMAP status: Array
>> (
>>    [uidnext] => 31702
>>    [uidvalidity] => 989246025
>>    [highestmodseq] => 1493
>> )
>>
>> 2013-07-08T18:28:04+02:00 INFO: [4031] Found 0 message changes in f1443163.
>>
>> and with a new mail arrived:
>>
>> 2013-07-08T18:31:07+02:00 INFO: All synckeys confirmed. Continuing with SYNC
>> 2013-07-08T18:31:07+02:00 DEBUG: [4031] O  <Synchronize>
>> 2013-07-08T18:31:07+02:00 DEBUG: [4031] O   <Status>
>> 2013-07-08T18:31:07+02:00 DEBUG: [4031] O    1
>> 2013-07-08T18:31:07+02:00 DEBUG: [4031] O   </Status>
>> 2013-07-08T18:31:07+02:00 INFO: [4031] Initializing state for  
>> collection: INBOX, synckey: {51dac604-8df0-4fe1-bfaf-08dad5a44353}38
>> 2013-07-08T18:31:07+02:00 INFO: [4031] Loading state for synckey  
>> {51dac604-8df0-4fe1-bfaf-08dad5a44353}38
>> 2013-07-08T18:31:07+02:00 INFO: [4031] Initializing message diff  
>> engine for f1443163 (INBOX)
>> 2013-07-08T18:31:07+02:00 INFO: [4031]  
>> Horde_Core_ActiveSync_Driver::getServerChanges(INBOX, 1373300374,  
>> 1373301067, 1370881867, 0)
>> 2013-07-08T18:31:07+02:00 INFO: IMAP status: Array
>> (
>>    [uidnext] => 31703
>>    [uidvalidity] => 989246025
>>    [highestmodseq] => 1494
>> )
>>
>> 2013-07-08T18:31:07+02:00 INFO: [4031] Found 0 message changes in f1443163.
>>
>> So highestmodseq and uidnext reflect the change, but horde still  
>> does not found a new message???
>>
>> System is latest stable Horde/IMP with Cyrus IMAP Server and  
>> ActiveSync client iOS 6.1.3 (iPhone 4S).
>>
>> Thanks for any help
>>
>> Andreas
>
> On further test we find the following:
>
> With Dovecot as IMAP server and nearly identical Horde/IMP setup  
> mail with ActiveSync works as expected. With Cyrus 2.4.17 new mail  
> is synced but no old mail ever disappear and no status changes are  
> synced. With IMAP debug i found the following for Cyrus
>
> S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=LOGIN   
> XIMAPPROXY] mailer Cyrus IMAP v2.4.17-Debian-2.4.17-1~precise+1  
> server ready
> 1 [LOGIN Command - username: xxxxxx]
> S: 1 OK User logged in
> C: 2 CAPABILITY
> S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA  
> MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT  
> CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT  
> SORT=MODSEQ SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES  
> ANNOTATEMORE LIST-EXTENDED WITHIN QRESYNC SCAN XLIST URLAUTH  
> URLAUTH=BINARY LOGINDISABLED AUTH=PLAIN AUTH=LOGIN COMPRESS=DEFLATE  
> IDLE
> S: 2 OK Completed
>>> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
> C: 3 ENABLE QRESYNC
> C: 4 NAMESPACE
> S: * ENABLED CONDSTORE QRESYNC
> S: 3 OK Completed
> S: * NAMESPACE (("INBOX." ".")) (("user." ".")) (("" "."))
> S: 4 OK Completed
> C: 5 STATUS INBOX (UIDNEXT UIDVALIDITY HIGHESTMODSEQ)
> S: * STATUS INBOX (UIDNEXT 31782 UIDVALIDITY 989246025 HIGHESTMODSEQ 1795)
> S: 5 OK Completed
> C: 6 LOGOUT
> S: * BYE LOGOUT received
> S: 6 OK Completed
> ------------------------------
>>> Fri, 12 Jul 2013 10:42:08 +0200
> S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=LOGIN   
> XIMAPPROXY] mailer Cyrus IMAP v2.4.17-Debian-2.4.17-1~precise+1  
> server ready
> 1 [LOGIN Command - username: xxxxxx]
> S: * OK [XPROXYREUSE] IMAP connection reused by imapproxy
> S: 1 OK User logged in
> C: 2 CAPABILITY
> S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA  
> MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT  
> CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT  
> SORT=MODSEQ SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES  
> ANNOTATEMORE LIST-EXTENDED WITHIN QRESYNC SCAN XLIST URLAUTH  
> URLAUTH=BINARY LOGINDISABLED AUTH=PLAIN AUTH=LOGIN COMPRESS=DEFLATE  
> IDLE
> S: 2 OK Completed
>>> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
> C: 3 ENABLE QRESYNC
> C: 4 NAMESPACE
> S: * ENABLED
> S: 3 OK Completed
> S: * NAMESPACE (("INBOX." ".")) (("user." ".")) (("" "."))
> S: 4 OK Completed
> C: 5 STATUS INBOX (UIDNEXT UIDVALIDITY)
> S: * STATUS INBOX (UIDNEXT 31782 UIDVALIDITY 989246025)
> S: 5 OK Completed
> C: 6 EXAMINE INBOX (CONDSTORE)
>
> So in the Cyrus case when ActiveSync is used first the INBOX STATUS  
> is asked with HIGHESTMODSEQ and after that without. From what i can  
> see HIGHESTMODSEQ is change when mail is deleted so might this be  
> the problem. In the Dovecot this double login does not occur and the  
> mailbox is EXAMINED straight away.

This is not what your ActiveSync log shows though. The log parts you  
posted early clearly show the MODSEQ values. If ActiveSync was not  
asking for it, the status would not be shown in the log. You are going  
to have to find out where in the code this is going wrong. You should  
start in Horde_ActiveSync_Imap_Adapter::getMessageChanges() (in  
Adapter.php). Specifically, look at the if statements that start at  
line 290. You need to find out which condition the code path takes and  
what the values of the various variables are there. If you need help  
with this, let me know.

Alternatively if you want to give me a test account on a  
non-production server I can attempt to figure out what is going on.

-- 
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-keys
Size: 2200 bytes
Desc: PGP Public Key
URL: <http://lists.horde.org/archives/horde/attachments/20130713/69da4688/attachment.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 6062 bytes
Desc: S/MIME Signature
URL: <http://lists.horde.org/archives/horde/attachments/20130713/69da4688/attachment-0001.bin>