z-push 2.6.1 state issues

Hi,

I’m running Ubuntu 20.04 with kopano 10.0.6. Webapp/deskapp , z-push 2.6.1 beta 1 and PHP7.4.
Kopano runs smoothly but Outlook 2019 with KOE 2.1.20 synchronizations gets stuck, apparantly on state issues.

Examples:

30/01/2021 14:51:25 [ 3771] [ERROR] [boudewijn] HandleSync(): error saving '{144a725f-4e5d-48a8-9235-14e715e60786}1' - no state information available
30/01/2021 14:51:25 [ 3771] [ERROR] [boudewijn] HandleSync(): error saving '{59fde6b3-d44a-4d76-afd1-8a3841f131da}1' - no state information available
30/01/2021 14:51:25 [ 3771] [ERROR] [boudewijn] HandleSync(): error saving '{d1d5b459-c6a0-460a-bbd5-fa35f32fbc56}1' - no state information available
30/01/2021 14:51:26 [ 3771] [ERROR] [boudewijn] HandleSync(): error saving '{ef8a38aa-a90b-43a0-a2dd-df3fd26ac104}1' - no state information available
30/01/2021 14:51:26 [ 3771] [ERROR] [boudewijn] HandleSync(): error saving '{3e1d7b2a-f4a8-45f2-a4bc-6f0b51795509}1' - no state information available
30/01/2021 14:51:26 [ 3771] [ERROR] [boudewijn] HandleSync(): error saving '{a0c17c08-85b1-44d6-be1b-246cf3fd08ae}1' - no state information available
30/01/2021 14:51:26 [ 3771] [ERROR] [boudewijn] HandleSync(): error saving '{a74036aa-524c-4f1b-8ab8-b34238021fb8}1' - no state information available
30/01/2021 14:51:27 [ 3771] [ERROR] [boudewijn] HandleSync(): error saving '{258c544d-8531-4cc4-b4eb-1f2f05024116}1' - no state information available

and likewise

30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197
30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197
30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197
30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197
30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197
30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197
30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197
30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197
30/01/2021 14:59:45 [ 3771] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197

The latter part is with state files in the database, but the result for the file system is the same.

Any ideas?

Manfred

Hi @boudewijn,

please upgrade to Z-Push 2.6.2 and test again. It contains an Outlook related fix (stuck calendar sync).

Manfred

@manfred Hi Manfred, thanks I will try and report back.

After installation of the 2.6.2 final, the behavior is still the same. A first clean sync only synced the folders, then got stuck for a while. A day later I started Outlook which surprisingly resumed sync but according to KOE only for maximum 25% of all the mailbox items, while it was set to sync all. Apparantly KOE overlooked the 75%. So after this completed still many folders were empty.
Error log showed tons of the messages as above,

I did experience the calendar issue in the past but this was fixed in one of the latest betas. The issue mentioned here is still remaining.

Manfred

Hi @boudewijn,

are there any other errors in Z-Push log?

Are there any Z-Push related errors in the webserver log?

Do the sync requests take several minutes to complete?

What is the size of the store? Are you trying to sync all items or just the last month? If the store is large than 10GB and you’re syncing all, try syncing only one month. Additionally you may try setting SYNC_MAX_ITEMS in Z-Push config to a lower value, e.g. 256 or 128.

Manfred

Hi @manfred,

Thanks for your reply.
What I did as a follow up:

deleted all state files by removing all devices and verified no records were left in the z-push database (except for the version record)
Set SYNC_MAX_ITEMS to 128
deleted the outlook profile and recreated a fresh one with only 1 month sync
Started outlook

Regarding to sync, I noticed:

inbox, sent items and deleted items seem to sync properly within the limit which I set to 1 month
other folders only sync their structure but not their content
calendar items seem to sync completely regardless of the 1 month limit
contact items seem to sync completely

The first log entries are:

