29/06/2017 15:15:58 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:53:31 [23493] [DEBUG] [test6] -------- Start
29/06/2017 15:53:31 [23493] [DEBUG] [test6] cmd='Ping' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='POST'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::CommandNeedsProvisioning(18): false
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::CommandNeedsAuthentication(18): true
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '24077' bytes from file: '/var/lib/z-push/0/4/androidc110596740-devicedata'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ASDevice data loaded for user: 'test6'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] TopCollector(): Initialized mutexid Resource id #77 and memid Resource id #78.
29/06/2017 15:53:31 [23493] [DEBUG] [test6] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] LoopDetection(): Initialized mutexid Resource id #82 and memid Resource id #83.
29/06/2017 15:53:31 [23493] [DEBUG] [test6] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::HierarchyCommand(18): false
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::CommandNeedsPlainInput(18): false
29/06/2017 15:53:31 [23493] [WBXML] [test6] I  <Ping:Ping>
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '714' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bb77fef1-d3a4-4910-bb46-ce947605de1e-fd'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'c/Ccalendar' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739224'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncCollections->AddCollection(): Updated reference PolicyKey '239207610', reference Lifetime '780', Last sync at '1498739224'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{bb77fef1-d3a4-4910-bb46-ce947605de1e}1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bb77fef1-d3a4-4910-bb46-ce947605de1e-1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '708' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e6011232-7a3f-4732-be6a-9b19a408b3c9-fd'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Tcalendar'): 'false'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'c/Tcalendar' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739229'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncCollections->AddCollection(): Updated reference PolicyKey '239207610', reference Lifetime '780', Last sync at '1498739229'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{e6011232-7a3f-4732-be6a-9b19a408b3c9}1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e6011232-7a3f-4732-be6a-9b19a408b3c9-1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '712' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e12ce87b-92c1-42fa-9a9d-585f6416e835-fd'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('d/contacts'): 'false'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'd/contacts' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739227'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{e12ce87b-92c1-42fa-9a9d-585f6416e835}1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e12ce87b-92c1-42fa-9a9d-585f6416e835-1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '983' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-fd'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'i/f7b8fbc4' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739217'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{2fb9dd2a-a8e5-4550-811d-e4536138580c}2'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '160' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-2'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '912' bytes from file: '/var/lib/z-push/0/4/androidc110596740-c14d9310-9046-470a-a758-0e1044bf94e2-fd'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/0a273bb5'): 'false'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'i/0a273bb5' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739223'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{c14d9310-9046-470a-a758-0e1044bf94e2}5'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '314' bytes from file: '/var/lib/z-push/0/4/androidc110596740-c14d9310-9046-470a-a758-0e1044bf94e2-5'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-fd'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id '' : ref. PolicyKey '239207610', ref. Lifetime '10', last sync at '1498739215'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{5ff598a6-fade-4519-b95b-baa17e099ad6}1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] StateManager->loadHierarchyCache(): 'androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '2103' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '933' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-1'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] HandlePing(): reference PolicyKey for PING: 239207610
29/06/2017 15:53:31 [23493] [DEBUG] [test6] HandlePing(): initialization data received
29/06/2017 15:53:31 [23493] [WBXML] [test6] I   <Ping:LifeTime>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    780
29/06/2017 15:53:31 [23493] [WBXML] [test6] I   </Ping:LifeTime>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I   <Ping:Folders>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      i/f7b8fbc4
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      Email
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:53:31 [23493] [DEBUG] [test6] HandlePing(): using saved sync state for 'Email' id 'i/f7b8fbc4'
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      i/0a273bb5
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      Email
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:53:31 [23493] [DEBUG] [test6] HandlePing(): using saved sync state for 'Email' id 'i/0a273bb5'
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      c/Ccalendar
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      Calendar
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:53:31 [23493] [DEBUG] [test6] HandlePing(): using saved sync state for 'Calendar' id 'c/Ccalendar'
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      c/Tcalendar
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      Tasks
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:53:31 [23493] [DEBUG] [test6] HandlePing(): using saved sync state for 'Tasks' id 'c/Tcalendar'
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      d/contacts
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I      Contacts
29/06/2017 15:53:31 [23493] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:53:31 [23493] [DEBUG] [test6] HandlePing(): using saved sync state for 'Contacts' id 'd/contacts'
29/06/2017 15:53:31 [23493] [WBXML] [test6] I   </Ping:Folders>
29/06/2017 15:53:31 [23493] [WBXML] [test6] I  </Ping:Ping>
29/06/2017 15:53:31 [23493] [DEBUG] [test6] DeviceManager->DoAutomaticASDeviceSaving(): save automatically: false
29/06/2017 15:53:31 [23493] [DEBUG] [test6] PingTracking(): Initialized mutexid Resource id #223 and memid Resource id #224.
29/06/2017 15:53:31 [23493] [DEBUG] [test6] PingTracking initialised with IPC provider 'IpcSharedMemoryProvider' with type '2'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Announce process as PUSH connection
29/06/2017 15:53:31 [23493] [ INFO] [test6] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 780 seconds)
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCombined->HasChangesSink()
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCombined->HasChangesSink - Number ChangesSink found: 3
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Ccalendar')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Ccalendar') is supported, initializing
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCalDAV->ChangesSinkInitialize(): folderid 'Ccalendar'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Tcalendar'): 'false'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Tcalendar')
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Tcalendar') is supported, initializing
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCalDAV->ChangesSinkInitialize(): folderid 'Tcalendar'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('d/contacts'): 'false'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('d/contacts')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('d/contacts') is supported, initializing
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCardDAV->ChangesSinkInitialize(): folderid 'contacts'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/f7b8fbc4')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/f7b8fbc4') is supported, initializing
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->ChangesSinkInitialize(): folderid 'f7b8fbc4'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] FileStateMachine->GetState() read '1597' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/0a273bb5'): 'false'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/0a273bb5')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/0a273bb5') is supported, initializing
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->ChangesSinkInitialize(): folderid '0a273bb5'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:53:32 [23493] [DEBUG] [test6] Combined->GetExporter('')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ExportChangesCombined constructed
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ExportChangesCombined->Config(...)
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ExportChangesCombined->Config() success
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...)
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('i',...)
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('INBOX') = f7b8fbc4
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->convertImapId('INBOX') = f7b8fbc4
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('saved-messages') = 6a432e8c
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->convertImapId('saved-messages') = 6a432e8c
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Trash') = 12b12969
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->convertImapId('Trash') = 12b12969
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Sent') = 0a273bb5
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->convertImapId('Sent') = 0a273bb5
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Spam') = 22ef492a
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->convertImapId('Spam') = 22ef492a
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('sent-mail') = 80b47162
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->convertImapId('sent-mail') = 80b47162
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Drafts') = 22a258df
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->convertImapId('Drafts') = 22a258df
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Archive') = d8a50c2b
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendIMAP->convertImapId('Archive') = d8a50c2b
29/06/2017 15:53:32 [23493] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '8' changes for 'hierarchy'
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('c',...)
29/06/2017 15:53:32 [23493] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCalDAV->GetFolderList(): Getting all folders.
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCalDAV->StatFolder('Ccalendar')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCalDAV->GetFolder('Ccalendar')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCalDAV->StatFolder('Tcalendar')
29/06/2017 15:53:32 [23493] [DEBUG] [test6] BackendCalDAV->GetFolder('Tcalendar')
29/06/2017 15:53:33 [23493] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('d',...)
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendCardDAV::GetFolderList()
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendCardDAV::StatFolder('contacts')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendCardDAV::GetFolder('contacts')
29/06/2017 15:53:33 [23493] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...) success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ExportChangesCombined->Synchronize()
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('f7b8fbc4')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant.
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('6a432e8c')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'saved-messages' will not be sent as modification is not relevant.
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('12b12969')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Trash' will not be sent as modification is not relevant.
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('0a273bb5')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Sent' will not be sent as modification is not relevant.
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22ef492a')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Junk' will not be sent as modification is not relevant.
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('80b47162')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'sent-mail' will not be sent as modification is not relevant.
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22a258df')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Drafts' will not be sent as modification is not relevant.
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('d8a50c2b')
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Archive' will not be sent as modification is not relevant.
29/06/2017 15:53:33 [23493] [DEBUG] [test6] ExportChangesCombined->Synchronize() success
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:53:33 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:53:42 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:53:51 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:54:00 [23493] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:54:00 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:54:00 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:54:00 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:54:09 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:54:18 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:54:27 [23493] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:54:27 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:54:27 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:54:27 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:54:36 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:54:45 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:54:54 [23493] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:54:54 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:54:54 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:54:54 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:55:03 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:55:12 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:55:21 [23493] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:55:21 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:55:21 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:55:21 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:55:30 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:55:39 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:55:48 [23493] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:55:48 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:55:48 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:55:48 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:55:57 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:56:06 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:56:15 [23493] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:56:15 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:56:15 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:56:15 [23493] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:56:18 [17674] [DEBUG] [test6] -------- Start
29/06/2017 15:56:18 [17674] [DEBUG] [test6] cmd='' devType='' devId='' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='OPTIONS'
29/06/2017 15:56:18 [17674] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:56:18 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:56:18 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:56:18 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:56:18 [17674] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:56:18 [17674] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:56:18 [17674] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:56:18 [17674] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:56:18 [17674] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:56:18 [17674] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:56:19 [17674] [DEBUG] [test6] NoPostRequestException: Options request - code: 1 - file: /usr/share/z-push/index.php:66
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings
29/06/2017 15:56:19 [17674] [ INFO] [test6] Options request
29/06/2017 15:56:19 [17674] [ INFO] [test6] cmd='' memory='4.28 MiB/4.75 MiB' time='0.74s' devType='' devId='' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' idle='0s' version='2.3.7' method='OPTIONS' httpcode='200'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] -------- End
29/06/2017 15:56:19 [17674] [WARN] [test6] Unknown:0 Unknown: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN (errflg=1) (8)
29/06/2017 15:56:19 [17674] [DEBUG] [test6] -------- Start
29/06/2017 15:56:19 [17674] [DEBUG] [test6] cmd='FolderSync' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='POST'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ZPush::CommandNeedsProvisioning(9): true
29/06/2017 15:56:19 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '24077' bytes from file: '/var/lib/z-push/0/4/androidc110596740-devicedata'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ASDevice data loaded for user: 'test6'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] TopCollector(): Initialized mutexid Resource id #61 and memid Resource id #62.
29/06/2017 15:56:19 [17674] [DEBUG] [test6] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] LoopDetection(): Initialized mutexid Resource id #66 and memid Resource id #67.
29/06/2017 15:56:19 [17674] [DEBUG] [test6] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ZPush::HierarchyCommand(9): true
29/06/2017 15:56:19 [17674] [DEBUG] [test6] DeviceManager->ProvisioningRequired('239207610') saved device key '239207610': false
29/06/2017 15:56:19 [17674] [DEBUG] [test6] DeviceManager->getPolicyName(): determined policy name: 'default'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ZPush::CommandNeedsAuthentication(9): true
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ZPush::CommandNeedsPlainInput(9): false
29/06/2017 15:56:19 [17674] [WBXML] [test6] I  <FolderHierarchy:FolderSync>
29/06/2017 15:56:19 [17674] [WBXML] [test6] I   <FolderHierarchy:SyncKey>
29/06/2017 15:56:19 [17674] [WBXML] [test6] I    {5ff598a6-fade-4519-b95b-baa17e099ad6}1
29/06/2017 15:56:19 [17674] [WBXML] [test6] I   </FolderHierarchy:SyncKey>
29/06/2017 15:56:19 [17674] [DEBUG] [test6] StateManager->loadHierarchyCache(): 'androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '2103' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '933' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-1'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-fd'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:19 [17674] [WBXML] [test6] I  </FolderHierarchy:FolderSync>
29/06/2017 15:56:19 [17674] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionAddStatus: 'hierarchy' with status 1
29/06/2017 15:56:19 [17674] [DEBUG] [test6] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
29/06/2017 15:56:19 [17674] [DEBUG] [test6] Combined->GetExporter('')
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ExportChangesCombined constructed
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ExportChangesCombined->Config(...)
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ExportChangesCombined->Config() success
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...)
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('i',...)
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:56:19 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '1597' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('INBOX') = f7b8fbc4
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('INBOX') = f7b8fbc4
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('saved-messages') = 6a432e8c
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('saved-messages') = 6a432e8c
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Trash') = 12b12969
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Trash') = 12b12969
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Sent') = 0a273bb5
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Sent') = 0a273bb5
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Spam') = 22ef492a
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Spam') = 22ef492a
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('sent-mail') = 80b47162
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('sent-mail') = 80b47162
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Drafts') = 22a258df
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Drafts') = 22a258df
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Archive') = d8a50c2b
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Archive') = d8a50c2b
29/06/2017 15:56:19 [17674] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '8' changes for 'hierarchy'
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('c',...)
29/06/2017 15:56:19 [17674] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:56:19 [17674] [DEBUG] [test6] BackendCalDAV->GetFolderList(): Getting all folders.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCalDAV->StatFolder('Ccalendar')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCalDAV->GetFolder('Ccalendar')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCalDAV->StatFolder('Tcalendar')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCalDAV->GetFolder('Tcalendar')
29/06/2017 15:56:20 [17674] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('d',...)
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCardDAV::GetFolderList()
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCardDAV::StatFolder('contacts')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCardDAV::GetFolder('contacts')
29/06/2017 15:56:20 [17674] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...) success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ExportChangesCombined->GetChangeCount()
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ExportChangesCombined->GetChangeCount() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ExportChangesCombined->Synchronize()
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('f7b8fbc4')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('6a432e8c')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'saved-messages' will not be sent as modification is not relevant.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('12b12969')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Trash' will not be sent as modification is not relevant.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('0a273bb5')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Sent' will not be sent as modification is not relevant.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22ef492a')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Junk' will not be sent as modification is not relevant.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('80b47162')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'sent-mail' will not be sent as modification is not relevant.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22a258df')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Drafts' will not be sent as modification is not relevant.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('d8a50c2b')
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Archive' will not be sent as modification is not relevant.
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ExportChangesCombined->Synchronize() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ExportChangesCombined->GetState()
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ExportChangesCombined->GetState() success
29/06/2017 15:56:20 [17674] [WBXML] [test6] O  <FolderHierarchy:FolderSync>
29/06/2017 15:56:20 [17674] [WBXML] [test6] O   <FolderHierarchy:Status>
29/06/2017 15:56:20 [17674] [WBXML] [test6] O   1
29/06/2017 15:56:20 [17674] [WBXML] [test6] O   </FolderHierarchy:Status>
29/06/2017 15:56:20 [17674] [WBXML] [test6] O   <FolderHierarchy:SyncKey>
29/06/2017 15:56:20 [17674] [WBXML] [test6] O   {5ff598a6-fade-4519-b95b-baa17e099ad6}1
29/06/2017 15:56:20 [17674] [WBXML] [test6] O   </FolderHierarchy:SyncKey>
29/06/2017 15:56:20 [17674] [WBXML] [test6] O   <FolderHierarchy:Changes>
29/06/2017 15:56:20 [17674] [WBXML] [test6] O    <FolderHierarchy:Count>
29/06/2017 15:56:20 [17674] [WBXML] [test6] O    0
29/06/2017 15:56:20 [17674] [WBXML] [test6] O    </FolderHierarchy:Count>
29/06/2017 15:56:20 [17674] [WBXML] [test6] O   </FolderHierarchy:Changes>
29/06/2017 15:56:20 [17674] [DEBUG] [test6] DeviceManager->CheckFolderData() checking integrity of hierarchy cache with synchronized folders
29/06/2017 15:56:20 [17674] [DEBUG] [test6] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11
29/06/2017 15:56:20 [17674] [WBXML] [test6] O  </FolderHierarchy:FolderSync>
29/06/2017 15:56:20 [17674] [DEBUG] [test6] WBXMLEncoder->endTag() WBXML output completed
29/06/2017 15:56:20 [17674] [WBXML] [test6] WBXML-OUT: AwFqAAAHVkwDMQABUgN7NWZmNTk4YTYtZmFkZS00NTE5LWI5NWItYmFhMTdlMDk5YWQ2fTEAAU5XAzAAAQEB
29/06/2017 15:56:20 [17674] [WBXML] [test6] WBXML-IN : AwFqAAAHVlIDezVmZjU5OGE2LWZhZGUtNDUxOS1iOTViLWJhYTE3ZTA5OWFkNn0xAAEB
29/06/2017 15:56:20 [17674] [DEBUG] [test6] Combined->Logoff()
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:56:20 [17674] [DEBUG] [test6] FileStateMachine->SetState() written 1597 bytes on file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCalDAV->Logoff(): disconnected from CALDAV server
29/06/2017 15:56:20 [17674] [DEBUG] [test6] BackendCardDAV->Logoff(): disconnected from CARDDAV server
29/06/2017 15:56:20 [17674] [DEBUG] [test6] Combined->Logoff() success
29/06/2017 15:56:20 [17674] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionTerminate()
29/06/2017 15:56:20 [17674] [ INFO] [test6] cmd='FolderSync' memory='6.82 MiB/7.25 MiB' time='1.57s' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' idle='0s' version='2.3.7' method='POST' httpcode='200'
29/06/2017 15:56:20 [17674] [DEBUG] [test6] -------- End
29/06/2017 15:56:21 [17674] [DEBUG] [test6] -------- Start
29/06/2017 15:56:21 [17674] [DEBUG] [test6] cmd='Sync' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='POST'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:56:21 [17674] [DEBUG] [test6] ZPush::CommandNeedsProvisioning(0): true
29/06/2017 15:56:21 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '24077' bytes from file: '/var/lib/z-push/0/4/androidc110596740-devicedata'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] ASDevice data loaded for user: 'test6'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] TopCollector(): Initialized mutexid Resource id #61 and memid Resource id #62.
29/06/2017 15:56:21 [17674] [DEBUG] [test6] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] LoopDetection(): Initialized mutexid Resource id #66 and memid Resource id #67.
29/06/2017 15:56:21 [17674] [DEBUG] [test6] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] ZPush::HierarchyCommand(0): false
29/06/2017 15:56:21 [17674] [DEBUG] [test6] DeviceManager->ProvisioningRequired('239207610') saved device key '239207610': false
29/06/2017 15:56:21 [17674] [DEBUG] [test6] DeviceManager->getPolicyName(): determined policy name: 'default'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
29/06/2017 15:56:21 [17674] [DEBUG] [test6] ZPush::CommandNeedsAuthentication(0): true
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:56:21 [17674] [DEBUG] [test6] ZPush::CommandNeedsPlainInput(0): false
29/06/2017 15:56:21 [17674] [WBXML] [test6] I  <Synchronize>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I   <Folders>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I    <Folder>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     <SyncKey>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I      {2fb9dd2a-a8e5-4550-811d-e4536138580c}2
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     </SyncKey>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     <FolderId>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I      i/f7b8fbc4
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     </FolderId>
29/06/2017 15:56:21 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '983' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-fd'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:21 [17674] [DEBUG] [test6] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'i/f7b8fbc4', returning as is.
29/06/2017 15:56:21 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'i/f7b8fbc4' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739217'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Updated reference PolicyKey '239207610', reference Lifetime '780', Last sync at '1498739217'
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     <DeletesAsMoves>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I      1
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     </DeletesAsMoves>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     <GetChanges/>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     <WindowSize>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I      10
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     </WindowSize>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     <Options>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I      <FilterType>
29/06/2017 15:56:21 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:21 [17674] [WBXML] [test6] I       3
29/06/2017 15:56:21 [17674] [WBXML] [test6] I      </FilterType>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I      <AirSyncBase:BodyPreference>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I       <AirSyncBase:Type>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I        2
29/06/2017 15:56:21 [17674] [WBXML] [test6] I       </AirSyncBase:Type>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I       <AirSyncBase:TruncationSize>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I        200000
29/06/2017 15:56:21 [17674] [WBXML] [test6] I       </AirSyncBase:TruncationSize>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I      </AirSyncBase:BodyPreference>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I     </Options>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I    </Folder>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I   </Folders>
29/06/2017 15:56:21 [17674] [WBXML] [test6] I  </Synchronize>
29/06/2017 15:56:21 [17674] [DEBUG] [test6] HandleSync(): Start Output
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Sync->loadStates(): loading states for folder 'i/f7b8fbc4'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '160' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-2'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:21 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->GetExporter('i/f7b8fbc4')
29/06/2017 15:56:21 [17674] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '2' messages in state
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendIMAP->GetMessageList('f7b8fbc4','1498139781')
29/06/2017 15:56:21 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '1597' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendIMAP->GetMessageList(): searching with sequence '1,2'
29/06/2017 15:56:21 [17674] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'f7b8fbc4'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionAddStatus: 'i/f7b8fbc4' with status 1
29/06/2017 15:56:21 [17674] [DEBUG] [test6] HandleSync: No changes found for Email folder id 'i/f7b8fbc4'. Omitting output.
29/06/2017 15:56:21 [17674] [WBXML] [test6] WBXML-IN : AwFqAEVcT0sDezJmYjlkZDJhLWE4ZTUtNDU1MC04MTFkLWU0NTM2MTM4NTgwY30yAAFSA2kvZjdiOGZiYzQAAV4DMQABE1UDMTAAAVdYAzMAAQARRUYDMgABRwMyMDAwMDAAAQEBAQEB
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->Logoff()
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:56:21 [17674] [DEBUG] [test6] FileStateMachine->SetState() written 1597 bytes on file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendCalDAV->Logoff(): disconnected from CALDAV server
29/06/2017 15:56:21 [17674] [DEBUG] [test6] BackendCardDAV->Logoff(): disconnected from CARDDAV server
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Combined->Logoff() success
29/06/2017 15:56:21 [17674] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionTerminate()
29/06/2017 15:56:21 [17674] [ INFO] [test6] cmd='Sync' memory='7.09 MiB/7.50 MiB' time='0.73s' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' idle='0s' version='2.3.7' method='POST' httpcode='200'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] -------- End
29/06/2017 15:56:21 [17674] [DEBUG] [test6] -------- Start
29/06/2017 15:56:21 [17674] [DEBUG] [test6] cmd='Ping' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='POST'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:56:21 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::CommandNeedsProvisioning(18): false
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::CommandNeedsAuthentication(18): true
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '24077' bytes from file: '/var/lib/z-push/0/4/androidc110596740-devicedata'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ASDevice data loaded for user: 'test6'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] TopCollector(): Initialized mutexid Resource id #77 and memid Resource id #78.
29/06/2017 15:56:22 [17674] [DEBUG] [test6] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] LoopDetection(): Initialized mutexid Resource id #82 and memid Resource id #83.
29/06/2017 15:56:22 [17674] [DEBUG] [test6] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::HierarchyCommand(18): false
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::CommandNeedsPlainInput(18): false
29/06/2017 15:56:22 [17674] [WBXML] [test6] I  <Ping:Ping>
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '714' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bb77fef1-d3a4-4910-bb46-ce947605de1e-fd'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'c/Ccalendar' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739224'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Updated reference PolicyKey '239207610', reference Lifetime '780', Last sync at '1498739224'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{bb77fef1-d3a4-4910-bb46-ce947605de1e}1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bb77fef1-d3a4-4910-bb46-ce947605de1e-1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '708' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e6011232-7a3f-4732-be6a-9b19a408b3c9-fd'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Tcalendar'): 'false'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'c/Tcalendar' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739229'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Updated reference PolicyKey '239207610', reference Lifetime '780', Last sync at '1498739229'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{e6011232-7a3f-4732-be6a-9b19a408b3c9}1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e6011232-7a3f-4732-be6a-9b19a408b3c9-1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '712' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e12ce87b-92c1-42fa-9a9d-585f6416e835-fd'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('d/contacts'): 'false'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'd/contacts' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739227'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{e12ce87b-92c1-42fa-9a9d-585f6416e835}1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e12ce87b-92c1-42fa-9a9d-585f6416e835-1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '983' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-fd'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'i/f7b8fbc4' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739217'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{2fb9dd2a-a8e5-4550-811d-e4536138580c}2'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '160' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-2'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '912' bytes from file: '/var/lib/z-push/0/4/androidc110596740-c14d9310-9046-470a-a758-0e1044bf94e2-fd'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/0a273bb5'): 'false'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'i/0a273bb5' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739223'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{c14d9310-9046-470a-a758-0e1044bf94e2}5'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '314' bytes from file: '/var/lib/z-push/0/4/androidc110596740-c14d9310-9046-470a-a758-0e1044bf94e2-5'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-fd'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id '' : ref. PolicyKey '239207610', ref. Lifetime '10', last sync at '1498739215'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{5ff598a6-fade-4519-b95b-baa17e099ad6}1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] StateManager->loadHierarchyCache(): 'androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '2103' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '933' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-1'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] HandlePing(): reference PolicyKey for PING: 239207610
29/06/2017 15:56:22 [17674] [DEBUG] [test6] HandlePing(): initialization data received
29/06/2017 15:56:22 [17674] [WBXML] [test6] I   <Ping:LifeTime>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    780
29/06/2017 15:56:22 [17674] [WBXML] [test6] I   </Ping:LifeTime>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I   <Ping:Folders>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      i/f7b8fbc4
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      Email
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:56:22 [17674] [DEBUG] [test6] HandlePing(): using saved sync state for 'Email' id 'i/f7b8fbc4'
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      i/0a273bb5
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      Email
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:56:22 [17674] [DEBUG] [test6] HandlePing(): using saved sync state for 'Email' id 'i/0a273bb5'
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      c/Ccalendar
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      Calendar
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:56:22 [17674] [DEBUG] [test6] HandlePing(): using saved sync state for 'Calendar' id 'c/Ccalendar'
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      c/Tcalendar
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      Tasks
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:56:22 [17674] [DEBUG] [test6] HandlePing(): using saved sync state for 'Tasks' id 'c/Tcalendar'
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      d/contacts
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I      Contacts
29/06/2017 15:56:22 [17674] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:56:22 [17674] [DEBUG] [test6] HandlePing(): using saved sync state for 'Contacts' id 'd/contacts'
29/06/2017 15:56:22 [17674] [WBXML] [test6] I   </Ping:Folders>
29/06/2017 15:56:22 [17674] [WBXML] [test6] I  </Ping:Ping>
29/06/2017 15:56:22 [17674] [DEBUG] [test6] DeviceManager->DoAutomaticASDeviceSaving(): save automatically: false
29/06/2017 15:56:22 [17674] [DEBUG] [test6] PingTracking(): Initialized mutexid Resource id #223 and memid Resource id #224.
29/06/2017 15:56:22 [17674] [DEBUG] [test6] PingTracking initialised with IPC provider 'IpcSharedMemoryProvider' with type '2'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Announce process as PUSH connection
29/06/2017 15:56:22 [17674] [ INFO] [test6] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 780 seconds)
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendCombined->HasChangesSink()
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendCombined->HasChangesSink - Number ChangesSink found: 3
29/06/2017 15:56:22 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false'
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Ccalendar')
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Ccalendar') is supported, initializing
29/06/2017 15:56:22 [17674] [DEBUG] [test6] BackendCalDAV->ChangesSinkInitialize(): folderid 'Ccalendar'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Tcalendar'): 'false'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Tcalendar')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Tcalendar') is supported, initializing
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCalDAV->ChangesSinkInitialize(): folderid 'Tcalendar'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('d/contacts'): 'false'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('d/contacts')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('d/contacts') is supported, initializing
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCardDAV->ChangesSinkInitialize(): folderid 'contacts'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/f7b8fbc4')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/f7b8fbc4') is supported, initializing
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->ChangesSinkInitialize(): folderid 'f7b8fbc4'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] FileStateMachine->GetState() read '1597' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/0a273bb5'): 'false'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/0a273bb5')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/0a273bb5') is supported, initializing
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->ChangesSinkInitialize(): folderid '0a273bb5'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:56:23 [17674] [DEBUG] [test6] Combined->GetExporter('')
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ExportChangesCombined constructed
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ExportChangesCombined->Config(...)
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ExportChangesCombined->Config() success
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...)
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('i',...)
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('INBOX') = f7b8fbc4
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('INBOX') = f7b8fbc4
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('saved-messages') = 6a432e8c
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('saved-messages') = 6a432e8c
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Trash') = 12b12969
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Trash') = 12b12969
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Sent') = 0a273bb5
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Sent') = 0a273bb5
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Spam') = 22ef492a
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Spam') = 22ef492a
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('sent-mail') = 80b47162
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('sent-mail') = 80b47162
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Drafts') = 22a258df
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Drafts') = 22a258df
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Archive') = d8a50c2b
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendIMAP->convertImapId('Archive') = d8a50c2b
29/06/2017 15:56:23 [17674] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '8' changes for 'hierarchy'
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('c',...)
29/06/2017 15:56:23 [17674] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:56:23 [17674] [DEBUG] [test6] BackendCalDAV->GetFolderList(): Getting all folders.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCalDAV->StatFolder('Ccalendar')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCalDAV->GetFolder('Ccalendar')
29/06/2017 15:56:24 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCalDAV->StatFolder('Tcalendar')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCalDAV->GetFolder('Tcalendar')
29/06/2017 15:56:24 [17674] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('d',...)
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCardDAV::GetFolderList()
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCardDAV::StatFolder('contacts')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCardDAV::GetFolder('contacts')
29/06/2017 15:56:24 [17674] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...) success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ExportChangesCombined->Synchronize()
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('f7b8fbc4')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('6a432e8c')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'saved-messages' will not be sent as modification is not relevant.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('12b12969')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Trash' will not be sent as modification is not relevant.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('0a273bb5')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Sent' will not be sent as modification is not relevant.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22ef492a')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Junk' will not be sent as modification is not relevant.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('80b47162')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'sent-mail' will not be sent as modification is not relevant.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22a258df')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Drafts' will not be sent as modification is not relevant.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('d8a50c2b')
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Archive' will not be sent as modification is not relevant.
29/06/2017 15:56:24 [17674] [DEBUG] [test6] ExportChangesCombined->Synchronize() success
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:56:24 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:56:33 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:56:33 [23493] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:56:42 [23493] [ INFO] [test6] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 190s from 780s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
29/06/2017 15:56:42 [23493] [DEBUG] [test6] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
29/06/2017 15:56:42 [23493] [WBXML] [test6] O  <Ping:Ping>
29/06/2017 15:56:42 [23493] [WBXML] [test6] O   <Ping:Status>
29/06/2017 15:56:42 [23493] [WBXML] [test6] O   1
29/06/2017 15:56:42 [23493] [WBXML] [test6] O   </Ping:Status>
29/06/2017 15:56:42 [23493] [WBXML] [test6] O  </Ping:Ping>
29/06/2017 15:56:42 [23493] [DEBUG] [test6] WBXMLEncoder->endTag() WBXML output completed
29/06/2017 15:56:42 [23493] [WBXML] [test6] WBXML-OUT: AwFqAAANRUcDMQABAQ==
29/06/2017 15:56:42 [23493] [WBXML] [test6] WBXML-IN : AwFqAAANRUgDNzgwAAFJSksDaS9mN2I4ZmJjNAABTANFbWFpbAABAUpLA2kvMGEyNzNiYjUAAUwDRW1haWwAAQFKSwNjL0NjYWxlbmRhcgABTANDYWxlbmRhcgABAUpLA2MvVGNhbGVuZGFyAAFMA1Rhc2tzAAEBSksDZC9jb250YWN0cwABTANDb250YWN0cwABAQEB
29/06/2017 15:56:42 [23493] [DEBUG] [test6] Combined->Logoff()
29/06/2017 15:56:42 [23493] [DEBUG] [test6] FileStateMachine->SetState() written 1597 bytes on file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:56:42 [23493] [DEBUG] [test6] BackendCalDAV->Logoff(): disconnected from CALDAV server
29/06/2017 15:56:42 [23493] [DEBUG] [test6] BackendCardDAV->Logoff(): disconnected from CARDDAV server
29/06/2017 15:56:42 [23493] [DEBUG] [test6] Combined->Logoff() success
29/06/2017 15:56:42 [23493] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionTerminate()
29/06/2017 15:56:42 [23493] [ INFO] [test6] cmd='Ping' memory='7.10 MiB/7.50 MiB' time='191.05s' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' idle='190s' version='2.3.7' method='POST' httpcode='200'
29/06/2017 15:56:42 [23493] [DEBUG] [test6] -------- End
29/06/2017 15:56:42 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:56:51 [17674] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:56:51 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:56:51 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:56:51 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:57:00 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:57:09 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:57:18 [17674] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:57:18 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:57:18 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:57:18 [17674] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:57:20 [11399] [DEBUG] [test6] -------- Start
29/06/2017 15:57:20 [11399] [DEBUG] [test6] cmd='' devType='' devId='' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='OPTIONS'
29/06/2017 15:57:20 [11399] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:57:20 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:57:20 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:57:20 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:57:20 [11399] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:57:20 [11399] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:57:20 [11399] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:57:20 [11399] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:57:20 [11399] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:57:20 [11399] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:57:21 [11399] [DEBUG] [test6] NoPostRequestException: Options request - code: 1 - file: /usr/share/z-push/index.php:66
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings
29/06/2017 15:57:21 [11399] [ INFO] [test6] Options request
29/06/2017 15:57:21 [11399] [ INFO] [test6] cmd='' memory='4.28 MiB/4.75 MiB' time='0.71s' devType='' devId='' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' idle='0s' version='2.3.7' method='OPTIONS' httpcode='200'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] -------- End
29/06/2017 15:57:21 [11399] [WARN] [test6] Unknown:0 Unknown: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN (errflg=1) (8)
29/06/2017 15:57:21 [11399] [DEBUG] [test6] -------- Start
29/06/2017 15:57:21 [11399] [DEBUG] [test6] cmd='FolderSync' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='POST'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ZPush::CommandNeedsProvisioning(9): true
29/06/2017 15:57:21 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '24077' bytes from file: '/var/lib/z-push/0/4/androidc110596740-devicedata'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ASDevice data loaded for user: 'test6'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] TopCollector(): Initialized mutexid Resource id #61 and memid Resource id #62.
29/06/2017 15:57:21 [11399] [DEBUG] [test6] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] LoopDetection(): Initialized mutexid Resource id #66 and memid Resource id #67.
29/06/2017 15:57:21 [11399] [DEBUG] [test6] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ZPush::HierarchyCommand(9): true
29/06/2017 15:57:21 [11399] [DEBUG] [test6] DeviceManager->ProvisioningRequired('239207610') saved device key '239207610': false
29/06/2017 15:57:21 [11399] [DEBUG] [test6] DeviceManager->getPolicyName(): determined policy name: 'default'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ZPush::CommandNeedsAuthentication(9): true
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ZPush::CommandNeedsPlainInput(9): false
29/06/2017 15:57:21 [11399] [WBXML] [test6] I  <FolderHierarchy:FolderSync>
29/06/2017 15:57:21 [11399] [WBXML] [test6] I   <FolderHierarchy:SyncKey>
29/06/2017 15:57:21 [11399] [WBXML] [test6] I    {5ff598a6-fade-4519-b95b-baa17e099ad6}1
29/06/2017 15:57:21 [11399] [WBXML] [test6] I   </FolderHierarchy:SyncKey>
29/06/2017 15:57:21 [11399] [DEBUG] [test6] StateManager->loadHierarchyCache(): 'androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '2103' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '933' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-1'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-fd'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:21 [11399] [WBXML] [test6] I  </FolderHierarchy:FolderSync>
29/06/2017 15:57:21 [11399] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionAddStatus: 'hierarchy' with status 1
29/06/2017 15:57:21 [11399] [DEBUG] [test6] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
29/06/2017 15:57:21 [11399] [DEBUG] [test6] Combined->GetExporter('')
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ExportChangesCombined constructed
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ExportChangesCombined->Config(...)
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ExportChangesCombined->Config() success
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...)
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('i',...)
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:57:21 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '1597' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('INBOX') = f7b8fbc4
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('INBOX') = f7b8fbc4
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('saved-messages') = 6a432e8c
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('saved-messages') = 6a432e8c
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Trash') = 12b12969
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Trash') = 12b12969
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Sent') = 0a273bb5
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Sent') = 0a273bb5
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Spam') = 22ef492a
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Spam') = 22ef492a
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('sent-mail') = 80b47162
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('sent-mail') = 80b47162
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Drafts') = 22a258df
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Drafts') = 22a258df
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Archive') = d8a50c2b
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Archive') = d8a50c2b
29/06/2017 15:57:21 [11399] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '8' changes for 'hierarchy'
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('c',...)
29/06/2017 15:57:21 [11399] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:57:21 [11399] [DEBUG] [test6] BackendCalDAV->GetFolderList(): Getting all folders.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCalDAV->StatFolder('Ccalendar')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCalDAV->GetFolder('Ccalendar')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCalDAV->StatFolder('Tcalendar')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCalDAV->GetFolder('Tcalendar')
29/06/2017 15:57:22 [11399] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('d',...)
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCardDAV::GetFolderList()
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCardDAV::StatFolder('contacts')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCardDAV::GetFolder('contacts')
29/06/2017 15:57:22 [11399] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...) success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ExportChangesCombined->GetChangeCount()
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ExportChangesCombined->GetChangeCount() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ExportChangesCombined->Synchronize()
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('f7b8fbc4')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('6a432e8c')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'saved-messages' will not be sent as modification is not relevant.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('12b12969')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Trash' will not be sent as modification is not relevant.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('0a273bb5')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Sent' will not be sent as modification is not relevant.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22ef492a')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Junk' will not be sent as modification is not relevant.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('80b47162')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'sent-mail' will not be sent as modification is not relevant.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22a258df')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Drafts' will not be sent as modification is not relevant.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('d8a50c2b')
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Archive' will not be sent as modification is not relevant.
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ExportChangesCombined->Synchronize() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ExportChangesCombined->GetState()
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ExportChangesCombined->GetState() success
29/06/2017 15:57:22 [11399] [WBXML] [test6] O  <FolderHierarchy:FolderSync>
29/06/2017 15:57:22 [11399] [WBXML] [test6] O   <FolderHierarchy:Status>
29/06/2017 15:57:22 [11399] [WBXML] [test6] O   1
29/06/2017 15:57:22 [11399] [WBXML] [test6] O   </FolderHierarchy:Status>
29/06/2017 15:57:22 [11399] [WBXML] [test6] O   <FolderHierarchy:SyncKey>
29/06/2017 15:57:22 [11399] [WBXML] [test6] O   {5ff598a6-fade-4519-b95b-baa17e099ad6}1
29/06/2017 15:57:22 [11399] [WBXML] [test6] O   </FolderHierarchy:SyncKey>
29/06/2017 15:57:22 [11399] [WBXML] [test6] O   <FolderHierarchy:Changes>
29/06/2017 15:57:22 [11399] [WBXML] [test6] O    <FolderHierarchy:Count>
29/06/2017 15:57:22 [11399] [WBXML] [test6] O    0
29/06/2017 15:57:22 [11399] [WBXML] [test6] O    </FolderHierarchy:Count>
29/06/2017 15:57:22 [11399] [WBXML] [test6] O   </FolderHierarchy:Changes>
29/06/2017 15:57:22 [11399] [DEBUG] [test6] DeviceManager->CheckFolderData() checking integrity of hierarchy cache with synchronized folders
29/06/2017 15:57:22 [11399] [DEBUG] [test6] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11
29/06/2017 15:57:22 [11399] [WBXML] [test6] O  </FolderHierarchy:FolderSync>
29/06/2017 15:57:22 [11399] [DEBUG] [test6] WBXMLEncoder->endTag() WBXML output completed
29/06/2017 15:57:22 [11399] [WBXML] [test6] WBXML-OUT: AwFqAAAHVkwDMQABUgN7NWZmNTk4YTYtZmFkZS00NTE5LWI5NWItYmFhMTdlMDk5YWQ2fTEAAU5XAzAAAQEB
29/06/2017 15:57:22 [11399] [WBXML] [test6] WBXML-IN : AwFqAAAHVlIDezVmZjU5OGE2LWZhZGUtNDUxOS1iOTViLWJhYTE3ZTA5OWFkNn0xAAEB
29/06/2017 15:57:22 [11399] [DEBUG] [test6] Combined->Logoff()
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:57:22 [11399] [DEBUG] [test6] FileStateMachine->SetState() written 1597 bytes on file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCalDAV->Logoff(): disconnected from CALDAV server
29/06/2017 15:57:22 [11399] [DEBUG] [test6] BackendCardDAV->Logoff(): disconnected from CARDDAV server
29/06/2017 15:57:22 [11399] [DEBUG] [test6] Combined->Logoff() success
29/06/2017 15:57:22 [11399] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionTerminate()
29/06/2017 15:57:22 [11399] [ INFO] [test6] cmd='FolderSync' memory='6.82 MiB/7.25 MiB' time='1.59s' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' idle='0s' version='2.3.7' method='POST' httpcode='200'
29/06/2017 15:57:22 [11399] [DEBUG] [test6] -------- End
29/06/2017 15:57:23 [11399] [DEBUG] [test6] -------- Start
29/06/2017 15:57:23 [11399] [DEBUG] [test6] cmd='Sync' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='POST'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:57:23 [11399] [DEBUG] [test6] ZPush::CommandNeedsProvisioning(0): true
29/06/2017 15:57:23 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '24077' bytes from file: '/var/lib/z-push/0/4/androidc110596740-devicedata'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] ASDevice data loaded for user: 'test6'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] TopCollector(): Initialized mutexid Resource id #61 and memid Resource id #62.
29/06/2017 15:57:23 [11399] [DEBUG] [test6] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] LoopDetection(): Initialized mutexid Resource id #66 and memid Resource id #67.
29/06/2017 15:57:23 [11399] [DEBUG] [test6] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] ZPush::HierarchyCommand(0): false
29/06/2017 15:57:23 [11399] [DEBUG] [test6] DeviceManager->ProvisioningRequired('239207610') saved device key '239207610': false
29/06/2017 15:57:23 [11399] [DEBUG] [test6] DeviceManager->getPolicyName(): determined policy name: 'default'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
29/06/2017 15:57:23 [11399] [DEBUG] [test6] ZPush::CommandNeedsAuthentication(0): true
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:57:23 [11399] [DEBUG] [test6] ZPush::CommandNeedsPlainInput(0): false
29/06/2017 15:57:23 [11399] [WBXML] [test6] I  <Synchronize>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I   <Folders>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I    <Folder>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     <SyncKey>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I      {2fb9dd2a-a8e5-4550-811d-e4536138580c}2
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     </SyncKey>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     <FolderId>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I      i/f7b8fbc4
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     </FolderId>
29/06/2017 15:57:23 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '983' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-fd'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:23 [11399] [DEBUG] [test6] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'i/f7b8fbc4', returning as is.
29/06/2017 15:57:23 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'i/f7b8fbc4' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739217'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Updated reference PolicyKey '239207610', reference Lifetime '780', Last sync at '1498739217'
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     <DeletesAsMoves>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I      1
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     </DeletesAsMoves>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     <GetChanges/>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     <WindowSize>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I      10
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     </WindowSize>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     <Options>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I      <FilterType>
29/06/2017 15:57:23 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:23 [11399] [WBXML] [test6] I       3
29/06/2017 15:57:23 [11399] [WBXML] [test6] I      </FilterType>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I      <AirSyncBase:BodyPreference>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I       <AirSyncBase:Type>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I        2
29/06/2017 15:57:23 [11399] [WBXML] [test6] I       </AirSyncBase:Type>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I       <AirSyncBase:TruncationSize>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I        200000
29/06/2017 15:57:23 [11399] [WBXML] [test6] I       </AirSyncBase:TruncationSize>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I      </AirSyncBase:BodyPreference>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I     </Options>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I    </Folder>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I   </Folders>
29/06/2017 15:57:23 [11399] [WBXML] [test6] I  </Synchronize>
29/06/2017 15:57:23 [11399] [DEBUG] [test6] HandleSync(): Start Output
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Sync->loadStates(): loading states for folder 'i/f7b8fbc4'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '160' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-2'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:23 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->GetExporter('i/f7b8fbc4')
29/06/2017 15:57:23 [11399] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '2' messages in state
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendIMAP->GetMessageList('f7b8fbc4','1498139843')
29/06/2017 15:57:23 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '1597' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendIMAP->GetMessageList(): searching with sequence '1,2'
29/06/2017 15:57:23 [11399] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'f7b8fbc4'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionAddStatus: 'i/f7b8fbc4' with status 1
29/06/2017 15:57:23 [11399] [DEBUG] [test6] HandleSync: No changes found for Email folder id 'i/f7b8fbc4'. Omitting output.
29/06/2017 15:57:23 [11399] [WBXML] [test6] WBXML-IN : AwFqAEVcT0sDezJmYjlkZDJhLWE4ZTUtNDU1MC04MTFkLWU0NTM2MTM4NTgwY30yAAFSA2kvZjdiOGZiYzQAAV4DMQABE1UDMTAAAVdYAzMAAQARRUYDMgABRwMyMDAwMDAAAQEBAQEB
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->Logoff()
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:57:23 [11399] [DEBUG] [test6] FileStateMachine->SetState() written 1597 bytes on file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendCalDAV->Logoff(): disconnected from CALDAV server
29/06/2017 15:57:23 [11399] [DEBUG] [test6] BackendCardDAV->Logoff(): disconnected from CARDDAV server
29/06/2017 15:57:23 [11399] [DEBUG] [test6] Combined->Logoff() success
29/06/2017 15:57:23 [11399] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionTerminate()
29/06/2017 15:57:23 [11399] [ INFO] [test6] cmd='Sync' memory='7.09 MiB/7.50 MiB' time='0.77s' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' idle='0s' version='2.3.7' method='POST' httpcode='200'
29/06/2017 15:57:23 [11399] [DEBUG] [test6] -------- End
29/06/2017 15:57:24 [11399] [DEBUG] [test6] -------- Start
29/06/2017 15:57:24 [11399] [DEBUG] [test6] cmd='Ping' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' version='2.3.7' method='POST'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Used timezone 'Europe/Prague'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined 3 backends loaded.
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Request::ProcessHeaders() ASVersion: 14.0
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::CommandNeedsProvisioning(18): false
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::CommandNeedsAuthentication(18): true
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Logon('test6', '',***))
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendIMAP->Logon(): User 'test6' is authenticated on '{localhost:143/imap/notls/norsh}'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCardDAV::discoverAddressbooks() Found addressbook 'http://groupware.xxx.cz:80/caldav.php/test6/adresar/'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Logon() success
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '24077' bytes from file: '/var/lib/z-push/0/4/androidc110596740-devicedata'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ASDevice data loaded for user: 'test6'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] TopCollector(): Initialized mutexid Resource id #77 and memid Resource id #78.
29/06/2017 15:57:24 [11399] [DEBUG] [test6] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] LoopDetection(): Initialized mutexid Resource id #82 and memid Resource id #83.
29/06/2017 15:57:24 [11399] [DEBUG] [test6] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::HierarchyCommand(18): false
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::CommandNeedsPlainInput(18): false
29/06/2017 15:57:24 [11399] [WBXML] [test6] I  <Ping:Ping>
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '714' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bb77fef1-d3a4-4910-bb46-ce947605de1e-fd'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'c/Ccalendar' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739224'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Updated reference PolicyKey '239207610', reference Lifetime '780', Last sync at '1498739224'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{bb77fef1-d3a4-4910-bb46-ce947605de1e}1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bb77fef1-d3a4-4910-bb46-ce947605de1e-1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '708' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e6011232-7a3f-4732-be6a-9b19a408b3c9-fd'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Tcalendar'): 'false'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'c/Tcalendar' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739229'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Updated reference PolicyKey '239207610', reference Lifetime '780', Last sync at '1498739229'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{e6011232-7a3f-4732-be6a-9b19a408b3c9}1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e6011232-7a3f-4732-be6a-9b19a408b3c9-1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '712' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e12ce87b-92c1-42fa-9a9d-585f6416e835-fd'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('d/contacts'): 'false'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'd/contacts' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739227'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{e12ce87b-92c1-42fa-9a9d-585f6416e835}1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/0/4/androidc110596740-e12ce87b-92c1-42fa-9a9d-585f6416e835-1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '983' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-fd'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'i/f7b8fbc4' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739217'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{2fb9dd2a-a8e5-4550-811d-e4536138580c}2'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '160' bytes from file: '/var/lib/z-push/0/4/androidc110596740-2fb9dd2a-a8e5-4550-811d-e4536138580c-2'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '912' bytes from file: '/var/lib/z-push/0/4/androidc110596740-c14d9310-9046-470a-a758-0e1044bf94e2-fd'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/0a273bb5'): 'false'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id 'i/0a273bb5' : ref. PolicyKey '239207610', ref. Lifetime '780', last sync at '1498739223'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{c14d9310-9046-470a-a758-0e1044bf94e2}5'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '314' bytes from file: '/var/lib/z-push/0/4/androidc110596740-c14d9310-9046-470a-a758-0e1044bf94e2-5'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-fd'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->UseCPO('DEFAULT')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncCollections->AddCollection(): Folder id '' : ref. PolicyKey '239207610', ref. Lifetime '10', last sync at '1498739215'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] SyncParameters->GetLatestSyncKey(): '{5ff598a6-fade-4519-b95b-baa17e099ad6}1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] StateManager->loadHierarchyCache(): 'androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '2103' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-hc-1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '933' bytes from file: '/var/lib/z-push/0/4/androidc110596740-5ff598a6-fade-4519-b95b-baa17e099ad6-1'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] HandlePing(): reference PolicyKey for PING: 239207610
29/06/2017 15:57:24 [11399] [DEBUG] [test6] HandlePing(): initialization data received
29/06/2017 15:57:24 [11399] [WBXML] [test6] I   <Ping:LifeTime>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    780
29/06/2017 15:57:24 [11399] [WBXML] [test6] I   </Ping:LifeTime>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I   <Ping:Folders>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      i/f7b8fbc4
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      Email
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:57:24 [11399] [DEBUG] [test6] HandlePing(): using saved sync state for 'Email' id 'i/f7b8fbc4'
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      i/0a273bb5
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      Email
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:57:24 [11399] [DEBUG] [test6] HandlePing(): using saved sync state for 'Email' id 'i/0a273bb5'
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      c/Ccalendar
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      Calendar
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:57:24 [11399] [DEBUG] [test6] HandlePing(): using saved sync state for 'Calendar' id 'c/Ccalendar'
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      c/Tcalendar
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      Tasks
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:57:24 [11399] [DEBUG] [test6] HandlePing(): using saved sync state for 'Tasks' id 'c/Tcalendar'
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    <Ping:Folder>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      d/contacts
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:ServerEntryId>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     <Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I      Contacts
29/06/2017 15:57:24 [11399] [WBXML] [test6] I     </Ping:FolderType>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I    </Ping:Folder>
29/06/2017 15:57:24 [11399] [DEBUG] [test6] HandlePing(): using saved sync state for 'Contacts' id 'd/contacts'
29/06/2017 15:57:24 [11399] [WBXML] [test6] I   </Ping:Folders>
29/06/2017 15:57:24 [11399] [WBXML] [test6] I  </Ping:Ping>
29/06/2017 15:57:24 [11399] [DEBUG] [test6] DeviceManager->DoAutomaticASDeviceSaving(): save automatically: false
29/06/2017 15:57:24 [11399] [DEBUG] [test6] PingTracking(): Initialized mutexid Resource id #223 and memid Resource id #224.
29/06/2017 15:57:24 [11399] [DEBUG] [test6] PingTracking initialised with IPC provider 'IpcSharedMemoryProvider' with type '2'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Announce process as PUSH connection
29/06/2017 15:57:24 [11399] [ INFO] [test6] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 780 seconds)
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCombined->HasChangesSink()
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCombined->HasChangesSink - Number ChangesSink found: 3
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Ccalendar')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Ccalendar') is supported, initializing
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCalDAV->ChangesSinkInitialize(): folderid 'Ccalendar'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('c/Tcalendar'): 'false'
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Tcalendar')
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('c/Tcalendar') is supported, initializing
29/06/2017 15:57:24 [11399] [DEBUG] [test6] BackendCalDAV->ChangesSinkInitialize(): folderid 'Tcalendar'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('d/contacts'): 'false'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('d/contacts')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('d/contacts') is supported, initializing
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCardDAV->ChangesSinkInitialize(): folderid 'contacts'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/f7b8fbc4'): 'false'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/f7b8fbc4')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/f7b8fbc4') is supported, initializing
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->ChangesSinkInitialize(): folderid 'f7b8fbc4'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] FileStateMachine->GetState() read '1597' bytes from file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ZPush::GetAdditionalSyncFolderStore('i/0a273bb5'): 'false'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/0a273bb5')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCombined->ChangesSinkInitialize('i/0a273bb5') is supported, initializing
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->ChangesSinkInitialize(): folderid '0a273bb5'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->Setup('', 'false', '', 'false')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->Setup() success
29/06/2017 15:57:25 [11399] [DEBUG] [test6] Combined->GetExporter('')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ExportChangesCombined constructed
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ExportChangesCombined->Config(...)
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ExportChangesCombined->Config() success
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...)
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('i',...)
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('INBOX') = f7b8fbc4
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('INBOX') = f7b8fbc4
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('saved-messages') = 6a432e8c
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('saved-messages') = 6a432e8c
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Trash') = 12b12969
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Trash') = 12b12969
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Sent') = 0a273bb5
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Sent') = 0a273bb5
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Spam') = 22ef492a
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Spam') = 22ef492a
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('sent-mail') = 80b47162
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('sent-mail') = 80b47162
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Drafts') = 22a258df
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Drafts') = 22a258df
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->getFolderIdFromImapId('Archive') = d8a50c2b
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendIMAP->convertImapId('Archive') = d8a50c2b
29/06/2017 15:57:25 [11399] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '8' changes for 'hierarchy'
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('c',...)
29/06/2017 15:57:25 [11399] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCalDAV->GetFolderList(): Getting all folders.
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCalDAV->StatFolder('Ccalendar')
29/06/2017 15:57:25 [11399] [DEBUG] [test6] BackendCalDAV->GetFolder('Ccalendar')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendCalDAV->StatFolder('Tcalendar')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendCalDAV->GetFolder('Tcalendar')
29/06/2017 15:57:26 [11399] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->__construct('d',...)
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendCardDAV::GetFolderList()
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendCardDAV::StatFolder('contacts')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendCardDAV::GetFolder('contacts')
29/06/2017 15:57:26 [11399] [ INFO] [test6] ExportChangesDiff->InitializeExporter(): Found '0' changes for 'hierarchy'
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ExportChangesCombined->InitializeExporter(...) success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ExportChangesCombined->Synchronize()
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('f7b8fbc4') = INBOX
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('f7b8fbc4'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('f7b8fbc4')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant.
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('6a432e8c') = saved-messages
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('6a432e8c'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('6a432e8c')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'saved-messages' will not be sent as modification is not relevant.
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('12b12969') = Trash
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('12b12969'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('12b12969')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Trash' will not be sent as modification is not relevant.
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('0a273bb5') = Sent
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('0a273bb5'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('0a273bb5')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Sent' will not be sent as modification is not relevant.
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22ef492a') = Spam
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('22ef492a'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22ef492a')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Junk' will not be sent as modification is not relevant.
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('80b47162') = sent-mail
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('80b47162'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('80b47162')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'sent-mail' will not be sent as modification is not relevant.
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('22a258df') = Drafts
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('22a258df'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('22a258df')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Drafts' will not be sent as modification is not relevant.
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->getImapIdFromFolderId('d8a50c2b') = Archive
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->GetFolder('d8a50c2b'): 'SyncFolder (
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange('d8a50c2b')
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ImportHierarchyChangesCombinedWrap->ImportFolderChange() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Archive' will not be sent as modification is not relevant.
29/06/2017 15:57:26 [11399] [DEBUG] [test6] ExportChangesCombined->Synchronize() success
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:57:26 [11399] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server
29/06/2017 15:57:27 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:57:35 [11399] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 10
29/06/2017 15:57:36 [17674] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:57:44 [11399] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 10
29/06/2017 15:57:45 [17674] [ INFO] [test6] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 82s from 780s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
29/06/2017 15:57:45 [17674] [DEBUG] [test6] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
29/06/2017 15:57:45 [17674] [WBXML] [test6] O  <Ping:Ping>
29/06/2017 15:57:45 [17674] [WBXML] [test6] O   <Ping:Status>
29/06/2017 15:57:45 [17674] [WBXML] [test6] O   1
29/06/2017 15:57:45 [17674] [WBXML] [test6] O   </Ping:Status>
29/06/2017 15:57:45 [17674] [WBXML] [test6] O  </Ping:Ping>
29/06/2017 15:57:45 [17674] [DEBUG] [test6] WBXMLEncoder->endTag() WBXML output completed
29/06/2017 15:57:45 [17674] [WBXML] [test6] WBXML-OUT: AwFqAAANRUcDMQABAQ==
29/06/2017 15:57:45 [17674] [WBXML] [test6] WBXML-IN : AwFqAAANRUgDNzgwAAFJSksDaS9mN2I4ZmJjNAABTANFbWFpbAABAUpLA2kvMGEyNzNiYjUAAUwDRW1haWwAAQFKSwNjL0NjYWxlbmRhcgABTANDYWxlbmRhcgABAUpLA2MvVGNhbGVuZGFyAAFMA1Rhc2tzAAEBSksDZC9jb250YWN0cwABTANDb250YWN0cwABAQEB
29/06/2017 15:57:45 [17674] [DEBUG] [test6] Combined->Logoff()
29/06/2017 15:57:45 [17674] [DEBUG] [test6] FileStateMachine->SetState() written 1597 bytes on file: '/var/lib/z-push/0/4/androidc110596740-bs-1498654702'
29/06/2017 15:57:45 [17674] [DEBUG] [test6] BackendCalDAV->Logoff(): disconnected from CALDAV server
29/06/2017 15:57:45 [17674] [DEBUG] [test6] BackendCardDAV->Logoff(): disconnected from CARDDAV server
29/06/2017 15:57:45 [17674] [DEBUG] [test6] Combined->Logoff() success
29/06/2017 15:57:45 [17674] [DEBUG] [test6] LoopDetection->ProcessLoopDetectionTerminate()
29/06/2017 15:57:45 [17674] [ INFO] [test6] cmd='Ping' memory='7.11 MiB/7.50 MiB' time='83.93s' devType='Android' devId='androidc110596740' getUser='test6' from='2a02:8304:2:15:14dd:e505:66a6:3871' idle='82s' version='2.3.7' method='POST' httpcode='200'
29/06/2017 15:57:45 [17674] [DEBUG] [test6] -------- End
29/06/2017 15:57:53 [11399] [DEBUG] [test6] BackendCombined->ChangesSink(30)
29/06/2017 15:57:53 [11399] [DEBUG] [test6] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
29/06/2017 15:57:53 [11399] [DEBUG] [test6] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
29/06/2017 15:57:53 [11399] [DEBUG] [test6] BackendIMAP->close_connection(): disconnected from IMAP server