6.0.0-git
2019-04-24

[#13334] Activesync: error 500 while handling FolderUpdate
Summary Activesync: error 500 while handling FolderUpdate
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-08 (1751 days ago)
Due
Updated 2014-07-11 (1748 days ago)
Assigned 2014-07-10 (1749 days ago)
Resolved 2014-07-11 (1748 days ago)
Milestone
Patch No

History
2014-07-11 02:37:04 Michael Rubinsky Comment #12
State ⇒ Resolved
Reply to this comment
Silly, silly typo.

Fixed for Horde_Core 2.12.5
2014-07-11 02:36:02 Git Commit Comment #11 Reply to this comment
Changes have been made in Git (master):

commit 2c28ef420442261badd33b8613a213bfbdff2522
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Thu Jul 10 22:33:34 2014 -0400

     Bug: 13334 Fix broken CHANGEFOLDER functionality for NOTES collections.

  .../Core/lib/Horde/Core/ActiveSync/Connector.php   |    1 +
  1 files changed, 1 insertions(+), 0 deletions(-)

http://github.com/horde/horde/commit/2c28ef420442261badd33b8613a213bfbdff2522
2014-07-10 19:03:56 software-horde (at) interfasys (dot) ch Comment #10 Reply to this comment
I'll have to download the latest simulator and test.
I think I've identified the problem, looking at this different trace:

2014-07-10T20:48:43+02:00 ERR: HORDE Returning HTTP 500 while handling 
FolderUpdate command. [pid 52217 on line 159 of "/horde/rpc.php"]
2014-07-10T20:48:43+02:00 ERR: HORDE Error in communicating with 
ActiveSync server: Share name _siqWNjWBqAIyNNy2m8i not found [pid 
52217 on line 162 of "/php/Horde/Rpc/ActiveSync.php"]
2014-07-10T20:48:43+02:00 ERR: HORDE #0 
/php/Horde/Share/Base.php(199): 
Horde_Share_Sql->_getShare('_siqWNjWBqAIy...')
#1 [internal function]: Horde_Share_Base->getShare('_siqWNjWBqAIy...')
#2 /php/Horde/Core/Share/Driver.php(63): call_user_func_array(Array, Array)
#3 /horde/nag/lib/Api.php(131): 
Horde_Core_Share_Driver->__call('getShare', Array)
#4 /horde/nag/lib/Api.php(131): 
Horde_Core_Share_Driver->getShare('_siqWNjWBqAIy...')
#5 [internal function]: Nag_Api->getTasklist('_siqWNjWBqAIy...')
#6 /php/Horde/Registry.php(1136): call_user_func_array(Array, Array)
#7 /php/Horde/Registry.php(1093): Horde_Registry->callByPackage('nag', 
'getTasklist', Array)
#8 /php/Horde/Registry/Caller.php(41): 
Horde_Registry->call('tasks/getTaskli...', Array)
#9 /php/Horde/Core/ActiveSync/Connector.php(1219): 
Horde_Registry_Caller->__call('getTasklist', Array)
#10 /php/Horde/Core/ActiveSync/Connector.php(1219): 
Horde_Registry_Caller->getTasklist('_siqWNjWBqAIy...')
#11 /php/Horde/Core/ActiveSync/Driver.php(718): 
Horde_Core_ActiveSync_Connector->changeFolder('Notes', 
'_siqWNjWBqAIy...', 'Notes (o@of)')
#12 /php/Horde/ActiveSync/Connector/Importer.php(347): 
Horde_Core_ActiveSync_Driver->changeFolder('Notes:_IqHpMZrX...', 
'Notes (o@of)', '0', 'N65f21b18', false)
#13 /php/Horde/ActiveSync/Request/FolderCreate.php(149): 
Horde_ActiveSync_Connector_Importer->importFolderChange('N65f21b18', 
'Notes (o@of)', '0', false)
#14 /php/Horde/ActiveSync/Request/Base.php(253): 
Horde_ActiveSync_Request_FolderCreate->_handle()
#15 /php/Horde/ActiveSync.php(880): Horde_ActiveSync_Request_Base->handle()
#16 /php/Horde/Rpc/ActiveSync.php(143): 
Horde_ActiveSync->handleRequest('FolderUpdate', 'BB1234ABCD')
#17 /horde/rpc.php(159): Horde_Rpc_ActiveSync->getResponse(NULL)
#18 {main} [pid 52217 on line 162 of "/php/Horde/Rpc/ActiveSync.php"]