09/02/2021 08:00:48 [66490] [ INFO] [boudewijn] Options request
09/02/2021 08:00:48 [66490] [ INFO] [boudewijn] cmd='' memory='3.11 MiB/4.00 MiB' time='0.34s' devType='' devId='' getUser='boudewijn' from='192.168.0.1' idle='0s' version='2.6.2+0-0' method='OPTIONS' httpcode='200'
09/02/2021 08:01:05 [67530] [ INFO] [boudewijn] Options request
09/02/2021 08:01:05 [67530] [ INFO] [boudewijn] cmd='' memory='1.47 MiB/2.00 MiB' time='0.05s' devType='' devId='' getUser='boudewijn' from='192.168.0.1' idle='0s' version='2.6.2+0-0' method='OPTIONS' httpcode='200'
09/02/2021 08:01:05 [67530] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetStateHash(): Could not locate state with error code: 00000 - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:145
09/02/2021 08:01:05 [67530] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetStateHash(): Could not locate state with error code: 00000 - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:145
09/02/2021 08:01:05 [67530] [ INFO] [boudewijn] Announcing latest AS version to device: 12.0,12.1,14.0,14.1
09/02/2021 08:01:15 [67530] [ INFO] [boudewijn] Linking device ID '37149fcd696a46eab0a7e0932d718b94' to user 'boudewijn'
09/02/2021 08:01:16 [67530] [ INFO] [boudewijn] cmd='FolderSync' memory='11.69 MiB/14.00 MiB' time='10.91s' devType='WindowsOutlook' devId='37149fcd696a46eab0a7e0932d718b94' getUser='boudewijn' from='192.168.0.1' idle='0s' version='2.6.2+0-0' method='POST' httpcode='200'

followed by about 900 errors like this:

09/02/2021 08:12:38 [36631] [ERROR] [boudewijn] HandleSync(): error saving '{c7f4987c-f3c6-4db3-a883-666d82ff3810}1' - no state information available

then I get almost 400 of these:

09/02/2021 08:15:40 [36632] [ INFO] [boudewijn] MAPIProvider->getEmailAddressFromSearchKey(): fall back to PR_SEARCH_KEY or PR_SENT_REPRESENTING_SEARCH_KEY to resolve user and get email address

with intermittent some other informational message

then again some 900 of:

09/02/2021 08:31:30 [36627] [ INFO] [boudewijn] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /usr/share/z-push/backend/sqlstatemachine/sqlstatemachine.php:197

followed by some 850 of:

09/02/2021 08:36:38 [36629] [ERROR] [boudewijn] HandleSync(): error saving '{adf52dd3-97b1-41f3-958c-ca97142d2da9}1' - no state information available

and these last 2 seem to repeat.

Some more answers to your questions:

there are no other errors in the z-push logfile
no errors in the webserver
not sure how long the requests take, you can see the progress from the timestamps above
the store size is a little over 4G

Please let me know if any other info is required, I would be happy to send you the logfile but I don’t want to share it here because it contains some not-found email addresses.

Manfred

Hi @boudewijn,

if you have a valid Kopano subscription, you may open a ticket with the support and attach the log files to the ticket.

What is the store size of the user?

At INFO loglevel there’s a line at the end of the request like:

09/02/2021 08:01:05 [67530] [ INFO] [boudewijn] cmd='' memory='1.47 MiB/2.00 MiB' time='0.05s' devType='' devId='' getUser='boudewijn' from='192.168.0.1' idle='0s' version='2.6.2+0-0' method='OPTIONS' httpcode='200'

“time” value is how long the request took.

Manfred

Hi @manfred,

I don’t have a support subscription so that won’t help.
All that was left was to start from scratch so I purged any z-push package from my server and installed z-push again.
And to my big surprise Outlook started to sync without any state errors and completed the full sync after some time.
So, cause unknown but issue resolved.

Thanks for your support!

Best regards,
Boudewijn