fmbiete / Z-Push-contrib

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

Android 5.0.2 - Deleting mail breaks sync #188

Closed TheoRettisch closed 9 years ago

TheoRettisch commented 9 years ago

Hi,

as soon as i delete an email on my android the whole sync stops working until i do a complete resync. The last sync time in z-push admin also changes from last sync date to "never". The error can be reproduce.

If i remember right there was a problem with the way android preserves mails for undoing the remove action. Seems there are still some issues.

18/05/2015 16:20:29 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 2
18/05/2015 16:20:31 [15542] [ INFO] [***] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 31s from 480s due to other process - code: 3 - file: /var/www/html/zpush/lib/core/synccollections.php:487
18/05/2015 16:20:31 [15542] [DEBUG] [***] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
18/05/2015 16:20:31 [15542] [WBXML] [***] O  <Ping:Ping>
18/05/2015 16:20:31 [15542] [WBXML] [***] O   <Ping:Status>
18/05/2015 16:20:31 [15542] [WBXML] [***] O   1
18/05/2015 16:20:31 [15542] [WBXML] [***] O   </Ping:Status>
18/05/2015 16:20:31 [15542] [WBXML] [***] O  </Ping:Ping>
18/05/2015 16:20:31 [15542] [DEBUG] [***] WBXMLEncoder->endTag() WBXML output completed
18/05/2015 16:20:31 [15542] [DEBUG] [***] Flushing 13, headers already sent ? false
18/05/2015 16:20:31 [15542] [DEBUG] [***] Combined->Logoff()
18/05/2015 16:20:31 [15542] [DEBUG] [***] BackendIMAP->Logoff(): IMAP connection closed
18/05/2015 16:20:31 [15542] [DEBUG] [***] FileStateMachine->SetState() written 776 bytes on file: '/var/lib/z-push/4/4/android1426585788244-bs-1431958346'
18/05/2015 16:20:31 [15542] [DEBUG] [***] BackendCalDAV->Logoff()
18/05/2015 16:20:31 [15542] [DEBUG] [***] BackendCardDAV->Logoff()
18/05/2015 16:20:31 [15542] [DEBUG] [***] FileStateMachine->SetState() written 776 bytes on file: '/var/lib/z-push/4/4/android1426585788244-bs-1431958346'
18/05/2015 16:20:31 [15542] [DEBUG] [***] Combined->Logoff() success
18/05/2015 16:20:31 [15542] [DEBUG] [***] LoopDetection->ProcessLoopDetectionTerminate()
18/05/2015 16:20:31 [15542] [DEBUG] [***] -------- End - max mem: 5897872/6291456 - time: 33.2382 - code: 200
18/05/2015 16:20:34 [16745] [DEBUG] [***] BackendCombined->ChangesSink(30)
18/05/2015 16:20:34 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 2
18/05/2015 16:20:39 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 2
18/05/2015 16:20:44 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 2
18/05/2015 16:20:50 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 2
18/05/2015 16:20:55 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 2
18/05/2015 16:21:00 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 2
18/05/2015 16:21:03 [25060] [DEBUG] [***] -------- Start
18/05/2015 16:21:03 [25060] [ INFO] [***] Version='SVN-trunk-r1938' method='POST' from='80.187.***.***' cmd='MoveItems' getUser='***' devId='android***' devType='Android'
18/05/2015 16:21:03 [25060] [DEBUG] [***] Used timezone 'Europe/Berlin'
18/05/2015 16:21:03 [25060] [DEBUG] [***] Request::ProcessHeaders() ASVersion: 14.0
18/05/2015 16:21:03 [25060] [DEBUG] [***] Including backend file: '/var/www/html/zpush/backend/combined/combined.php'
18/05/2015 16:21:03 [25060] [DEBUG] [***] Including backend file: '/var/www/html/zpush/backend/imap/imap.php'
18/05/2015 16:21:03 [25060] [DEBUG] [***] Including backend file: '/var/www/html/zpush/backend/caldav/caldav.php'
18/05/2015 16:21:03 [25060] [DEBUG] [***] Including backend file: '/var/www/html/zpush/backend/carddav/carddav.php'
18/05/2015 16:21:03 [25060] [DEBUG] [***] Combined 3 backends loaded.
18/05/2015 16:21:03 [25060] [DEBUG] [***] ZPush::CommandNeedsAuthentication(13): true
18/05/2015 16:21:03 [25060] [DEBUG] [***] Combined->Logon('***', '',***))
18/05/2015 16:21:03 [25060] [DEBUG] [***] BackendIMAP->Logon(): User '***' is authenticated on '{localhost:143/imap/notls/norsh}'
18/05/2015 16:21:04 [25060] [DEBUG] [***] BackendCalDAV->Logon(): User '***' is authenticated on CalDAV
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendCardDAV->Logon(): User '***' is authenticated on 'https://***:443/addressbooks/***/'
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendCardDAV::discoverAddressbooks() Found addressbook 'https://***:443/addressbooks/***/default/'
18/05/2015 16:21:05 [25060] [DEBUG] [***] Combined->Logon() success
18/05/2015 16:21:05 [25060] [DEBUG] [***] Combined->Setup('***', 'true', '')
18/05/2015 16:21:05 [25060] [DEBUG] [***] Combined->Setup() success
18/05/2015 16:21:05 [25060] [DEBUG] [***] FileStateMachine->GetState() on file: '/var/lib/z-push/4/4/android1426585788244-devicedata'
18/05/2015 16:21:05 [25060] [DEBUG] [***] ASDevice data loaded for user: '***'
18/05/2015 16:21:05 [25060] [DEBUG] [***] TopCollector(): Initialized mutexid Resource id #81 and memid Resource id #82.
18/05/2015 16:21:05 [25060] [DEBUG] [***] LoopDetection(): Initialized mutexid Resource id #86 and memid Resource id #87.
18/05/2015 16:21:05 [25060] [DEBUG] [***] ZPush::HierarchyCommand(13): false
18/05/2015 16:21:05 [25060] [DEBUG] [***] ZPush::CommandNeedsPlainInput(13): false
18/05/2015 16:21:05 [25060] [WBXML] [***] I  <Move:Moves>
18/05/2015 16:21:05 [25060] [WBXML] [***] I   <Move:Move>
18/05/2015 16:21:05 [25060] [WBXML] [***] I    <Move:SrcMsgId>
18/05/2015 16:21:05 [25060] [WBXML] [***] I     19
18/05/2015 16:21:05 [25060] [WBXML] [***] I    </Move:SrcMsgId>
18/05/2015 16:21:05 [25060] [WBXML] [***] I    <Move:SrcFldId>
18/05/2015 16:21:05 [25060] [WBXML] [***] I     i/ede49700
18/05/2015 16:21:05 [25060] [WBXML] [***] I    </Move:SrcFldId>
18/05/2015 16:21:05 [25060] [WBXML] [***] I    <Move:DstFldId>
18/05/2015 16:21:05 [25060] [WBXML] [***] I     i/37286bae
18/05/2015 16:21:05 [25060] [WBXML] [***] I    </Move:DstFldId>
18/05/2015 16:21:05 [25060] [WBXML] [***] I   </Move:Move>
18/05/2015 16:21:05 [25060] [WBXML] [***] I  </Move:Moves>
18/05/2015 16:21:05 [25060] [DEBUG] [***] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
18/05/2015 16:21:05 [25060] [WBXML] [***] O  <Move:Moves>
18/05/2015 16:21:05 [25060] [WBXML] [***] O   <Move:Response>
18/05/2015 16:21:05 [25060] [WBXML] [***] O    <Move:SrcMsgId>
18/05/2015 16:21:05 [25060] [WBXML] [***] O    19
18/05/2015 16:21:05 [25060] [WBXML] [***] O    </Move:SrcMsgId>
18/05/2015 16:21:05 [25060] [DEBUG] [***] ZPush::GetAdditionalSyncFolderStore('i/ede49700'): 'false'
18/05/2015 16:21:05 [25060] [DEBUG] [***] Combined->Setup('', 'false', '')
18/05/2015 16:21:05 [25060] [DEBUG] [***] Combined->Setup() success
18/05/2015 16:21:05 [25060] [DEBUG] [***] Combined->GetImporter() Content: ImportChangesCombined:('i/ede49700')
18/05/2015 16:21:05 [25060] [DEBUG] [***] FileStateMachine->GetState() on file: '/var/lib/z-push/4/4/android1426585788244-f97b3619-96c1-4a95-90ef-55745b9999cc-fd'
18/05/2015 16:21:05 [25060] [DEBUG] [***] SyncParameters->UseCPO('DEFAULT')
18/05/2015 16:21:05 [25060] [DEBUG] [***] ImportChangesCombined->ConfigContentParameters()
18/05/2015 16:21:05 [25060] [DEBUG] [***] ImportChangesCombined->ConfigContentParameters() success
18/05/2015 16:21:05 [25060] [DEBUG] [***] ImportChangesCombined->ImportMessageMove('19', 'i/37286bae')
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendIMAP->MoveMessage('ede49700','19','37286bae')
18/05/2015 16:21:05 [25060] [DEBUG] [***] FileStateMachine->GetState() on file: '/var/lib/z-push/4/4/android1426585788244-bs-1431958346'
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendIMAP->getImapIdFromFolderId('ede49700') = INBOX
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendIMAP->getImapIdFromFolderId('37286bae') = INBOX/Trash
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendIMAP->imap_inside_cutoffdate(): Checking if the messages is withing the cutoffdate 1431354065, 19
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendIMAP->imap_inside_cutoffdate(): Message is INSIDE cutoffdate range
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendIMAP->MoveMessage('ede49700','19','37286bae'): result s-move: 'true' s-expunge: 'true' unset-Flags: 'true' set-Flags: 'true'
18/05/2015 16:21:05 [25060] [DEBUG] [***] ImportMessageMove(): Force resync of dest folder (37286bae)
18/05/2015 16:21:05 [25060] [DEBUG] [***] FileStateMachine->GetState() on file: '/var/lib/z-push/4/4/android1426585788244-devicedata'
18/05/2015 16:21:05 [25060] [DEBUG] [***] ASDevice data loaded for user: '***'
18/05/2015 16:21:05 [25060] [DEBUG] [***] ZPushAdmin::ResyncFolder(): folder '37286bae' on device 'android1426585788244' of user '***' marked to be re-synchronized.
18/05/2015 16:21:05 [25060] [DEBUG] [***] FileStateMachine->SetState() written 4 bytes on file: '/var/lib/z-push/4/4/android1426585788244-devicedata'
18/05/2015 16:21:05 [25060] [DEBUG] [***] ZPushAdmin::ResyncFolder(): saved updated device data of device 'android1426585788244' of user '***'
18/05/2015 16:21:05 [25060] [WBXML] [***] O    <Move:Status>
18/05/2015 16:21:05 [25060] [WBXML] [***] O    3
18/05/2015 16:21:05 [25060] [WBXML] [***] O    </Move:Status>
18/05/2015 16:21:05 [25060] [WBXML] [***] O    <Move:DstMsgId>
18/05/2015 16:21:05 [25060] [WBXML] [***] O    7
18/05/2015 16:21:05 [25060] [WBXML] [***] O    </Move:DstMsgId>
18/05/2015 16:21:05 [25060] [WBXML] [***] O   </Move:Response>
18/05/2015 16:21:05 [25060] [WBXML] [***] O  </Move:Moves>
18/05/2015 16:21:05 [25060] [DEBUG] [***] WBXMLEncoder->endTag() WBXML output completed
18/05/2015 16:21:05 [25060] [DEBUG] [***] Flushing 26, headers already sent ? false
18/05/2015 16:21:05 [25060] [DEBUG] [***] Combined->Logoff()
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendIMAP->Logoff(): IMAP connection closed
18/05/2015 16:21:05 [25060] [DEBUG] [***] FileStateMachine->SetState() written 776 bytes on file: '/var/lib/z-push/4/4/android1426585788244-bs-1431958346'
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendCalDAV->Logoff()
18/05/2015 16:21:05 [25060] [DEBUG] [***] BackendCardDAV->Logoff()
18/05/2015 16:21:05 [25060] [DEBUG] [***] Combined->Logoff() success
18/05/2015 16:21:05 [25060] [DEBUG] [***] LoopDetection->ProcessLoopDetectionTerminate()
18/05/2015 16:21:05 [25060] [DEBUG] [***] -------- End - max mem: 5809024/6291456 - time: 1.4721 - code: 200
18/05/2015 16:21:05 [16745] [DEBUG] [***] BackendCombined->ChangesSink(30)
18/05/2015 16:21:05 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 2
18/05/2015 16:21:05 [16745] [DEBUG] [***] BackendIMAP->getFolderIdFromImapId('INBOX') = ede49700
18/05/2015 16:21:05 [16745] [DEBUG] [***] BackendIMAP->ChangesSink(): ChangesSink detected!!
18/05/2015 16:21:05 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendCalDAV' with 2
18/05/2015 16:21:05 [15477] [DEBUG] [***] -------- Start
18/05/2015 16:21:05 [15477] [ INFO] [***] Version='SVN-trunk-r1938' method='POST' from='80.187.***.***' cmd='Sync' getUser='***' devId='android1426585788244' devType='Android'
18/05/2015 16:21:05 [15477] [DEBUG] [***] Used timezone 'Europe/Berlin'
18/05/2015 16:21:05 [15477] [DEBUG] [***] Request::ProcessHeaders() ASVersion: 14.0
18/05/2015 16:21:05 [15477] [DEBUG] [***] Including backend file: '/var/www/html/zpush/backend/combined/combined.php'
18/05/2015 16:21:05 [15477] [DEBUG] [***] Including backend file: '/var/www/html/zpush/backend/imap/imap.php'
18/05/2015 16:21:06 [15477] [DEBUG] [***] Including backend file: '/var/www/html/zpush/backend/caldav/caldav.php'
18/05/2015 16:21:06 [15477] [DEBUG] [***] Including backend file: '/var/www/html/zpush/backend/carddav/carddav.php'
18/05/2015 16:21:06 [15477] [DEBUG] [***] Combined 3 backends loaded.
18/05/2015 16:21:06 [15477] [DEBUG] [***] ZPush::CommandNeedsAuthentication(0): true
18/05/2015 16:21:06 [15477] [DEBUG] [***] Combined->Logon('***', '',***))
18/05/2015 16:21:06 [15477] [DEBUG] [***] BackendIMAP->Logon(): User '***' is authenticated on '{localhost:143/imap/notls/norsh}'
18/05/2015 16:21:06 [15477] [DEBUG] [***] BackendCalDAV->Logon(): User '***' is authenticated on CalDAV
18/05/2015 16:21:07 [15477] [DEBUG] [***] BackendCardDAV->Logon(): User '***' is authenticated on 'https://***:443/addressbooks/***/'
18/05/2015 16:21:07 [15477] [DEBUG] [***] BackendCardDAV::discoverAddressbooks() Found addressbook 'https://***:443/addressbooks/***/default/'
18/05/2015 16:21:07 [15477] [DEBUG] [***] Combined->Logon() success
18/05/2015 16:21:07 [15477] [DEBUG] [***] Combined->Setup('***', 'true', '')
18/05/2015 16:21:07 [15477] [DEBUG] [***] Combined->Setup() success
18/05/2015 16:21:07 [15477] [DEBUG] [***] FileStateMachine->GetState() on file: '/var/lib/z-push/4/4/android1426585788244-devicedata'
18/05/2015 16:21:07 [15477] [DEBUG] [***] TopCollector(): Initialized mutexid Resource id #80 and memid Resource id #81.
18/05/2015 16:21:07 [15477] [DEBUG] [***] LoopDetection(): Initialized mutexid Resource id #85 and memid Resource id #86.
18/05/2015 16:21:07 [15477] [DEBUG] [***] ZPush::HierarchyCommand(0): false
18/05/2015 16:21:07 [15477] [DEBUG] [***] ZPush::GetSupportedProtocolVersions(): 2.5,12.0,12.1,14.0
18/05/2015 16:21:07 [15477] [ INFO] [***] Announcing latest AS version to device: 2.5,12.0,12.1,14.0
18/05/2015 16:21:07 [15477] [DEBUG] [***] ZPush::CommandNeedsPlainInput(0): false
18/05/2015 16:21:07 [15477] [WBXML] [***] I  <Synchronize>
18/05/2015 16:21:07 [15477] [WBXML] [***] I   <Folders>
18/05/2015 16:21:07 [15477] [WBXML] [***] I    <Folder>
18/05/2015 16:21:07 [15477] [WBXML] [***] I     <SyncKey>
18/05/2015 16:21:07 [15477] [WBXML] [***] I      {f97b3619-96c1-4a95-90ef-55745b9999cc}2
18/05/2015 16:21:07 [15477] [WBXML] [***] I     </SyncKey>
18/05/2015 16:21:07 [15477] [WBXML] [***] I     <FolderId>
18/05/2015 16:21:07 [15477] [WBXML] [***] I      i/ede49700
18/05/2015 16:21:07 [15477] [WBXML] [***] I     </FolderId>
18/05/2015 16:21:07 [15477] [ INFO] [***] NoHierarchyCacheAvailableException: Folderid 'i/ede49700' is not fully synchronized on the device - code: 0 - file: /var/www/html/zpush/lib/core/devicemanager.php:397
18/05/2015 16:21:07 [15477] [ INFO] [***] Full device resync requested
18/05/2015 16:21:07 [15477] [DEBUG] [***] SyncCollections->AddCollection(): Folder id 'i/ede49700' : ref. PolicyKey '1', ref. Lifetime '10', last sync at ''
18/05/2015 16:21:07 [15477] [ WARN] [***] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
18/05/2015 16:21:07 [15477] [WBXML] [***] I     <DeletesAsMoves>
18/05/2015 16:21:07 [15477] [WBXML] [***] I      1
18/05/2015 16:21:07 [15477] [WBXML] [***] I     </DeletesAsMoves>
18/05/2015 16:21:07 [15477] [WBXML] [***] I     <GetChanges/>
18/05/2015 16:21:07 [15477] [WBXML] [***] I     <WindowSize>
18/05/2015 16:21:07 [15477] [WBXML] [***] I      10
18/05/2015 16:21:07 [15477] [WBXML] [***] I     </WindowSize>
18/05/2015 16:21:07 [15477] [WBXML] [***] I     <Options>
18/05/2015 16:21:07 [15477] [WBXML] [***] I      <FilterType>
18/05/2015 16:21:07 [15477] [DEBUG] [***] SyncParameters->UseCPO('DEFAULT')
18/05/2015 16:21:07 [15477] [WBXML] [***] I       3
18/05/2015 16:21:07 [15477] [WBXML] [***] I      </FilterType>
18/05/2015 16:21:07 [15477] [WBXML] [***] I      <AirSyncBase:BodyPreference>
18/05/2015 16:21:07 [15477] [WBXML] [***] I       <AirSyncBase:Type>
18/05/2015 16:21:07 [15477] [WBXML] [***] I        2
18/05/2015 16:21:07 [15477] [WBXML] [***] I       </AirSyncBase:Type>
18/05/2015 16:21:07 [15477] [WBXML] [***] I       <AirSyncBase:TruncationSize>
18/05/2015 16:21:07 [15477] [WBXML] [***] I        200000
18/05/2015 16:21:07 [15477] [WBXML] [***] I       </AirSyncBase:TruncationSize>
18/05/2015 16:21:07 [15477] [WBXML] [***] I      </AirSyncBase:BodyPreference>
18/05/2015 16:21:07 [15477] [WBXML] [***] I     </Options>
18/05/2015 16:21:07 [15477] [WBXML] [***] I    </Folder>
18/05/2015 16:21:07 [15477] [DEBUG] [***] HierarchyCache is also not available. Triggering HierarchySync to device
18/05/2015 16:21:07 [15477] [WBXML] [***] I   </Folders>
18/05/2015 16:21:07 [15477] [WBXML] [***] I  </Synchronize>
18/05/2015 16:21:07 [15477] [DEBUG] [***] HandleSync(): Start Output
18/05/2015 16:21:07 [15477] [DEBUG] [***] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
18/05/2015 16:21:07 [15477] [WBXML] [***] O  <Synchronize>
18/05/2015 16:21:07 [15477] [WBXML] [***] O   <Folders>
18/05/2015 16:21:07 [15477] [WBXML] [***] O    <Folder>
18/05/2015 16:21:07 [15477] [WBXML] [***] O     <SyncKey>
18/05/2015 16:21:07 [15477] [WBXML] [***] O     {f97b3619-96c1-4a95-90ef-55745b9999cc}2
18/05/2015 16:21:07 [15477] [WBXML] [***] O     </SyncKey>
18/05/2015 16:21:07 [15477] [WBXML] [***] O     <FolderId>
18/05/2015 16:21:07 [15477] [WBXML] [***] O     i/ede49700
18/05/2015 16:21:07 [15477] [WBXML] [***] O     </FolderId>
18/05/2015 16:21:07 [15477] [WBXML] [***] O     <Status>
18/05/2015 16:21:07 [15477] [WBXML] [***] O     12
18/05/2015 16:21:07 [15477] [WBXML] [***] O     </Status>
18/05/2015 16:21:07 [15477] [WBXML] [***] O    </Folder>
18/05/2015 16:21:07 [15477] [DEBUG] [***] SyncCollections->SaveCollection(): Data of folder 'i/ede49700' changed
18/05/2015 16:21:07 [15477] [DEBUG] [***] StateManager::linkState(#ASDevice, 'f97b3619-96c1-4a95-90ef-55745b9999cc','i/ede49700'): linked to uuid 'f97b3619-96c1-4a95-90ef-55745b9999cc'.
18/05/2015 16:21:07 [15477] [DEBUG] [***] FileStateMachine->SetState() written 635 bytes on file: '/var/lib/z-push/4/4/android1426585788244-f97b3619-96c1-4a95-90ef-55745b9999cc-fd'
18/05/2015 16:21:07 [15477] [WBXML] [***] O   </Folders>
18/05/2015 16:21:07 [15477] [WBXML] [***] O  </Synchronize>
18/05/2015 16:21:07 [15477] [DEBUG] [***] WBXMLEncoder->endTag() WBXML output completed
18/05/2015 16:21:07 [15477] [DEBUG] [***] Flushing 73, headers already sent ? false
18/05/2015 16:21:07 [15477] [DEBUG] [***] Combined->Logoff()
18/05/2015 16:21:07 [15477] [DEBUG] [***] BackendIMAP->Logoff(): IMAP connection closed
18/05/2015 16:21:07 [15477] [DEBUG] [***] BackendCalDAV->Logoff()
18/05/2015 16:21:07 [15477] [DEBUG] [***] BackendCardDAV->Logoff()
18/05/2015 16:21:07 [15477] [DEBUG] [***] Combined->Logoff() success
18/05/2015 16:21:07 [15477] [DEBUG] [***] DeviceManager->Save(): Device data changed
18/05/2015 16:21:07 [15477] [ INFO] [***] Linking device ID 'android1426585788244' to user '***'
18/05/2015 16:21:07 [15477] [DEBUG] [***] FileStateMachine->LinkUserDevice(): nothing changed
18/05/2015 16:21:07 [15477] [DEBUG] [***] FileStateMachine->SetState() written 569 bytes on file: '/var/lib/z-push/4/4/android1426585788244-devicedata'
18/05/2015 16:21:07 [15477] [DEBUG] [***] DeviceManager->Save(): Device data saved
18/05/2015 16:21:07 [15477] [DEBUG] [***] LoopDetection->ProcessLoopDetectionTerminate()
18/05/2015 16:21:07 [15477] [DEBUG] [***] -------- End - max mem: 5970616/6291456 - time: 1.2925 - code: 200
18/05/2015 16:21:10 [16745] [DEBUG] [***] BackendCombined->ChangesSink - Calling in 'BackendCardDAV' with 2
18/05/2015 16:21:16 [16745] [DEBUG] [***] Combined->Setup('', 'false', '')
18/05/2015 16:21:16 [16745] [DEBUG] [***] Combined->Setup() success
18/05/2015 16:21:16 [16745] [DEBUG] [***] Combined->GetExporter('i/ede49700')
18/05/2015 16:21:16 [16745] [DEBUG] [***] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '9' messages in state
18/05/2015 16:21:16 [16745] [DEBUG] [***] BackendIMAP->GetMessageList('ede49700','1431354076')
18/05/2015 16:21:16 [16745] [DEBUG] [***] BackendIMAP->getImapIdFromFolderId('ede49700') = INBOX
18/05/2015 16:21:16 [16745] [DEBUG] [***] BackendIMAP->GetMessageList(): searching with sequence '1,2,3,4,5,6,7,8'
18/05/2015 16:21:16 [16745] [ INFO] [***] ExportChangesDiff->InitializeExporter(): Found 1 changes
18/05/2015 16:21:16 [16745] [DEBUG] [***] SyncCollections->CheckForChanges(): Notification received on folder 'i/ede49700'
18/05/2015 16:21:16 [16745] [DEBUG] [***] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
18/05/2015 16:21:16 [16745] [WBXML] [***] O  <Ping:Ping>
18/05/2015 16:21:16 [16745] [WBXML] [***] O   <Ping:Status>
18/05/2015 16:21:16 [16745] [WBXML] [***] O   2
18/05/2015 16:21:16 [16745] [WBXML] [***] O   </Ping:Status>
18/05/2015 16:21:16 [16745] [WBXML] [***] O   <Ping:Folders>
18/05/2015 16:21:16 [16745] [WBXML] [***] O    <Ping:Folder>
18/05/2015 16:21:16 [16745] [WBXML] [***] O    i/ede49700
18/05/2015 16:21:16 [16745] [WBXML] [***] O    </Ping:Folder>
18/05/2015 16:21:16 [16745] [WBXML] [***] O   </Ping:Folders>
18/05/2015 16:21:16 [16745] [WBXML] [***] O  </Ping:Ping>
18/05/2015 16:21:16 [16745] [DEBUG] [***] WBXMLEncoder->endTag() WBXML output completed
18/05/2015 16:21:16 [16745] [DEBUG] [***] Flushing 29, headers already sent ? false
18/05/2015 16:21:16 [16745] [DEBUG] [***] Combined->Logoff()
18/05/2015 16:21:16 [16745] [DEBUG] [***] BackendIMAP->Logoff(): IMAP connection closed
18/05/2015 16:21:16 [16745] [DEBUG] [***] FileStateMachine->SetState() written 776 bytes on file: '/var/lib/z-push/4/4/android1426585788244-bs-1431958346'
18/05/2015 16:21:16 [16745] [DEBUG] [***] BackendCalDAV->Logoff()
18/05/2015 16:21:16 [16745] [DEBUG] [***] BackendCardDAV->Logoff()
18/05/2015 16:21:16 [16745] [DEBUG] [***] FileStateMachine->SetState() written 776 bytes on file: '/var/lib/z-push/4/4/android1426585788244-bs-1431958346'
18/05/2015 16:21:16 [16745] [DEBUG] [***] Combined->Logoff() success
18/05/2015 16:21:16 [16745] [DEBUG] [***] LoopDetection->ProcessLoopDetectionTerminate()
18/05/2015 16:21:16 [16745] [DEBUG] [***] -------- End - max mem: 5884760/6291456 - time: 74.5383 - code: 200
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] Including backend file: '/var/www/html/zpush/backend/combined/combined.php'
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] Including backend file: '/var/www/html/zpush/backend/imap/imap.php'
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] Including backend file: '/var/www/html/zpush/backend/caldav/caldav.php'
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] Including backend file: '/var/www/html/zpush/backend/carddav/carddav.php'
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] Combined 3 backends loaded.
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] FileStateMachine->GetState() on file: '/var/lib/z-push/4/4/android1426585788244-devicedata'
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] FileStateMachine->GetState() on file: '/var/lib/z-push/4/4/android1426585788244-devicedata'
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] ASDevice data loaded for user: '***'
18/05/2015 16:21:22 [26061] [DEBUG] [unknown] ZPush::HierarchyCommand(0): false
fmbiete commented 9 years ago

