search

fmbiete / Z-Push-contrib

Z-Push fork with changes that I will try to contrib
GNU Affero General Public License v3.0
134 stars 62 forks source link

Feature: Ping operation; use cutoff dates received for Sync #197

Open jpfox156 opened 9 years ago

jpfox156 commented 9 years ago

Hi Fmbiete,

While comparing the behaviour of z-push during Sync and Ping requests, I have noticed that Ping requests does not take into account mobile-set folder sync parameters, leading to greater server load.

My Setup: I am using the combined backend with a CalDAV server (SOGo) to serve multiple calendars to a number of devices. One of those calendars contains 320 appointments over a time period of a couple of years. While my Z-push config does not limit sync interval (SYNC_FILTERTIME_MAX=SYNC_FILTERTYPE_ALL), my devices are set to only sync items within the last 6 months (89 appointments for this particular calendar).

I've included debug logs for both a sync event and a ping event on the same calendar. Of note are the two lines in bold on each: it can be seen that Ping calls GetEvents() without a lower limit, whereas the 6 month limit is set for sync events. The results is not only more StatEvents, but also ExportChangesDiff->InitializeExporter() finding 231 events which don't exist every time a HanlePing is called.

Debug logs for a sync with my calendar looks like this: [DEBUG] SqlStateMachine->GetState(): 'lgmcaioy05m2xxxx', 'fd', 'c9460012-1ab8-4d3b-bcdb-de86c1a1bbcf', '', '1' [DEBUG] SyncParameters->UseCPO('DEFAULT') [DEBUG] SyncParameters->checkCPO() called with 'DEFAULT' [DEBUG] SyncCollections->AddCollection(): Folder id 'c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0' : ref. PolicyKey '328681297', ref. Lifetime '1200', last sync at '1433502131' [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '328681297', reference Lifetime '1200', Last sync at '1433502131' [DEBUG] HandleSync(): specified options block with foldertype 'Calendar' [DEBUG] SyncParameters->UseCPO(): removed existing DEFAULT CPO as it is obsolete [DEBUG] SyncParameters->UseCPO('CALENDAR') [DEBUG] SyncParameters->checkCPO() called with 'CALENDAR' [DEBUG] HandleSync(): Start Output [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml [DEBUG] Sync->loadStates(): loading states for folder 'c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0' [DEBUG] SqlStateMachine->GetState(): 'lgmcaioy05m2xxxx', '', 'c9460012-1ab8-4d3b-bcdb-de86c1a1bbcf', '56', '1' [DEBUG] SqlStateMachine->CleanStates(): 'lgmcaioy05m2xxxx', '', 'c9460012-1ab8-4d3b-bcdb-de86c1a1bbcf', '56' [DEBUG] ZPush::GetAdditionalSyncFolderStore('c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0'): 'false' [DEBUG] Combined->Setup('', 'false', '') [DEBUG] Combined->Setup() success [DEBUG] ZPush::GetAdditionalSyncFolderStore('c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0'): 'false' [DEBUG] Combined->Setup('', 'false', '') [DEBUG] Combined->Setup() success [DEBUG] Combined->GetExporter('c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0') [DEBUG] SyncParameters->GetCPO() called with 'DEFAULT' [DEBUG] SyncParameters->normalizeType(): using CALENDAR for requested DEFAULT [DEBUG] SyncParameters->checkCPO() called with 'CALENDAR' [DEBUG] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '89' messages in state [DEBUG] BackendCalDAV->GetMessageList('Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0','1417435637') [DEBUG] z_caldav->GetEvents() called with start = '20141201T120717Z' and finish = '20380119T031407Z' [DEBUG] z_caldav->DoCalendarQuery() called [DEBUG] BackendCalDAV->StatMessage(... (StatMessages for 88 more appointments) [ INFO] ExportChangesDiff->InitializeExporter(): Found 0 change

Debug log for a ping looks like: (note that I've added a couple more debug messages to assist with my understanding of the programme flow). [DEBUG] HandlePing(): reference PolicyKey for PING: 328681297 [DEBUG] HandlePing(): initialization data received [DEBUG] HandlePing(): using saved sync state for 'Calendar' id 'c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0' [DEBUG] SyncCollections->SaveCollection(): Data of folder 'c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0' changed [DEBUG] SqlStateMachine->SetState(): 'lgmcaioy05m2xxxx', 'fd', 'c9460012-1ab8-4d3b-bcdb-de86c1a1bbcf', '' [DEBUG] PingTracking(): Initialized mutexid Resource id #163 and memid Resource id #164. [DEBUG] Announce process as PUSH connection [ INFO] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 1200 seconds) [DEBUG] BackendCombined->HasChangesSink() [DEBUG] BackendCombined->HasChangesSink - Number ChangesSink found: 3 [DEBUG] ZPush::GetAdditionalSyncFolderStore('c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0'): 'false' [DEBUG] Combined->Setup('', 'false', '') [DEBUG] Combined->Setup() success [DEBUG] BackendCombined->ChangesSinkInitialize('c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0') [DEBUG] BackendCombined->ChangesSinkInitialize('c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0') is supported, initializing [DEBUG] BackendCalDAV->ChangesSinkInitialize(): folderid 'Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0' [DEBUG] SqlStateMachine->GetStateHash(): 'lgmcaioy05m2xxxx', 'devicedata', '', '' [DEBUG] SqlStateMachine->GetStateHash(): return '1432812529' [DEBUG] Combined->Setup('', 'false', '') [DEBUG] Combined->Setup() success [DEBUG] Combined->GetExporter('c/Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0') [DEBUG] SyncParameters->GetCPO() called with 'DEFAULT' [DEBUG] SyncParameters->normalizeType() called with 'DEFAULT' [DEBUG] SyncParameters->checkCPO() called with 'DEFAULT' [DEBUG] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '89' messages in state [DEBUG] BackendCalDAV->GetMessageList('Cxxxxxxxx_6D6-544E3000-1-2CFBF8C0','0') [DEBUG] z_caldav->GetEvents() called with start = '19700101T000000Z' and finish = '20380119T031407Z' [DEBUG] z_caldav->DoCalendarQuery() called [DEBUG] BackendCalDAV->StatMessage(... (StatMessages for 319 more appointments) [ INFO] ExportChangesDiff->InitializeExporter(): Found 231 changes [DEBUG] SyncCollections->CheckForChanges(): Using ChangesSink but found relevant changes on regular export

fmbiete commented 9 years ago

Can you check the log in WBXML level. I'm not sure that the Ping operation is receiving the limits.

fmbiete commented 9 years ago

Indeed, the Ping operation doesn't receive the cutoff dates. So we will need to do this:

jpfox156 commented 9 years ago

Thanks Fmbiete,

Hmm. The fix is a bit more complicated than i expected. Maybe the problem needs to be looked at differently; how do i limit the need for undertaking statmessages during ping events altogether? How should the sync collection specification play into this? As I'm using SOGo server, my CALDAV_SUPPORTS_SYNC is set to true, which would (from my preliminary googling) suggest that zpush should be relying on sync collection to tell it whether a sync is required. Or have i misunderstood sync collection's purpose?

Thanks,

James

fmbiete commented 9 years ago

Ping it's the magic push mechanism of ActiveSync. Shortly it does something like this:

  1. Device Pings the server: I will be listening for XXX seconds, so if anything comes up let me know
  2. Server does a initial lookup in the backends. We get all the messages/calendar/contacts/object IDs to "create" a initial state in the process memory.
  3. Server checks for new/changed objects using SYNC (if available in DAV). SYNC only gets the differences from the full operation in 2, so it's faster and cheaper.
  4. Server announce changes to the client, or the end of those XXX seconds without changes.

So, what we need to do is: In 2: Limit that initial sync with the cutoff dates from the last FolderSync operation

I hope you understand now better the problem.

jpfox156 commented 9 years ago

Thanks Fmbiete,

So, to test my understanding against the debug logs above... Step 1 --> HandlePing() is called Step 2 --> ChangesSink is initialised; SQL State Machine is queried; SinkParameters are setup (without the cached information necessary to filter by time period); MessageDiff engine initialised. Step 3 --> BackendCalDav calls GetMessageList(); list of object ID's and etags returned; then recursively calls StatMessage() on each calendar item to return object contents. Step 4 --> SinkCollections-CheckForChanges() compares changes are reports back to the client.

With regards to Step 3, why is StatMessage() called? Have I missunderstood the logic?

fmbiete commented 9 years ago

GetMessageList returns a collection of the result returned by StatMessage. In fact, StatMessage doesn't retrieve the "events" data from the DAV server, since it would be very slow and it's not needed there. It only gets the "e-tag" used as the unique identifier of the event.

You only request the data in the GetMessage, and that operation is over one element each time.