[Tickets #12175] ActiveSync misses changes from history database

Thu Apr 11 13:52:16 UTC 2013

DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.

Ticket URL: http://bugs.horde.org/ticket/12175
------------------------------------------------------------------------------
  Ticket             | 12175
  Created By         | Thomas Jarosch <thomas.jarosch at intra2net.com>
  Summary            | ActiveSync misses changes from history database
  Queue              | Horde Framework Packages
  Version            | Git master
  Type               | Bug
  State              | Unconfirmed
  Priority           | 1. Low
  Milestone          |
  Patch              |
  Owners             |
------------------------------------------------------------------------------

Thomas Jarosch <thomas.jarosch at intra2net.com> (2013-04-11 13:52) wrote:

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