Mobile loop detected!



  • Hi,

    I/m having with 1 user the following error messages in z-push-error.log
    What is this and how to resolve this.
    Kopano Core: 8.5.8.2
    Z-Push: 2.5.1+0

    Appreciate the support

    30/09/2019 11:50:51 [41997] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    30/09/2019 11:50:52 [63107] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 2 items in order to identify the conflict
    30/09/2019 11:50:52 [63107] [ERROR] [xxxxxxx] Ignored broken message (SyncAppointment). Reason: '2' Folderid: 'Ud42b6' message id 'Ud42b6:39f4b04e30b74bcd8c5378fcdb847d4d4e2201000000'
    30/09/2019 11:50:52 [53121] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 2 items in order to identify the conflict
    30/09/2019 11:50:52 [53121] [ERROR] [xxxxxxx] Ignored broken message (SyncAppointment). Reason: '2' Folderid: 'Ud42b6' message id 'Ud42b6:39f4b04e30b74bcd8c5378fcdb847d4d472201000000'
    30/09/2019 11:50:53 [57551] [WARN] [xxxxxxx] /usr/share/z-push/backend/kopano/mapiprovider.php:274 mapi_zarafa_getuser_by_name(): Unable to resolve the user: 8004010F (2)
    30/09/2019 11:50:54 [53122] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    30/09/2019 11:50:55 [41999] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    30/09/2019 11:50:55 [57549] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    30/09/2019 11:50:56 [65515] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    30/09/2019 11:50:59 [53121] [WARN] [xxxxxxx] /usr/share/z-push/backend/kopano/mapiprovider.php:274 mapi_zarafa_getuser_by_name(): Unable to resolve the user: 8004010F (2)
    30/09/2019 11:51:05 [41997] [WARN] [xxxxxxx] /usr/share/z-push/backend/kopano/mapiprovider.php:274 mapi_zarafa_getuser_by_name(): Unable to resolve the user: 8004010F (2)
    30/09/2019 11:51:06 [63107] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    30/09/2019 11:51:07 [57551] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    30/09/2019 11:51:08 [30327] [WARN] [xxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict```
    
    z-push-admin -a list -d xxxxxx
    
    
    DeviceId:               xxxxxxxx
    Device type:            iPhone
    UserAgent:              Apple-iPhone9C3/1701.854
    Device Model:           iPhone9C3
    Device friendly name:   iPhone 7
    Device OS:              iOS 13.1.1 17A854
    Device OS Language:     nl
    ActiveSync version:     14.1
    First sync:             2018-10-21 16:32
    Last sync:              2019-09-30 12:31
    Sync Period:            unlimited (0)
    Total folders:          15
    Short folder Ids:       Yes
    Synchronized folders:   13 (1 in progress)
    Synchronized data:      Emails(9) Contacts Calendars Notes Tasks
    Synchronization progress:
            Folder: Agenda               Sync: Synchronizing Status:  0% (0/275)
    Additional Folders:     none
    Status:                 OK
    WipeRequest on:         not set
    WipeRequest by:         not set
    Wiped on:               not set
    Policy name:            default
    Attention needed:       No errors known
    

    Looks like the agenda is not synchronizing
    Folder: Agenda Sync: Synchronizing Status: 0% (0/275)


  • Kopano

    Hi @madpatrick,

    more information on loop detection is available in Z-Push wiki: https://wiki.z-hub.io/display/ZP/Loop+detection.

    It looks like you have some broken appointments. Did you run kopano-fsck on the user’s calendar?

    Manfred



  • I’ve deleted a lot of old appointment which solved the synchronization.
    Unfortunately still error in the log

    kopano-fsk

    Statistics:
    IPF.Appointment
            Folders:        1
            Entries:        24
            Problems:       0
            Fixed:          0
            Deleted:        0
    IPF.Contact
            Folders:        1
            Entries:        94
            Problems:       0
            Fixed:          0
            Deleted:        0
    IPF.Task
            Folders:        1
            Entries:        2
            Problems:       0
            Fixed:          0
            Deleted:        0
    
    

    The information on the wiki is not completely clear for me what to do.
    Therefor some assistance is appreciated


  • Kopano

    Hi @madpatrick,

    what error is still in the log? Please provide WBXML level log for the request with the error.

    Did you run z-push-admin -a clearloop -u user -d deviceid after you deleted those old appointments?

    Manfred



  • @Manfred

    I’ve run the clearloop command and also fixstates.
    Still getting the erros in the log.

    here my output of the WBXML log. I hope this helps to find the problem.

    02/10/2019 12:12:32 [60067] [WBXML] [linda] WBXML-IN : AwFqAEVcT0sDezk0N2YxYzNjLWRjZGYtNGM0MS1iYjYyLWM1OWVkNmQ3MDBhM30xAAFSA1VkNDJiNgABE1UDMjUAAVcAEUVGAzEAAUcDMzI3NjgAAQEBAQEB
    02/10/2019 12:12:32 [60067] [DEBUG] [linda] DeviceManager->Save(): Device data changed
    02/10/2019 12:12:32 [60067] [DEBUG] [linda] FileStateMachine->SetState() written 5006 bytes on file: '/var/lib/z-push/0/l/889d6c4jrd5f5e2lejtl6t1pl0-devicedata'
    02/10/2019 12:12:32 [60067] [DEBUG] [linda] DeviceManager->Save(): Device data saved
    02/10/2019 12:12:32 [60067] [DEBUG] [linda] LoopDetection->ProcessLoopDetectionTerminate()
    02/10/2019 12:12:32 [60067] [ INFO] [linda] cmd='Sync' memory='7.77 MiB/8.25 MiB' time='0.18s' devType='iPhone' devId='889d6c4jrd5f5e2lejtl6t1pl0' getUser='linda' from='192.168.1.195' idle='0s' version='2.5.1+0' method='POST' httpcode='200'
    02/10/2019 12:12:32 [60067] [DEBUG] [linda] -------- End
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] -------- Start
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] cmd='Sync' devType='iPhone' devId='889d6c4jrd5f5e2lejtl6t1pl0' getUser='linda' from='192.168.1.195' version='2.5.1+0' method='POST'
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] Used timezone 'Europe/Amsterdam'
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] ZPush::GetBackend(): trying autoload backend 'BackendKopano'
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] BackendKopano using PHP-MAPI version: 8.5.8.2 - PHP version: 5.4.16
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] Request::ProcessHeaders() ASVersion: 14.1
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] ZPush::CommandNeedsProvisioning(0): true
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] FileStateMachine->GetState() read '5006' bytes from file: '/var/lib/z-push/0/l/889d6c4jrd5f5e2lejtl6t1pl0-devicedata'
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] ASDevice data loaded for user: 'linda'
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] InterProcessData:__construct type: '889d6c4jrd5f5e2lejtl6t1pl0'
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] TopCollector(): Initialized mutexid Resource id #58 and memid Resource id #59.
    02/10/2019 12:12:32 [45978] [DEBUG] [linda] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] InterProcessData:__construct type: '889d6c4jrd5f5e2lejtl6t1pl0'
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] LoopDetection(): Initialized mutexid Resource id #64 and memid Resource id #65.
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] ZPush::HierarchyCommand(0): false
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] DeviceManager->ProvisioningRequired('811893419') saved device key '811893419': false
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] DeviceManager->getPolicyName(): determined policy name: 'default'
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] ZPush::CommandNeedsAuthentication(0): true
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] KopanoBackend->Logon(): Trying to authenticate user 'linda'..
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] KopanoBackend->openMessageStore('linda'): Found 'DEFAULT' store: 'Resource id #80'
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] KopanoBackend->Logon(): User 'linda' is authenticated
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] Store supports properties containing Unicode characters.
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] ZPush::CommandNeedsPlainInput(0): false
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I  <Synchronize>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I   <Folders>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I    <Folder>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     <SyncKey>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I      {3c3dfb1e-a426-4104-b576-3273433ca835}2
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     </SyncKey>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     <FolderId>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I      Ud42b6
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     </FolderId>
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] FileStateMachine->GetState() read '982' bytes from file: '/var/lib/z-push/0/l/889d6c4jrd5f5e2lejtl6t1pl0-947f1c3c-dcdf-4c41-bb62-c59ed6d700a3-fd'
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] SyncParameters->UseCPO('DEFAULT')
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] HandleSync(): Synckey does not match latest saved for this folder or there is a move state, removing folderstat to force Exporter setup
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] DeviceManager->GetBackendIdForFolderId(): folderid Ud42b6 => 39f4b04e30b74bcd8c5378fcdb847d4d580000000000
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] SyncCollections->AddCollection(): Folder id 'Ud42b6' : ref. PolicyKey '811893419', ref. Lifetime '889', last sync at '1570011152'
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] SyncCollections->AddCollection(): Updated reference PolicyKey '811893419', reference Lifetime '889', Last sync at '1570011152'
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     <GetChanges/>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     <WindowSize>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I      25
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     </WindowSize>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     <Options>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I      <AirSyncBase:BodyPreference>
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] SyncParameters->UseCPO('DEFAULT')
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I       <AirSyncBase:Type>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I        1
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I       </AirSyncBase:Type>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I       <AirSyncBase:TruncationSize>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I        32768
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I       </AirSyncBase:TruncationSize>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I      </AirSyncBase:BodyPreference>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I     </Options>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I    </Folder>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I   </Folders>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] I  </Synchronize>
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] HandleSync(): Start Output
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] HasFolderSyncStatus(): saved folder status for Ud42b6: 2
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] Sync(): forcing exporter setup for 'Ud42b6' as a sync status is saved - ignoring backend folder stats
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] Sync->loadStates(): loading states for folder 'Ud42b6'
    02/10/2019 12:12:33 [45978] [ INFO] [linda] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/0/l/889d6c4jrd5f5e2lejtl6t1pl0-3c3dfb1e-a426-4104-b576-3273433ca835-2' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:126
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] Folder type: Calendar
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O  <Synchronize>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O   <Folders>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O    <Folder>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     <SyncKey>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     {3c3dfb1e-a426-4104-b576-3273433ca835}2
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     </SyncKey>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     <FolderId>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     Ud42b6
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     </FolderId>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     <Status>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     3
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O     </Status>
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] LoopDetection->ProcessLoopDetectionAddStatus: 'Ud42b6' with status 3
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] LoopDetection->Detect(): folderid:'Ud42b6' uuid:'3c3dfb1e-a426-4104-b576-3273433ca835' counter:'2' max:'25' queued:''
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] LoopDetection->Detect(): UUID changed for folder
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] LoopDetection->Detect(): UUID changed and while items where sent to device - forcing loop mode
    02/10/2019 12:12:33 [45978] [WARN] [linda] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O    </Folder>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O   </Folders>
    02/10/2019 12:12:33 [45978] [WBXML] [linda] O  </Synchronize>
    02/10/2019 12:12:33 [45978] [DEBUG] [linda] WBXMLEncoder->endTag() WBXML output completed
    

  • Kopano

    Hi @madpatrick,

    the Z-Push states and the device states don’t match at least for calendar. Run z-push-admin -a resync -t calendar -u linda to resync the calendar only.

    If that doesn’t help, remove the account from the device, remove device from the list with z-push-admin -a remove -u linda -d 889d6c4jrd5f5e2lejtl6t1pl0, configure the account on the device again.

    Manfred



  • Hi @Manfred

    I’ve removed the account and device as described.
    Currently (approx. 2 hours) no errors in the log



  • @Manfred
    The errors do not come back.
    It looks like it appeared after an IOS13 upgrade.
    With another user i had the same errors in the log after an updae to IOS13


Log in to reply