@TheoRettisch I would check the server configuration first; nginx/apache and php. I'm not having those errors with Android.

TheoRettisch commented 9 years ago

@fmbiete its apache and php-fpm. Im quite sure the server config is ok because with the zarafa z-push everything works fine. im not aware that your z-push needs some special config.

fmbiete commented 9 years ago

Look at the timeouts in both apache and php-fpm, they should be big enough. 900 seconds is a good value. In your log, you can see how multiples processes run at the same time. If they are for the same devices it could signal a problem in the server, usually timeout on php execution.

tigs001 commented 9 years ago

I believe I am also experiencing this problem. I am using iOS 8.3 and every time I delete a message, everything breaks until a full resync is completed.

I note in the above, that the BackendCombined is being used. I have been running BackendIMAP (only) for years successfully, however recently started playing with BackendCombined. I'm using the example configuration in the wiki page, https://github.com/fmbiete/Z-Push-contrib/wiki/Example-Configuration#combined-configuration. BackendCardDAV and BackendCalDAV work well, but when combined with BackendIMAP, the problem occurs.

If I change my main config.php and change the backend to BackendIMAP, the system works correctly, so from this I conclude that my IMAP configuration is working.

With my configuration, if I only enable Calendar, Contacts, Reminders, and Notes on my iPhone, everything works well.

