[sync] ActiveSync: got "ERR: Invalid address book" on Nokia Mail for exchange, but worked on WindowsMobile 6.1

Lukas Gradl horde at ssn.at
Thu May 20 17:21:13 UTC 2010


On 2010-05-20 02:15, Lukas Gradl wrote:
> Hi!
>
> I tried to use ActiveSync for Horde.
>

OK after some further testing I discovered that when synching with Mail 
for Exchange 3 in function listContacts() in turba/lib/Api.php the 
variable $cfgSources is an empty array. When synching with WM 6.1 
everything works fine...

I made a trace of the synching-attempt with Mail for Exchange on a Nokia 
E90 Communicator.

Anyone an Idea what I missed?

Regards
Lukas

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 sync mailing list