6.0.0-git
2019-03-18

[#12523] AS: mix of unix timestamp and modseq breaks sync
Summary AS: mix of unix timestamp and modseq breaks sync
Queue Synchronization
Queue Version Git master
Type Bug
State Resolved
Priority 2. Medium
Owners mrubinsk (at) horde (dot) org
Requester thomas.jarosch (at) intra2net (dot) com
Created 2013-08-01 (2055 days ago)
Due
Updated 2013-08-08 (2048 days ago)
Assigned 2013-08-08 (2048 days ago)
Resolved 2013-08-08 (2048 days ago)
Milestone
Patch Yes

History
2013-08-08 15:37:30 Michael Rubinsky State ⇒ Resolved
 
2013-08-08 15:37:01 Git Commit Comment #17 Reply to this comment
Changes have been made in Git (master):

commit 39365ceb6aa5ebd6f4568018830952bf2d8c66b3
Author: Thomas Jarosch <thomas.jarosch@intra2net.com>
Date:   Thu Aug 8 15:29:23 2013 +0200

     Fix sync crash caused by invalid object name

     Bug: 12523

     Signed-off-by: Thomas Jarosch <thomas.jarosch@intra2net.com>
     Signed-off-by: Michael J Rubinsky <mrubinsk@horde.org>

  .../lib/Horde/ActiveSync/Connector/Importer.php    |    4 ++--
  1 files changed, 2 insertions(+), 2 deletions(-)

http://git.horde.org/horde-git/-/commit/39365ceb6aa5ebd6f4568018830952bf2d8c66b3
2013-08-08 13:37:43 Thomas Jarosch Comment #16
State ⇒ Assigned
Patch ⇒ Yes
New Attachment: 0001-Fix-sync-crash-caused-by-invalid-object-name.patch Download
Reply to this comment
Going to call this resolved unless I hear from OP otherwise.
The OP needs to rain on your parade :o)
Please see attached patch to fix sync crashes due to typos.

We should really _test_ the code at least once before
pushing it out to the pear channel...

2013-08-07 23:34:55 Michael Rubinsky Comment #15
State ⇒ Resolved
Reply to this comment
Going to call this resolved unless I hear from OP otherwise.
2013-08-07 22:06:44 Michael Rubinsky Comment #14 Reply to this comment
We should replace the time() call in importMessageMove(), too.
Even though moving groupware objects is currently unsupported,
it will be a PITA to debug in the future if we ever support it.
I changed it, but there is nowhere to move groupware objects to since 
there is only one collection of each object type.
Reading my comments, it seems like I did it on purpose, but to be
honest, I'm not sure that the points I make are really necessary.
I'll have to revisit this.
I'll have a look at the git history tomorrow, too.
May be there's a hint in there.
It had to do with conflict detection/resolution but re-reading the 
specs, DELETE always takes precedence anyway so it was not needed 
after all. Changed.


2013-08-07 21:59:34 Git Commit Comment #13 Reply to this comment
Changes have been made in Git (master):

commit 8efcc05926bb91f2be798e0151402537964a7558
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Wed Aug 7 17:56:59 2013 -0400

     Use ::getSyncStamp() for consistency.

     Bug: 12523

  .../lib/Horde/ActiveSync/Connector/Importer.php    |    3 ++-
  1 files changed, 2 insertions(+), 1 deletions(-)

http://git.horde.org/horde-git/-/commit/8efcc05926bb91f2be798e0151402537964a7558
2013-08-07 21:59:31 Git Commit Comment #12 Reply to this comment
Changes have been made in Git (master):

commit 1629c3e418494acd743116585c51f5deb345655d
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Wed Aug 7 17:56:15 2013 -0400

     Update the state after the messages are deleted.

     Bug: 12523

  .../lib/Horde/ActiveSync/Connector/Importer.php    |   16 ++++++----------
  1 files changed, 6 insertions(+), 10 deletions(-)

http://git.horde.org/horde-git/-/commit/1629c3e418494acd743116585c51f5deb345655d
2013-08-07 21:59:27 Git Commit Comment #11 Reply to this comment
Changes have been made in Git (master):

commit bfc7cfd8680ceef77a54fc7ebfef5a8f06eef0f5
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Wed Aug 7 17:44:40 2013 -0400

     Per MS-ASCMD 2.2.3.34, DELETE never conflicts - it always takes 
precedence.

     Bug: 12523

  .../lib/Horde/ActiveSync/Connector/Importer.php    |   14 --------------
  1 files changed, 0 insertions(+), 14 deletions(-)

http://git.horde.org/horde-git/-/commit/bfc7cfd8680ceef77a54fc7ebfef5a8f06eef0f5
2013-08-07 21:11:50 Thomas Jarosch Comment #10 Reply to this comment
Importer::importMessageDeletion() will still write time() to $change['mod'],
Driver::changeMessage() is not used in this code path. Or is it?

I'm 99% sure it will go wrong though I haven't tested the new code yet.
Eh. You are right of course. I have no idea what I was looking at 
when I said that =)
:)

We should replace the time() call in importMessageMove(), too.
Even though moving groupware objects is currently unsupported,
it will be a PITA to debug in the future if we ever support it.

