Navigation

    Kopano
    • Register
    • Login
    • Search
    • Categories
    • Get Official Kopano Support
    • Recent
    Statement regarding the closure of the Kopano community forum and the end of the community edition

    Suffering from sync loops

    Synchronising (mobile) devices via Z-Push
    4
    5
    420
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • divB
      divB last edited by

      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!

      1 Reply Last reply Reply Quote 0
      • baurmatt
        baurmatt last edited by

        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.

        1 Reply Last reply Reply Quote 0
        • Manfred
          Manfred Kopano last edited by

          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

          1 Reply Last reply Reply Quote 0
          • baurmatt
            baurmatt last edited by

            @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.

            1 Reply Last reply Reply Quote 0
            • thctlo
              thctlo last edited by

              @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.

              1 Reply Last reply Reply Quote 0
              • First post
                Last post