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


  • Kopano

    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



  • 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


  • Kopano

    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



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


  • Kopano

    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



  • 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



  • 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


  • Kopano

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



  • @Sebastian

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

    G



  • 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


Log in to reply
 

Looks like your connection to Kopano Community Forum was lost, please wait while we try to reconnect.