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

Log in to reply

Looks like your connection to Kopano Community Forum was lost, please wait while we try to reconnect.