Menu ▾ ▴

WBXML error with iOS and 2.2.9 and Zimbra backend

Open Discussion
Maxxer
2016-06-13
2016-06-13

  • Maxxer

    Maxxer - 2016-06-13

    Hi.
    An user reported me an issue with his iPhone6, Z-Push 2.2.9 and Zimbra backend, where he could not sync calendar items.
    I enabled WBXML log and found the followig:

    [...]   
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] Zimbra->Logon(): Primary Folders - Addressbook [f7] - Calendar [f10] - Task [] - Note []
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] Zimbra->Logon(): END Logon { connected = true; uid = stefano.rusconi - 89 Folders Loaded }
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] Zimbra->Setup(): START Setup { store = user@domain.it; checkACLonly = 1; folderid =  }
[...]
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] Zimbra->Setup(): [88] id=-1; devid=FakeOutbox; name=Outbox; parentid=0; view=message; include=1; virtual=0; primary=0; external=0; recursive=0; linkid=; owner=; search=; i4ms=; perm=; path=Outbox
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] Zimbra->Setup(): Checking ACLs for main user - Return TRUE.
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] Zimbra->Setup(): END Setup {TRUE} { 89 Folders in Store }
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] ZPush::CommandNeedsPlainInput(0): false
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] StringStreamWrapper::stream_open(): initialized stream length: 0
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] StringStreamWrapper::stream_open(): initialized stream length: 0
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I  <Synchronize>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I   <Folders>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I    <Folder>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <SyncKey>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      {2b907830-0779-478c-847a-eff2130be10b}1712
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     </SyncKey>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <FolderId>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      f10
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     </FolderId>
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] FileStateMachine->GetState() read '846' bytes from file: '/var/lib/z-push/4/9/b1ohkpl3l55dv2v7k2m71l7a94-2b907830-0779-478c-847a-eff2130be10b-fd'
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] SyncParameters->UseCPO('DEFAULT')
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] SyncCollections->AddCollection(): Folder id 'f10' : ref. PolicyKey '-1', ref. Lifetime '600', last sync at '1465462560'
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] SyncCollections->AddCollection(): Updated reference PolicyKey '-1', reference Lifetime '600', Last sync at '1465462560'
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <GetChanges/>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <WindowSize>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      25
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     </WindowSize>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <Options>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      <AirSyncBase:BodyPreference>
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] SyncParameters->UseCPO('DEFAULT')
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] SyncCollections->AddCollection(): Folder id 'f10' : ref. PolicyKey '-1', ref. Lifetime '600', last sync at '1465462560'
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] SyncCollections->AddCollection(): Updated reference PolicyKey '-1', reference Lifetime '600', Last sync at '1465462560'
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <GetChanges/>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <WindowSize>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      25   
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     </WindowSize>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <Options>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      <AirSyncBase:BodyPreference>
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] SyncParameters->UseCPO('DEFAULT')
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I       <AirSyncBase:Type>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        1
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I       </AirSyncBase:Type>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I       <AirSyncBase:TruncationSize>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        32768
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I       </AirSyncBase:TruncationSize>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      </AirSyncBase:BodyPreference>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     </Options>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     <Perform>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      <Add>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I       <ClientEntryId>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        3243
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I       </ClientEntryId>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I       <Data>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <AirSyncBase:Body>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         <AirSyncBase:Type>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I          1
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         </AirSyncBase:Type>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         <AirSyncBase:Data/>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </AirSyncBase:Body>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:Timezone>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         xP///wAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAMAAAAFAAIAAAAAAAAAxP///w==
09/06/2016 11:09:25 [16352] [ERROR] [user@domain.it] WBXMLDecoder->getElementEndTag(): could not read end tag in '/dati/www-ssl/z-push-2.2.9/lib/request/sync.php:436'. Please enable the LOGLEVEL_WBXML and send the log to the Z-Push dev team. 
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:Timezone>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:AllDayEvent>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         0
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:AllDayEvent>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:BusyStatus>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         2
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:BusyStatus>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:DtStamp>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         20160609T085702Z
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:DtStamp>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:EndTime>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         20160610T130000Z
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:EndTime>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:Reminder>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         30
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:Reminder>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:Sensitivity>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         0
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:Sensitivity>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:Subject>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         Incontro schock
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:Subject>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:StartTime>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         20160610T120000Z
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:StartTime>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:UID>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         A5941B38309C459C9830FCCEE359FC990
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:UID>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        <POOMCAL:MeetingStatus>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I         0
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I        </POOMCAL:MeetingStatus>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I       </Data>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I      </Add>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I     </Perform>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I    </Folder>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I   </Folders>
09/06/2016 11:09:25 [16352] [WBXML] [user@domain.it] I  </Synchronize>
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] WBXMLDecoder->readRemainingData() reading remaining data from input stream
09/06/2016 11:09:25 [16352] [FATAL] [user@domain.it] WBXMLException: Debug data: AwFqAEVcT0sDezJiOTA3ODMwLTA3NzktNDc4Yy04NDdhLWVmZjIxMzBiZTEwYn0xNzEyAAFSA2YxMAABE1UDMjUAAVcAEUVGAzEAAUcDMzI3NjgAAQEBAABWR0wDMzI0MwABXQARSkYDMQABCwEABEUDeFAvLy93QUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQW9BQUFBRkFBTUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFNQUFBQUZBQUlBQUFBQUFBQUF4UC8vL3c9PQABRgMwAAFNAzIAAVEDMjAxNjA2MDlUMDg1NzAyWgABUgMyMDE2MDYxMFQxMzAwMDBaAAFkAzMwAAFlAzAAAWYDSW5jb250cm8gc2Nob2NrAAFnAzIwMTYwNjEwVDEyMDAwMFoAAWgDQTU5NDFCMzgzMDlDNDU5Qzk4MzBGQ0NFRTM1OUZDOTkwAAFYAzAAAQEBAQEBAQ== - code: 0 - file: /dati/www-ssl/z-push-2.2.9/lib/request/requestprocessor.php:137
09/06/2016 11:09:25 [16352] [ INFO] [user@domain.it] User-agent: 'Apple-iPhone7C2/1306.69'
09/06/2016 11:09:25 [16352] [FATAL] [user@domain.it] Request could not be processed correctly due to a WBXMLException. Please report this including WBXML debug data logged. Be aware that the debug data could contain confidential information.
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] Zimbra->BackendSearchZimbra(): BackendSearchZimbra Instantiated
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] LoopDetection->ProcessLoopDetectionTerminate()
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] Memory usage information: 60.31 MiB/61.00 MiB (63236456 B/63963136 B) - Execution time: 2,00s - HTTP responde code: 200
09/06/2016 11:09:25 [16352] [DEBUG] [user@domain.it] -------- End

    Is this an issue with the backend or with zpush itself?
    I know there's a newer version of zp, but from what I've seen there should be no improvement on this side.

    Please let me know if you need further information to debug the issue.

    Thanks

     

  • LiverpoolFCfan

    LiverpoolFCfan - 2016-06-13

    If it is failing in WBXML decoding this is z-push before it hands off to the backend.

    There is a release 2.2.10, and 2.2.11beta1 has also been released. You could try one of those - or otherwise open a ticket on the z-push "Other backends" forum. https://forums.zarafa.com/forumdisplay.php?72-Z-Push-when-using-other-backends

     

  • Maxxer

    Maxxer - 2016-06-13

    I upgraded to 2.2.10 and apparently it's working... /me been stupid, I could have upgraded before even if there was no reference to such errors. It's always worth trying the latest version.

    Thanks for the feedback

     

Log in to post a comment.