Z-Push / KOE not syncing anymore



  • Hi,

    i am running out of ideas in troubleshooting an issue which appeared abou 1 month ago after updating. Several iOS Device are synced without probs so far. Just one outlook 2016 makes trouble. I tried also on a outlook 2013 without success. Its getting the first 400 Mails and then stops… I already tried to delete, wipe, remove, clearloop and fixstates with z-push-admin. No difference. Further updating to the latest didn´t bring any changes to that.
    How can i get the prob solved? I would be glad about tips.

    Kopano Core 8.5.81.197
    Webapp 3.4.6.1210
    MDM 2.1.0.28
    z-push 2.3.8.beta2

    Thanks in advance.

    Best regards,
    Markus


  • Kopano

    Some logging would be nice. https://wiki.z-hub.io/display/ZP/Debugging

    PS: are you also using KOE? Outlook has shown to request some folder over and over again even if they are long gone on the backend. The only thing to solve this is to get rid of the profile in Outlook (resyncing from z-push-admin is not enough here).



  • Hi,
    Same problem with Outlook, I have create many profil in Outlook and test in other computer.
    After 1 month I don’t have solution and Kopano too :(
    If you have solution I’m happy to know it

    Best regard



  • Hi,

    thanks for answering. Yeah i indeed have already tried to delete the whole profile, removed all .pst files and added a new profile. Also i have tried by another machine. Today i recongnized that it seems to stuck at the calender…
    What logs do you need and how should i post them?
    Best regards
    Markus



  • Hi,

    i got lots of errors in th ez-push.log like:

    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] HandlePing(): unknown collection 'U21301', triggering HierarchySync
    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] NoHierarchyCacheAvailableException: Folderid 'U21f33' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:448
    10/02/2018 14:04:50 [ 1910] [ INFO] [gustav] StateNotFoundException: No hierarchy UUID linked to device. Requesting folder resync. - code: 0 - file: /usr/share/z-push/lib/core/statemanager.php:486
    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] HandlePing(): unknown collection 'U21f33', triggering HierarchySync
    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] NoHierarchyCacheAvailableException: Folderid 'U2276b' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:448
    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] HandlePing(): unknown collection 'U2276b', triggering HierarchySync
    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] NoHierarchyCacheAvailableException: Folderid 'U22f50' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:448
    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] HandlePing(): unknown collection 'U22f50', triggering HierarchySync
    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] NoHierarchyCacheAvailableException: Folderid 'U23b41' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:448
    10/02/2018 14:04:50 [ 4642] [ INFO] [gustav] HandlePing(): unknown collection 'U23b41', triggering HierarchySync
    
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-6579ee23-fd3c-4628-a034-ccf1da8775ee-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-ec062ab5-b7c8-4d7a-8828-35c57e6c14f1-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-411f31c2-77c1-4a90-81b4-d5a65afbcd06-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-0f355a4b-0e25-44c1-acd2-1dab7fe6c6c5-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-a5639e80-dcf0-4283-9178-bee66a5d7d86-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-7d96c1f2-645e-481d-9b9e-9220d641772a-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-bac7e561-53c9-477c-a6db-4b5e75456c00-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-89eea5dd-a9d8-485c-8a1f-b33ac5094209-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-591c3c39-39f0-46bd-a80b-f93dbbca1706-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/4/f728750dbe95435594c1a85d4e01ef43-7af91ccb-f18b-4d4b-b201-5af4e558c7c5-1' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    10/02/2018 14:04:53 [ 1910] [ INFO] [gustav] cmd='Sync' memory='7.02 MiB/7.75 MiB' time='0.85s' devType='WindowsOutlook' devId='f728750dbe95435594c1a85d4e01ef43' getUser='gustav' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:04:56 [ 1910] [ INFO] [gustav] cmd='Sync' memory='12.95 MiB/13.75 MiB' time='2.93s' devType='WindowsOutlook' devId='f728750dbe95435594c1a85d4e01ef43' getUser='gustav' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:04:57 [30887] [ INFO] [gustav] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 3540 seconds)
    10/02/2018 14:04:57 [30887] [ INFO] [gustav] cmd='Ping' memory='8.06 MiB/8.50 MiB' time='0.48s' devType='WindowsOutlook' devId='f728750dbe95435594c1a85d4e01ef43' getUser='gustav' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:04:58 [ 1910] [WARN] [gustav] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    10/02/2018 14:05:07 [ 1910] [ INFO] [gustav] cmd='Sync' memory='11.41 MiB/12.25 MiB' time='10.02s' devType='WindowsOutlook' devId='f728750dbe95435594c1a85d4e01ef43' getUser='gustav' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:05:18 [ 4642] [ INFO] [gustav] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 3540 seconds)
    10/02/2018 14:05:18 [ 4642] [ INFO] [gustav] cmd='Ping' memory='7.82 MiB/8.25 MiB' time='0.43s' devType='WindowsOutlook' devId='f728750dbe95435594c1a85d4e01ef43' getUser='gustav' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:05:36 [ 4642] [ INFO] [markus] cmd='Sync' memory='2.35 MiB/3.00 MiB' time='0.06s' devType='iPhone' devId='k56o6sg1kp4lt6jj6t55mfd4tk' getUser='markus' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:05:36 [30887] [ INFO] [icey] cmd='Sync' memory='2.34 MiB/3.00 MiB' time='0.04s' devType='iPhone' devId='k56o6sg1kp4lt6jj6t55mfd4tk' getUser='icey' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:05:36 [ 4642] [ INFO] [markus] cmd='Sync' memory='2.35 MiB/3.00 MiB' time='0.04s' devType='iPhone' devId='k56o6sg1kp4lt6jj6t55mfd4tk' getUser='markus' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:05:39 [30887] [ INFO] [icey] cmd='Sync' memory='2.34 MiB/3.00 MiB' time='0.04s' devType='iPhone' devId='k56o6sg1kp4lt6jj6t55mfd4tk' getUser='icey' from='193.159.133.181' idle='0s' version='2.3.9' method='POST' httpcode='200'
    10/02/2018 14:05:54 [ 1910] [ INFO] [gustav] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 900 seconds)
    10/02/2018 14:06:11 [ 2155] [ INFO] [gustav] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 360s from 900s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
    10/02/2018 14:06:11 [ 2155] [ INFO] [gustav] cmd='Ping' memory='7.98 MiB/8.25 MiB' time='360.39s' devType='iPhone' devId='c3kf4d2u4d4ed81gqj9d40uf74' getUser='gustav' from='80.187.111.129' idle='360s' version='2.3.9' method='POST' httpcode='200'
    

    The device id with the fault is f728750dbe95435594c1a85d4e01ef43



  • What are the file/folder permissions on /var/lib/z-push ? they should be of the web server you’re using (eg www-data for apache)

    rg
    christian



  • Hi,

    so they are. owner and group are www-data and it is 0755

    Markus


  • Kopano

    @icey said in Z-Push / KOE not syncing anymore:

    What logs do you need and how should i post them?

    I’ve already posted link for you that explains how to get debug logging. To have something meaningful in the log you should enable the logging and the create a new profile in outlook.

    Since the log is the likely to big for a single post you could put it on a public pastebin.

    If you have a kopano subscription you could also attach the log to a service case.



  • Hi fbartels,

    i hope i got the logs you want :) i putted them on the server to doenload. They are indeed to big. Because i tried to sync a new client they are very full.
    http://sapper-plus.de/kopano.rar

    Thanks so far for helping.
    Markus


  • Kopano

    Just briefly scrolled through the wbxml of the Outlook account. on first look I could not find anything suspicious. Did the sync already stop when you copied the file?



  • Hi Felix,
    it is indeed very curious… The log ends on 12:06 but the outlook is still opened, with the status “Folder Calendar is being syncronized” and the timestamp of the log is 14:12…
    Do you need any further informations or logs?

    Kind regards
    Markus


  • Kopano

    Hi Markus,

    is there more of gustav.log? Because there are errors in z-push.log at 14:50 and gustav.log ends at 12:06.

    Manfred



  • Hi Manfred,
    i just deleted the old log and gave a new try. Now i got many errors in the gustav.log… Also the outlook is hanging with ‘Folder calender is beeing syncronised’

    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'Uebd3b' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'Uef5de' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'Uf0896' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'U1165b' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'Uf3beb' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'Uf9dfa' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'Ufa01c' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'Ufe2c4' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'U96306' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Sync(): no exporter setup for 'U75bef' as GlobalWindowSize is full.
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] Global WindowSize for amount of exported changes reached, omitting output for collection.
    17/02/2018 08:43:59 [18744] [WBXML] [gustav] [f728750dbe95435594c1a85d4e01ef43] O   </Folders>
    17/02/2018 08:43:59 [18744] [WBXML] [gustav] [f728750dbe95435594c1a85d4e01ef43] O  </Synchronize>
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] WBXMLEncoder->endTag() WBXML output completed
    17/02/2018 08:43:59 [18744] [WBXML] [gustav] [f728750dbe95435594c1a85d4e01ef43] WBXML-OUT: more than 512K of data
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] HandleSync: Processed 163 folders
    17/02/2018 08:43:59 [18744] [WBXML] [gustav] [f728750dbe95435594c1a85d4e01ef43] WBXML-IN : Aw(.....)AzUxMgABV1gDMAABYgMyAAFjAzgAAQARRUYDNAABSAMxAAEBAQEAAE9LA3tjZWQ4MzMzYy0wNjBmLQ==
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] LoopDetection->ProcessLoopDetectionTerminate()
    17/02/2018 08:43:59 [18744] [ INFO] [gustav] [f728750dbe95435594c1a85d4e01ef43] cmd='Sync' memory='7.07 MiB/7.75 MiB' time='1.82s' devType='WindowsOutlook' devId='f728750dbe95435594c1a85d4e01ef43' getUser='gustav' from='193.159.136.15' idle='0s' version='2.3.9' method='POST' httpcode='200'
    17/02/2018 08:43:59 [18744] [DEBUG] [gustav] [f728750dbe95435594c1a85d4e01ef43] -------- End
    

    z-push-error.log:

    17/02/2018 08:03:46 [17207] [ERROR] [gustav] Ignored broken message (SyncMail). Reason: '2' Folderid: 'U81c68' message id 'U81c68:a898e84976e34829848f9b0e374f6630a69202000000'
    17/02/2018 08:03:46 [17207] [WARN] [gustav] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:03:46 [17207] [WARN] [gustav] Mobile loop detected! Messages sent to the mobile will be restricted to 2 items in order to identify the conflict
    17/02/2018 08:03:46 [17207] [ERROR] [gustav] Ignored broken message (SyncTask). Reason: '2' Folderid: 'U62dd1' message id 'U62dd1:a898e84976e34829848f9b0e374f66302c3d02000000'
    17/02/2018 08:03:46 [17207] [WARN] [gustav] Mobile loop detected! Messages sent to the mobile will be restricted to 2 items in order to identify the conflict
    17/02/2018 08:03:47 [17207] [ERROR] [gustav] Ignored broken message (SyncMail). Reason: '2' Folderid: 'U1165b' message id 'U1165b:a898e84976e34829848f9b0e374f6630c23e02000000'
    17/02/2018 08:03:47 [17207] [WARN] [gustav] Mobile loop detected! Messages sent to the mobile will be restricted to 2 items in order to identify the conflict
    17/02/2018 08:03:48 [17207] [ERROR] [gustav] Ignored broken message (SyncMail). Reason: '2' Folderid: 'U12150' message id 'U12150:a898e84976e34829848f9b0e374f6630277b02000000'
    17/02/2018 08:42:04 [17207] [WARN] [gustav] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:42:04 [17207] [WARN] [gustav] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:43:58 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:43:58 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:43:58 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.```
    

    z-push.log

    17/02/2018 08:43:57 [18744] [ INFO] [gustav] [] Options request
    17/02/2018 08:43:57 [18744] [ INFO] [gustav] [] cmd='' memory='1.59 MiB/2.00 MiB' time='0.02s' devType='' devId='' getUser='gustav' from='193.159.136.15' idle='0s' version='2.3.9' method='OPTIONS' httpcode='200'
    17/02/2018 08:43:57 [18744] [ INFO] [gustav] [f728750dbe95435594c1a85d4e01ef43] cmd='FolderSync' memory='4.40 MiB/4.75 MiB' time='0.08s' devType='WindowsOutlook' devId='f728750dbe95435594c1a85d4e01ef43' getUser='gustav' from='193.159.136.15' idle='0s' version='2.3.9' method='POST' httpcode='200'
    17/02/2018 08:43:58 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:43:58 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:43:58 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [WARN] [gustav] [f728750dbe95435594c1a85d4e01ef43] SyncObject->Check(): object from type SyncMail: parameter 'from' contains an invalid email address '"" <>'. Address is removed.
    17/02/2018 08:43:59 [18744] [ INFO] [gustav] [f728750dbe95435594c1a85d4e01ef43] cmd='Sync' memory='7.07 MiB/7.75 MiB' time='1.82s' devType='WindowsOutlook' devId='f728750dbe95435594c1a85d4e01ef43' getUser='gustav' from='193.159.136.15' idle='0s' version='2.3.9' method='POST' httpcode='200'
    17/02/2018 08:44:37 [17207] [ INFO] [gustav] [webservice] Announcing latest AS version to device: 12.0,12.1,14.0
    17/02/2018 08:44:37 [17207] [ INFO] [gustav] [webservice] WebserviceDevice::GetDeviceDetails('6980e5336cb54957b08d23cb45e3e817'): getting device details from state of user 'gustav'
    17/02/2018 08:44:37 [17207] [ INFO] [gustav] [webservice] cmd='WebserviceDevice' memory='5.65 MiB/6.25 MiB' time='0.21s' devType='webservice' devId='webservice' getUser='gustav' from='93.213.48.228' idle='0s' version='2.3.9' method='POST' httpcode='200'
    17/02/2018 08:45:37 [17095] [ INFO] [gustav] [webservice] Announcing latest AS version to device: 12.0,12.1,14.0
    17/02/2018 08:45:37 [17095] [ INFO] [gustav] [webservice] WebserviceDevice::GetDeviceDetails('6980e5336cb54957b08d23cb45e3e817'): getting device details from state of user 'gustav'
    17/02/2018 08:45:37 [17095] [ INFO] [gustav] [webservice] cmd='WebserviceDevice' memory='5.65 MiB/6.25 MiB' time='0.20s' devType='webservice' devId='webservice' getUser='gustav' from='93.213.48.228' idle='0s' version='2.3.9' method='POST' httpcode='200'
    17/02/2018 08:46:37 [18744] [ INFO] [gustav] [webservice] Announcing latest AS version to device: 12.0,12.1,14.0
    17/02/2018 08:46:37 [18744] [ INFO] [gustav] [webservice] WebserviceDevice::GetDeviceDetails('6980e5336cb54957b08d23cb45e3e817'): getting device details from state of user 'gustav'
    17/02/2018 08:46:37 [18744] [ INFO] [gustav] [webservice] cmd='WebserviceDevice' memory='5.65 MiB/6.25 MiB' time='0.22s' devType='webservice' devId='webservice' getUser='gustav' from='93.213.48.228' idle='0s' version='2.3.9' method='POST' httpcode='200'
    17/02/2018 08:47:37 [18744] [ INFO] [gustav] [webservice] Announcing latest AS version to device: 12.0,12.1,14.0
    17/02/2018 08:47:37 [18744] [ INFO] [gustav] [webservice] WebserviceDevice::GetDeviceDetails('6980e5336cb54957b08d23cb45e3e817'): getting device details from state of user 'gustav'
    17/02/2018 08:47:37 [18744] [ INFO] [gustav] [webservice] cmd='WebserviceDevice' memory='5.65 MiB/6.25 MiB' time='0.21s' devType='webservice' devId='webservice' getUser='gustav' from='93.213.48.228' idle='0s' version='2.3.9' method='POST' httpcode='200'
    

    Markus


  • Kopano

    These are no errors, but INFO and DEBUG messages! Errors would be FATAL, ERROR or even WARN.

    You are in loop detection. Why is another question, but it’s per se no error.
    You could try to force loop detection to terminate via z-push-admin. But if you have broken items in your store it will just kick in again.
    Read more about loop detection here: https://wiki.z-hub.io/display/ZP/Loop+detection

    Cheers,
    Sebastian



  • H i Sebastian,
    ok so far. When i delete the system wide loop detection data it syncs a few more mails and stops again… so how can i get closer to the prob. it is an outlook and i got a good network/inet connection…

    Markus


  • Kopano

    Beto a WBXML log. The wiki has more details (debugging).



  • Hi Manfred and Sebastian,

    i would like to provide you the wbxml.log. i am not getting an idea out of it :(
    Hopefully you can find an error where i can solve the problem.

    Thanks in advance

    Markus


  • Kopano

    Hi Markus,

    yes, you can post the link to the WBXML log and we will take a look at it.

    Manfred



  • Great, thanks! There you go: https://sapper-plus.de/log/gustav.rar


  • Kopano

    Hi Markus,

    I’ve looked through the log and didn’t find anything obviously wrong. I have some questions though.

    There are quite some folders and messages you’re syncing. Have you tried synchronising 1 month instead of all items?

    What is the size of the .ost file associated to this Outlook profile?

    The both broken appointments, “Internorga 2013” and “Sapper Göppingen” have a quite unusual UID. Are they invitations from external system?

    Have you tried running kopano-fsck?

    Manfred



  • Hi Manfred,
    thanks a lot so far. These two appointments had as date 01.01.1753. Why? I don’t know… May you tell how you found these? How did you search? I now get it synct up to 33% and it gets stucked again… So i would like to give it a try to find it by myself.
    You talked about kopano-fsck. don’t know this tool yet. when i make a --checkonly i get the following results:
    Statistics:

    IPF.Appointment
            Folders:        1
            Entries:        541
            Problems:       38
            Fixed:          0
            Deleted:        0
    IPF.Contact
            Folders:        13
            Entries:        3387
            Problems:       293
            Fixed:          0
            Deleted:        0
    IPF.Task
            Folders:        1
            Entries:        13
            Problems:       0
            Fixed:          0
            Deleted:        0
    

    Should i try a --autofix or what would you suggest? I can’t just delete all the contacts and so on…

    Thanks in advance
    Markus