[horde] AS email not current

Simon Wilson simon at simonandkate.net
Sat Apr 13 03:07:51 UTC 2013


----- Message from Michael J Rubinsky <mrubinsk at horde.org> ---------
     Date: Wed, 06 Mar 2013 11:54:32 -0500
     From: Michael J Rubinsky <mrubinsk at horde.org>
Reply-To: mrubinsk at horde.org
  Subject: Re: [horde] AS email not current
       To: simon at simonandkate.net
       Cc: "horde at lists.horde.org" <horde at lists.horde.org>


> Quoting simon at simonandkate.net:
>
>> Simon Wilson
>> M: 0400 12 11 16
>>
>> On 06/03/2013, at 11:42 AM, Michael J Rubinsky <mrubinsk at horde.org> wrote:
>>
>>>
>>> Quoting simon at simonandkate.net:
>>>
>>>>> Quoting Simon Wilson <simon at simonandkate.net>:
>>>>>
>>>>>>>>> Quoting Simon Wilson <simon at simonandkate.net>:
>>>>>>>>>
>>>>>>>>>>> Quoting Simon Wilson <simon at simonandkate.net>:
>>>>>>>>>>>
>>>>>>>>>>>>>> On 02/03/2013 4:22 AM, Simon Wilson wrote:
>>>>>>>>>>>>>>> But if I delete emails in Imp, the deleted messages are not
>>>>>>>>>>>>>>> sync'ed, and those emails continue to show in the iOS devices
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> http://wiki.horde.org/ActiveSync
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> "Deleting from a MUA: If the MUA is not configured to move
>>>>>>>>>>>>>> messages to the trash, and instead just flags them as
>>>>>>>>>>>>>> deleted, these message deletions will NOT be synched to the
>>>>>>>>>>>>>> ActiveSync client, as there is no equivalent command in the
>>>>>>>>>>>>>> protocol. These messages will only be removed from the
>>>>>>>>>>>>>> ActiveSync client once expunged from the mailbox. This is in
>>>>>>>>>>>>>> accordance with the ActiveSync protocol specs.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *If you wish to ensure all message deletions are synched
>>>>>>>>>>>>>> quickly to the device, you should configure the use of a
>>>>>>>>>>>>>> Trash folder.*"
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> --
>>>>>>>>>>>>>> Horde mailing list
>>>>>>>>>>>>>> Frequently Asked Questions: http://horde.org/faq/
>>>>>>>>>>>>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>>>>>>>>>>>>
>>>>>>>>>>>>> As per my other reply, Imp is configured to move to trash
>>>>>>>>>>>>> folder, and purge from Inbox.
>>>>>>>>>>>>>
>>>>>>>>>>>>> It does not just flag as deleted.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Simon
>>>>>>>>>>>>> --
>>>>>>>>>>>>
>>>>>>>>>>>> OK - did an experiment... deleting an email on the same iOS
>>>>>>>>>>>> device in Apple Mail (via a direct IMAP connection), and the
>>>>>>>>>>>> resultant sync back to the AS email connection removes the
>>>>>>>>>>>> deleted email correctly.
>>>>>>>>>>>>
>>>>>>>>>>>> Delete an email in Imp and it does not.
>>>>>>>>>>>>
>>>>>>>>>>>> My Imp's mail deletion prefs are set as per following screen shot:
>>>>>>>>>>>>
>>>>>>>>>>>> http://www.simonandkate.net/impprefs.png
>>>>>>>>>>>>
>>>>>>>>>>>> So what is happening in Imp that it is not flagging those
>>>>>>>>>>>> deletions back through AS?
>>>>>>>>>>>
>>>>>>>>>>> Not sure. Those settings are correct.
>>>>>>>>>>> --
>>>>>>>>>>> mike
>>>>>>>>>>
>>>>>>>>>> :( troubleshooting suggestions?
>>>>>>>>>>
>>>>>>>>>> If I empty the AS log, delete an email in Imp, and post the sync
>>>>>>>>>> log will that help?
>>>>>>>>>
>>>>>>>>> I doubt it, though I'll look at it if you send it me. The device
>>>>>>>>> is not being told to remove the email, so it won't be in the log.
>>>>>>>>>
>>>>>>>>>> What about Imap log for the delete transaction?
>>>>>>>>>
>>>>>>>>> Not really. The email is obviously being removed from your INBOX
>>>>>>>>> since you no longer see it in IMP (or other MUA).
>>>>>>>>>
>>>>>>>>>> What is the process that a delete triggers?
>>>>>>>>>
>>>>>>>>> This happens in one of two ways depending on the features of your
>>>>>>>>> IMAP server. If you don't support CONDSTORE or per-mailbox MODSEQ
>>>>>>>>> values (which, if I remember right from looking at your log, is
>>>>>>>>> your case) - we basically compare the UID list that we have
>>>>>>>>> cached in the ActiveSync state with what the IMAP server returns
>>>>>>>>> as being present in the mailbox. Anything not listed in the IMAP
>>>>>>>>> server's list of UIDs, but present in the ActiveSync list is
>>>>>>>>> removed from the device.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> Does AS care WHERE the email is deleted to? I have Cyrus IMAP
>>>>>>>>>> with a "Deleted Items" folder that Imp calls Trash, seems to
>>>>>>>>>> function fine. Should I be using virtual trash in Imp?
>>>>>>>>>
>>>>>>>>> It doesn't matter. From the point of view of ActiveSync, the
>>>>>>>>> message is just vanished from the INBOX (or whatever folder we
>>>>>>>>> are talking about). Adding it to the Deleted Items/Trash/Whatever
>>>>>>>>> folder is a separate operation.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>> mike
>>>>>>>>
>>>>>>>> Thanks Mike. You know how much I hate it when things start working
>>>>>>>> by themselves with no change????? Lots.
>>>>>>>>
>>>>>>>> I tried today in Outlook with an IMAP connection to my mailbox.
>>>>>>>> Deleted some emails. When my iOS devices next connected, the
>>>>>>>> mailbox changes (deletions) were correctly sent through. So that
>>>>>>>> is with both Apple Mail and MS Outlook 2010 that deletions in
>>>>>>>> other MUAs are correctly sync'ed through AS.
>>>>>>>>
>>>>>>>> Then tried in Imp again. And it updated. :-O
>>>>>>>>
>>>>>>>> Man I hate that.
>>>>>>>>
>>>>>>>> I haven't changed ANYTHING.
>>>>>>>>
>>>>>>>> Anyway, apologies for the noise, I'll monitor and see if it reoccurs.
>>>>>>>>
>>>>>>>> Simon.
>>>>>>>
>>>>>>> I spoke too soon. It was updating automatically for a while, then
>>>>>>> stopped again.
>>>>>>>
>>>>>>> At this stage I have one email that ActiveSync thinks is there but
>>>>>>> that isn't.
>>>>>>>
>>>>>>> I have confirmed that the email does NOT exist in the Cyrus
>>>>>>> partition, so the IMAP delete has successfully completed.
>>>>>>>
>>>>>>> Is there any way to see what UIDs ActiveSync has cached, and what
>>>>>>> it is getting from IMAP to compare?
>>>>>>>
>>>>>>> I then deleted a second email from Imp, and it also hung up...
>>>>>>> deleted OK on the Cyrus partition, but AS still thinks it's there.
>>>>>>>
>>>>>>> Third email deleted then from Outlook - and it also hung up... as
>>>>>>> per last one, gone in Cyrus, AS still thinks it's there.
>>>>>>>
>>>>>>> Sounding to me like AS caching something incorrectly reading the
>>>>>>> Cyrus list. Could it be related to bug 11115?
>>>>>>>
>>>>>>> Simon
>>>>>>
>>>>>> I have the following set in backends.local.php. Cache was set to
>>>>>> true, but setting to false hasn't changed anything. :
>>>>>>
>>>>>> <?php
>>>>>>
>>>>>> $servers['imap'] = array(
>>>>>>  'disabled' => false,
>>>>>>  'name' => 'Cyrus IMAP Server',
>>>>>>  'hostspec' => 'server04.simonandkate.lan',
>>>>>>  'hordeauth' => true,
>>>>>>  'protocol' => 'imap',
>>>>>>  'secure' => 'tls',
>>>>>>  'port' => 143,
>>>>>>  'quota' => array(
>>>>>>      'driver' => 'imap',
>>>>>>      'params' => array(
>>>>>>              'hide_quota_when_unlimited' => true,
>>>>>>              'unit' => 'MB'
>>>>>>       )
>>>>>>  ),
>>>>>>  'maildomain' => 'simonandkate.net',
>>>>>>  'acl' => true,
>>>>>>  'cache' => false,
>>>>>> //    'debug' => ($GLOBALS['registry']->getAuth() == 'simon') ?
>>>>>> '/var/log/hordeas/impdebug' : false,
>>>>>>  'debug' => '/var/log/hordeas/impdebug',
>>>>>>  'debug_raw' => false,
>>>>>> );
>>>>>>
>>>>>> Setting Impdebug gives some info...
>>>>>>
>>>>>> Initial connection:
>>>>
>>>>>> Snip
>>>>
>>>>>> Doing an update on the iPhone's AS Inbox generates this IMAP debug log:
>>>>>>
>>>>>> http://www.simonandkate.net/imaplog.txt
>>>>>>
>>>>>> That UID list returned from Cyrus is correct - 46072 is the last
>>>>>> (newest) email that is actually in the mailbox. It appears that
>>>>>> Cyrus is sending the correct info. Imp shows this correctly. Yet AS
>>>>>> into iOS is not showing this, with four emails showing that are newer.
>>>>>>
>>>>>> The AS log for this is as follows:
>>>>>>
>>>>>> http://www.simonandkate.net/asimap.txt
>>>>>>
>>>>>> That also shows the correct UID sequence. Yet iPhone continues to
>>>>>> show the old list of emails - not being told to update?
>>>>>
>>>>> Actually, this log was very helpful. It doesn't contain *any* UID
>>>>> Sequences at all. I'm not talking about just the UIDNEXT value, but
>>>>> the entire sequence of message UIDs that ActiveSync thinks is on the
>>>>> device. This should be visible in the 'm' parameter of the state that
>>>>> is saved (and would basically look like a large array of integers).
>>>>> Yours is showing an empty array. This would definitely cause deleted
>>>>> emails from not being detected since we perform an array_diff on the
>>>>> list we have and the list the IMAP server has. The question is, *why*
>>>>> you don't have a valid list of UIDs. Something must be wiping in the
>>>>> code somewhere, I'll have to dig further on that during my next coding
>>>>> sprint later this week.
>>>> Yay!! I was starting to get a bit disheartened, but that's great  
>>>> news that the log gives you something useful.
>>>
>>> I've spent about an hour trying to reproduce this and can't. I've  
>>> disabled features on my IMAP server to emulate not having  
>>> per-mailbox MODSEQ values like your IMAP server, tried IMAP  
>>> caching on/off, performed dozens of mailbox operations from  
>>> various MUAs and activesync clients. I'm not able to lose  
>>> ActiveSync's internal message cache nor am I able to see any code  
>>> path where the message state would be reset.
>>>
>>> You are going to need to start from a fresh account, synchronize  
>>> it, and find the point where your log goes from having the proper  
>>> state to an empty state.
>>>
>>> 2013-03-05T20:39:14-05:00 DEBUG: [8689] Saving state: Array
>>> (
>>>   [0] => {51369e16-4154-423a-bcf7-21f2c0a8015f}25
>>>   [1] => Horde_Db_Value_Binary Object
>>>       (
>>>           [_value:protected] =>  
>>> C:28:"Horde_ActiveSync_Folder_Imap":1184:{a:5:{s:1:"s";a:3:{s:7:"uidnext";s:6:"168028";s:11:"uidvalidity";s:10:"1292457115";s:13:"highestmodseq";i:0;}s:1:"m";a:21:{i:167587;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167604;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167612;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167638;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167642;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167643;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167648;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167665;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167666;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167672;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167679;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167712;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167721;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167753;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:167758;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:168018;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}i:168019;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:1680
 2
> 4;a
>>> :2:{s:4:
>>> "read";i:1;s:7:"flagged";i:0;}i:168025;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}i:168026;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}i:168027;a:2:{s:4:"read";i:0;s:7:"flagged";i:0;}}s:1:"f";s:5:"INBOX";s:1:"c";s:5:"Email";s:1:"v";i:1;}}
>>>       )
>>>
>>>   [2] => ApplGB024LGPZ3A
>>>   [3] => 1362533954
>>>   [4] => INBOX
>>>   [5] => mike
>>>   [6] => 0
>>> )
>>> Note the entries after the "m" value. This is the message state  
>>> for this folder. Now, YOUR log looks like this:
>>>
>>> 2013-03-04T11:30:07+00:00 DEBUG: [14497] Saving state: Array
>>> (
>>>   [0] => {51347830-a744-4382-b47a-214dc0a801e6}110
>>>   [1] => Horde_Db_Value_Binary Object
>>>       (
>>>           [_value:protected] =>  
>>> C:28:"Horde_ActiveSync_Folder_Imap":174:{a:5:{s:1:"s";a:3:{s:13:"highestmodseq";i:0;s:7:"uidnext";s:5:"46217";s:11:"uidvalidity";s:10:"1238677126";}s:1:"m";a:0:{}s:1:"f";s:5:"INBOX";s:1:"c";s:5:"Email";s:1:"v";i:1;}}
>>>       )
>>>
>>>   [2] => Appl79030T3BA4S
>>>   [3] => 1362396607
>>>   [4] => INBOX
>>>   [5] => simon
>>>   [6] => 0
>>> )
>>>
>>> Note the "m";a:0: value. This means your internal message state is  
>>> empty. I.e., the ActiveSync state cache thinks the INBOX on your  
>>> device is empty - so we have no context to pass to  
>>> Horde_Imap_Client when asking for the list of vanished messages.  
>>> (This will always return an empty list).
>>>
>>>
>>> --
>>> mike
>>>
>>> The Horde Project (www.horde.org)
>>> mrubinsk at horde.org
>>
>> Ok. I'll remove the device from AS in horde, remove its log file,  
>> and connect as my test account, that only has about 3 emails in it  
>> and 2 appts. Will the horde inline debug function that can be  
>> thrown into the php help me anywhere?
>
> Possibly, though since I have no idea where this is being cleared, I  
> don't know where to tell you to put it yet.
>
>
> -- 
Finally got some time to test this some more.

