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

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...

Going to call this resolved unless I hear from OP otherwise.

I changed it, but there is nowhere to move groupware objects to since 
there is only one collection of each object type.
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.

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

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

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

:)

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'll have a look at the git history tomorrow, too.
May be there's a hint in there.

Thanks for checking!

Thomas

Eh. You are right of course. I have no idea what I was looking at when 
I said that =)
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.
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.

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.
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

Does this fix?

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

It uses the same Horde_Core_ActiveSync_Driver::changeMethod call so 
this will be fixed by the same change.
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.

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().

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.

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.

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