[Show Quoted Text - 11 lines]
I'll have a look at the git history tomorrow, too.
May be there's a hint in there.

[Show Quoted Text - 11 lines]
Thanks for checking!

Thomas
2013-08-07 20:57:12 Michael Rubinsky Comment #9 Reply to this comment

[Show Quoted Text - 12 lines]
Eh. You are right of course. I have no idea what I was looking at when 
I said that =)
Sorry, I think I misread this somehow. The last time I read it,
the state update was before the moveMessage() call :)

UPDATE: I think I understand why I confused it: The importMessageDeletion()
_first_ updates the state and then does the deletion. In case the 
"backend" deletion
times out, the state is already updated. Is that intentional?
Reading my comments, it seems like I did it on purpose, but to be 
honest, I'm not sure that the points I make are really necessary. I'll 
have to revisit this.
I've grepped the codebase for 'mod' usage and found
two other places that look "interesting". Would be nice
if you could check them for correctness:
Both of those are used during foldersyncs, not collection syncs. For 
folder syncs, the only change we care about for an existing folder is 
a change in the name of the folder. We don't track folder name changes 
in history, so the only way to know it has changed is to compare the 
client's version of the name and the server's version of the name. We 
use the name as the 'mod' value since it's the only thing that changes 
with regard to a folder name.

2013-08-07 20:45:26 Thomas Jarosch Comment #8 Reply to this comment
Horde_ActiveSync_Connector_Importer::importMessageDeletion() looks
affected, too.
It uses the same Horde_Core_ActiveSync_Driver::changeMethod call so 
this will be fixed by the same change.
IMHO

Importer::importMessageDeletion() will still write time() to $change['mod'],
Driver::changeMessage() is not used in this code path. Or is it?

I'm 99% sure it will go wrong though I haven't tested the new code yet.
I'm not sure I follow. The exception in 
Horde_Core_ActiveSync_Driver::moveMessage() will be thrown before 
the state is updated. It's called in ::importMessageMove() on line 
277, the state is updated on line 295 - which won't be reached 
because the exception is not caught and propagates up the call stack.
Sorry, I think I misread this somehow. The last time I read it,
the state update was before the moveMessage() call :)

UPDATE: I think I understand why I confused it: The importMessageDeletion()
_first_ updates the state and then does the deletion. In case the 
"backend" deletion
times out, the state is already updated. Is that intentional?


I've grepped the codebase for 'mod' usage and found
two other places that look "interesting". Would be nice
if you could check them for correctness:

framework/ActiveSync/lib/Horde/ActiveSync/Connector/Exporter.php
public function sendNextChange()
{
...
$stat = array('id' => $change['id'], 'mod' => $change['id'], 0);       
<-- 'id' twice
...
}

and

framework/ActiveSync/lib/Horde/ActiveSync/Connector/Importer.php
public function importFolderChange()
{
...
$change['mod'] = $displayname;                <-- $displayname for the 
modseq column?
}


Thanks,
Thomas

2013-08-07 17:57:44 Michael Rubinsky Comment #7
State ⇒ Feedback
Reply to this comment
Does this fix?
2013-08-07 17:57:20 Git Commit Comment #6 Reply to this comment
Changes have been made in Git (master):

commit 1437e930ccf2cb2814a23f125e7d4bfa37337755
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Wed Aug 7 13:55:01 2013 -0400

     Don't assume we are using timestamps for the syncstamp.

     Bug: 12523

  .../Core/lib/Horde/Core/ActiveSync/Driver.php      |    8 ++++----
  1 files changed, 4 insertions(+), 4 deletions(-)

http://git.horde.org/horde-git/-/commit/1437e930ccf2cb2814a23f125e7d4bfa37337755
2013-08-07 17:54:52 Michael Rubinsky Comment #5 Reply to this comment
Horde_ActiveSync_Connector_Importer::importMessageDeletion() looks 
affected, too.
It uses the same Horde_Core_ActiveSync_Driver::changeMethod call so 
this will be fixed by the same change.
Same for ::importMessageMove() though that is unsupported by the 
Horde_Core part for non-message items. Still it would write wrong 
modseq value into the database before throwing the exception in 
Horde_Core_ActiveSync_Driver::moveMessage().
I'm not sure I follow. The exception in 
Horde_Core_ActiveSync_Driver::moveMessage() will be thrown before the 
state is updated. It's called in ::importMessageMove() on line 277, 
the state is updated on line 295 - which won't be reached because the 
exception is not caught and propagates up the call stack.
2013-08-01 15:52:32 Thomas Jarosch Comment #4 Reply to this comment
Horde_ActiveSync_Connector_Importer::importMessageDeletion() looks 
affected, too.

Same for ::importMessageMove() though that is unsupported by the 
Horde_Core part for non-message items. Still it would write wrong 
modseq value into the database before throwing the exception in 
Horde_Core_ActiveSync_Driver::moveMessage().

