[dev] ActiveSync: got "ERR: Invalid address book" on Nokia Mail for exchange, but worked on WindowsMobile 6.1
Lukas Gradl
horde at ssn.at
Tue May 25 16:21:42 UTC 2010
Hi!
I tried to use ActiveSync for Horde.
For testing I did a clean, fresh install of the GIT-Snapshots from
2010-05-15 (tried 2010-05-19 at first, but they crashed PHP).
My Addressbook is in a LDAP-Server (slapd 2.4).
I can use the addressbook in turba, I can sync from Nokia via SyncML.
I also managed to sync a Windows Mobile 6.1 Device - it took 3 tries
till I could sync all 390 Contacts, after that I did a full resysnc
which worked as expected on the first try.
Then I tried Nokia Mail for Exchange 3 on an Nokia E90 Communicator.
I can connect to the Server (seeing a connect in apache logs) and the
E90 and the Server start to talk to each other (e.g. I'm getting a
"starting FolderSync")
But nothing is synched and I get a "ERR: Invalid address book: privat"
in my logs... (full Log attached!)
It's the same user and the same server as for the WM6.1 sync - so the
Addressbook IS valid and accessible for Activesync.
Any Ideas how to proceed?
regards
Lukas
And here is the full Log from the Server:
2010-05-20T19:08:30+02:00 DEBUG: Horde_Rpc::__construct complete
2010-05-20T19:08:30+02:00 DEBUG: Horde_Rpc_ActiveSync::authorize() starting
2010-05-20T19:08:30+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: grl
2010-05-20T19:08:33+02:00 DEBUG: Horde_Rpc_ActiveSync::authorize() exiting
2010-05-20T19:08:33+02:00 DEBUG: Horde_Rpc_ActiveSync::getResponse()
starting for OPTIONS
2010-05-20T19:08:34+02:00 DEBUG: Horde_Rpc::__construct complete
2010-05-20T19:08:34+02:00 DEBUG: Horde_Rpc_ActiveSync::authorize() starting
2010-05-20T19:08:34+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: grl
2010-05-20T19:08:37+02:00 DEBUG: Horde_Rpc_ActiveSync::authorize() exiting
2010-05-20T19:08:37+02:00 DEBUG: Horde_Rpc_ActiveSync::getResponse()
starting for FolderSync
2010-05-20T19:08:37+02:00 DEBUG: [IMEI353659015123157] Device entry does
not exist, creating it.
2010-05-20T19:08:37+02:00 DEBUG: [IMEI353659015123157] Device entry does
not exist for user grl, creating it.
2010-05-20T19:08:37+02:00 INFO: Request received from device:
IMEI353659015123157 Supporting protocol version: 2.5
2010-05-20T19:08:37+02:00 INFO: [Horde_ActiveSync::handleFolderSync]
Beginning FOLDERSYNC
2010-05-20T19:08:37+02:00 DEBUG: Policykey: 0 verified.
2010-05-20T19:08:37+02:00 DEBUG: I <FolderHierarchy:FolderSync>
2010-05-20T19:08:37+02:00 DEBUG: I <FolderHierarchy:SyncKey>
2010-05-20T19:08:37+02:00 DEBUG: I 0
2010-05-20T19:08:37+02:00 DEBUG: I </FolderHierarchy:SyncKey>
2010-05-20T19:08:37+02:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
syncKey: 0
2010-05-20T19:08:37+02:00 DEBUG: [IMEI353659015123157] Resetting device
state.
2010-05-20T19:08:37+02:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
newSyncKey: {18c57e14-6825-4cd2-be35-7681d9b13bb5}1
2010-05-20T19:08:37+02:00 DEBUG: I </FolderHierarchy:FolderSync>
2010-05-20T19:08:37+02:00 DEBUG: Unmatched tagFolderHierarchy:Changes:
2010-05-20T19:08:37+02:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
Preparing to send changes to PIM
2010-05-20T19:08:37+02:00 DEBUG: [IMEI353659015123157] Initializing
folder diff engine
2010-05-20T19:08:37+02:00 DEBUG: Horde::getFolderList()
2010-05-20T19:08:37+02:00 DEBUG: Horde::statFolder(Calendar)
2010-05-20T19:08:37+02:00 DEBUG: Horde::statFolder(Contacts)
2010-05-20T19:08:37+02:00 DEBUG: Horde::statFolder(Tasks)
2010-05-20T19:08:37+02:00 DEBUG: [IMEI353659015123157] Found 3 folder
changes
2010-05-20T19:08:37+02:00 DEBUG: Horde::getFolder(Tasks)
2010-05-20T19:08:37+02:00 DEBUG: Horde::statFolder(Tasks)
2010-05-20T19:08:37+02:00 DEBUG: Updating state during foldersync
2010-05-20T19:08:37+02:00 DEBUG: Horde::getFolder(Contacts)
2010-05-20T19:08:37+02:00 DEBUG: Horde::statFolder(Contacts)
2010-05-20T19:08:37+02:00 DEBUG: Updating state during foldersync
2010-05-20T19:08:37+02:00 DEBUG: Horde::getFolder(Calendar)
2010-05-20T19:08:37+02:00 DEBUG: Horde::statFolder(Calendar)
2010-05-20T19:08:37+02:00 DEBUG: Updating state during foldersync
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:FolderSync>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Status>
2010-05-20T19:08:37+02:00 DEBUG: O 1
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Status/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:SyncKey>
2010-05-20T19:08:37+02:00 DEBUG: O {18c57e14-6825-4cd2-be35-7681d9b13bb5}1
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:SyncKey/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Changes>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Count>
2010-05-20T19:08:37+02:00 DEBUG: O 3
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Count/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Add>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2010-05-20T19:08:37+02:00 DEBUG: O Tasks
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ParentId>
2010-05-20T19:08:37+02:00 DEBUG: O 0
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ParentId/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:DisplayName>
2010-05-20T19:08:37+02:00 DEBUG: O Tasks
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:DisplayName/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Type>
2010-05-20T19:08:37+02:00 DEBUG: O 7
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Type/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Add/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Add>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2010-05-20T19:08:37+02:00 DEBUG: O Contacts
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ParentId>
2010-05-20T19:08:37+02:00 DEBUG: O 0
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ParentId/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:DisplayName>
2010-05-20T19:08:37+02:00 DEBUG: O Contacts
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:DisplayName/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Type>
2010-05-20T19:08:37+02:00 DEBUG: O 9
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Type/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Add/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Add>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2010-05-20T19:08:37+02:00 DEBUG: O Calendar
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ParentId>
2010-05-20T19:08:37+02:00 DEBUG: O 0
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:ParentId/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:DisplayName>
2010-05-20T19:08:37+02:00 DEBUG: O Calendar
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:DisplayName/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Type>
2010-05-20T19:08:37+02:00 DEBUG: O 8
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Type/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Add/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:Changes/>
2010-05-20T19:08:37+02:00 DEBUG: O <FolderHierarchy:FolderSync/>
2010-05-20T19:08:37+02:00 DEBUG: [IMEI353659015123157] Saving state for
synckey {18c57e14-6825-4cd2-be35-7681d9b13bb5}1
2010-05-20T19:08:37+02:00 INFO: User grl logged off
2010-05-20T19:08:38+02:00 DEBUG: Horde_Rpc::__construct complete
2010-05-20T19:08:38+02:00 DEBUG: Horde_Rpc_ActiveSync::authorize() starting
2010-05-20T19:08:38+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: grl
2010-05-20T19:08:42+02:00 DEBUG: Horde_Rpc_ActiveSync::authorize() exiting
2010-05-20T19:08:42+02:00 DEBUG: Horde_Rpc_ActiveSync::getResponse()
starting for Sync
2010-05-20T19:08:42+02:00 DEBUG: SQL QUERY: SELECT device_type,
device_agent, device_ping, device_policykey, device_rwstatus,
device_supported FROM horde_activesync_device d INNER JOIN
horde_activesync_device_users u ON d.device_id = u.device_id WHERE
u.device_id = ? AND u.device_user = ? VALUES: IMEI353659015123157 grl
2010-05-20T19:08:42+02:00 INFO: Request received from device:
IMEI353659015123157 Supporting protocol version: 2.5
2010-05-20T19:08:42+02:00 INFO: [IMEI353659015123157] Handling SYNC command.
2010-05-20T19:08:42+02:00 DEBUG: Policykey: 0 verified.
2010-05-20T19:08:42+02:00 DEBUG: I <Synchronize>
2010-05-20T19:08:42+02:00 DEBUG: I <Folders>
2010-05-20T19:08:42+02:00 DEBUG: I <Folder>
2010-05-20T19:08:42+02:00 DEBUG: I <FolderType>
2010-05-20T19:08:42+02:00 DEBUG: I Contacts
2010-05-20T19:08:42+02:00 INFO: [IMEI353659015123157] Syncing folder
class: Contacts
2010-05-20T19:08:42+02:00 DEBUG: I </FolderType>
2010-05-20T19:08:42+02:00 DEBUG: I <SyncKey>
2010-05-20T19:08:42+02:00 DEBUG: I 0
2010-05-20T19:08:42+02:00 DEBUG: I </SyncKey>
2010-05-20T19:08:42+02:00 DEBUG: I <FolderId>
2010-05-20T19:08:42+02:00 DEBUG: I Contacts
2010-05-20T19:08:42+02:00 INFO: [IMEI353659015123157] Folder server id:
Contacts
2010-05-20T19:08:42+02:00 DEBUG: I </FolderId>
2010-05-20T19:08:42+02:00 DEBUG: I </Folder>
2010-05-20T19:08:42+02:00 DEBUG: Unmatched tagSupported:
2010-05-20T19:08:42+02:00 DEBUG: Unmatched tagDeletesAsMoves:
2010-05-20T19:08:42+02:00 DEBUG: Unmatched tagGetChanges:
2010-05-20T19:08:42+02:00 DEBUG: Unmatched tagWindowSize:
2010-05-20T19:08:42+02:00 DEBUG: Unmatched tagOptions:
2010-05-20T19:08:42+02:00 DEBUG: [IMEI353659015123157] Resetting device
state.
2010-05-20T19:08:42+02:00 DEBUG: Unmatched tagCommands:
2010-05-20T19:08:42+02:00 DEBUG: I </Folders>
2010-05-20T19:08:42+02:00 DEBUG: Unmatched tagFolder:
2010-05-20T19:08:42+02:00 DEBUG: I </Synchronize>
2010-05-20T19:08:42+02:00 INFO: [IMEI353659015123157] Beginning SYNC
Response.
2010-05-20T19:08:42+02:00 DEBUG: O <Synchronize>
2010-05-20T19:08:42+02:00 DEBUG: O <Folders>
2010-05-20T19:08:42+02:00 DEBUG: O <Folder>
2010-05-20T19:08:42+02:00 DEBUG: O <FolderType>
2010-05-20T19:08:42+02:00 DEBUG: O Contacts
2010-05-20T19:08:42+02:00 DEBUG: O <FolderType/>
2010-05-20T19:08:42+02:00 DEBUG: O <SyncKey>
2010-05-20T19:08:42+02:00 DEBUG: O {497e376d-d562-4f55-8a0d-5689e6c4fd65}1
2010-05-20T19:08:42+02:00 DEBUG: O <SyncKey/>
2010-05-20T19:08:42+02:00 DEBUG: O <FolderId>
2010-05-20T19:08:42+02:00 DEBUG: O Contacts
2010-05-20T19:08:42+02:00 DEBUG: O <FolderId/>
2010-05-20T19:08:42+02:00 DEBUG: O <Status>
2010-05-20T19:08:42+02:00 DEBUG: O 1
2010-05-20T19:08:42+02:00 DEBUG: O <Status/>
2010-05-20T19:08:42+02:00 DEBUG: O <Folder/>
2010-05-20T19:08:42+02:00 DEBUG: [IMEI353659015123157] Saving state for
synckey {497e376d-d562-4f55-8a0d-5689e6c4fd65}1
2010-05-20T19:08:42+02:00 DEBUG: O <Folders/>
2010-05-20T19:08:42+02:00 DEBUG: O <Synchronize/>
2010-05-20T19:08:42+02:00 INFO: User grl logged off
2010-05-20T19:08:43+02:00 DEBUG: Horde_Rpc::__construct complete
2010-05-20T19:08:43+02:00 DEBUG: Horde_Rpc_ActiveSync::authorize() starting
2010-05-20T19:08:43+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: grl
2010-05-20T19:08:46+02:00 DEBUG: Horde_Rpc_ActiveSync::authorize() exiting
2010-05-20T19:08:46+02:00 DEBUG: Horde_Rpc_ActiveSync::getResponse()
starting for Sync
2010-05-20T19:08:46+02:00 DEBUG: SQL QUERY: SELECT device_type,
device_agent, device_ping, device_policykey, device_rwstatus,
device_supported FROM horde_activesync_device d INNER JOIN
horde_activesync_device_users u ON d.device_id = u.device_id WHERE
u.device_id = ? AND u.device_user = ? VALUES: IMEI353659015123157 grl
2010-05-20T19:08:46+02:00 INFO: Request received from device:
IMEI353659015123157 Supporting protocol version: 2.5
2010-05-20T19:08:46+02:00 INFO: [IMEI353659015123157] Handling SYNC command.
2010-05-20T19:08:46+02:00 DEBUG: Policykey: 0 verified.
2010-05-20T19:08:46+02:00 DEBUG: I <Synchronize>
2010-05-20T19:08:46+02:00 DEBUG: I <Folders>
2010-05-20T19:08:46+02:00 DEBUG: I <Folder>
2010-05-20T19:08:46+02:00 DEBUG: I <FolderType>
2010-05-20T19:08:46+02:00 DEBUG: I Contacts
2010-05-20T19:08:46+02:00 INFO: [IMEI353659015123157] Syncing folder
class: Contacts
2010-05-20T19:08:46+02:00 DEBUG: I </FolderType>
2010-05-20T19:08:46+02:00 DEBUG: I <SyncKey>
2010-05-20T19:08:46+02:00 DEBUG: I {497e376d-d562-4f55-8a0d-5689e6c4fd65}1
2010-05-20T19:08:46+02:00 DEBUG: I </SyncKey>
2010-05-20T19:08:46+02:00 DEBUG: I <FolderId>
2010-05-20T19:08:46+02:00 DEBUG: I Contacts
2010-05-20T19:08:46+02:00 INFO: [IMEI353659015123157] Folder server id:
Contacts
2010-05-20T19:08:46+02:00 DEBUG: I </FolderId>
2010-05-20T19:08:46+02:00 DEBUG: I <DeletesAsMoves/>
2010-05-20T19:08:46+02:00 DEBUG: Unmatched tagSupported:
2010-05-20T19:08:46+02:00 DEBUG: I <GetChanges/>
2010-05-20T19:08:46+02:00 DEBUG: I <WindowSize>
2010-05-20T19:08:46+02:00 DEBUG: I 50
2010-05-20T19:08:46+02:00 DEBUG: I </WindowSize>
2010-05-20T19:08:46+02:00 DEBUG: I <Options>
2010-05-20T19:08:46+02:00 DEBUG: I <FilterType>
2010-05-20T19:08:46+02:00 DEBUG: I 0
2010-05-20T19:08:46+02:00 DEBUG: I </FilterType>
2010-05-20T19:08:46+02:00 DEBUG: I <Truncation>
2010-05-20T19:08:46+02:00 DEBUG: I 2
2010-05-20T19:08:46+02:00 DEBUG: I </Truncation>
2010-05-20T19:08:46+02:00 DEBUG: I <Conflict>
2010-05-20T19:08:46+02:00 DEBUG: Unmatched tagRtfTruncation:
2010-05-20T19:08:46+02:00 DEBUG: Unmatched tagMIMESupport:
2010-05-20T19:08:46+02:00 DEBUG: Unmatched tagMIMETruncation:
2010-05-20T19:08:46+02:00 DEBUG: I 1
2010-05-20T19:08:46+02:00 DEBUG: I </Conflict>
2010-05-20T19:08:46+02:00 DEBUG: I </Options>
2010-05-20T19:08:46+02:00 DEBUG: [IMEI353659015123157] Loading state for
synckey {497e376d-d562-4f55-8a0d-5689e6c4fd65}1
2010-05-20T19:08:46+02:00 DEBUG: [IMEI353659015123157] SQL query by
Horde_ActiveSync_State:_gc(): SELECT sync_key FROM
horde_activesync_state WHERE sync_devid = ? AND sync_folderid = ?
VALUES: Array
(
[0] => IMEI353659015123157
[1] => Contacts
)
2010-05-20T19:08:46+02:00 DEBUG: I </Folder>
2010-05-20T19:08:46+02:00 DEBUG: Unmatched tagCommands:
2010-05-20T19:08:46+02:00 DEBUG: I </Folders>
2010-05-20T19:08:46+02:00 DEBUG: Unmatched tagFolder:
2010-05-20T19:08:46+02:00 DEBUG: I </Synchronize>
2010-05-20T19:08:46+02:00 INFO: [IMEI353659015123157] Beginning SYNC
Response.
2010-05-20T19:08:46+02:00 DEBUG: O <Synchronize>
2010-05-20T19:08:46+02:00 DEBUG: O <Folders>
2010-05-20T19:08:46+02:00 DEBUG: O <Folder>
2010-05-20T19:08:46+02:00 DEBUG: O <FolderType>
2010-05-20T19:08:46+02:00 DEBUG: O Contacts
2010-05-20T19:08:46+02:00 DEBUG: O <FolderType/>
2010-05-20T19:08:46+02:00 DEBUG: O <SyncKey>
2010-05-20T19:08:46+02:00 DEBUG: O {497e376d-d562-4f55-8a0d-5689e6c4fd65}2
2010-05-20T19:08:46+02:00 DEBUG: O <SyncKey/>
2010-05-20T19:08:46+02:00 DEBUG: O <FolderId>
2010-05-20T19:08:46+02:00 DEBUG: O Contacts
2010-05-20T19:08:46+02:00 DEBUG: O <FolderId/>
2010-05-20T19:08:46+02:00 DEBUG: O <Status>
2010-05-20T19:08:46+02:00 DEBUG: O 1
2010-05-20T19:08:46+02:00 DEBUG: O <Status/>
2010-05-20T19:08:46+02:00 DEBUG: [IMEI353659015123157] Initializing
message diff engine for Contacts
2010-05-20T19:08:46+02:00 DEBUG:
Horde_ActiveSync_Driver_Horde::getServerChanges(Contacts, 0, 1274375326, 0)
2010-05-20T19:08:46+02:00 ERR: Invalid address book: privat
2010-05-20T19:08:46+02:00 DEBUG: [IMEI353659015123157] Found 0 message
changes, checking for PIM initiated changes.
2010-05-20T19:08:46+02:00 DEBUG: [IMEI353659015123157] No PIM changes
present, returning all messages.
2010-05-20T19:08:46+02:00 DEBUG: O <Folder/>
2010-05-20T19:08:46+02:00 DEBUG: [IMEI353659015123157] Saving state for
synckey {497e376d-d562-4f55-8a0d-5689e6c4fd65}2
2010-05-20T19:08:46+02:00 DEBUG: O <Folders/>
2010-05-20T19:08:46+02:00 DEBUG: O <Synchronize/>
2010-05-20T19:08:46+02:00 INFO: User grl logged off
--
----------------------------
software security networks
Lukas Gradl <horde#ssn.at>
Eduard-Bodem-Gasse 5
A - 6020 Innsbruck
Tel: +43-512-214040-0
Fax: +43-512-214040-21
----------------------------
More information about the dev
mailing list