6.0.0-beta1
7/17/25

[#13338] Activesync: Column 'sync_key' cannot be null
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

History
07/12/2014 03:45:56 PM Michael Rubinsky State ⇒ Resolved
 
07/12/2014 03:45:46 PM Michael Rubinsky Comment #19
State ⇒ Not A Bug
Reply to this comment
How about now?
It still doesn't work.
But the fatal database error is gone, and that is the only thing Horde 
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.

[Show Quoted Text - 55 lines]
07/12/2014 12:08:21 PM software-horde (at) interfasys (dot) ch Comment #18 Reply to this comment
I provisioned another device and did the same things: remove, update 
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
07/12/2014 10:40:28 AM software-horde (at) interfasys (dot) ch Comment #17 Reply to this comment
How about now?
It still doesn't work.

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




07/12/2014 04:54:55 AM Michael Rubinsky Comment #16 Reply to this comment
How about now?
07/12/2014 04:54:09 AM Git Commit Comment #15 Reply to this comment
Changes have been made in Git (master):

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
07/11/2014 02:52:36 PM Michael Rubinsky Comment #14 Reply to this comment
Did you update to the latest Horde_ActiveSync package?
Yes, I performed an upgrade of all the packages before trying.
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
Yes, and that's the exact issue the commit listed in this ticket was 
supposed to fix.

I'll have a look when I'm back at my office.
07/11/2014 02:46:47 PM software-horde (at) interfasys (dot) ch Comment #13 Reply to this comment
Did you update to the latest Horde_ActiveSync package?
Yes, I performed an upgrade of all the packages before trying.
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
07/11/2014 02:31:31 PM Michael Rubinsky Comment #12
State ⇒ Feedback
Reply to this comment
Did you update to the latest Horde_ActiveSync package?
07/11/2014 11:12:10 AM software-horde (at) interfasys (dot) ch Comment #11 Reply to this comment
And removing the device in Horde does not reset the sync relationship.

07/11/2014 10:02:08 AM software-horde (at) interfasys (dot) ch Comment #10 Reply to this comment
After having fixed the previous problem with Notes sync (#13334), I 
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.
07/10/2014 05:59:31 PM Michael Rubinsky State ⇒ Resolved
 
07/10/2014 05:52:55 PM software-horde (at) interfasys (dot) ch Comment #9 Reply to this comment
  Sounds like your state is all kinds of broken.

Try removing the account from the client, removing the pairing from 
Horde, and recreate the account from scratch on the client.
Yes. It all happened when trying to sync some additional folders in 
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.
07/10/2014 05:29:57 PM Michael Rubinsky Comment #8 Reply to this comment
  Sounds like your state is all kinds of broken.

Try removing the account from the client, removing the pairing from 
Horde, and recreate the account from scratch on the client.
07/10/2014 05:28:19 PM software-horde (at) interfasys (dot) ch Comment #7 Reply to this comment
Does this fix?
I can't tell yet, because I tried to access an email to trigger a 
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.


07/10/2014 05:01:15 PM Michael Rubinsky Version ⇒ FRAMEWORK_5_2
Queue ⇒ Synchronization
 
07/10/2014 04:53:47 PM Michael Rubinsky Comment #6
Assigned to Michael Rubinsky
Reply to this comment
Does this fix?
07/10/2014 04:52:46 PM Git Commit Comment #5 Reply to this comment
Changes have been made in Git (master):

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
07/09/2014 09:37:00 PM software-horde (at) interfasys (dot) ch Comment #4 Reply to this comment
I've just had a look at the DB table and the sync key is indeed not in 
the list.

All the accounts which can't sync are missing entries in that table.

07/09/2014 09:25:30 PM software-horde (at) interfasys (dot) ch Comment #3 Reply to this comment
OK, I've found something

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

07/09/2014 06:08:22 PM Michael Rubinsky Comment #2
State ⇒ Feedback
Reply to this comment
Need to see the synclog to see why the synckey is not being provided.
07/09/2014 05:30:47 PM software-horde (at) interfasys (dot) ch Comment #1
Priority ⇒ 1. Low
State ⇒ Unconfirmed
Patch ⇒ No
Milestone ⇒
Summary ⇒ Activesync: Column 'sync_key' cannot be null
Type ⇒ Bug
Queue ⇒ Horde Groupware Webmail Edition
Reply to this comment
I have many accounts which have now stopped syncing. I have removed 
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"]


Saved Queries