[sync] Error when syncing.
Mike
barjunk at attglobal.net
Sat Jan 14 14:29:34 UTC 2023
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?
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"]
More information about the sync
mailing list