6.0.0-git
2019-04-23

[#13351] Activesync Error 500: FOLDERUPDATE Unmatched end tag FolderHierarchy:ParentId
Summary Activesync Error 500: FOLDERUPDATE Unmatched end tag FolderHierarchy:ParentId
Queue Horde Framework Packages
Queue Version Git master
Type Bug
State Resolved
Priority 1. Low
Owners mrubinsk (at) horde (dot) org
Requester software-horde (at) interfasys (dot) ch
Created 2014-07-11 (1747 days ago)
Due
Updated 2014-07-14 (1744 days ago)
Assigned 2014-07-11 (1747 days ago)
Resolved 2014-07-14 (1744 days ago)
Milestone
Patch No

History
2014-07-14 03:26:06 Michael Rubinsky State ⇒ Resolved
 
2014-07-14 00:28:12 software-horde (at) interfasys (dot) ch Comment #16 Reply to this comment
I got there in the end. I think the fact that the message wasn't 
rejected mid-way any more helped clear things on the device and after 
a few de/re-installation cycles, the account seems stable.

One thing that might have made things worse is this problem (#13359) 
where folders created on the device are removed as soon as they're 
created in Horde.
2014-07-12 23:11:03 software-horde (at) interfasys (dot) ch Comment #15 Reply to this comment
Can you try what I just committed?
OK, I just did and now Horde ignores the bad entry but ends up 
throwing the error described in #13338

I did some more testing and as soon as push is enabled, even if the 
only thing that is allowed to sync is email, I get these ghost folders 
from a previous sync which appear on the device. Some I can delete, 
which throws a new error #13358 and some I can't because of the policy 
you've described in #13357.

Since the device doesn't care about having a bad synckey, the only way 
I found to get around #13338 was to recreate the account, which in 
this case doesn't work, so I don't think I'll be able to get out of 
this one without wiping the device O_o

2014-07-12 15:25:28 Michael Rubinsky Comment #14 Reply to this comment
Can you try what I just committed?
2014-07-12 15:24:39 Git Commit Comment #13 Reply to this comment
Changes have been made in Git (master):

commit f61a0d4311bbb371c9fdb46bb0b89203ffce448b
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Sat Jul 12 11:24:01 2014 -0400

     Bug: 13351  Attempt to work around broken BB clients that cause 
WBXML parsing errors.

  .../lib/Horde/ActiveSync/Request/FolderCreate.php  |    6 ++++--
  1 files changed, 4 insertions(+), 2 deletions(-)

http://github.com/horde/horde/commit/f61a0d4311bbb371c9fdb46bb0b89203ffce448b
2014-07-12 15:17:47 Michael Rubinsky Comment #12 Reply to this comment
What i CAN do, though, is sniff out the empty tag and allow the 
parsing to continue and see if throwing a different error (a missing 
synckey) will help the device know to reset....
2014-07-12 15:16:30 Michael Rubinsky Comment #11 Reply to this comment
It seems it's not the first time a BlackBerry device has misbehaved
https://github.com/horde/horde/commit/dd1f7c37bf6ee94c6fa13d66d56e703f8dd93021
And yes, BB is sending a broken tag in that commit too, but it can be 
worked around since the tag in the SYNC request is optional (it's not 
even supposed to be sent in certain versions of EAS). The data that it 
normally contains is obtainable from other sources in a SYNC request.

In a FOLDERUPDATE request, all we know is the name of the folder - the 
tag that is missing in your case, so it's impossible to work it out 
from any other means.
2014-07-12 15:15:47 software-horde (at) interfasys (dot) ch Comment #10 Reply to this comment
Essentially, BB isn't expiring it's internal cache properly and 
continues to issue the request even though the account is no longer 
active.
That's what I was afraid of... I don't know yet how to solve this 
(short of a full wipe) but will try to reboot to see if it helps.
2014-07-12 15:12:52 Michael Rubinsky Comment #9 Reply to this comment
It seems it's not the first time a BlackBerry device has misbehaved
https://github.com/horde/horde/commit/dd1f7c37bf6ee94c6fa13d66d56e703f8dd93021

but I think the problem here has more to do with the fact that the 
client is using a non-existent sync_key to try and perform an update.
I don't know anything about the protocol, but it seems strange that 
Horde is trying to honour a folderupdate request when it doesn't 
have a sync relationship with the device first.
Horde doesn't know anything until it parses the incoming request. It' 
can't parse the incoming request because it is invalid WBXML and 
cannot understand it. Even if it DID know that the synckey was expired 
or removed, the error would still be the same because the entire WBXML 
request must be parsed before a response can be sent. Since the 
parsing would fail, the response would be the same.

Essentially, BB isn't expiring it's internal cache properly and 
continues to issue the request even though the account is no longer 
active.
2014-07-12 14:44:46 software-horde (at) interfasys (dot) ch Comment #8 Reply to this comment
It seems it's not the first time a BlackBerry device has misbehaved
https://github.com/horde/horde/commit/dd1f7c37bf6ee94c6fa13d66d56e703f8dd93021

but I think the problem here has more to do with the fact that the 
client is using a non-existent sync_key to try and perform an update.
I don't know anything about the protocol, but it seems strange that 
Horde is trying to honour a folderupdate request when it doesn't have 
a sync relationship with the device first.
2014-07-12 14:18:58 software-horde (at) interfasys (dot) ch Comment #7 Reply to this comment
The account, on the same device was fine on 5.1.
The only thing I can think of is that it has something to do with 
the multiple account support, since that is the only thing of 
consequence to this bug that has changed. I would need to see the 
entire sync log, or at least the part of it where the folder 
hierarchy is FIRST sent to the client to determine if there is 
anything I can do from Horde's end.
I've re-created the 2 accounts I'm having problems with on a new 
device and no problem there. I can make all the changes to notes and 
tasks that I want and the FOLDERUPDATE message is built properly.

I think that on the first device, there is a ghost folder with no 
parent. I was hoping for Horde to be able to identify the issue and 
re-sync from scratch, but it doesn't seem to be happening. The device 
keeps wanting to send that broken folder.

2014-07-11 20:39:40 Michael Rubinsky Comment #6
Assigned to Michael Rubinsky
State ⇒ Feedback
Reply to this comment
The account, on the same device was fine on 5.1.
The only thing I can think of is that it has something to do with the 
multiple account support, since that is the only thing of consequence 
to this bug that has changed. I would need to see the entire sync log, 
or at least the part of it where the folder hierarchy is FIRST sent to 
the client to determine if there is anything I can do from Horde's end.
2014-07-11 19:14:10 software-horde (at) interfasys (dot) ch Comment #5 Reply to this comment
es, by sending a HTTP 500 response, which is what we do.
In this case, I even recreated the account on the device, but soon
after the initial sync, the problem was back. I have no idea what is
causing it.
I told you what is causing it, your client is sending broken wbxml.
The same client is synchronising 6 other accounts, so not everything 
is broken. There must be one folder, message, note, event or task 
which is triggering the sync message to be broken.
The account, on the same device was fine on 5.1.
I see 3 simlar sync keys in the state table which contain the synckey
indicated in the logs, each with the sync_folderid set to foldersync.
Can I just remove them and get the device to resync folders?
That's what removing the state from the UI does.
I did and the same error comes up even though the 
horde_activesync_state table doesn't contain the sync key any more. 
The account shows up as being provisioned.

Maybe this is related to the sync_key problem in #13338
2014-07-11 18:51:47 Michael Rubinsky Comment #4 Reply to this comment
Well, the problem is that it completely blocks the synchronisation 
of everything else for that account, so the user will stop getting 
emails because of a problem in Notes per example.
Isn't there a way to let the device know that there is a problem?
Yes, by sending a HTTP 500 response, which is what we do.
In this case, I even recreated the account on the device, but soon 
after the initial sync, the problem was back. I have no idea what is 
causing it.
I told you what is causing it, your client is sending broken wbxml.
I see 3 simlar sync keys in the state table which contain the 
synckey indicated in the logs, each with the sync_folderid set to 
foldersync.
Can I just remove them and get the device to resync folders?
That's what removing the state from the UI does.
2014-07-11 18:42:02 software-horde (at) interfasys (dot) ch Comment #3 Reply to this comment

[Show Quoted Text - 14 lines]
Well, the problem is that it completely blocks the synchronisation of 
everything else for that account, so the user will stop getting emails 
because of a problem in Notes per example.
Isn't there a way to let the device know that there is a problem?

In this case, I even recreated the account on the device, but soon 
after the initial sync, the problem was back. I have no idea what is 
causing it.

I see 3 simlar sync keys in the state table which contain the synckey 
indicated in the logs, each with the sync_folderid set to foldersync.
Can I just remove them and get the device to resync folders?
2014-07-11 14:29:19 Michael Rubinsky Comment #2
State ⇒ Not A Bug
Reply to this comment

[Show Quoted Text - 9 lines]
^^^ Your client is sending an empty SERVERENTRYID tag. This is a 
violation of the protocol. This is a REQUIRED value, and it makes 
sense. A FOLDERUPDATE command makes absolutely no sense if the client 
isn't telling the server WHICH folder we are updating.
2014-07-11 09:48:37 software-horde (at) interfasys (dot) ch Comment #1
Type ⇒ Bug
State ⇒ Unconfirmed
Priority ⇒ 1. Low
Summary ⇒ Activesync Error 500: FOLDERUPDATE Unmatched end tag FolderHierarchy:ParentId
Queue ⇒ Horde Framework Packages
Milestone ⇒
Patch ⇒ No
Reply to this comment
This account has not been able to sync with Horde after the 5.2 upgrade.
I did create a new tasks folder on the device and moved tasks around.
I haven't tried to re-create the account on the device yet.

Here is the log:
2014-07-11T11:27:36+02:00 ERR: HORDE Buffer contents:  [pid 31538 on 
line 162 of "/usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php"]
2014-07-11T11:27:43+02:00 ERR: HORDE Returning HTTP 500 while handling 
FolderUpdate command. [pid 31538 on line 159 of 
"/var/www/html/webmail/rpc.php"]
2014-07-11T11:27:43+02:00 ERR: HORDE Error in communicating with 
ActiveSync server: Protocol Error [pid 31538 on line 162 of 
"/usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php"]
2014-07-11T11:27:43+02:00 ERR: HORDE #0 
/usr/local/php54/lib/php/Horde/ActiveSync/Request/Base.php(253): 
Horde_ActiveSync_Request_FolderCreate->_handle()
#1 /usr/local/php54/lib/php/Horde/ActiveSync.php(880): 
Horde_ActiveSync_Request_Base->handle()
#2 /usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php(143): 
Horde_ActiveSync->handleRequest('FolderUpdate', 'BB1234ABCD')
#3 /var/www/html/webmail/rpc.php(159): Horde_Rpc_ActiveSync->getResponse(NULL)
#4 {main} [pid 31538 on line 162 of 
"/usr/local/php54/lib/php/Horde/Rpc/ActiveSync.php"]



2014-07-11T11:27:42+02:00 INFO: [31538] 
Horde_Core_ActiveSync_Driver::authenticate() attempt for user@domain.tld
2014-07-11T11:27:43+02:00 INFO: [31538] FOLDERUPDATE request received 
for user user@domain.tld
2014-07-11T11:27:43+02:00 INFO: [31538] Device entry exists for 
BB1234ABCD, updating userAgent and version.
2014-07-11T11:27:43+02:00 INFO: [31538] Request being handled for 
device: BB1234ABCD, Supporting protocol version: 14.1, Using 
Horde_ActiveSync v2.16.10
2014-07-11T11:27:43+02:00 INFO: [31538] GET VARIABLES: Array
(
     [Cmd] => FolderUpdate
     [DeviceType] => BlackBerry
     [User] => user@domain.tld
     [DeviceId] => BB1234ABCD
)

2014-07-11T11:27:43+02:00 INFO: [BB1234ABCD] Handling 
FOLDER[CREATE|DELETE|CHANGE] command.
2014-07-11T11:27:43+02:00 DEBUG: [31538] I  <FolderHierarchy:FolderUpdate>
2014-07-11T11:27:43+02:00 DEBUG: [31538] I   <FolderHierarchy:SyncKey>
2014-07-11T11:27:43+02:00 DEBUG: [31538] I     
{5394b0ef-ba80-4f73-9261-945f904cae96}2
2014-07-11T11:27:43+02:00 DEBUG: [31538] I   </FolderHierarchy:SyncKey>
2014-07-11T11:27:43+02:00 DEBUG: [31538] I   <FolderHierarchy:ServerEntryId />
2014-07-11T11:27:43+02:00 DEBUG: [31538] I   <FolderHierarchy:ParentId>
2014-07-11T11:27:43+02:00 ERR: [31538] Unmatched end tag:
2014-07-11T11:27:43+02:00 ERR: Array
(
     [1] => 1
     [2] => FolderHierarchy:ParentId
     [4] => 1
)

2014-07-11T11:27:43+02:00 ERR: Protocol Error
2014-07-11T11:27:43+02:00 INFO: [31333] SyncCache collections refreshed.


Saved Queries