ActiveSync is looking for a Mnemo share using the Nag driver
The share only exists in mnemo_sharesng, not in nag_sharesng


2014-07-10 18:34:16 Michael Rubinsky Comment #9
Assigned to Michael Rubinsky
State ⇒ Assigned
Reply to this comment
I'll have to download the latest simulator and test.
2014-07-10 18:15:46 software-horde (at) interfasys (dot) ch Comment #8 Reply to this comment
Are we talking about Tasks, or Notes? You reference both.

Also, what client is this?
That's a BlackBerry 10 device with OS 10.2. I'm testing the support 
for multiple tasks and notes folder synchronisation.

The error I'm presently seeing is about a note share which is not 
found. We're using sharesng, but it shouldn't make a difference, since 
everything went fine in the initial sync.

The name of the share (share_name) starts with an underscore and is 
followed by an alphanumeric sequence, sorry for calling it _randomised.
_siqWNjWBqAIyNNy2m8i


2014-07-10 18:08:01 Michael Rubinsky State ⇒ Feedback
 
2014-07-10 18:07:30 Michael Rubinsky Comment #7 Reply to this comment

[Show Quoted Text - 10 lines]
Are we talking about Tasks, or Notes? You reference both.

Also, what client is this?

2014-07-10 18:05:27 Michael Rubinsky Comment #6 Reply to this comment
2014-07-10T19:48:45+02:00 ERR: Share name _randomised not found
Does it actually say "_randomised"??
2014-07-10 18:03:01 software-horde (at) interfasys (dot) ch Comment #5 Reply to this comment
On a newly added account, after the initial sync, this error comes back:
2014-07-10T19:48:45+02:00 ERR: Share name _randomised not found

The log is similar to what I posted earlier in the log.

I did not make any modifications to the notes in the phone or in 
Horde, except for changing the colour of the folder in the phone.

I did move a task from one folder to another, but there is no 
complaint about that.

