[horde] AS email not current
Simon Wilson
simon at simonandkate.net
Sat Apr 13 08:40:54 UTC 2013
----- Message from Simon Wilson <simon at simonandkate.net> ---------
Date: Sat, 13 Apr 2013 07:09:07 +0000
From: Simon Wilson <simon at simonandkate.net>
Reply-To: simon at simonandkate.net
Subject: Re: [horde] AS email not current
To: horde at lists.horde.org
> ----- Message from Michael J Rubinsky <mrubinsk at horde.org> ---------
> Date: Sat, 13 Apr 2013 02:45:17 -0400
> From: Michael J Rubinsky <mrubinsk at horde.org>
> Reply-To: mrubinsk at horde.org
> Subject: Re: [horde] AS email not current
> To: horde at lists.horde.org
>
>
>> Quoting Simon Wilson <simon at simonandkate.net>:
>>
>>>>> 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:
1
> 6
>> 8
>>>
>>>> 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.
>>
>> And this is *still* wrong. That is actually not even a valid
>> serialized value.
>>
>> According to your earlier logs, your IMAP server does not support
>> per-mailbox MODSEQ values. In this case, the messages array (which
>> is what "m" represents) contains both the message uids AND the flag
>> data (see my example posted earlier in the thread above). Unless
>> *this* account, for some reason, has MODSEQ support enabled, this
>> makes absolutely no sense to me whatsoever.
>>
>>
>>
>> --
>> mike
>>
>
> The whole line from when using my test account is in the link I posted:
>
> [_value:protected] =>
> C:28:"Horde_ActiveSync_Folder_Imap":215:{a:5:{s:1:"s";a:3:{s:13:"highestmodseq";i:0;s:7:"uidnext";s:2:"19";s:11:"uidvalidity";s:10:"1238677130";}s:1:"m";a:1:{i:18;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;}}
>
> Simon.
>
Hmmm, I just checked my iPhone, and an email that I had deleted
earlier in Imp disappeared when it refreshed.
The relevant entry in the AS Device log included this:
2013-04-13T08:31:00+00:00 DEBUG: [26909] Saving state: Array
(
[0] => {516496a4-8660-4650-a643-673dc0a801e6}207
[1] => Horde_Db_Value_Binary Object
(
[_value:protected] =>
C:28:"Horde_ActiveSync_Folder_Imap":1162:{a:5:{s:1:"s";a:3:{s:13:"highestmodseq";i:0;s:7:"uidnext";s:5:"47532";s:11:"uidvalidity";s:10:"1238677126";}s:1:"m";a:21:{i:47408;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47410;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47417;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47419;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47423;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47424;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47428;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47435;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47436;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47440;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47442;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47464;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47465;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47466;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47467;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47468;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47481;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47489;a:2:{s:4:"read";i:1;
s:7:"fla
gged";i:0;}i:47499;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47508;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}i:47521;a:2:{s:4:"read";i:1;s:7:"flagged";i:0;}}s:1:"f";s:5:"INBOX";s:1:"c";s:5:"Email";s:1:"v";i:1;}}
)
[2] => APPL79030T3BA4S
[3] => 1365841859
[4] => INBOX
[5] => simon
[6] => 0
)
2013-04-13T08:31:00+00:00 DEBUG: [26909] O <Folder/>
THAT is working OK for a while.
iPad with the same deleted email is not showing it - still 0 and an
empty array.
:-/
I'm lost.
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/0a53fcc8/attachment-0001.bin>
More information about the horde
mailing list