Summary | Activesync: Column 'sync_key' cannot be null |
Queue | Synchronization |
Queue Version | FRAMEWORK_5_2 |
Type | Bug |
State | Resolved |
Priority | 1. Low |
Owners | mrubinsk (at) horde (dot) org |
Requester | software-horde (at) interfasys (dot) ch |
Created | 07/09/2014 (4026 days ago) |
Due | |
Updated | 07/12/2014 (4023 days ago) |
Assigned | 07/11/2014 (4024 days ago) |
Resolved | 07/12/2014 (4023 days ago) |
Github Issue Link | |
Github Pull Request | |
Milestone | |
Patch | No |
State ⇒ Not A Bug
can control. The client is sending a command to rename a folder, but
it's using an old synckey that the server knows nothing about. In
return, the server is sending back an appropriate error code (9) that
tells the client the synckey is bad and it should reset it's internal
state.
If the client ignores this advice, there is nothing Horde can do about it.
settings and I never see a FOLDERUPDATE request.
In case of a sync request when the key is missing, I see a
State not found sending STATUS_KEYMISM
I'm going to add another account to see if it changes something
I reset the state in Horde and re-saved the settings on the device.
I can see the device getting provisioned with an error I see with all
accounts but which doesn't seem to stop things
2014-07-12T12:00:41+02:00 DEBUG: [2615] I <Settings:Settings>
2014-07-12T12:00:41+02:00 DEBUG: [2615] I
<Settings:RightsManagementInformation>
2014-07-12T12:00:41+02:00 ERR: [2615] Unmatched end tag:
2014-07-12T12:00:41+02:00 ERR: Array
(
[1] => 1
[2] => Settings:RightsManagementInformation
[4] => 1
)
2014-07-12T12:00:41+02:00 DEBUG: [2615] O <Settings:Settings>
2014-07-12T12:00:41+02:00 DEBUG: [2615] O <Settings:Status>
2014-07-12T12:00:41+02:00 DEBUG: [2615] O 1
2014-07-12T12:00:41+02:00 DEBUG: [2615] O </Settings:Status>
2014-07-12T12:00:41+02:00 DEBUG: [2615] O </Settings:Settings>
After that the same items are logged as before, except the saving part
INFO: [BB1234ABCD] Handling
FOLDER[CREATE|DELETE|CHANGE] command.
DEBUG: [56058] I <FolderHierarchy:FolderUpdate>
DEBUG: [56058] I <FolderHierarchy:SyncKey>
DEBUG: [56058] I
{53944bbf-adf4-4bd1-b3ca-24b2904cae96}3
DEBUG: [56058] I </FolderHierarchy:SyncKey>
DEBUG: [56058] I <FolderHierarchy:ServerEntryId>
DEBUG: [56058] I Ncf4f9a88
DEBUG: [56058] I </FolderHierarchy:ServerEntryId>
DEBUG: [56058] I <FolderHierarchy:ParentId>
DEBUG: [56058] I 0
DEBUG: [56058] I </FolderHierarchy:ParentId>
DEBUG: [56058] I <FolderHierarchy:DisplayName>
DEBUG: [56058] I Notepad of user@domain.tld
DEBUG: [56058] I </FolderHierarchy:DisplayName>
DEBUG: [56058] I </FolderHierarchy:FolderUpdate>
INFO: [56058] Loading state for synckey
{53944bbf-adf4-4bd1-b3ca-24b2904cae96}3
ERR: [56058] Could not find state for
synckey {53944bbf-adf4-4bd1-b3ca-24b2904cae96}3.
DEBUG: [56058] O <FolderHierarchy:FolderUpdate>
DEBUG: [56058] O <FolderHierarchy:Status>
DEBUG: [56058] O 9
DEBUG: [56058] O </FolderHierarchy:Status>
DEBUG: [56058] O </FolderHierarchy:FolderUpdate>
Sync keys are never created in the database
The device stops asking for any data
commit 3383e67d9274aacc6e8fe88b9d9f9fbd4c35481e
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date: Sat Jul 12 00:52:10 2014 -0400
Don't save the state, either, if we were not successful.
Another part of the fix for
Bug: 13338.../lib/Horde/ActiveSync/Request/FolderCreate.php | 7 +++++--
1 files changed, 5 insertions(+), 2 deletions(-)
http://github.com/horde/horde/commit/3383e67d9274aacc6e8fe88b9d9f9fbd4c35481e
Looking at this message, it seems the client refuses the new synckey
and then Horde tries to save the state anyway with a NULL value for
the sync_key
supposed to fix.
I'll have a look when I'm back at my office.
Looking at this message, it seems the client refuses the new synckey
and then Horde tries to save the state anyway with a NULL value for
the sync_key
2014-07-09T23:19:33+02:00 INFO: [56058] Saving state:
a:8:{i:0;N;i:1;O:21:"Horde_Db_Value_Binary":1:{s:5:"value";s:0:"";}i:2;s:10:"BB1234ABCD";i:3;i:0;i:4;s:10:"foldersync";i:5;s:18:"user@domain.tld";i:6;i:0;i:7;i:1404940773;}
2014-07-09T23:19:33+02:00 NOTICE: [56058] Previous request processing
for synckey failed to be accepted by the client, removing previous
state and trying again.
2014-07-09T23:19:33+02:00 ERR: SQLSTATE[23000]: Integrity constraint
violation: 1048 Column 'sync_key' cannot be null
State ⇒ Feedback
triggered a sync from the device and the sync_key problem is back.
Log is exactly the same as in comment 3.
horde_activesync_state has zero entries for that email account.
Try removing the account from the client, removing the pairing from
Horde, and recreate the account from scratch on the client.
mnemo and nag. Because it didn't work, I removed the devices in Horde
and started to get the sync_key problem.
I've re-created one of the accounts and the initial sync worked, but
updating Notes folders doesn't. I'll update the other ticket.
Try removing the account from the client, removing the pairing from
Horde, and recreate the account from scratch on the client.
reaction and I see different errors now:
2014-07-10T19:22:33+02:00 INFO: [40212] ITEMOPERATIONS request
received for user user@domain.tld
2014-07-10T19:22:33+02:00 INFO: [40212] Device entry exists for
BB1234ABCD, updating userAgent and version.
2014-07-10T19:22:33+02:00 INFO: [40212] Request being handled for
device: BB1234ABCD, Supporting protocol version: 14.1, Using
Horde_ActiveSync v2.16.9
2014-07-10T19:22:33+02:00 INFO: [40212] GET VARIABLES: Array
(
[Cmd] => ItemOperations
[DeviceType] => BlackBerry
[User] => user@domain.tld
[DeviceId] => BB1234ABCD
)
2014-07-10T19:22:33+02:00 ERR: [40212]
Horde_ActiveSync_Collections::getBackendIdForFolderUid failed because
folder was not found in cache.
2014-07-10T19:22:33+02:00 ERR: Folder not found in cache.
Queue ⇒ Synchronization
Assigned to Michael Rubinsky
commit 589fabd91f2c0da2e64468ff14c3025ec0039f4a
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date: Thu Jul 10 12:49:32 2014 -0400
Only attempt to update the collections cache if there were no errors.
Related to
Bug: 13338.../lib/Horde/ActiveSync/Request/FolderCreate.php | 10 +++++++---
1 files changed, 7 insertions(+), 3 deletions(-)
http://github.com/horde/horde/commit/589fabd91f2c0da2e64468ff14c3025ec0039f4a
the list.
All the accounts which can't sync are missing entries in that table.
2014-07-09T23:19:32+02:00 INFO: [56058]
Horde_Core_ActiveSync_Driver::authenticate() attempt for user@domain.tld
2014-07-09T23:19:33+02:00 INFO: [56058] FOLDERUPDATE request received
for user user@domain.tld
2014-07-09T23:19:33+02:00 INFO: [56058] Device entry exists for
BB1234ABCD, updating userAgent and version.
2014-07-09T23:19:33+02:00 INFO: [56058] Request being handled for
device: BB1234ABCD, Supporting protocol version: 14.1, Using
Horde_ActiveSync v2.16.9
2014-07-09T23:19:33+02:00 INFO: [56058] GET VARIABLES: Array
(
[Cmd] => FolderUpdate
[DeviceType] => BlackBerry
[User] => user@domain.tld
[DeviceId] => BB1234ABCD
)
2014-07-09T23:19:33+02:00 INFO: [BB1234ABCD] Handling
FOLDER[CREATE|DELETE|CHANGE] command.
2014-07-09T23:19:33+02:00 DEBUG: [56058] I <FolderHierarchy:FolderUpdate>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I <FolderHierarchy:SyncKey>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I
{53944bbf-adf4-4bd1-b3ca-24b2904cae96}3
2014-07-09T23:19:33+02:00 DEBUG: [56058] I </FolderHierarchy:SyncKey>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I <FolderHierarchy:ServerEntryId>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I Ncf4f9a88
2014-07-09T23:19:33+02:00 DEBUG: [56058] I </FolderHierarchy:ServerEntryId>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I <FolderHierarchy:ParentId>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I 0
2014-07-09T23:19:33+02:00 DEBUG: [56058] I </FolderHierarchy:ParentId>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I <FolderHierarchy:DisplayName>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I Notepad of user@domain.tld
2014-07-09T23:19:33+02:00 DEBUG: [56058] I </FolderHierarchy:DisplayName>
2014-07-09T23:19:33+02:00 DEBUG: [56058] I </FolderHierarchy:FolderUpdate>
2014-07-09T23:19:33+02:00 INFO: [56058] Loading state for synckey
{53944bbf-adf4-4bd1-b3ca-24b2904cae96}3
2014-07-09T23:19:33+02:00 ERR: [56058] Could not find state for
synckey {53944bbf-adf4-4bd1-b3ca-24b2904cae96}3.
2014-07-09T23:19:33+02:00 INFO: [56058] Collection without id found:
a:1:{s:8:"serverid";N;}
2014-07-09T23:19:33+02:00 INFO: [56058] Updating serverid in folder
state. Setting for .
2014-07-09T23:19:33+02:00 INFO: [56058] Replacing SYNC_CACHE entry for
user user@domain.tld and device BB1234ABCD:
a:11:{s:18:"confirmed_synckeys";a:0:{}s:17:"lasthbsyncstarted";b:0;s:17:"lastsyncendnormal";b:0;s:9:"timestamp";s:10:"1404940773";s:4:"wait";b:0;s:10:"hbinterval";b:0;s:7:"folders";a:1:{s:0:"";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";N;}}s:9:"hierarchy";b:0;s:11:"collections";a:0:{}s:13:"pingheartbeat";b:0;s:14:"synckeycounter";a:0:{}}
2014-07-09T23:19:33+02:00 DEBUG: [56058] O <FolderHierarchy:FolderUpdate>
2014-07-09T23:19:33+02:00 DEBUG: [56058] O <FolderHierarchy:Status>
2014-07-09T23:19:33+02:00 DEBUG: [56058] O 9
2014-07-09T23:19:33+02:00 DEBUG: [56058] O </FolderHierarchy:Status>
2014-07-09T23:19:33+02:00 DEBUG: [56058] O </FolderHierarchy:FolderUpdate>
2014-07-09T23:19:33+02:00 INFO: [56058] Saving state:
a:8:{i:0;N;i:1;O:21:"Horde_Db_Value_Binary":1:{s:5:"value";s:0:"";}i:2;s:10:"BB1234ABCD";i:3;i:0;i:4;s:10:"foldersync";i:5;s:18:"user@domain.tld";i:6;i:0;i:7;i:1404940773;}
2014-07-09T23:19:33+02:00 NOTICE: [56058] Previous request processing
for synckey failed to be accepted by the client, removing previous
state and trying again.
2014-07-09T23:19:33+02:00 ERR: SQLSTATE[23000]: Integrity constraint
violation: 1048 Column 'sync_key' cannot be null
State ⇒ Feedback
Priority ⇒ 1. Low
State ⇒ Unconfirmed
Patch ⇒ No
Milestone ⇒
Summary ⇒ Activesync: Column 'sync_key' cannot be null
Type ⇒ Bug
Queue ⇒ Horde Groupware Webmail Edition
them from Horde and re-initiated a sync from the device.
The accounts now show as being provisioned but still don't sync.
The ones which have problems are the ones which sync more than email.
Here is what I see in the logs:
2014-07-09T18:13:09+02:00 ERR: HORDE SQL QUERY FAILED:
SQLSTATE[23000]: Integrity constraint violation: 1048 Column
'sync_key' cannot be null
INSERT INTO horde_activesync_state (sync_key, sync_data, sync_devid,
sync_mod, sync_folderid, sync_user, sync_pending, sync_timestamp)
VALUES (NULL, '', 'BB1234ABCD', 0, 'foldersync', 'user@domain.tld',
'', 1404922389) [pid 34839 on line 204 of
"/php/Horde/Db/Adapter/Pdo/Base.php"]
2014-07-09T18:13:09+02:00 ERR: HORDE Returning HTTP 500 while handling
FolderUpdate command. [pid 34839 on line 159 of "/horde/rpc.php"]
2014-07-09T18:13:09+02:00 ERR: HORDE Error in communicating with
ActiveSync server: SQLSTATE[23000]: Integrity constraint violation:
1048 Column 'sync_key' cannot be null [pid 34839 on line 162 of
"/php/Horde/Rpc/ActiveSync.php"]
2014-07-09T18:13:09+02:00 ERR: HORDE #0
/php/Horde/Db/Adapter/Pdo/Base.php(234):
Horde_Db_Adapter_Pdo_Base->execute('INSERT INTO hor...', Array, NULL)
#1/php/Horde/ActiveSync/State/Sql.php(348):Horde_Db_Adapter_Pdo_Base->insert('INSERT INTO hor...', Array)
#2/php/Horde/ActiveSync/Request/FolderCreate.php(223):Horde_ActiveSync_State_Sql->save()
#3/php/Horde/ActiveSync/Request/Base.php(253):Horde_ActiveSync_Request_FolderCreate->_handle()
#4/php/Horde/ActiveSync.php(880): Horde_ActiveSync_Request_Base->handle()#5/php/Horde/Rpc/ActiveSync.php(143):Horde_ActiveSync->handleRequest('FolderUpdate', 'BB1234ABCD')
#6/horde/rpc.php(159): Horde_Rpc_ActiveSync->getResponse(NULL)#7{main} [pid 34839 on line 162 of "/php/Horde/Rpc/ActiveSync.php"]