[sync] ***UNCHECKED*** Re: Error when syncing.
Michael J Rubinsky
mrubinsk at horde.org
Sat Jan 14 15:37:40 UTC 2023
Quoting Mike <barjunk at attglobal.net>:
> Quoting Michael J Rubinsky <mrubinsk at horde.org>:
>
>> I would first check the sync log for the device.
>>
>>
>> ________________________________
>> From: Mike <barjunk at attglobal.net>
>> Sent: Tuesday, January 10, 2023 10:57 PM
>> To: sync at lists.horde.org
>> Subject: [sync] Error when syncing.
>>
>>>
>>> I noticed this error in my log today, it has been there for a
>>> while (November of 2022?). There aren't many users on the server,
>>> so just now getting to it.
>>>
>>> ERR: HORDE Error in communicating with ActiveSync server:
>>> Permission Denied [pid 23577 on line 166 of
>>> "/usr/share/php/Horde/Rpc/ActiveSync.php"]
>>> It is evidenced by the fact that when I add a contact, this is
>>> what shows up in the log.
>>>
>>> The strange thing is...if I delete the account and recreate it,
>>> everything gets loaded to the phone, email, contacts and calendar.
>>>
>>> But if I edit a contact or add one, I get this.
>>>
>>> What things should I do to track this down?
>>>
>>> It isn't clear where permission error lies, in the filesystem, in
>>> the horde prefs, etc.
>>>
>>> ActiveSync-2.41.9
>>> Horde-5.2.23
>>> Turba-4.2.29
>>>
>>> Thoughts about things to try?
>>>
>>> --
>>> sync mailing list
>>> Frequently Asked Questions: http://wiki.horde.org/FAQ
>>> To unsubscribe, mail: sync-unsubscribe at lists.horde.org
>>>
>
> I apologize for not saying so sooner, I did do that as well, for
> completeness I've included, what I consider to be the relevant
> parts, here.
>
> To start, I removed the account on the phone and restarted the
> device to ensure there were no remnants of the account on the device.
>
> Additionally, I reset the activesync for that specific user, so that
> it would download everything once again.
>
> Initial setup seems to have worked as expected and all my contacts
> that are in the horde server show up on my phone.
>
> This is the resulting log after I attempt to edit one of my test contacts.
>
> What should I be doing next?
It looks to me like you either don't have permissions to at least one
of the calendars you are trying to sync. Admittedly, it looks like
the error isn't being handled cleanly, but that appears to be the root
cause of the error. It's being thrown from Kronolith::listEvents while
trying to get a list of events to sync, and according to the log snip,
doesn't appear to have anything to do with trying to *edit* the
message. What's weird is that it synchronized the events to begin with.
I would start by looking at the kronolith synchronization preferences.
Do you have "support separate calendars" checked?
It might be worth also re-saving the synchronization prefs page after
making sure you have selected the correct calendars in the "Select
additional calendars to sync" preference. It's possible that pref has
some stale value in it the doesn't correspond to an active calendar.
>
> Device Log:
>
> [21278][2023-01-14T05:17:07-09:00] INFO:
> ----------Horde_Core_ActiveSync_Driver::authenticate() attempt for
> mbarsalou----------
> [21278][2023-01-14T05:17:07-09:00] INFO: ----------FOLDERSYNC
> request received for user mbarsalou
> [21278][2023-01-14T05:17:07-09:00] INFO: ----------Request being
> handled for device: ANDROIDC208026672, of type: Android, supporting
> protocol version: 14.1, using Horde_ActiveSync v2.41.9
> [21278][2023-01-14T05:17:07-09:00] INFO: Policykey: 1701183357 verified.
> [21278][2023-01-14T05:17:07-09:00] I: <FolderHierarchy:FolderSync>
> [21278][2023-01-14T05:17:07-09:00] I: <FolderHierarchy:SyncKey>
> [21278][2023-01-14T05:17:07-09:00] I:
> {63c2b5c9-21cc-49b7-be5c-5324c0a8060a}1
> [21278][2023-01-14T05:17:07-09:00] I: </FolderHierarchy:SyncKey>
> [21278][2023-01-14T05:17:07-09:00] I: </FolderHierarchy:FolderSync>
> [21278][2023-01-14T08:17:07-06:00] O: <FolderHierarchy:FolderSync>
> [21278][2023-01-14T08:17:07-06:00] O: <FolderHierarchy:Status>
> [21278][2023-01-14T08:17:07-06:00] O: 1
> [21278][2023-01-14T08:17:07-06:00] O: </FolderHierarchy:Status>
> [21278][2023-01-14T08:17:07-06:00] O: <FolderHierarchy:SyncKey>
> [21278][2023-01-14T08:17:07-06:00] O:
> {63c2b5c9-21cc-49b7-be5c-5324c0a8060a}1
> [21278][2023-01-14T08:17:07-06:00] O: </FolderHierarchy:SyncKey>
> [21278][2023-01-14T08:17:07-06:00] O: <FolderHierarchy:Changes>
> [21278][2023-01-14T08:17:07-06:00] O: <FolderHierarchy:Count>
> [21278][2023-01-14T08:17:07-06:00] O: 0
> [21278][2023-01-14T08:17:07-06:00] O: </FolderHierarchy:Count>
> [21278][2023-01-14T08:17:07-06:00] O: </FolderHierarchy:Changes>
> [21278][2023-01-14T08:17:07-06:00] O: </FolderHierarchy:FolderSync>
> [21278][2023-01-14T08:17:07-06:00] INFO: Maximum memory usage for
> ActiveSync request: 2097152 bytes.
> [21278][2023-01-14T05:17:08-09:00] INFO:
> ----------Horde_Core_ActiveSync_Driver::authenticate() attempt for
> mbarsalou----------
> [21278][2023-01-14T05:17:08-09:00] INFO: ----------SYNC request
> received for user mbarsalou
> [21278][2023-01-14T05:17:08-09:00] INFO: ----------Request being
> handled for device: ANDROIDC208026672, of type: Android, supporting
> protocol version: 14.1, using Horde_ActiveSync v2.41.9
> [21278][2023-01-14T05:17:08-09:00] INFO: Policykey: 1701183357 verified.
> [21278][2023-01-14T05:17:08-09:00] I: <Synchronize>
> [21278][2023-01-14T05:17:08-09:00] I: <Folders>
> [21278][2023-01-14T05:17:08-09:00] I: <Folder>
> [21278][2023-01-14T05:17:08-09:00] I: <SyncKey>
> [21278][2023-01-14T05:17:08-09:00] I:
> {63c2b5ca-fdc8-4df7-9729-5324c0a8060a}8
> [21278][2023-01-14T05:17:08-09:00] I: </SyncKey>
> [21278][2023-01-14T05:17:08-09:00] I: <FolderId>
> [21278][2023-01-14T05:17:08-09:00] I: F9c8ace29
> [21278][2023-01-14T05:17:08-09:00] I: </FolderId>
> [21278][2023-01-14T05:17:08-09:00] I: <DeletesAsMoves>
> [21278][2023-01-14T05:17:08-09:00] I: 1
> [21278][2023-01-14T05:17:08-09:00] I: </DeletesAsMoves>
> [21278][2023-01-14T05:17:08-09:00] I: <GetChanges />
> [21278][2023-01-14T05:17:08-09:00] I: <WindowSize>
> [21278][2023-01-14T05:17:08-09:00] I: 50
> [21278][2023-01-14T05:17:08-09:00] I: </WindowSize>
> [21278][2023-01-14T05:17:08-09:00] I: <Options>
> [21278][2023-01-14T05:17:08-09:00] I: <FilterType>
> [21278][2023-01-14T05:17:08-09:00] I: 3
> [21278][2023-01-14T05:17:08-09:00] I: </FilterType>
> [21278][2023-01-14T05:17:08-09:00] I: <AirSyncBase:BodyPreference>
> [21278][2023-01-14T05:17:08-09:00] I: <AirSyncBase:Type>
> [21278][2023-01-14T05:17:08-09:00] I: 2
> [21278][2023-01-14T05:17:08-09:00] I: </AirSyncBase:Type>
> [21278][2023-01-14T05:17:08-09:00] I: <AirSyncBase:TruncationSize>
> [21278][2023-01-14T05:17:08-09:00] I: 200000
> [21278][2023-01-14T05:17:08-09:00] I: </AirSyncBase:TruncationSize>
> [21278][2023-01-14T05:17:08-09:00] I: </AirSyncBase:BodyPreference>
> [21278][2023-01-14T05:17:08-09:00] I: </Options>
> [21278][2023-01-14T05:17:08-09:00] I: </Folder>
> [21278][2023-01-14T05:17:08-09:00] I: </Folders>
> [21278][2023-01-14T05:17:08-09:00] I: </Synchronize>
> [21278][2023-01-14T05:17:08-09:00] INFO: Completed parsing incoming
> request. Peak memory usage: 2097152.
> [21278][2023-01-14T05:17:08-09:00] O: <Synchronize>
> [21278][2023-01-14T05:17:08-09:00] O: <Status>
> [21278][2023-01-14T05:17:08-09:00] O: 1
> [21278][2023-01-14T05:17:08-09:00] O: </Status>
> [21278][2023-01-14T05:17:08-09:00] INFO: COLLECTIONS: Initializing
> state for collection: INBOX, synckey:
> {63c2b5ca-fdc8-4df7-9729-5324c0a8060a}8
> [21278][2023-01-14T05:17:08-09:00] O: <Folders>
> [21278][2023-01-14T05:17:08-09:00] O: <Folder>
> [21278][2023-01-14T05:17:08-09:00] O: <SyncKey>
> [21278][2023-01-14T05:17:08-09:00] O:
> {63c2b5ca-fdc8-4df7-9729-5324c0a8060a}8
> [21278][2023-01-14T05:17:08-09:00] O: </SyncKey>
> [21278][2023-01-14T05:17:08-09:00] O: <FolderId>
> [21278][2023-01-14T05:17:08-09:00] O: F9c8ace29
> [21278][2023-01-14T05:17:08-09:00] O: </FolderId>
> [21278][2023-01-14T05:17:08-09:00] O: <Status>
> [21278][2023-01-14T05:17:08-09:00] O: 1
> [21278][2023-01-14T05:17:08-09:00] O: </Status>
> [21278][2023-01-14T05:17:08-09:00] O: </Folder>
> [21278][2023-01-14T05:17:08-09:00] O: </Folders>
> [21278][2023-01-14T05:17:08-09:00] O: </Synchronize>
> [21278][2023-01-14T05:17:08-09:00] INFO: Maximum memory usage for
> ActiveSync request: 2097152 bytes.
> [21278][2023-01-14T05:17:09-09:00] INFO:
> ----------Horde_Core_ActiveSync_Driver::authenticate() attempt for
> mbarsalou----------
> [21278][2023-01-14T05:17:09-09:00] INFO: ----------SYNC request
> received for user mbarsalou
> [21278][2023-01-14T05:17:09-09:00] INFO: ----------Request being
> handled for device: ANDROIDC208026672, of type: Android, supporting
> protocol version: 14.1, using Horde_ActiveSync v2.41.9
> [21278][2023-01-14T05:17:09-09:00] INFO: Policykey: 1701183357 verified.
> [21278][2023-01-14T05:17:09-09:00] I: <Synchronize>
> [21278][2023-01-14T05:17:09-09:00] I: <Folders>
> [21278][2023-01-14T05:17:09-09:00] I: <Folder>
> [21278][2023-01-14T05:17:09-09:00] I: <SyncKey>
> [21278][2023-01-14T05:17:09-09:00] I:
> {63c2b5eb-d93c-4382-b2aa-5324c0a8060a}3
> [21278][2023-01-14T05:17:09-09:00] I: </SyncKey>
> [21278][2023-01-14T05:17:09-09:00] I: <FolderId>
> [21278][2023-01-14T05:17:09-09:00] I: Fc31801f7
> [21278][2023-01-14T05:17:09-09:00] I: </FolderId>
> [21278][2023-01-14T05:17:09-09:00] I: <DeletesAsMoves>
> [21278][2023-01-14T05:17:09-09:00] I: 1
> [21278][2023-01-14T05:17:09-09:00] I: </DeletesAsMoves>
> [21278][2023-01-14T05:17:09-09:00] I: <GetChanges />
> [21278][2023-01-14T05:17:09-09:00] I: <WindowSize>
> [21278][2023-01-14T05:17:09-09:00] I: 50
> [21278][2023-01-14T05:17:09-09:00] I: </WindowSize>
> [21278][2023-01-14T05:17:09-09:00] I: <Options>
> [21278][2023-01-14T05:17:09-09:00] I: <FilterType>
> [21278][2023-01-14T05:17:09-09:00] I: 3
> [21278][2023-01-14T05:17:09-09:00] I: </FilterType>
> [21278][2023-01-14T05:17:09-09:00] I: <AirSyncBase:BodyPreference>
> [21278][2023-01-14T05:17:09-09:00] I: <AirSyncBase:Type>
> [21278][2023-01-14T05:17:09-09:00] I: 2
> [21278][2023-01-14T05:17:09-09:00] I: </AirSyncBase:Type>
> [21278][2023-01-14T05:17:09-09:00] I: <AirSyncBase:TruncationSize>
> [21278][2023-01-14T05:17:09-09:00] I: 200000
> [21278][2023-01-14T05:17:09-09:00] I: </AirSyncBase:TruncationSize>
> [21278][2023-01-14T05:17:09-09:00] I: </AirSyncBase:BodyPreference>
> [21278][2023-01-14T05:17:09-09:00] I: </Options>
> [21278][2023-01-14T05:17:09-09:00] I: </Folder>
> [21278][2023-01-14T05:17:09-09:00] I: </Folders>
> [21278][2023-01-14T05:17:09-09:00] I: </Synchronize>
> [21278][2023-01-14T05:17:09-09:00] INFO: Completed parsing incoming
> request. Peak memory usage: 2097152.
> [21278][2023-01-14T05:17:09-09:00] O: <Synchronize>
> [21278][2023-01-14T05:17:09-09:00] O: <Status>
> [21278][2023-01-14T05:17:09-09:00] O: 1
> [21278][2023-01-14T05:17:09-09:00] O: </Status>
> [21278][2023-01-14T05:17:09-09:00] INFO: COLLECTIONS: Initializing
> state for collection: Sent, synckey:
> {63c2b5eb-d93c-4382-b2aa-5324c0a8060a}3
> [21278][2023-01-14T05:17:09-09:00] O: <Folders>
> [21278][2023-01-14T05:17:09-09:00] O: <Folder>
> [21278][2023-01-14T05:17:09-09:00] O: <SyncKey>
> [21278][2023-01-14T05:17:09-09:00] O:
> {63c2b5eb-d93c-4382-b2aa-5324c0a8060a}3
> [21278][2023-01-14T05:17:09-09:00] O: </SyncKey>
> [21278][2023-01-14T05:17:09-09:00] O: <FolderId>
> [21278][2023-01-14T05:17:09-09:00] O: Fc31801f7
> [21278][2023-01-14T05:17:09-09:00] O: </FolderId>
> [21278][2023-01-14T05:17:09-09:00] O: <Status>
> [21278][2023-01-14T05:17:09-09:00] O: 1
> [21278][2023-01-14T05:17:09-09:00] O: </Status>
> [21278][2023-01-14T05:17:09-09:00] O: </Folder>
> [21278][2023-01-14T05:17:09-09:00] O: </Folders>
> [21278][2023-01-14T05:17:09-09:00] O: </Synchronize>
> [21278][2023-01-14T05:17:09-09:00] INFO: Maximum memory usage for
> ActiveSync request: 2097152 bytes.
> [21278][2023-01-14T05:17:10-09:00] INFO:
> ----------Horde_Core_ActiveSync_Driver::authenticate() attempt for
> mbarsalou----------
> [21278][2023-01-14T05:17:10-09:00] INFO: ----------SYNC request
> received for user mbarsalou
> [21278][2023-01-14T05:17:10-09:00] INFO: ----------Request being
> handled for device: ANDROIDC208026672, of type: Android, supporting
> protocol version: 14.1, using Horde_ActiveSync v2.41.9
> [21278][2023-01-14T05:17:10-09:00] INFO: Policykey: 1701183357 verified.
> [21278][2023-01-14T05:17:10-09:00] I: <Synchronize>
> [21278][2023-01-14T05:17:10-09:00] I: <Folders>
> [21278][2023-01-14T05:17:10-09:00] I: <Folder>
> [21278][2023-01-14T05:17:10-09:00] I: <SyncKey>
> [21278][2023-01-14T05:17:10-09:00] I:
> {63c2b5ed-2400-479c-b401-5324c0a8060a}2
> [21278][2023-01-14T05:17:10-09:00] I: </SyncKey>
> [21278][2023-01-14T05:17:10-09:00] I: <FolderId>
> [21278][2023-01-14T05:17:10-09:00] I: A3cbbfe78
> [21278][2023-01-14T05:17:10-09:00] I: </FolderId>
> [21278][2023-01-14T05:17:10-09:00] I: <DeletesAsMoves />
> [21278][2023-01-14T05:17:10-09:00] I: <GetChanges />
> [21278][2023-01-14T05:17:10-09:00] I: <WindowSize>
> [21278][2023-01-14T05:17:10-09:00] I: 10
> [21278][2023-01-14T05:17:10-09:00] I: </WindowSize>
> [21278][2023-01-14T05:17:10-09:00] I: <Options>
> [21278][2023-01-14T05:17:10-09:00] I: <FilterType>
> [21278][2023-01-14T05:17:10-09:00] I: 4
> [21278][2023-01-14T05:17:10-09:00] I: </FilterType>
> [21278][2023-01-14T05:17:10-09:00] I: <AirSyncBase:BodyPreference>
> [21278][2023-01-14T05:17:10-09:00] I: <AirSyncBase:Type>
> [21278][2023-01-14T05:17:10-09:00] I: 1
> [21278][2023-01-14T05:17:10-09:00] I: </AirSyncBase:Type>
> [21278][2023-01-14T05:17:10-09:00] I: <AirSyncBase:TruncationSize>
> [21278][2023-01-14T05:17:10-09:00] I: 200000
> [21278][2023-01-14T05:17:10-09:00] I: </AirSyncBase:TruncationSize>
> [21278][2023-01-14T05:17:10-09:00] I: </AirSyncBase:BodyPreference>
> [21278][2023-01-14T05:17:10-09:00] I: </Options>
> [21278][2023-01-14T05:17:10-09:00] I: </Folder>
> [21278][2023-01-14T05:17:10-09:00] I: </Folders>
> [21278][2023-01-14T05:17:10-09:00] I: </Synchronize>
> [21278][2023-01-14T05:17:10-09:00] INFO: Completed parsing incoming
> request. Peak memory usage: 2097152.
> [21278][2023-01-14T05:17:10-09:00] O: <Synchronize>
> [21278][2023-01-14T05:17:10-09:00] O: <Status>
> [21278][2023-01-14T05:17:10-09:00] O: 1
> [21278][2023-01-14T05:17:10-09:00] O: </Status>
> [21278][2023-01-14T05:17:10-09:00] INFO: COLLECTIONS: Initializing
> state for collection: @Calendar@, synckey:
> {63c2b5ed-2400-479c-b401-5324c0a8060a}2
> [21278][2023-01-14T08:17:10-06:00] ERR: Permission Denied
>
>
> Horde log:
>
> 2023-01-14T08:17:10-06:00 ERR: HORDE Returning HTTP 500 while
> handling Sync command. Error is: Permission Denied [pid 21278 on
> line 160 of "/usr/share/horde/rpc.php"]
> 2023-01-14T08:17:10-06:00 ERR: HORDE Error in communicating with
> ActiveSync server: Permission Denied [pid 21278 on line 166 of
> "/usr/share/php/Horde/Rpc/ActiveSync.php"]
> 2023-01-14T08:17:10-06:00 ERR: HORDE #0
> /usr/share/php/Horde/Registry.php(1132):
> Kronolith_Api->listEvents(1673704942, 1672496230, Array, false,
> false, false, true, false)
> #1 /usr/share/php/Horde/Registry.php(1089):
> Horde_Registry->callByPackage('kronolith', 'listEvents', Array)
> #2 /usr/share/php/Horde/Registry/Caller.php(41):
> Horde_Registry->call('calendar/listEv...', Array)
> #3 /usr/share/php/Horde/Core/ActiveSync/Connector.php(1189):
> Horde_Registry_Caller->__call('listEvents', Array)
> #4 /usr/share/php/Horde/Core/ActiveSync/Driver.php(1017):
> Horde_Core_ActiveSync_Connector->softDelete('calendar', 1673704942,
> 1672496230, NULL)
> #5 /usr/share/php/Horde/ActiveSync/State/Base.php(428):
> Horde_Core_ActiveSync_Driver->getServerChanges(Object(Horde_ActiveSync_Folder_Collection), 2804, 2804, 1672496230, false, true, 100,
> false)
> #6 /usr/share/php/Horde/ActiveSync/Collections.php(1390):
> Horde_ActiveSync_State_Base->getChanges(Array)
> #7 /usr/share/php/Horde/ActiveSync/Collections.php(1406):
> Horde_ActiveSync_Collections->getCollectionChanges(false)
> #8 /usr/share/php/Horde/ActiveSync/Request/Sync.php(362):
> Horde_ActiveSync_Collections->getCollectionChangeCount()
> #9 /usr/share/php/Horde/ActiveSync/Request/Base.php(250):
> Horde_ActiveSync_Request_Sync->_handle()
> #10 /usr/share/php/Horde/ActiveSync.php(840):
> Horde_ActiveSync_Request_Base->handle()
> #11 /usr/share/php/Horde/Rpc/ActiveSync.php(144):
> Horde_ActiveSync->handleRequest('Sync', 'ANDROIDC2080266...')
> #12 /usr/share/horde/rpc.php(160): Horde_Rpc_ActiveSync->getResponse(NULL)
> #13 {main} [pid 21278 on line 166 of
> "/usr/share/php/Horde/Rpc/ActiveSync.php"]
> 2023-01-14T08:17:10-06:00 ERR: HORDE Buffer contents: [pid 21278 on
> line 166 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
--
mike
The Horde Project
http://www.horde.org
https://www.facebook.com/hordeproject
https://www.twitter.com/hordeproject
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-keys
Size: 9386 bytes
Desc: PGP Public Key
URL: <https://lists.horde.org/archives/sync/attachments/20230114/dfe525c5/attachment-0001.key>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 851 bytes
Desc: PGP Digital Signature
URL: <https://lists.horde.org/archives/sync/attachments/20230114/dfe525c5/attachment-0001.sig>
More information about the sync
mailing list