Upgrade to z-push 2.3.7 logging lots of no changes received from Exporter

Galen

Hi Manfred,

There are two additional folders defined in config.php.
DEBUG gives this in z-push.log for one user

07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 2
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] ZPush::GetAdditionalSyncFolders(): Requested AS folderids as keys for additional folders array, converting
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '019026a9ffa5497a8db81d23c9a23ee0b40d00000000'. Returning as is!
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '019026a9ffa5497a8db81d23c9a23ee075d00f000000'. Returning as is!
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] ChangesMemoryWrapper->Config(AdditionalFolders) : process folder 'CAL'
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] KopanoBackend->Setup(): Checking for 'read' ACLs on '019026a9ffa5497a8db81d23c9a23ee0b40d00000000' of store 'SYSTEM': 'true'
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'CAL' will not be sent as modification is not relevant.
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] ChangesMemoryWrapper->Config(AdditionalFolders) : process folder 'UAMB'
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] KopanoBackend->Setup(): Checking for 'read' ACLs on '019026a9ffa5497a8db81d23c9a23ee075d00f000000' of store 'SYSTEM': 'true'
07/08/2017 20:16:44 [ 8793] [DEBUG] [USERBM] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'UAMB' will not be sent as modification is not relevant.
07/08/2017 20:16:44 [ 8793] [WARN] [USERBM] SyncCollections->countHierarchyChange(): no changes received from Exporter.

With this line in z-push-error.log

07/08/2017 20:16:44 [ 8793] [WARN] [USERBM] SyncCollections->countHierarchyChange(): no changes received from Exporter.

I’ve noticed there are some FATALs in the error log that are new with 2.3.7 too

07/08/2017 19:59:24 [ 8142] [FATAL] [USERNC] WBXML 10K debug data: 
07/08/2017 19:59:24 [ 8142] [FATAL] [USERNC] Exception: (StateInvalidException) - Unexpected synckey value oldcounter: '1140' synckey: '{d6d6bc48-9fed-4058-96f9-e7efa20ab72a}1141' internal key: '{d6d6bc48-9fed-4058-96f9-e7efa20ab72a}70'

G

externa1

@Galen
Hi Galen

Did you follow the recommendet upgrade procedure for upgrading 2.2.x to 2.3.x ? as outlined here:

https://wiki.z-hub.io/display/ZP/Upgrade+to+Z-Push+2.3#UpgradetoZ-Push2.3-UpgradefromZ-Push2.2.x

rg
Christian

Manfred

Hi Galen,

are “CAL” and “UAMB” those additional folders?

Could you also post the output of z-push-admin -a list -u USERBM ?

Have you resynced the devices after the update to Z-Push 2.3.7?

Manfred

Galen

I did fixstates and have performed a resync on some but not all users after the upgrade. I had done the resync for this particular user, but i have wiped the phone and created a new Outlook profile again earlier this evening. I removed the z-push state information on the server also.

This is the result of z-push-admin -a list -u USERBM after letting Outlook complete its synchronisation.

Synchronized devices of user: USERBM
-----------------------------------------------------
DeviceId:		694d47379092581b025d99e4cdbf2430
Device type:		WP
UserAgent:		MSFT-WP/8.10.15148
Device Model:		RM-1038_1030
Device IMEI:		REDACTED
Device friendly name:	Lumia 735
Device OS:		Windows Phone 8.10.15148
Device OS Language:	English
ActiveSync version:	14
First sync:		2017-08-08 18:35
Last sync:		2017-08-09 00:45
Total folders:		19
Short folder Ids:	Yes
Synchronized folders:	9
Synchronized data:	Calendars(2) Emails(5) Contacts Tasks 
Additional Folders:	2
	Configured Calendar SYSTEM         CAL                  Inactive (not yet synchronized or no permissions) 
	Configured Email    SYSTEM         UAMB                 Inactive (not yet synchronized or no permissions) 
Status:			OK
WipeRequest on:		not set
WipeRequest by:		not set
Wiped on:		not set
Policy name:		default
Attention needed:	1 messages need attention because they could not be synchronized
	Broken object:	'SyncMail' ignored on '2017-08-09 00:06'
	Information:	Subject: 'REDACTED <groups-noreply@linkedin.com>'
	Reason: 	Message was causing loop (2)
	Item/Parent id: Cb637c:019026a9ffa5497a8db81d23c9a23ee0a7d53a000000/Cb637c


-----------------------------------------------------
DeviceId:		62e510d85ca44b1d804bfa6d1f27521b
Device type:		WindowsOutlook
UserAgent:		Outlook/15.0 (15.0.4945.1000; C2R; x86)
ActiveSync version:	14.0
First sync:		2017-08-08 20:19
Last sync:		2017-08-08 23:12
Total folders:		19
Short folder Ids:	Yes
Synchronized folders:	15
Synchronized data:	Calendars(2) Emails(11) Contacts Tasks 
Additional Folders:	2
	Configured Calendar SYSTEM         CAL                  Inactive (not yet synchronized or no permissions) 
	Configured Email    SYSTEM         UAMB                 Inactive (not yet synchronized or no permissions) 
Status:			Not available
WipeRequest on:		not set
WipeRequest by:		not set
Wiped on:		not set
Policy name:		default
Attention needed:	No errors known

Although the additional folders are showing as inactive Outlook has the folder data and the messages and events can be viewed.

z-push-admin -a list -u USERBM is logging this in z-push-error.log

08/08/2017 23:23:24 [18960] [WARN] [unknown] /usr/share/z-push/z-push-admin.php:825 Undefined variable: name (8)

