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 | 07/11/2014 (4093 days ago) |
Due | |
Updated | 07/14/2014 (4090 days ago) |
Assigned | 07/11/2014 (4093 days ago) |
Resolved | 07/14/2014 (4090 days ago) |
Github Issue Link | |
Github Pull Request | |
Milestone | |
Patch | No |
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.
throwing the error described in
#13338I 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
#13358and some I can't because of the policyyou've described in
#13357.Since the device doesn't care about having a bad synckey, the only way
I found to get around
#13338was to recreate the account, which inthis 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
commit f61a0d4311bbb371c9fdb46bb0b89203ffce448b
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date: Sat Jul 12 11:24:01 2014 -0400
Bug: 13351Attempt to work around broken BB clients that causeWBXML parsing errors.
.../lib/Horde/ActiveSync/Request/FolderCreate.php | 6 ++++--
1 files changed, 4 insertions(+), 2 deletions(-)
http://github.com/horde/horde/commit/f61a0d4311bbb371c9fdb46bb0b89203ffce448b
parsing to continue and see if throwing a different error (a missing
synckey) will help the device know to reset....
https://github.com/horde/horde/commit/dd1f7c37bf6ee94c6fa13d66d56e703f8dd93021
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.
continues to issue the request even though the account is no longer
active.
(short of a full wipe) but will try to reboot to see if it helps.
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.
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.
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.
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.
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.
State ⇒ Feedback
Assigned to Michael Rubinsky
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.
after the initial sync, the problem was back. I have no idea what is
causing it.
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.
indicated in the logs, each with the sync_folderid set to foldersync.
Can I just remove them and get the device to resync folders?
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
#13338of 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?
after the initial sync, the problem was back. I have no idea what is
causing it.
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?
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?
State ⇒ Not A Bug
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.
Priority ⇒ 1. Low
Type ⇒ Bug
Summary ⇒ Activesync Error 500: FOLDERUPDATE Unmatched end tag FolderHierarchy:ParentId
Queue ⇒ Horde Framework Packages
Milestone ⇒
Patch ⇒ No
State ⇒ Unconfirmed
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.