Z-Push / KOE not syncing anymore

icey

Hi,

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

Markus

fbartels

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

icey

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

fbartels

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?

icey

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

Manfred

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

icey

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

Sebastian

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

icey

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

Sebastian

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

icey

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

Manfred

Hi Markus,

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

Manfred

icey

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

Manfred

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

icey

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

Manfred

Hi Markus,

I was looking for “potential broken message id” in the log and noticed the unusual uid. Now that you say the timestamp is pretty strange indeed as well.

I would suggest you run kopano-fsck for calendar only without --autofix. If I remember correctly it will show you what it would fix, so that you can decide if you want to accept it or not.
There are quite some contacts with problems, so running without --autofix might be quite tedious.
Anyway, I think kopano-fsck should get you further in sync.

Is it actually an older installation with some updates of Zarafa/Kopano or have you migrated from some other solution?

Manfred

icey

Hi Manfred,
no it is a running installation since years now. Originally it was Zarafa, then migrated to kopano, and since a few reinstallation and server movings it runs on that server since 2 years i think. without any probs so far. just i think after the last upate the probs began…
So what is the indication for an unusual id? when it ends with “2000000” so then there would be many…
kopano-fsck without an option asks if it should delete the item or not… a bit annoying to type 38 times “yes” \o/ ^^

Regards
Markus

Manfred

Hi Markus,

the usual uids start with 0400000082… (e.g. 040000008200E00074C5B7101A82E0080000000000734468419CD301000000000000000010000000F59DB9B0B89CD0B831193088D7E52010).

But it might be also other issues with the items, not uid only (like end before start or property value out of range defined in ActiveSync). It’s not easy to spot such issues.

I didn’t remember that kopano-fsck was deleting items. But if you don’t need them anymore, that’s probably the way to go.

Manfred

icey

Hi Manfred,
i come back to you because i can´t get the prob fixed. So i tried with kopano-fsck for the appointments, but it didn´t help. So in outlook it says “Folder Inbox is being synced” but it stucks… For what may i search in the gustav.log ?
Further i recognized that i got errors in server.log finding some attachements. Nobody deleted anything…
Also in webapp only at gustav it shows some curious errror messages in setting like: “can not get list of delegates” and when saving an appointement “could not save the message” but it is saved(sometimes)…?!

Another thing on my own installation and that installation is, when i create a contact on the iphone which is connected via zpush, in webapp is shown at the field fullname:

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2//EN"><HTML><HEAD><META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=us-ascii"><META NAME="Generator" CONTENT="Kopano HTML builder 1.0"><TITLE></TITLE></HEAD><BODY><!-- Converted from text/plain

Sorry this is very much at one time i know \o/ Hopefully you are able to give me some hints, I will try figuring the errors out on saturday, because i got very less time at the moment…

Thanks a lot in advance!

Cheers Markus

Coffee_is_life

Good Morning @icey,

since its “only” this store, you could try to

backup the store with kopano-backup

kopano-backup -u gustav -O <output-dir>

unhook the store

kopano-admin --unhook-store gustav

now you got 2 options:
3 a) disable gustav for e-mail (for ldap, disable the user in ad), wait for kopano to sync

kopano-admin -l      (gustav not shown)

enable again, wait for kopano to get this change aswell. it should create a new store for gustav

or 3 b) create a store manually

kopano-admin --create-store gustav

and finally restore the backup

kopano-backup --restore <previous_output_folder>/gustav

if this is successful you can delete the orphaned store

kopano-admin --list-orphans (gustav should be guessed by kopano, you can see its id)
kopano-admin -remove-store <orphaned_id>

if this does not work, try to fix the folder ids by running

python fix_delegates.py --user gustav --modify

(https://stash.kopano.io/projects/KSC/repos/core-tools/browse/fix-delegates)

hope you can fix it

coffee_is_life