I took my iPad, deleted the account on it, restarted it. Removed the  
Horde AS device log file, and removed from the AS device list in Horde.

Added as my test account on the iPad, and added ONLY mail.  
Interestingly, the autodiscover redirect failed to strip the @domain  
name, and I had to manually configure.

Immediately sync'ed up, and iPad showed no emails (3 in the account  
but too old, so were filtered out).

Sent an email to the account, and it appeared fine on the iPad. Read  
it in Imp, and the flag change worked and synced to iPad.

Deleted it in Imp, and it disappeared in iPad. The log shows "m";a:1.

I sent some more emails to the test account, and they all sync through  
fine. Deletions sync through OK, and it appears to work as planned.

Log file is here:

http://www.simonandkate.net/img/ipad-test.txt


I deleted the account on iPad, from Horde AS devices, and deleted the  
AS log file.

Added account as me on iPad, rinse and repeat. Autodiscover worked  
fine for my username, no manual config needed.

I have about 68 emails in my inbox, and they all appeared. Immediately  
though, I notice that the log file is full of "m";a:0

Confirmed by deleting an email in Imp, and it still appears in iPad  
after sync.

Log file is here:

http://www.simonandkate.net/img/ipad-test2.txt

Something with my account?? Seems strange... accounts are on the same  
IMAP server.

Simon


--
Simon Wilson
M: 0400 12 11 16
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 198 bytes
Desc: PGP Digital Signature
URL: <http://lists.horde.org/archives/horde/attachments/20130413/9e2a28ee/attachment-0001.bin>


More information about the horde mailing list