Tickets :: Comment on [#12175] Add modification sequence support to Horde

* Your Email Address
* Spam protection	Enter the letters below: __. .._.\ /.__ (__ \| \| >< \| \ .__)\__\|_\|_/ \\|__/
Comment	> Hi, > > I've just discovered a problem in the way ActiveSync gets the changes > from the history database. I had a Kolab based contacts folder with > 30 contacts and deleted them all at once. > During that time an iPad and some other devices were syncing in the > background. > > Checking the iPad later on, seven contacts still existed on the device. Oops. > > The server is a rather slow VM and it took a few seconds to delete > all contacts. Our ActiveSync implementation internally uses > getServerChanges($start_ts, $end_ts). This boils down to a simplified > history database query like > "select * from horde_histories WHERE history_ts > $start_ts AND > history_ts < $end_ts" > > > I've picked on still existing contact and dumped the history for it: > > history_id\|object_uid\|history_action\|history_ts\|history_desc\|history_who\|history_extra > 759\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877dc-d794-4d57-aae8-60b3ac100184\|add\|1365665371\|\|mueller\| > 812\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877dc-d794-4d57-aae8-60b3ac100184\|delete\|1365669188\|\|mueller\| > > > Relevant getServerChanges() calls from the log: > 2013-04-11T10:32:59+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365665778, 1365669179, 0, 1) > 2013-04-11T10:32:59+02:00 DEBUG: [3473] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365665778, 1365669179, 0, 0) > 2013-04-11T10:33:02+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669179, 1365669182, 0, 1) > 2013-04-11T10:33:03+02:00 DEBUG: [3473] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669179, 1365669183, 0, 0) > 2013-04-11T10:33:07+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669183, 1365669187, 0, 1) > 2013-04-11T10:33:08+02:00 DEBUG: [3473] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669183, 1365669188, 0, 0) > 2013-04-11T10:33:11+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669188, 1365669191, 0, 1) > 2013-04-11T10:33:16+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669188, 1365669196, 0, 1) > 2013-04-11T10:33:21+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669188, 1365669201, 0, 1) > 2013-04-11T10:33:26+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669188, 1365669206, 0, 1) > 2013-04-11T10:33:31+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669188, 1365669211, 0, 1) > 2013-04-11T10:33:36+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669188, 1365669216, 0, 1) > 2013-04-11T10:33:41+02:00 DEBUG: [2253] > Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, > 1365669188, 1365669221, 0, 1) > ... > > As you can see it queries for "ts > 1365669183 and ts < 1365669188". > Next time it queries for "> 1365669188 and < 1365669191". Since the > change happened exactly on 1365669188, the history query missed it. > > I'm not sure if the listBy() / getChanges() horde app API should > include a change if it's exactly on the desired end timestamp or not > (history_ts <= $end_ts). If not, we should do a "thisSyncTS+1" query > in the ActiveSync backend. > > > But there is more :) Here's a short dump from my history database: > > sqlite> select * from horde_histories where history_ts >= 1365669183 > and history_ts <= 1365669188; > history_id\|object_uid\|history_action\|history_ts\|history_desc\|history_who\|history_extra > 800\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877dc-668c-44ce-b0c2-60b3ac100184\|delete\|1365669183\|\|mueller\| > 801\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877de-3368-4245-80e2-60b3ac100184\|delete\|1365669183\|\|mueller\| > 802\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877d6-2dfc-4b22-aa60-60b3ac100184\|delete\|1365669183\|\|mueller\| > 803\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877dd-c208-4ae6-9f64-60b3ac100184\|delete\|1365669184\|\|mueller\| > 804\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877df-2fdc-4685-92b7-60b3ac100184\|delete\|1365669184\|\|mueller\| > 805\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877d7-8e9c-4bfb-8ce4-60b3ac100184\|delete\|1365669185\|\|mueller\| > 806\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877d4-e070-410d-9205-60b3ac100184\|delete\|1365669185\|\|mueller\| > 807\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877e0-1584-4846-82c7-60b3ac100184\|delete\|1365669186\|\|mueller\| > 808\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877de-b8d4-4a8d-8386-60b3ac100184\|delete\|1365669186\|\|mueller\| > 809\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877d4-eaf4-4a74-9146-60b3ac100184\|delete\|1365669187\|\|mueller\| > 810\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877d9-8c1c-4d62-9621-60b3ac100184\|delete\|1365669187\|\|mueller\| > 811\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877df-8aac-402e-8a4e-60b3ac100184\|delete\|1365669188\|\|mueller\| > 812\|turba:X-SLUZ40uwb8ZZt1JOhQWg4:514877dc-d794-4d57-aae8-60b3ac100184\|delete\|1365669188\|\|mueller\| > > > As you can see there are several entries with the same change > timestamp. An ActiveSync client might query for "history_ts < > 1365669188" and only see the first entry (id: 811). The delete > request via the web UI is still running and adds the second delete > request to the history database also with ts = 1365669188 (id: 812). > > The ActiveSync client will miss this one as it already queried for > all changes up to 1365669188. Classic race condition :) > > Any idea how to fix this one? A monotonic counter would be best but > that's a rather intrusive change. > > If we change the history database query to "history_ts >= start_ts > AND history_ts <= end_ts", we might deliver some changes twice to the > client. That must be avoided, too. > > Cheers, > Thomas >
Attachment
Watch this ticket

Saved Queries