The CAL shared folder has externally generated events imported into it via curl .
This folder has generated Undefined offset: 1713045762 (8) warnings for a long time. When i asked about the warnings on the Zarafa forum Sebastian said the cause was PR_MAILBOX_OWNER_ENTRYID is not defined for the public folder. The Undefined variable name (8) might be related to this?

No further “SyncCollections->countHierarchyChange(): no changes received from Exporter.” have been logged since the resync of Outlook and the phone.

I wiped and resyced the phone that was causing the FATALs again to see if it has any effect.

I’ve saved the email that gave reason 2 if it’s of interest.

G

Manfred

Hi Galen,

@Galen said in Upgrade to z-push 2.3.7 logging lots of no changes received from Exporter:

z-push-admin -a list -u USERBM is logging this in z-push-error.log
08/08/2017 23:23:24 [18960] [WARN] [unknown] /usr/share/z-push/z-push-admin.php:825 Undefined variable: name (8)

That’s a new bug. I created a JIRA issue for it: https://jira.z-hub.io/browse/ZP-1268.

@Galen said in Upgrade to z-push 2.3.7 logging lots of no changes received from Exporter:

The CAL shared folder has externally generated events imported into it via curl .
This folder has generated Undefined offset: 1713045762 (8) warnings for a long time. When i asked about the warnings on the Zarafa forum Sebastian said the cause was PR_MAILBOX_OWNER_ENTRYID is not defined for the public folder. The Undefined variable name (8) might be related to this?

Yes, a public folder doesn’t have this property and as these events don’t come from Kopano directly I suppose they lack some properties which an appointment is expected to have in Kopano realm.

Manfred

Galen

@Manfred said in Upgrade to z-push 2.3.7 logging lots of no changes received from Exporter:

Yes, a public folder doesn’t have this property and as these events don’t come from Kopano directly I suppose they lack some properties which an appointment is expected to have in Kopano realm.

Could you skip those checks for public folders to keep the logs cleaner?

BTW i’ve noticed another oddity whilst resyncing another user.
Checking on the progress with z-push-admin -a list -u username i’m seeing Folder: unknown for the folders still syncing.

Synchronized data:	Calendars(2) Emails(8) Contacts Tasks 
Synchronization progress:
	Folder: unknown              Sync: Initialized   Status:  0% (0/414)
	Folder: unknown              Sync: Initialized   Status:  0% (0/2)
	Folder: unknown              Sync: Synchronizing Status:  6% (39/632)
	Folder: unknown              Sync: Synchronizing Status: 32% (85/262)
	Folder: unknown              Sync: Initialized   Status:  0% (0/6)
	Folder: unknown              Sync: Initialized   Status:  0% (0/36)
	Folder: unknown              Sync: Initialized   Status:  0% (0/11)
	Folder: unknown              Sync: Initialized   Status:  0% (0/14)
	Folder: unknown              Sync: Initialized   Status:  0% (0/2)

Didn’t this used to show the folder type?

G

Manfred

Hi Galen,

@Galen said in Upgrade to z-push 2.3.7 logging lots of no changes received from Exporter:

@Manfred said in Upgrade to z-push 2.3.7 logging lots of no changes received from Exporter:

Yes, a public folder doesn’t have this property and as these events don’t come from Kopano directly I suppose they lack some properties which an appointment is expected to have in Kopano realm.

Could you skip those checks for public folders to keep the logs cleaner?

It’s not a check, but a property Z-Push expects an appointment to have. We could check if an appointment has it, but if it wouldn’t, we’d still output a warning in log, so it would still be the same.

BTW i’ve noticed another oddity whilst resyncing another user.
Checking on the progress with z-push-admin -a list -u username i’m seeing Folder: unknown for the folders still syncing.

That’s a known issue: https://jira.z-hub.io/browse/ZP-1262

Manfred

Galen

The FATALs that i received from the previous user still haven;t returned but another user has started to generate them. This particular user doesn’t have a mobile connection just a single outlook 2013 client.

15/08/2017 16:20:37 [13643] [ERROR] [USERMF] WBXMLDecoder->getElementEndTag(): could not read end tag in '/usr/share/z-push/lib/request/sync.php:492'. Please enable the LOGLEVEL_WBXML and send the log to the Z-Push dev team.
15/08/2017 16:20:37 [13643] [FATAL] [USERMF] WBXMLException: Unknown error in Sync->Handle() - code: 0 - file: /usr/share/z-push/lib/request/requestprocessor.php:113
15/08/2017 16:20:37 [13643] [FATAL] [USERMF] WBXML 10K debug data: DATA REDACTED
15/08/2017 16:20:37 [13643] [FATAL] [USERMF] Exception: (WBXMLException) - Unknown error in Sync->Handle()
15/08/2017 16:20:37 [13643] [FATAL] [USERMF] Request could not be processed correctly due to a WBXMLException. Please report this including the 'WBXML debug data' logged. Be aware that the debug data could contain confidential information.

I’ll grab some extra logging for this user.

G

Galen

If i’m reading the log file right the problem appears to be with

Folder name:	Suggested Contacts
Folder ID:	019026a9ffa5497a8db81d23c9a23ee0c6f40d000000
Type:		SYNC_FOLDER_TYPE_USER_CONTACT

I’ve removed the state data from the server and resynced again and the FATALs are gone.

This user was wiped and resynced 4 days ago and was showing “Short folder Ids: Yes”. Why would the user need resyncing again so soon?

G

Sebastian

@galen The redacted data is exactly what we would need to look at why the wbxml decoding failed. Could you send this? Perhaps over a private channel or in a support ticket.

Galen

@Sebastian

Just emailed a session from the log to feedback@ for you.

G

Galen

I haven’t followed this up because vacation took over :)

@Sebastian did you get the session log i sent over for you and did it give any insight?

G