2013-08-01 15:14:34 Thomas Jarosch Comment #3 Reply to this comment
The question, then, is why does $change['mod'] contain a timestamp 
in Horde_ActiveSync_State_Sql::updateState() and not the current 
modseq value for that particular collection? It looks like the 
problem is in Horde_Core_ActiveSync_Driver::changeMessage() we 
unconditionally return the current time() as the mod value. We need 
to poll the backend to find out if it supports modsequences and use 
them, similar to what is done in the history related api calls.
yep, correct, I came to the same conclusion later on after dumping the 
activesync_map db table.

Next guess: It didn't cause a problem for you during development since
you migrated to modseq using the old timestamp values.

2013-08-01 15:06:09 Michael Rubinsky Comment #2
Assigned to Michael Rubinsky
State ⇒ Assigned
Priority ⇒ 2. Medium
Reply to this comment
It's actually be a problem with writing the change when the client's 
change (add) is initially imported. The syncMapTable stores either TS 
or MODSEQ value in the syncmodtime field. The code doesn't care what 
the value represents, as long as it's a value that increments with time.

The question, then, is why does $change['mod'] contain a timestamp in 
Horde_ActiveSync_State_Sql::updateState() and not the current modseq 
value for that particular collection? It looks like the problem is in 
Horde_Core_ActiveSync_Driver::changeMessage() we unconditionally 
return the current time() as the mod value. We need to poll the 
backend to find out if it supports modsequences and use them, similar 
to what is done in the history related api calls.
2013-08-01 09:27:21 Thomas Jarosch Comment #1
Type ⇒ Bug
State ⇒ Unconfirmed
Priority ⇒ 1. Low
Summary ⇒ AS: mix of unix timestamp and modseq breaks sync
Queue ⇒ Synchronization
Milestone ⇒
Patch ⇒ No
Reply to this comment
Hi,

I found a bug mixing unix timestamps and modseq numbers which breaks 
the AS sync:

One ActiveSync client wrote a contact to the server.
I then modified the contact on the server and wanted to sync it back.
This failed with " Ignoring PIM initiated change for XXXXX".

Here's the relevant ActiveSync log:
---------------------------------------
2013-08-01T10:22:51+02:00 INFO: [6611] Initializing state for 
collection: @Contacts@, synckey: {51fa1ab1-ed48-4d7d-a02a-19d3ac100191}3
2013-08-01T10:22:51+02:00 INFO: [6611] Loading state for synckey 
{51fa1ab1-ed48-4d7d-a02a-19d3ac100191}3
2013-08-01T10:22:51+02:00 INFO: [6611] Using MODSEQ 6105 for @Contacts@.
2013-08-01T10:22:51+02:00 INFO: [6611] Initializing message diff 
engine for @Contacts@ (@Contacts@)
2013-08-01T10:22:51+02:00 INFO: [6611] 
Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 6102, 6105, 
0, 0)
2013-08-01T10:22:51+02:00 INFO: [6611] Fetching changes for contacts 
using MODSEQ.
2013-08-01T10:22:51+02:00 INFO: [6611] Found 1 message changes in @Contacts@.
2013-08-01T10:22:51+02:00 INFO: [6611] Checking for PIM initiated changes.
2013-08-01T10:22:51+02:00 INFO: [6611] 
Horde_Core_ActiveSync_Driver::_smartStatMessage(@Contacts@, 
51fa1ab1-17ac-49c8-b2ea-19d3ac100191)
2013-08-01T10:22:51+02:00 INFO: [6611] Ignoring PIM initiated change 
for 51fa1ab1-17ac-49c8-b2ea-19d3ac100191 (PIM TS: 1375345329 Stat TS: 
6105)
---------------------------------------

Corresponding Horde_History database dump:
---------------------------------------
sqlite> select * from horde_histories where history_who='clean';
history_id|object_uid|history_action|history_ts|history_desc|history_who|history_extra|history_modseq
6084|Kolab_History_Sync:0d557a9f952c2c6133f5aedec9a1b911|sync|1375345224||clean||6092
6085|Kolab_History_Sync:1a24c92e4e92615aa1dffe70a9f68b98|sync|1375345221||clean||6090
6086|Kolab_History_Sync:43b14f5d0d455283cffbb1c411de821e|sync|1375347126||clean||6107
6087|Kolab_History_Sync:6dd200ddbb206b50615ff802e58f315e|sync|1375345225||clean||6093
6088|turba:8jZheX0ejM69bpifbWqxRQ1:51fa1ab1-17ac-49c8-b2ea-19d3ac100191|add|1375345329||clean||6099
6089|turba:8jZheX0ejM69bpifbWqxRQ1:51fa1ab1-4010-4193-bca2-19d3ac100191|add|1375345329||clean||6102
6090|turba:8jZheX0ejM69bpifbWqxRQ1:51fa1ab1-17ac-49c8-b2ea-19d3ac100191|modify|1375345361||clean||6105

---------------------------------------

The problem is that the logic for "Ignoring PIM initiated change" 
mixes unix timestamps
and the new modseq numbers: "(PIM TS: 1375345329 Stat TS: 6105)".

This boils down to the "Horde_ActiveSync_State_Sql::_getPIMChangeTS()" 
function
which does not seem to use modseq numbers.

Cheers,
Thomas

Saved Queries