Suffering from sync loops



  • Hi,

    I am using z-push with the kopano backend. From time to time my iPhone battery drains super fast and everytime the same thing: Log into my z-push server, inspect the logs, finding entries like:

    [...]
    12/11/2019 03:44:20 [13574] [ INFO] [user] LoopDetection->ProcessLoopDetectionIsHierarchyResyncRequired(): Potential loop detected. Full hierarchysync indicated.
    12/11/2019 03:44:20 [13574] [ INFO] [user] cmd='FolderSync' memory='1.78 MiB/2.25 MiB' time='0.53s' devType='iPhone' devId='sf1cn9o2mh19r3g7vr82mnmjfo' getUser='user' from='66.116.40.76' idle='0s' version='2.5.1+0-0' method='POST' httpcode='200'
    12/11/2019 03:44:22 [14588] [ INFO] [user] cmd='FolderSync' memory='1.88 MiB/2.25 MiB' time='1.13s' devType='iPhone' devId='sf1cn9o2mh19r3g7vr82mnmjfo' getUser='user' from='66.116.40.76' idle='0s' version='2.5.1+0-0' method='POST' httpcode='200'
    12/11/2019 03:44:24 [13579] [WARN] [user] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0x8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230
    [...]
    

    I hoped I would be able to pin-point the messages to a particular element (appointment or task which has inconsistent data) which I could delete then. After enabling WBXML debug I zoom into the error message and see:

    12/11/2019 04:56:55 [20532] [DEBUG] [user] -------- Start
    12/11/2019 04:56:55 [20532] [DEBUG] [user] cmd='Sync' devType='iPhone' devId='sf1cn9o2mh19r3g7vr82mnmjfo' getUser='user' from='66.116.40.76' version='2.5.1+0-0' method=
    12/11/2019 04:56:55 [20532] [DEBUG] [user] Used timezone 'Europe/Amsterdam'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::GetBackend(): trying autoload backend 'BackendKopano'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] BackendKopano using PHP-MAPI version: 7.2.6-10 - PHP version: 5.6.40-0+deb8u7
    12/11/2019 04:56:55 [20532] [DEBUG] [user] Request::ProcessHeaders() ASVersion: 14.1
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::CommandNeedsProvisioning(0): true
    12/11/2019 04:56:55 [20532] [DEBUG] [user] FileStateMachine->GetState() read '3426' bytes from file: '/var/lib/z-push/o/f/sf1cn9o2mh19r3g7vr82mnmjfo-devicedata'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ASDevice data loaded for user: 'user'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] InterProcessData:__construct type: 'sf1cn9o2mh19r3g7vr82mnmjfo'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] TopCollector(): Initialized mutexid Resource id #19 and memid Resource id #20.
    12/11/2019 04:56:55 [20532] [DEBUG] [user] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] InterProcessData:__construct type: 'sf1cn9o2mh19r3g7vr82mnmjfo'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] LoopDetection(): Initialized mutexid Resource id #24 and memid Resource id #25.
    12/11/2019 04:56:55 [20532] [DEBUG] [user] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::HierarchyCommand(0): false
    12/11/2019 04:56:55 [20532] [DEBUG] [user] DeviceManager->ProvisioningRequired('660508202') saved device key '660508202': false
    12/11/2019 04:56:55 [20532] [DEBUG] [user] DeviceManager->getPolicyName(): determined policy name: 'default'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::CommandNeedsAuthentication(0): true
    12/11/2019 04:56:55 [20532] [DEBUG] [user] KopanoBackend->Logon(): Trying to authenticate user 'user'..
    12/11/2019 04:56:55 [20532] [DEBUG] [user] KopanoBackend->openMessageStore('user'): Found 'DEFAULT' store: 'Resource id #36'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] KopanoBackend->Logon(): User 'user' is authenticated
    12/11/2019 04:56:55 [20532] [DEBUG] [user] Store supports properties containing Unicode characters.
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::CommandNeedsPlainInput(0): false
    12/11/2019 04:56:55 [20532] [WBXML] [user] I  <Synchronize>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I   <Folders>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I    <Folder>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I     <SyncKey>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I      0
    12/11/2019 04:56:55 [20532] [WBXML] [user] I     </SyncKey>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I     <FolderId>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I      U1b889
    12/11/2019 04:56:55 [20532] [WBXML] [user] I     </FolderId>
    12/11/2019 04:56:55 [20532] [DEBUG] [user] SyncParameters->RemoveSyncKey(): saved sync key removed
    12/11/2019 04:56:55 [20532] [DEBUG] [user] DeviceManager->GetBackendIdForFolderId(): folderid U1b889 => 0efa6f03327c4d4db2965f7c2f1264c23f00000000000000
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::GetFolderClassFromFolderType('8'): Calendar
    12/11/2019 04:56:55 [20532] [DEBUG] [user] GetFolderClassFromCacheByID from Device Manager: 'Calendar' for id:'U1b889'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] SyncCollections->AddCollection(): Folder id 'U1b889' : ref. PolicyKey '1', ref. Lifetime '10', last sync at ''
    12/11/2019 04:56:55 [20532] [WBXML] [user] I     <Options>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I      <FilterType>
    12/11/2019 04:56:55 [20532] [DEBUG] [user] SyncParameters->UseCPO('DEFAULT')
    12/11/2019 04:56:55 [20532] [WBXML] [user] I       6
    12/11/2019 04:56:55 [20532] [WBXML] [user] I      </FilterType>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I      <AirSyncBase:BodyPreference>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I       <AirSyncBase:Type>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I        1
    12/11/2019 04:56:55 [20532] [WBXML] [user] I       </AirSyncBase:Type>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I       <AirSyncBase:TruncationSize>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I        32768
    12/11/2019 04:56:55 [20532] [WBXML] [user] I       </AirSyncBase:TruncationSize>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I      </AirSyncBase:BodyPreference>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I     </Options>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I    </Folder>
    12/11/2019 04:56:55 [20532] [DEBUG] [user] HandleSync(): FilterType has changed (old: '', new: '6'), removing folderstat to force Exporter setup
    12/11/2019 04:56:55 [20532] [WBXML] [user] I   </Folders>
    12/11/2019 04:56:55 [20532] [WBXML] [user] I  </Synchronize>
    12/11/2019 04:56:55 [20532] [DEBUG] [user] HandleSync(): Start Output
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::GetAdditionalSyncFolderStore('0efa6f03327c4d4db2965f7c2f1264c23f00000000000000'): 'false'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] KopanoBackend->GetFolderStat() fetched status information of 46 folders for store 'user'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] SyncParameters->IsExporterRunRequired(): true - current: 1573527697/5584/48/3 - saved: false - expiring: not set
    12/11/2019 04:56:55 [20532] [DEBUG] [user] Sync->loadStates(): loading states for folder 'U1b889'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::GetAdditionalSyncFolderStore('0efa6f03327c4d4db2965f7c2f1264c23f00000000000000'): 'false'
    12/11/2019 04:56:55 [20532] [DEBUG] [user] ZPush::GetAdditionalSyncFolderStore('0efa6f03327c4d4db2965f7c2f1264c23f00000000000000'): 'false'
    12/11/2019 04:56:56 [20532] [DEBUG] [user] ExportChangesICS->Config(): synching inital data
    12/11/2019 04:56:56 [20532] [DEBUG] [user] ExportChangesICS->Config() initialized with state: 0x0000000000000000
    12/11/2019 04:56:56 [20532] [WARN] [user] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0x8004010F - code: 12 - fi
    12/11/2019 04:56:56 [20532] [DEBUG] [user] LoopDetection->ProcessLoopDetectionAddStatus: 'U1b889' with status 12
    12/11/2019 04:56:56 [20532] [DEBUG] [user] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
    12/11/2019 04:56:56 [20532] [WBXML] [user] O  <Synchronize>
    12/11/2019 04:56:56 [20532] [WBXML] [user] O   <Status>
    12/11/2019 04:56:56 [20532] [WBXML] [user] O   12
    12/11/2019 04:56:56 [20532] [WBXML] [user] O   </Status>
    12/11/2019 04:56:56 [20532] [WBXML] [user] O  </Synchronize>
    12/11/2019 04:56:56 [20532] [DEBUG] [user] WBXMLEncoder->endTag() WBXML output completed
    12/11/2019 04:56:56 [20532] [WBXML] [user] WBXML-OUT: AwFqAEVOAzEyAAEB
    12/11/2019 04:56:56 [20532] [WBXML] [user] WBXML-IN : AwFqAEVcT0sDMAABUgNVMWI4ODkAAVdYAzYAAQARRUYDMQABRwMzMjc2OAABAQEBAQE=
    12/11/2019 04:56:56 [20532] [DEBUG] [user] LoopDetection->ProcessLoopDetectionTerminate()
    12/11/2019 04:56:56 [20532] [ INFO] [user] cmd='Sync' memory='1.78 MiB/2.25 MiB' time='0.65s' devType='iPhone' devId='sf1cn9o2mh19r3g7vr82mnmjfo' getUser='user' from='6
    12/11/2019 04:56:56 [20532] [DEBUG] [user] -------- End
    

    From my understanding both issues (the error message and the loop) is caused by the element with the ID U1b889 which is the folder “Calendar”.

    That’s clearly not something I can delete because it includes my entire calendar!

    Any hope to fix this?
    Thanks!



  • Having the same problem. Feels like it started with iOS 13. Tried running kopano-fsck and re-added the account a couple of times. Re-adding the account helps for a couple of hours/days, but the problem comes back after some time. Feels like it starts showing up after creating an calender appointment.

    https://forum.kopano.io/topic/2726/mobile-loop-detected/8 describes the same problem.


  • Kopano

    Hi @divB @baurmatt,

    did you try my suggestions from https://forum.kopano.io/post/15163?

    If that also doesn’t help, try removing the ActiveSync account from the device, remove the device with z-push-admin, restart the device, add the account again.

    @divB you are using a quite old Zarafa version. Consider upgrading to a recent Kopano Core version.

    Manfred



  • @Manfred I tried a couple of things:

    1. Clear loop
    2. Resyncing
    3. Remove the account from the phone without removing it in z-push
    4. Remove the account from the phone and removing it in z-push

    All of this didn’t help and/or the problem showed up sooner or later. I’ve just did 3 again this morning. Next time I will try to reboot the phone before re-adding the account.

    FYI: I’m running the latest Kopano Core/z-push version.



  • @divB said in Suffering from sync loops:
    Try a different mail app. i have seen simular things on android. due to… i still have one zarafa 6.30 running with an old z-push.
    I also notice with some apps, that if they have a mail and contacts and callendar, you need to install all of the same supplier.

    0x8004010F - code: 12, if its the same as on a real exchange, disable GAB in z-push is worth a try.
    or create one that the use can access.

    if in the mail app, an option exist about offline adress books, disable it.

    A few suggestion you could try, to keep it running, but upgrading is the best option.


Log in to reply