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.019/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.
-
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 : 693350827-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