6.0.0-alpha14
6/24/25

[#13038] Error saving state for synckey - no Inbox synchronization
Summary Error saving state for synckey - no Inbox synchronization
Queue Synchronization
Queue Version Git master
Type Bug
State Resolved
Priority 1. Low
Owners mrubinsk (at) horde (dot) org
Requester samuel.wolf (at) wolf-maschinenbau (dot) de
Created 03/12/2014 (4122 days ago)
Due
Updated 03/24/2014 (4110 days ago)
Assigned 03/13/2014 (4121 days ago)
Resolved 03/24/2014 (4110 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch No

History
03/24/2014 10:16:25 PM Michael Rubinsky Comment #27
State ⇒ Resolved
Reply to this comment
Horde_ActiveSync-2.13.3 is out.

Sorry for the recent issues all....
03/24/2014 10:08:43 PM arjen+horde (at) de-korte (dot) org Comment #26 Reply to this comment
OK, I see now what you are saying.  Is there a fix being contemplated/needed?
See http://bugs.horde.org/ticket/13052#c6
03/24/2014 10:08:03 PM Michael Rubinsky Comment #25 Reply to this comment
Running a last "the new release doesn't blow up my computer" test as we speak.
03/24/2014 09:59:38 PM skaman (dot) tx (at) gmail (dot) com Comment #24 Reply to this comment

[Show Quoted Text - 38 lines]
OK, I see now what you are saying.  Is there a fix being contemplated/needed?

03/24/2014 09:55:28 PM Michael Rubinsky Comment #23 Reply to this comment
Hmmm, then why is the same device using EAS 14.1 and now syncing 
just fine under ActiveSync v2.13.2?  Recall from my previous post 
that once I downgraded to 2.12.4, then manuall sync'd the device, 
then upgraded to 2.13.2, the device works just fine.  Doesn't seem 
right somehow.
If the device was paired while running 2.12.4 (and therefore 
negotiated EAS version 12.x), it will continue to work under that 
version until it is told otherwise.
03/24/2014 09:54:57 PM arjen+horde (at) de-korte (dot) org Comment #22 Reply to this comment

[Show Quoted Text - 29 lines]
The device isn't using EAS 12.1, Horde is using EAS 14.1. This will 
work as long as Horde is not using something that wasn't available in 
EAS 12.1. But as soon as it does, synchronization will break again.
  Recall from my previous post that once I downgraded to 2.12.4, then 
manuall sync'd the device, then upgraded to 2.13.2, the device works 
just fine.  Doesn't seem right somehow.
03/24/2014 09:49:09 PM skaman (dot) tx (at) gmail (dot) com Comment #21 Reply to this comment

[Show Quoted Text - 26 lines]
Hmmm, then why is the same device using EAS 14.1 and now syncing just 
fine under ActiveSync v2.13.2?  Recall from my previous post that once 
I downgraded to 2.12.4, then manuall sync'd the device, then upgraded 
to 2.13.2, the device works just fine.  Doesn't seem right somehow.

03/24/2014 09:37:06 PM arjen+horde (at) de-korte (dot) org Comment #20 Reply to this comment

[Show Quoted Text - 17 lines]
The device uses EAS 12.1 and therefor will not work with the 
Horde_ActiveSync-2.13.2. So yes, if you revert this commit, it will 
most likely work if it worked with Horde_ActiveSync-2.12.4.
The 2.13.2 entry shows the following:

Request being handled for device: ANDROIDC135954261, Supporting 
protocol version: 14.1, Using Horde_ActiveSync v2.13.2
03/24/2014 09:32:59 PM skaman (dot) tx (at) gmail (dot) com Comment #19 Reply to this comment

[Show Quoted Text - 11 lines]
The log file I posted contains entries while running under 2.13.2 and 
2.12.4.  The 2.12.4 entry shows the following:

equest being handled for device: ANDROIDC135954261, Supporting 
protocol version: 12.1, Using Horde_ActiveSync v2.12.4

The 2.13.2 entry shows the following:

Request being handled for device: ANDROIDC135954261, Supporting 
protocol version: 14.1, Using Horde_ActiveSync v2.13.2

03/24/2014 09:27:08 PM Michael Rubinsky Comment #18 Reply to this comment
See attached log.  Includes error when running 2.13.2 and proper 
sync once downgraded to 2.12.4.  Note that once I downgraded to 
2.12.4 and synced the email accounts on the device manually, then 
upgraded to 2.13.2, the device sync'd just fine.  However, since I 
don't have control over my email users devices, I'm downgrading back 
to 2.12.4 since I know it "just works."
I'm not familiar with the Moto X, but since it's a fairly recent 
device I would imagine it uses EAS 14.1? Can you look at your logs 
when using 2.12.4 and see what the initial log entry says about the 
EAS version in  use?
03/24/2014 09:24:41 PM Michael Rubinsky Comment #17 Reply to this comment
Hard to say, as your log doesn't really show any thing to indicate an 
error. If this is an older device that can only talk a version less 
than 14.1, then it will likely help.
03/24/2014 01:10:11 PM samuel (dot) wolf (at) wolf-maschinenbau (dot) de Comment #16 Reply to this comment
http://article.gmane.org/gmane.comp.horde.user/34712

Maybe this fix my issue as well?
03/15/2014 08:23:26 AM samuel (dot) wolf (at) wolf-maschinenbau (dot) de Comment #15 Reply to this comment
This line number only contains a [] operator in version 2.12.4. Do 
you see any errors when running it under the current version?
You're right, this errors happens only with 2.12.4, not with 2.13.2.
Send you today my debug log by mail.
03/13/2014 05:02:29 PM skaman (dot) tx (at) gmail (dot) com Comment #14 Reply to this comment
See attached log.  Includes error when running 2.13.2 and proper 
sync once downgraded to 2.12.4.  Note that once I downgraded to 
2.12.4 and synced the email accounts on the device manually, then 
upgraded to 2.13.2, the device sync'd just fine.  However, since I 
don't have control over my email users devices, I'm downgrading back 
to 2.12.4 since I know it "just works."
Perhaps you can delete the attachment from the ticket once you've 
grabbed it as well.
03/13/2014 04:46:30 PM skaman (dot) tx (at) gmail (dot) com Comment #13
New Attachment: ANDROIDC135954261.zip Download
Reply to this comment
See attached log.  Includes error when running 2.13.2 and proper sync 
once downgraded to 2.12.4.  Note that once I downgraded to 2.12.4 and 
synced the email accounts on the device manually, then upgraded to 
2.13.2, the device sync'd just fine.  However, since I don't have 
control over my email users devices, I'm downgrading back to 2.12.4 
since I know it "just works."
03/13/2014 04:27:45 PM Michael Rubinsky Comment #12 Reply to this comment
I'm going to need a full synclog to see where this is failing.
03/13/2014 03:52:55 PM skaman (dot) tx (at) gmail (dot) com Comment #11 Reply to this comment
I can confirm that ActiveSync-2.13.1 and ActiveSync-2.13.2 do break 
sync on Android MOTO1080X.  Still works on Nexus 7 gen. 2.  Downgrade 
to ActiveSync-2.12.4 and all is working again on MOTO1080X.

03/13/2014 02:45:33 PM samuel (dot) wolf (at) wolf-maschinenbau (dot) de Comment #10 Reply to this comment
Work for some mails now and stop again:
2014-03-13T14:41:03+00:00 NOTICE: [4077] Error saving state for 
synckey {5320712f-xxxx-xxxx-xxxx-xxxxxxxxxxxx}42: QUERY FAILED: 
Duplicate entry '{5320712f-xxxx-xxxx-xxxx-xxxxxxxxxxxx}42' for key 
'PRIMARY' INSERT INTO horde_activesync_state (sync_key, sync_data, 
sync_devid, sync_mod, sync_folderid, sync_user, sync_pending, 
sync_timestamp) VALUES [...]
Is it a way to delete all AS database entries for my user, if yes which?
03/13/2014 01:50:44 PM Michael Rubinsky Comment #9 Reply to this comment
You mean this error was from 2.12.4?
Yes.
Watch it now for some hours and give you a feedback.
Maybe this fix my issue as well?
https://github.com/horde/horde/commit/1288a7436ba2d95159814f04e3c69264d5fa319e
Possible. It would have caused a bunch of old processes to hang around 
for a while, possibly corrupting some state.
03/13/2014 05:24:54 AM samuel (dot) wolf (at) wolf-maschinenbau (dot) de Comment #8 Reply to this comment
This line number only contains a [] operator in version 2.12.4. Do 
you see any errors when running it under the current version?
You mean this error was from 2.12.4? Possible and I do not noticed 
when i am testing between 2.12.4 and 2.13.1. Anyway, at the moment I 
do not see any errors after update to Horde_ActiveSync-2.13.2.
Watch it now for some hours and give you a feedback.

Maybe this fix my issue as well?
https://github.com/horde/horde/commit/1288a7436ba2d95159814f04e3c69264d5fa319e
03/13/2014 04:47:03 AM Michael Rubinsky State ⇒ Feedback
 
03/13/2014 04:46:52 AM Michael Rubinsky Comment #7 Reply to this comment
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP Fatal
error:  [] operator not supported for strings in
/usr/share/php/Horde/ActiveSync/Folder/Imap.php on line 222

This line number only contains a [] operator in version 2.12.4. Do you 
see any errors when running it under the current version?
03/12/2014 02:52:31 PM Michael Rubinsky Comment #6
State ⇒ Assigned
Assigned to Michael Rubinsky
Reply to this comment
Probably related to adding sequence string storage:

https://github.com/horde/horde/commit/8bc8f6433f808c5761bee3d609d230daf4281f23

Will take a look as soon as I'm able.
03/12/2014 11:47:49 AM samuel (dot) wolf (at) wolf-maschinenbau (dot) de Comment #5 Reply to this comment
Did you try to resynchronize devices? That's when the problems 
started for me. When a device is already synchronized, upgrading to 
Horde_ActiveSync-2.13.1 doesn't seem to break existing 
(synchronized) accounts. But as soon as a device is resynchronized, 
problems start.
I have tried:
* reset the device in horde
* delete the device in horde
* remove the as account on the smartphone and delete it in horde
* downgrade to Horde_ActiveSync-2.12.4, restore database (2.12.4), 
sync device and upgrade direct to Horde_ActiveSync-2.13.1 same problem

03/12/2014 11:38:05 AM arjen+horde (at) de-korte (dot) org Comment #4 Reply to this comment
Did you try to resynchronize devices? That's when the problems started 
for me. When a device is already synchronized, upgrading to 
Horde_ActiveSync-2.13.1 doesn't seem to break existing (synchronized) 
accounts. But as soon as a device is resynchronized, problems start.


03/12/2014 11:23:19 AM samuel (dot) wolf (at) wolf-maschinenbau (dot) de Comment #3 Reply to this comment
I see the same behavior here, but with a different mailbox. My guess 
is that you have a fair number of message in you Inbox, since here 
the mailbox that loses synchronization is the one with the most 
messages in it (over 500 messages).
I move all messages into a other folder, only one message is in the 
inbox, same problem.
At the moment only on device is affected, the other work as expected.

03/12/2014 10:57:51 AM arjen+horde (at) de-korte (dot) org Comment #2 Reply to this comment
My Android 4.1.2 device stop synchronize my mail Inbox with 
Horde_ActiveSync-2.13.1, other Mailfolders work fine. Reset the 
device does not help.
I see the same behavior here, but with a different mailbox. My guess 
is that you have a fair number of message in you Inbox, since here the 
mailbox that loses synchronization is the one with the most messages 
in it (over 500 messages).

It may or may not have something to do with this, but synchronization 
of the calendar also failed when resynchronizing the device. 
Downgrading to Horde_ActiveSync-2.12.4 resolved both the mailbox and 
calendar synchronization issues.
03/12/2014 08:59:50 AM samuel (dot) wolf (at) wolf-maschinenbau (dot) de Comment #1
Priority ⇒ 1. Low
State ⇒ Unconfirmed
Patch ⇒ No
Milestone ⇒
Summary ⇒ Error saving state for synckey - no Inbox synchronization
Type ⇒ Bug
Queue ⇒ Synchronization
Reply to this comment
My Android 4.1.2 device stop synchronize my mail Inbox with 
Horde_ActiveSync-2.13.1, other Mailfolders work fine. Reset the device 
does not help.

Horde Log:
2014-03-12T04:14:53+00:00 INFO: [25603] Updating state during change
2014-03-12T04:14:53+00:00 DEBUG: [25603] O     </Commands>
2014-03-12T04:14:53+00:00 INFO: [25603] Saving state: 
a:8:{i:0;s:39:"{531fddad-xxxx-xxxx-xxxx-xxxxxxxxxxxx}5";i:1;O:21:"Horde_Db_Value_Binary":1:{s:5:"value";s:206:"C:28:"Horde_ActiveSync_Folder_Imap":164:{{"s":{"messages":"1","uidnext":"5378","uidvalidity":"1342278888","highestmodseq":"12679"},"m":"5377","f":"INBOX","c":"Email","lsd":1393992593,"sd":1394597393,"v":2}}";}i:2;s:17:"ANDROID1xxxx";i:3;i:1394597693;i:4;s:9:"F3ef80eea";i:5;s:6:"samuel";i:6;i:0;i:7;i:1394597693;}
2014-03-12T04:14:53+00:00 NOTICE: [25603] Error saving state for 
synckey {531fddad-xxxx-xxxx-xxxx-xxxxxxxxxxxx}5: QUERY FAILED: 
Duplicate entry '{531fddad-xxxx-xxxx-xxxx-xxxxxxxxxxxx}5' for key 
'PRIMARY'

INSERT INTO horde_activesync_state (sync_key, sync_data, sync_devid, 
sync_mod, sync_folderid, sync_user, sync_pending, sync_timestamp) 
VALUES ('{531fddad-xxxx-xxxx-xxxx-xxxxxxxxxxxx}5', 
'C:28:"Horde_ActiveSync_Folder_Imap":164:{{"s":{"messages":"1","uidnext":"5378","uidvalidity":"1342278888","highestmodseq":"12679"},"m":"5377","f":"INBOX","c":"Email","lsd":1393992593,"sd":1394597393,"v":2}}', 'ANDROID1xxxx', 1394597693, 'F3ef80eea', 'samuel', 'a:0:{}', 1394597693) - removing previous sync state and trying 
again.
2014-03-12T04:14:53+00:00 DEBUG: [25603] O    </Folder>
2014-03-12T04:14:53+00:00 DEBUG: [25603] O   </Folders>
2014-03-12T04:14:53+00:00 DEBUG: [25603] O  </Synchronize>

Found some errors in the apache log:
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP Fatal 
error:  [] operator not supported for strings in 
/usr/share/php/Horde/ActiveSync/Folder/Imap.php on line 222
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP Stack trace:
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   1. 
{main}() /var/www/https/horde/rpc.php:0
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   2. 
Horde_Rpc_ActiveSync->getResponse() /var/www/https/horde/rpc.php:156
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   3. 
Horde_ActiveSync->handleRequest() 
/usr/share/php/Horde/Rpc/ActiveSync.php:143
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   4. 
Horde_ActiveSync_Request_Base->handle() 
/usr/share/php/Horde/ActiveSync.php:897
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   5. 
Horde_ActiveSync_Request_Sync->_handle() 
/usr/share/php/Horde/ActiveSync/Request/Base.php:249
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   6. 
Horde_ActiveSync_Collections->getCollectionChangeCount() 
/usr/share/php/Horde/ActiveSync/Request/Sync.php:399
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   7. 
Horde_ActiveSync_Collections->getCollectionChanges() 
/usr/share/php/Horde/ActiveSync/Collections.php:1216
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   8. 
Horde_ActiveSync_State_Base->getChanges() 
/usr/share/php/Horde/ActiveSync/Collections.php:1180
[Wed Mar 12 05:29:28 2014] [error] [client 93.201.xx.xx] PHP   9. 
Horde_ActiveSync_Folder_Imap->updateState() 
/usr/share/php/Horde/ActiveSync/State/Base.php:445

Downgrade to Horde_ActiveSync-2.12.4 help.
php5 5.4.4-14+deb7u8
Horde_Mime                2.3.0   stable
Horde_Imap_Client         2.19.0  stable


Saved Queries