Caldav : Issue to sync event from mobile to server
-
Hello,
I have an issue to sync events from mobile to server. I tried to find on the forum if someone had already seen the issue i’m currently facing at, but apparently not.
Everything is working pretty good except for the calendar part.
The events are well sync from the server to the mobile but if we create an event from the mobile nothing is synced to the server.
That’s what I thought at the beginning.
But by doing my troubleshooting , I noticed that a test event I had created from my mobile got synced one day after to the server without changing anything on the mobile or on the server part.Below you’ll find the logs when I created that event and the logs when it has been added into the calendar server.
For information my z-push version is 2.2.9 for those tests ( we also made some tests with the latest version, same thing).
And the calendar server we are using is the one from Oracle Communications Suite.Logs I have immediately when I’m creating a event from my mobile :
03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] -------- Start 03/04/2018 18:48:44 [18402] [ INFO] [test.test@example.com] [sec1b5a0e4f5adc2] Version='2.2.9' method='POST' from='217.109.140.26' cmd='Sync' getUser='test.test@example.com' devId='sec1b5a0e4f5adc2' devType='SAMSUNGSMGF' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Used timezone 'Europe/Paris' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Including backend file: '/data/zpush/www/backend/combined/combined.php' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Including backend file: '/data/zpush/www/backend/imap/imap.php' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Including backend file: '/data/zpush/www/backend/caldav/caldav.php' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Including backend file: '/data/zpush/www/backend/carddav/carddav.php' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined 3 backends loaded. 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Request::ProcessHeaders() ASVersion: 14.0 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::CommandNeedsProvisioning(0): true 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] FileStateMachine->GetState() read '4402' bytes from file: '/data/zpush/state/2/c/sec1b5a0e4f5adc2-devicedata' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ASDevice data loaded for user: 'test.test@example.com' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] TopCollector(): Initialized mutexid Resource id #124 and memid Resource id #125. 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] LoopDetection(): Initialized mutexid Resource id #126 and memid Resource id #127. 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::HierarchyCommand(0): false 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] DeviceManager->ProvisioningRequired('351058586') saved device key '351058586': false 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::CommandNeedsAuthentication(0): true 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Logon('test.test@example.com', '',***)) 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendIMAP->Logon(): User 'test.test@example.com' is authenticated on IMAP 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendIMAP->Logon in checkimap(): entered into the LDAP checkwith username test.test@example.com and password xxxx 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendLDAP->Logon(): bind ok on the LDAP Server 03/04/2018 18:48:44 [18402] [ INFO] [test.test@example.com] [sec1b5a0e4f5adc2] BackendLDAP->Logon(): User 'test.test@example.com' is authenticated on LDAP 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCalDAV->Logon(): User 'test.test@example.com' is authenticated on CalDAV 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCardDAV->Logon(): User 'test.test@example.com' is authenticated on 'http://localhost:10086/nabserver/dav/home/test.test@example.com/' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://localhost:10086/nabserver/dav/home/test.test@example.com/addressbook/' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Logon() success 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup('test.test@example.com', 'true', '') 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup() success 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::CommandNeedsPlainInput(0): false 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] StringStreamWrapper::stream_open(): initialized stream length: 0 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] StringStreamWrapper::stream_open(): initialized stream length: 0 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Synchronize> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Folders> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Folder> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <SyncKey> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I {5296c988-a103-432a-8691-458e3782dbdd}1 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </SyncKey> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <FolderId> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I c/Tcalendar 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </FolderId> 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] FileStateMachine->GetState() read '761' bytes from file: '/data/zpush/state/2/c/sec1b5a0e4f5adc2-5296c988-a103-432a-8691-458e3782dbdd-fd' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncParameters->UseCPO('DEFAULT') 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncCollections->AddCollection(): Folder id 'c/Tcalendar' : ref. PolicyKey '351058586', ref. Lifetime '470', last sync at '1522773890' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncCollections->AddCollection(): Updated reference PolicyKey '351058586', reference Lifetime '470', Last sync at '1522773890' 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <DeletesAsMoves/> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <GetChanges/> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <WindowSize> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 5 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </WindowSize> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Options> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:BodyPreference> 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncParameters->UseCPO('DEFAULT') 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:Type> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 1 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:Type> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:TruncationSize> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 400000 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:TruncationSize> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:BodyPreference> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </Options> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </Folder> 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SYNC_FILTERTIME_MAX defined. Filter set to value: 7 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </Folders> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </Synchronize> 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] HandleSync(): Start Output 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Sync->loadStates(): loading states for folder 'c/Tcalendar' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] FileStateMachine->GetState() read '6' bytes from file: '/data/zpush/state/2/c/sec1b5a0e4f5adc2-5296c988-a103-432a-8691-458e3782dbdd-1' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::GetAdditionalSyncFolderStore('c/Tcalendar'): 'false' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup('', 'false', '') 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup() success 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::GetAdditionalSyncFolderStore('c/Tcalendar'): 'false' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup('', 'false', '') 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup() success 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->GetExporter('c/Tcalendar') 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '0' messages in state 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCalDAV->GetMessageList('Tcalendar','') 03/04/2018 18:48:44 [18402] [ INFO] [test.test@example.com] [sec1b5a0e4f5adc2] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'Tcalendar' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncCollections->GetGlobalWindowSize() overwriting requested global window size of 512 by 50 forced in configuration. 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Folder type: Tasks 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O <Synchronize> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O <Folders> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O <Folder> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O <SyncKey> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O {5296c988-a103-432a-8691-458e3782dbdd}1 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O </SyncKey> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O <FolderId> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O c/Tcalendar 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O </FolderId> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O <Status> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O 1 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O </Status> 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] LoopDetection->Detect(): folderid:'c/Tcalendar' type:'Tasks' uuid:'5296c988-a103-432a-8691-458e3782dbdd' counter:'1' max:'5' queued:'0' 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncCollections->GetGlobalWindowSize() overwriting requested global window size of 512 by 50 forced in configuration. 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O </Folder> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O </Folders> 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] O </Synchronize> 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] WBXMLEncoder->endTag() WBXML output completed 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] WBXML-OUT: AwFqAEVcT0sDezUyOTZjOTg4LWExMDMtNDMyYS04NjkxLTQ1OGUzNzgyZGJkZH0xAAFSA2MvVGNhbGVuZGFyAAFOAzEAAQEBAQ== 03/04/2018 18:48:44 [18402] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] WBXML-IN : AwFqAEVcT0sDezUyOTZjOTg4LWExMDMtNDMyYS04NjkxLTQ1OGUzNzgyZGJkZH0xAAFSA2MvVGNhbGVuZGFyAAEeE1UDNQABVwARRUYDMQABRwM0MDAwMDAAAQEBAQEB 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Logoff() 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendIMAP->Logoff(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendIMAP->Logoff(): IMAP connection closed 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCalDAV->Logoff() 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCardDAV->Logoff() 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Logoff() success 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] LoopDetection->ProcessLoopDetectionTerminate() 03/04/2018 18:48:44 [18402] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Memory usage information: 8.72 MiB/9.50 MiB (9147296 B/9961472 B) - Execution time: 0,13s - HTTP responde code: 200
And the logs when that event has been added into the calendar server :
04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] -------- Start 04/04/2018 11:06:23 [11197] [ INFO] [test.test@example.com] [sec1b5a0e4f5adc2] Version='2.2.9' method='POST' from='217.109.140.26' cmd='Sync' getUser='test.test@example.com' devId='sec1b5a0e4f5adc2' devType='SAMSUNGSMGF' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Used timezone 'Europe/Paris' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Including backend file: '/data/zpush/www/backend/combined/combined.php' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Including backend file: '/data/zpush/www/backend/imap/imap.php' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Including backend file: '/data/zpush/www/backend/caldav/caldav.php' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Including backend file: '/data/zpush/www/backend/carddav/carddav.php' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined 3 backends loaded. 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Request::ProcessHeaders() ASVersion: 14.0 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::CommandNeedsProvisioning(0): true 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] FileStateMachine->GetState() read '4384' bytes from file: '/data/zpush/state/2/c/sec1b5a0e4f5adc2-devicedata' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ASDevice data loaded for user: 'test.test@example.com' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] TopCollector(): Initialized mutexid Resource id #124 and memid Resource id #125. 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] LoopDetection(): Initialized mutexid Resource id #126 and memid Resource id #127. 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::HierarchyCommand(0): false 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] DeviceManager->ProvisioningRequired('351058586') saved device key '351058586': false 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::CommandNeedsAuthentication(0): true 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Logon('test.test@example.com', '',***)) 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendIMAP->Logon(): User 'test.test@example.com' is authenticated on IMAP 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendIMAP->Logon in checkimap(): entered into the LDAP checkwith username test.test@example.com and password xxxx 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendLDAP->Logon(): bind ok on the LDAP Server 04/04/2018 11:06:23 [11197] [ INFO] [test.test@example.com] [sec1b5a0e4f5adc2] BackendLDAP->Logon(): User 'test.test@example.com' is authenticated on LDAP 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCalDAV->Logon(): User 'test.test@example.com' is authenticated on CalDAV 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCardDAV->Logon(): User 'test.test@example.com' is authenticated on 'http://localhost:10086/nabserver/dav/home/test.test@example.com/' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://localhost:10086/nabserver/dav/home/test.test@example.com/addressbook/' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Logon() success 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup('test.test@example.com', 'true', '') 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup() success 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::CommandNeedsPlainInput(0): false 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] StringStreamWrapper::stream_open(): initialized stream length: 0 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] StringStreamWrapper::stream_open(): initialized stream length: 0 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Synchronize> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Folders> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Folder> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <SyncKey> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I {c720742f-3a50-482b-899e-83b58a5dd3d8}5 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </SyncKey> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <FolderId> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I c/Ccalendar 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </FolderId> 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] FileStateMachine->GetState() read '829' bytes from file: '/data/zpush/state/2/c/sec1b5a0e4f5adc2-c720742f-3a50-482b-899e-83b58a5dd3d8-fd' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncParameters->UseCPO('DEFAULT') 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncCollections->AddCollection(): Folder id 'c/Ccalendar' : ref. PolicyKey '351058586', ref. Lifetime '470', last sync at '1522774945' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncCollections->AddCollection(): Updated reference PolicyKey '351058586', reference Lifetime '470', Last sync at '1522774945' 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <DeletesAsMoves/> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <GetChanges/> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <WindowSize> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 5 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </WindowSize> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Options> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <FilterType> 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] SyncParameters->UseCPO('DEFAULT') 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 4 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </FilterType> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:BodyPreference> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:Type> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 1 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:Type> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:TruncationSize> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 400000 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:TruncationSize> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:BodyPreference> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </Options> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Perform> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Add> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <ClientEntryId> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I c5c284a4-0478-4bf0-bdc7-a551f3b77b39 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </ClientEntryId> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <Data> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:Timezone> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I xP///wAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAEAAMAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAMAAAAFAAIAAAAAAAAAxP///w== 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:Timezone> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:AllDayEvent> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 0 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:AllDayEvent> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:StartTime> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 20180412T060000Z 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:StartTime> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:EndTime> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 20180412T070000Z 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:EndTime> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:DtStamp> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 20180404T090621Z 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:DtStamp> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:Subject> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I Tredr hhghj 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:Subject> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:Sensitivity> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 0 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:Sensitivity> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:Body> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:Type> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 1 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:Type> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <AirSyncBase:Data> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:Data> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </AirSyncBase:Body> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:OrganizerEmail> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I test.test@example.com 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:OrganizerEmail> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:Reminder> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 10 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:Reminder> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:UID> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I c5c284a4-0478-4bf0-bdc7-a551f3b77b39 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:UID> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:BusyStatus> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 2 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:BusyStatus> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I <POOMCAL:MeetingStatus> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I 0 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </POOMCAL:MeetingStatus> 04/04/2018 11:06:23 [11197] [WBXML] [test.test@example.com] [sec1b5a0e4f5adc2] I </Data> 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Sync->getImporter(): initialize importer 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Sync->loadStates(): loading states for folder 'c/Ccalendar' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] FileStateMachine->GetState() read '846' bytes from file: '/data/zpush/state/2/c/sec1b5a0e4f5adc2-c720742f-3a50-482b-899e-83b58a5dd3d8-5' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false' 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup('', 'false', '') 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->Setup() success 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] Combined->GetImporter() Content: ImportChangesCombined:('c/Ccalendar') 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ImportChangesCombined->Config(...) 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ImportChangesCombined->Config() success 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ImportChangesCombined->ConfigContentParameters() 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] ImportChangesCombined->ConfigContentParameters() success 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] LoopDetection->SetSyncStateUsage(): uuid: c720742f-3a50-482b-899e-83b58a5dd3d8 counter: 5 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] BackendCalDAV->ChangeMessage('Ccalendar','') 04/04/2018 11:06:23 [11197] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] No etag in: HTTP/1.1 201 Created^M Server: AppServer^M X-Powered-By: Servlet/3.0 JSP/2.2 (AppServer Java/Oracle Corporation/1.7)^M Content-Length: 0^M Date: Wed, 04 Apr 2018 09:06:22 GMT 04/04/2018 11:06:35 [ 6381] [DEBUG] [test.test@example.com] [sec1b5a0e4f5adc2] -------- Start
I tried several mobile devices with different android versions (6,7 and 8) same thing.
That one is a Samsung Galaxy S6 (Android version 7.0) and I’m using the native calendar from Samsung.If anyone can help me about that issue, I will appreciate, because I’m pretty stuck right now.
Thanks
-
Hi z-obaze,
Z-Push 2.2.9 is very old and not supported anymore. Please try with Z-Push 2.4.0 and post the logs then.
Manfred
-
Hello,
So I tried with the latest z-push version (2.4.0) and still same issue with calendar.
The events are well synced from server to mobile, but nothing is happening when I’m creating an event from my mobile.
Actually there is nothing at all into the z-push logs when i’m creating an event from the mobile.Otherwise, everything is ok for the mailbox part and also all good for the contacts (synced both ways).
So my issue is just about the calendar.I tried with several devices on several android version, always same issue with calendar.
I’m still using the native calendar from Samsung.So as I do not have any logs which could show something wrong, I do not what I could give you.
I tried to catch the logs from the mobile device with the adb tool but I’m not familiar with it at all, so if you could help me to catch the right logs I will appreciate it.I’ll see if during the night the event has been synced or not as it was for the zpush version 2.2.9, with few hours late.
Thanks
-
Hi z-obaze,
do you have multiple calendars on your device? Could it be possible that you’re creating events in e.g. google calendar instead of the caldav one?
If there’s nothing in z-push.log then it’s rather a client and not a Z-Push issue.
Manfred
-
Hi Manfred,
I just have the local calendar plus the remote one with z-push.
when I’m creating the event, I’m always checking if I took the z-push one.I tried by choosing “gmail: Exchange” when creating account instead of “Microsoft Exchange ActiveSync”.
And as I do not have so far the google calendar installed, It uses the native calendar from Samsung, so the same one than my previous tests, and then the sync works in both ways.So why that calendar app is working with the “gmail: exchange” and not with “Microsoft Exchange ActiveSync”?
I’m also having some trouble with the gmail app for the mailbox part when I’m choosing to sync everything into “Sync emails from:”.
In that case I do not have all the emails into the different folders, sometimes I can see them, but they disappear for some reason.
That’s another issue, I could open a new thread for it.Thanks
-
Hi z-obaze,
@z-obaze said in Caldav : Issue to sync event from mobile to server:
I tried by choosing “gmail: Exchange” when creating account instead of “Microsoft Exchange ActiveSync”.
And as I do not have so far the google calendar installed, It uses the native calendar from Samsung, so the same one than my previous tests, and then the sync works in both ways.So why that calendar app is working with the “gmail: exchange” and not with “Microsoft Exchange ActiveSync”?
Because these are two different apps and apparently gmail exchange does something differently than Microsoft Exchange ActiveSync. I personally never used the gmail exchange app, so I have no idea how good it works. What you could do, is to debug Microsoft Exchange ActiveSync on the device with logcat.
I’m also having some trouble with the gmail app for the mailbox part when I’m choosing to sync everything into “Sync emails from:”.
In that case I do not have all the emails into the different folders, sometimes I can see them, but they disappear for some reason.
That’s another issue, I could open a new thread for it.As I said I’m not familiar with the gmail app. Asking in the specific gmail forum would probably get you better answers than here.
Manfred
-
Hi Manfred,
Thanks for your answer.
Apparently my issue with the calendar is not related to the caldav server I’m using.
So , you never got that issue with the native calendar on android?
I will be surprised that I’m the only one, unless there is something specific with my configuration.Do you know the logcat command I could use? as I’ve never used it so far and I don’t know on which tag I could filter the logs.
Thanks
-
Hi z-obaze,
I’m using the native calendar on android (well, it’s samsung s planner, but the MS Exchange ActiveSync) for quite some time and haven’t had a similar issue. I’m using Kopano backend though. Sometimes it happens that the changes in the calendar on the device aren’t immediately synced to the server, but it never takes longer than a couple of minutes.
Have you tried clearing the cache for the account/calendar on the device?
Logcat tool: https://developer.android.com/studio/command-line/logcat.html
Manfred
-
Hi Manfred,
So you’re using the same calendar app than me with the same way to create the account.
I don’t know how it could work for you and not for me as the calendar backend seems to not be related to the issue.I tried clearing cache, still same issue.
I’m trying to get some logs from my device, but I don’t know on which tag I could filter and as there is a lot of logs from the device it’s kind of hard to find what could be the issue.
I’ll continue my troubleshooting, but I’m pretty stuck.
-
Hello,
I’m still looking for about what could be my issue.
I’m just wondering what the difference between this “Ccalendar” and 'Tcalendar" :
For example :
SyncCollections->AddCollection(): Folder id ‘c/Tcalendar’ : ref. PolicyKey ‘541847397’, ref. Lifetime ‘470’, last sync at ‘1523609141’
and
SyncCollections->AddCollection(): Folder id ‘c/Ccalendar’ : ref. PolicyKey ‘541847397’, ref. Lifetime ‘470’, last sync at ‘1523609144’
I only have one calendar on my account named “calendar”.
-
Hi z-obaze,
I guess “T” stands for tasks and “C” for calendar.
Manfred
-
Hi Manfred,
Ok thanks.
So with the native calendar, the tasks are well synced but not the events.
Could it be a Time zone issue?
My device is on “Central European Summer time” zone.
The server is configured with this “define(‘TIMEZONE’, ‘Europe/Paris’);” -
Hi z-obaze,
timezone issues are rather related to the items being on the wrong time (e.g. 1 hour too late or too soon). But it might be possible, yes.
You could test what happens if you disable task sync on the mobile and only sync calendar.
Manfred
-
i have the same problem with sansung a50, before it i use xiaomi and didnt have any problems with calendar syncing, but now i have. i use latest z-push combined backend