6.0.0-git
2019-05-27

[#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 2014-07-09 (1783 days ago)
Due
Updated 2014-07-12 (1780 days ago)
Assigned 2014-07-11 (1781 days ago)
Resolved 2014-07-12 (1780 days ago)
Milestone
Patch No

History
2014-07-12 15:45:56 Michael Rubinsky State ⇒ Resolved
 
2014-07-12 15:45:46 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]
2014-07-12 12:08:21 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
2014-07-12 10:40:28 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




2014-07-12 04:54:55 Michael Rubinsky Comment #16 Reply to this comment
How about now?
2014-07-12 04:54:09 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
2014-07-11 14:52:36 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.
2014-07-11 14:46:47 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
2014-07-11 14:31:31 Michael Rubinsky Comment #12
State ⇒ Feedback
Reply to this comment
Did you update to the latest Horde_ActiveSync package?
2014-07-11 11:12:10 software-horde (at) interfasys (dot) ch Comment #11 Reply to this comment
And removing the device in Horde does not reset the sync relationship.

2014-07-11 10:02:08 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.
2014-07-10 17:59:31 Michael Rubinsky State ⇒ Resolved
 
2014-07-10 17:52:55 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.
2014-07-10 17:29:57 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.
2014-07-10 17:28:19 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.


2014-07-10 17:01:15 Michael Rubinsky Version ⇒ FRAMEWORK_5_2
Queue ⇒ Synchronization
 
2014-07-10 16:53:47 Michael Rubinsky Comment #6
Assigned to Michael Rubinsky
Reply to this comment
Does this fix?
2014-07-10 16:52:46 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
2014-07-09 21:37:00 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.

2014-07-09 21:25:30 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

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