[horde] ActiveSync Ping/Sync flooding in webserver log

Thu Jul 20 08:51:00 UTC 2017

Quoting Volker Then <horde40 at volkerthen.com>:

> Hi Mike,
>
> I have activesync problems with two clients, both using Outlook  
> 15.0.4945 (and alos Outlook 16), and both are flooding the webserver  
> log with Ping/sync requests.
>
> In the device logs I found lines like this
>
> NOTICE: STATE: Error saving state, checking if this is due to  
> previous synckey {596f159b-37c0-4f03-aaa9-2a9494fb36a2}3 not being  
> accepted by client.
>
>
>
> [31116][2017-07-19T12:29:47+02:00] ERR: Permission Denied
> [822][2017-07-19T12:29:47+02:00] INFO:  
> ----------Horde_Core_ActiveSync_Driver::authenticate() attempt for  
> *********_wagner----------
> [822][2017-07-19T12:29:47+02:00] INFO: ----------PING request  
> received for user *********_wagner
> [822][2017-07-19T12:29:47+02:00] INFO: ----------Request being  
> handled for device: C7192254727E416BB3F0D430B5363C9E, Supporting  
> protocol version: 14.0, Using Horde_ActiveSync v2.38.6
>
>
> [886][2017-07-19T12:29:43+02:00] ERR: COLLECTIONS: Attempting to add  
> a collection
>                     to the sync cache while requiring a synckey, but no
>                     synckey could be found. Most likely a client error in
>                     requesting a collection during PING before it  
> has issued a
>
>
> Both users share their resources (calendars) with each other and  
> other users. Syncing on iOS and Android, both native and Outlook  
> work properly.
>
> What can cause the issue? I tried to remove the device and resync.  
> No success. Removing and reinstalling the accounts on Outlook, no  
> success.
>
> Regards,
>
> Volker

Hi,

seems I don't receive anymore list mails, something broken?

I checked the accounts now on an older Outlook version, but again the  
sync process floods the logfiles. Constant Login/Logouts on the IMAP  
server, and loads of error messages in the horde.log, "integrity  
constraint violation". Any way that I can fix this?

2017-07-20T10:40:15+02:00 ERR: HORDE Buffer contents:  [pid 28620 on  
line 165 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-07-20T10:40:16+02:00 NOTICE: HORDE [imp] Login success for  
user_petri (84.189.194.183) to {imap://localhost/} [pid 28833 on line  
157 of "/var/www/horde/imp/lib/Auth.php"]
2017-07-20T10:40:16+02:00 NOTICE: HORDE [imp] Login success for  
user_petri (84.189.194.183) to {imap://localhost/} [pid 29854 on line  
157 of "/var/www/horde/imp/lib/Auth.php"]
2017-07-20T10:40:16+02:00 ERR: HORDE SQL QUERY FAILED:  
SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry  
'{59706a84-5788-4862-8c5b-651b94fb36a2}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 (?, :binary0, ?,  
?, ?, ?, ?,
           ?) [pid 29854 on line 282 of  
"/usr/share/php/Horde/Db/Adapter/Pdo/Base.php"]
2017-07-20T10:40:17+02:00 ERR: HORDE SQL QUERY FAILED:  
SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry  
'{59706a84-be84-4252-89d1-651b94fb36a2}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 (?, :binary0, ?,  
?, ?, ?, ?,
           ?) [pid 29854 on line 282 of  
"/usr/share/php/Horde/Db/Adapter/Pdo/Base.php"]
2017-07-20T10:40:17+02:00 ERR: HORDE Returning HTTP 500 while handling  
Sync command. Error is: Permission Denied [pid 29854 on line 160 of  
"/var/www/horde/rpc.php"]
2017-07-20T10:40:17+02:00 ERR: HORDE Error in communicating with  
ActiveSync server: Permission Denied [pid 29854 on line 165 of  
"/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-07-20T10:40:17+02:00 ERR: HORDE #0 [internal function]:  
Kronolith_Api->listEvents(1500539585, 0, Array, false, false, false,  
true, false)
#1 /usr/share/php/Horde/Registry.php(1132): call_user_func_array(Array, Array)
#2 /usr/share/php/Horde/Registry.php(1089):  
Horde_Registry->callByPackage('kronolith', 'listEvents', Array)
#3 /usr/share/php/Horde/Registry/Caller.php(41):  
Horde_Registry->call('calendar/listEv...', Array)
#4 /usr/share/php/Horde/Core/ActiveSync/Connector.php(1187):  
Horde_Registry_Caller->__call('listEvents', Array)
#5 /usr/share/php/Horde/Core/ActiveSync/Connector.php(1187):  
Horde_Registry_Caller->listEvents(1500539585, 0, Array, false, false,  
false, true, false)
#6 /usr/share/php/Horde/Core/ActiveSync/Driver.php(1004):  
Horde_Core_ActiveSync_Connector->softDelete('calendar', 1500539585, 0,  
'RNE1Y4G7GEhobMo...')
#7 /usr/share/php/Horde/ActiveSync/State/Base.php(433):  
Horde_Core_ActiveSync_Driver->getServerChanges(Object(Horde_ActiveSync_Folder_Collection), 23552, 23552, 0, false, true, 100,  
false)
#8 /usr/share/php/Horde/ActiveSync/Collections.php(1395):  
Horde_ActiveSync_State_Base->getChanges(Array)
#9 /usr/share/php/Horde/ActiveSync/Collections.php(1411):  
Horde_ActiveSync_Collections->getCollectionChanges(false)
#10 /usr/share/php/Horde/ActiveSync/Request/Sync.php(371):  
Horde_ActiveSync_Collections->getCollectionChangeCount()
#11 /usr/share/php/Horde/ActiveSync/Request/Base.php(249):  
Horde_ActiveSync_Request_Sync->_handle()
#12 /usr/share/php/Horde/ActiveSync.php(839):  
Horde_ActiveSync_Request_Base->handle()
#13 /usr/share/php/Horde/Rpc/ActiveSync.php(143):  
Horde_ActiveSync->handleRequest('Sync', '4E5767145FF1415...')
#14 /var/www/horde/rpc.php(160): Horde_Rpc_ActiveSync->getResponse(NULL)
#15 {main} [pid 29854 on line 165 of  
"/usr/share/php/Horde/Rpc/ActiveSync.php"]