2.5.1.beta1+11 - WBXML Decoder - unhandled TAG - ResolveRecipients:MaxPictures


  • Hi guys.

    I just became aware of an error in my logs while testing a backend fix. Running z-push 2.5.1.beta1+11

    I have a new laptop that doesn’t have any of the JIRA stuff on it, otherwise I would try to figure it out myself. How do I trigger a call to ResolveRecipients? It’s been a long time since I looked at that part of the code.

    I can see that you have a resolverecipientspictures object in syncobjects that is defined for AS >= 14.1

    The zimbra backend reports as AS14

    19/08/2019 23:08:35 [ 2647] [DEBUG] cmd=‘Sync’ devType=‘SamsungDevice’ devId=‘sec1dc3…a381’ getUser=‘myUser’ from=‘81…208’ version=‘2.5.1.beta1+11’ method=‘POST’
    19/08/2019 23:08:35 [ 2647] [DEBUG] Used timezone ‘Europe/Dublin’
    19/08/2019 23:08:35 [ 2647] [DEBUG] Including backend file: ‘/usr/share/z-push/backend/zimbra/zimbra.php’
    19/08/2019 23:08:35 [ 2647] [DEBUG] Request::ProcessHeaders() ASVersion: 14.0

    19/08/2019 23:08:34 [28146] [WBXML] I  <ResolveRecipients:ResolveRecipients>
    19/08/2019 23:08:34 [28146] [WBXML] I   <ResolveRecipients:To>
    19/08/2019 23:08:34 [28146] [WBXML] I   myUser
    19/08/2019 23:08:34 [28146] [WBXML] I   </ResolveRecipients:To>
    19/08/2019 23:08:34 [28146] [WBXML] I   <ResolveRecipients:Options>
    19/08/2019 23:08:34 [28146] [WBXML] I    <ResolveRecipients:Picture>
    19/08/2019 23:08:34 [28146] [WBXML] I     <ResolveRecipients:MaxPictures>
    19/08/2019 23:08:34 [28146] [WBXML] I      1
    19/08/2019 23:08:34 [28146] [ERROR] WBXMLDecoder->getElementEndTag(): could not read end tag in '/usr/share/z-push/lib/request/resolverecipients.php:44'. Please enable the LOGLEVEL_WBXML and send the log to the Z-Push dev team.
    19/08/2019 23:08:34 [28146] [WBXML] I     </ResolveRecipients:MaxPictures>
    19/08/2019 23:08:34 [28146] [WBXML] I    </ResolveRecipients:Picture>
    19/08/2019 23:08:34 [28146] [WBXML] I   </ResolveRecipients:Options>
    19/08/2019 23:08:34 [28146] [WBXML] I  </ResolveRecipients:ResolveRecipients>
    19/08/2019 23:08:34 [28146] [FATAL] WBXMLException: Unknown error in ResolveRecipients->Handle() - code: 0 - file: /usr/share/z-push/lib/request/requestprocessor.php:117
    19/08/2019 23:08:34 [28146] [FATAL] WBXML 10K debug data: REMOVED=
    19/08/2019 23:08:34 [28146] [ INFO] User-agent: 'Android-SAMSUNG-SM-G950F/101.9'
    19/08/2019 23:08:34 [28146] [FATAL] Exception: (WBXMLException) - Unknown error in ResolveRecipients->Handle()
    

    I only see it logged for Samsung devices so, perhaps this is a Samsung bug making an unsupported request but, regardless, it is causing lots of [FATAL] errors.

  • Kopano

    Hi liverpoolfcfan,

    it’s possible to trigger ResolveRecipients by creating a new meeting and then checking the attendees’ free-busy times or by composing an encrypted email.

    I’m not sure right now if ResolveRecipients are called when you start typing something in “to” or “cc” fields when composing a new email and wait for the results from the server. That might be device-specific thing.

    Manfred


  • Hi @Manfred

    Weirdly, the instances I have found seem to be mostly unrelated to meeting requests. They almost all seem to be sandwiched between the end of a ping cycle, and the Start of a sync. In each case the resolve recipients request is passing over the email address of the user themselves.

    Vincent


  • I have several error “Exception: (WBXMLException) - Unknown error in ResolveRecipients->Handle()”

    Zimbra Version : Release 8.8.15.GA.3869.UBUNTU18.64 UBUNTU18_64 FOSS edition, Patch 8.8.15_P11.
    Z-push version : 2.5.2+0-0
    zimbrabackend version : 69

    3350827-21/07/2020 13:25:31 [ 4127] [DEBUG] -------- Start
    3350878-21/07/2020 13:25:31 [ 4127] [DEBUG] cmd='Ping' devType='SamsungDevice' devId='sec18a1a7dxxxxx' getUser='xxxx@yyyyy.com' from='xx.xx.xx.xx.xx' version='2.5.2+0-0' method='POST'
    3351059-21/07/2020 13:25:31 [ 4127] [DEBUG] Used timezone 'Europe/Berlin'
    3351125-21/07/2020 13:25:31 [ 4127] [DEBUG] Including backend file: '/usr/share/z-push/backend/zimbra/zimbra.php'
    3351231-21/07/2020 13:25:31 [ 4127] [DEBUG] Request::ProcessHeaders() ASVersion: 14.0
    3351309-21/07/2020 13:25:31 [ 4127] [DEBUG] ZPush::CommandNeedsProvisioning(18): false
    --
    3369172-21/07/2020 13:25:51 [ 4126] [WBXML] I    <ResolveRecipients:Picture>
    3369241-21/07/2020 13:25:51 [ 4126] [WBXML] I     <ResolveRecipients:MaxPictures>
    3369315-21/07/2020 13:25:51 [ 4126] [WBXMLSTACK] Tag 'ResolveRecipients:MaxPictures' unexpected in type XML type 'SyncResolveRecipientsPicture'
    3369451-21/07/2020 13:25:51 [ 4126] [WBXML] I      1
    3369496-21/07/2020 13:25:51 [ 4126] [WBXMLSTACK] WBXMLDecoder->getElementEndTag(): unmatched WBXML tag: '' type '3' flags ''
    3369613-21/07/2020 13:25:51 [ 4126] [ERROR] WBXMLDecoder->getElementEndTag(): could not read end tag in '/usr/share/z-push/lib/request/resolverecipients.php:44'. Please enable the LOGLEVEL_WBXML and send the log to the Z-Push dev team.
    3369841-21/07/2020 13:25:51 [ 4126] [WBXML] I     </ResolveRecipients:MaxPictures>
    3369916-21/07/2020 13:25:51 [ 4126] [WBXML] I    </ResolveRecipients:Picture>
    3369986-21/07/2020 13:25:51 [ 4126] [WBXML] I   </ResolveRecipients:Options>
    3370055-21/07/2020 13:25:51 [ 4126] [WBXML] I  </ResolveRecipients:ResolveRecipients>
    3370133:21/07/2020 13:25:51 [ 4126] [FATAL] WBXMLException: Unknown error in ResolveRecipients->Handle() - code: 0 - file: /usr/share/z-push/lib/request/requestprocessor.php:117
    3370303:21/07/2020 13:25:51 [ 4126] [FATAL] WBXML 10K debug data: AwFqAAAKRVADZG9zeWxAYm91cmRldHRlLmNvbQABT1pdAzEAAQEBAQ==
    3370418-21/07/2020 13:25:51 [ 4126] [ INFO] User-agent: 'Android-SAMSUNG-SM-A600FN/101.10'
    3370501:21/07/2020 13:25:51 [ 4126] [FATAL] Exception: (WBXMLException) - Unknown error in ResolveRecipients->Handle()
    3370612:21/07/2020 13:25:51 [ 4126] [FATAL] 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.
    3370843-21/07/2020 13:25:51 [ 4126] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate()
    3370926-21/07/2020 13:25:51 [ 4126] [ INFO] cmd='ResolveRecipients' memory='2.08 MiB/2.00 MiB' time='0.06s' devType='SamsungDevice' devId='sec18a1a7dbxxxxx' getUser='xxxxx@xxxxx.com' from='xx.xx.xx.xx' idle='0s' version='2.5.2+0-0' method='POST' httpcode='500'
    3371185-21/07/2020 13:25:51 [ 4126] [DEBUG] -------- End
    

  • It looks to be the exact same issue I reported - except your debug level is higher than mine