I can see the share in the DB, it has the correct share_owner. That 
Notebook was created on an earlier version of Horde and it starts with 
an underscore (not sure if it's relevant)



2014-07-10 16:58:20 Michael Rubinsky Comment #4
State ⇒ Duplicate
Reply to this comment
Going to mark this as at least related to Bug: 13338
2014-07-09 15:42:51 Michael Rubinsky State ⇒ Feedback
 
2014-07-09 15:42:40 Michael Rubinsky Comment #3 Reply to this comment
2014-07-09T03:40:22+02:00 INFO: [5683] Loading state for synckey 
{53944bcf-adf4-4bd1-b3ca-24b2904cae96}3
2014-07-09T03:40:22+02:00 INFO: [5683] Loading FOLDERSYNC state 
containing 12 folders
This shows that the sync state is still intact and available.
Horde_Core_ActiveSync_Driver::_getMailFolders()
2014-07-09T03:40:22+02:00 ERR: Share name _randomised not found
This means that in whatever application this is polling, the share is 
no longer available. It was either deleted or renamed, or this user no 
longer has permissions to it.

Re-saving the synchronization preferences for this app should rectify 
the situation.
2014-07-09 01:45:29 software-horde (at) interfasys (dot) ch Comment #2 Reply to this comment
It seems that the upgrade broke the sync relationship which existed 
between accounts on the device and Horde sync sources.

This is from the sync log:
2014-07-09T03:40:22+02:00 INFO: [5683] 
Horde_Core_ActiveSync_Driver::authenticate() attempt for user@domain.tld
2014-07-09T03:40:22+02:00 INFO: [5683] FOLDERUPDATE request received 
for user user@domain.tld
2014-07-09T03:40:22+02:00 INFO: [5683] Device entry exists for 
BB1234ABCD, updating userAgent and version.
2014-07-09T03:40:22+02:00 INFO: [5683] Request being handled for 
device: BB1234ABCD, Supporting protocol version: 14.1, Using 
Horde_ActiveSync v2.16.9
2014-07-09T03:40:22+02:00 INFO: [5683] GET VARIABLES: Array
(
     [Cmd] => FolderUpdate
     [DeviceType] => BlackBerry
     [User] => user@domain.tld
     [DeviceId] => BB1234ABCD
)

2014-07-09T03:40:22+02:00 INFO: [BB1234ABCD] Handling 
FOLDER[CREATE|DELETE|CHANGE] command.
2014-07-09T03:40:22+02:00 DEBUG: [5683] I  <FolderHierarchy:FolderUpdate>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I   <FolderHierarchy:SyncKey>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I     
{53944bcf-adf4-4bd1-b3ca-24b2904cae96}3
2014-07-09T03:40:22+02:00 DEBUG: [5683] I   </FolderHierarchy:SyncKey>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I   <FolderHierarchy:ServerEntryId>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I     Ncf4f9a88
2014-07-09T03:40:22+02:00 DEBUG: [5683] I   </FolderHierarchy:ServerEntryId>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I   <FolderHierarchy:ParentId>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I     0
2014-07-09T03:40:22+02:00 DEBUG: [5683] I   </FolderHierarchy:ParentId>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I   <FolderHierarchy:DisplayName>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I     Notepad of user@domain.tld
2014-07-09T03:40:22+02:00 DEBUG: [5683] I   </FolderHierarchy:DisplayName>
2014-07-09T03:40:22+02:00 DEBUG: [5683] I  </FolderHierarchy:FolderUpdate>
2014-07-09T03:40:22+02:00 INFO: [5683] Loading state for synckey 
{53944bcf-adf4-4bd1-b3ca-24b2904cae96}3
2014-07-09T03:40:22+02:00 INFO: [5683] Loading FOLDERSYNC state 
containing 12 folders.
2014-07-09T03:40:22+02:00 INFO: [5683] 
Horde_ActiveSync_Connector_Importer::importFolderChange(Ncf4f9a88, 
Notepad of user@domain.tld, 0, )
2014-07-09T03:40:22+02:00 INFO: [5683] 
Horde_Core_ActiveSync_Driver::changeFolder(Notes:_randomised, Notepad 
of user@domain.tld, 0, Ncf4f9a88, )
2014-07-09T03:40:22+02:00 INFO: [5683] Polling 
Horde_Core_ActiveSync_Driver::_getMailFolders()
2014-07-09T03:40:22+02:00 ERR: Share name _randomised not found
2014-07-08 23:59:24 software-horde (at) interfasys (dot) ch Comment #1
Type ⇒ Bug
State ⇒ Unconfirmed
Priority ⇒ 1. Low
Summary ⇒ Activesync: error 500 while handling FolderUpdate
Queue ⇒ Horde Framework Packages
Milestone ⇒
Patch ⇒ No
Reply to this comment
Synchronising from a BlackBerry device on 10.2.1

The logs show this:
T01:35:00+02:00 ERR: HORDE Returning HTTP 500 while handling 
FolderUpdate command. [pid 89163 on line 159 of 
"/var/www/html/webmail/rpc.php"]
T01:35:00+02:00 ERR: HORDE Error in communicating with ActiveSync 
server: Protocol Error [pid 89163 on line 162 of 
"/php/lib/php/Horde/Rpc/ActiveSync.php"]
T01:35:00+02:00 ERR: HORDE #0 
/php/lib/php/Horde/ActiveSync/Request/Base.php(253): 
Horde_ActiveSync_Request_FolderCreate->_handle()
#1 /php/lib/php/Horde/ActiveSync.php(880): 
Horde_ActiveSync_Request_Base->handle()
#2 /php/lib/php/Horde/Rpc/ActiveSync.php(143): 
Horde_ActiveSync->handleRequest('FolderUpdate', 'BBABCD1234')
#3 /var/www/html/webmail/rpc.php(159): Horde_Rpc_ActiveSync->getResponse(NULL)
#4 {main} [pid 89163 on line 162 of "/php/lib/php/Horde/Rpc/ActiveSync.php"]
T01:35:00+02:00 ERR: HORDE Buffer contents:  [pid 89163 on line 162 of 
"/php/lib/php/Horde/Rpc/ActiveSync.php"]

Saved Queries