I have also created a configuration where I use BackendCombined, but only enable the BackendIMAP, and I commented out all folders in the folderbackend array that are not using the BackendIMAP (i.e. 'i'). My phone was then configured to sync only email, and the problem occurs.

So to me, it seems that syncing IMAP (even as the only backend enabled), through the BackendCombined is broken.

I have some time available for testing, and am competent in PHP, so I would be happy to look into this further. I just do not know where to start, or if there is anything I should test or try. I would appreciate any comments or suggestions.

TheoRettisch commented 9 years ago

@tigs001: I can confirm your findings. After switching from BackendCombined to BackendIMAP E-Mail sync works and i can delete Mails.

@fmbiete: I tried every possible way to increase the PHP-FPM timeouts to 900 sec. but it makes no difference. Regarding to the multiple processes i found the following which indicates that the log output is no error: https://forums.zarafa.com/showthread.php?9670-Z-Push-2-1-0RC-released&p=43420&viewfull=1#post43420

fmbiete commented 9 years ago

@tigs001 Can you check if the delete operation succeded? Can you check with an Android device?

fmbiete commented 9 years ago

@tigs001 @TheoRettisch

The referenced commit should fix this bug.

As the commit messages says, this is a temporary workaround. We need to rethink the BackendCombined Importer/Exporter, it's not flexible enough.

tigs001 commented 9 years ago

@fmblete, I have installed the update and been running the system for several hours now. My specific test that failed previously do not fail any more. So far everything is working well.

For information, I am using an iPhone 5s, iOS 8.3, and am using the BackendCombined with IMAP (to Dovecot), CardDAV and CalDAV (to SOGo) enabled.

Many thanks for your efforts in fixing this issue.