[Tickets #8032] Error with funambol outlook plugin and horde rpc.php
bugs at horde.org
bugs at horde.org
Wed Feb 25 12:32:27 UTC 2009
DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.
Ticket URL: http://bugs.horde.org/ticket/8032
------------------------------------------------------------------------------
Ticket | 8032
Created By | emilio.campos.martin at gmail.com
Summary | Error with funambol outlook plugin and horde rpc.php
Queue | SyncML
Type | Enhancement
State | New
Priority | 2. Medium
Milestone |
Patch |
Owners |
------------------------------------------------------------------------------
emilio.campos.martin at gmail.com (2009-02-25 07:32) wrote:
Hello!
I`m using funambol outlook plugin v 7.0.7 and Horde Groupware Webmail
Edition 1.1
I configured my funambol outlook client to sync with horde with url
(http://10.234.16.84/rpc.php) for syncronize contacts, but y see the
error in client "sync not completed. see log for details
The outlook plugin log see:
--------------------------------------
13:27:31 GMT +1:00 [DEBUG] - Synchronization URL: http://10.234.16.84/rpc.php
13:27:31 GMT +1:00 [INFO] - Preparing synchronization of contact...
13:27:31 GMT +1:00 [DEBUG] - Checking devinfo...
13:27:31 GMT +1:00 [DEBUG] - devinfo hash: 0KUYxD1VA1Df/eKlizJMxw==
13:27:31 GMT +1:00 [DEBUG] - devinfo unchanged, no need to send
13:27:31 GMT +1:00 [DEBUG] - Initialization message:
13:27:31 GMT +1:00 [DEBUG] - User Agent = Funambol Outlook Plug-in v. 7.0.7
13:27:31 GMT +1:00 [DEBUG] - Initialization sent.
13:27:31 GMT +1:00 [DEBUG] - <?xml version="1.0" encoding="UTF-8"?>
<SyncML>
<SyncHdr><VerDTD>1.1</VerDTD>
<VerProto>SyncML/1.1</VerProto>
<SessionID>1235564851</SessionID>
<MsgID>1</MsgID>
<Target><LocURI>http://10.234.16.84/rpc.php</LocURI>
</Target>
<Source><LocURI>fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg==</LocURI>
</Source>
<Cred><Meta><Format xmlns="syncml:metinf">b64</Format>
<Type xmlns="syncml:metinf">syncml:auth-basic</Type>
</Meta>
<Data>cm9ibGVkb2VkdWFyZG85OXI6cm9ibGVkb2VkdWFyZG85OVI=</Data>
</Cred>
<Meta><MaxMsgSize xmlns="syncml:metinf">250000</MaxMsgSize>
</Meta>
</SyncHdr>
<SyncBody><Alert><CmdID>1</CmdID>
<Data>200</Data>
<Item><Target><LocURI>contacts</LocURI>
</Target>
<Source><LocURI>contact</LocURI>
</Source>
<Meta><Anchor xmlns="syncml:metinf"><Last>0</Last>
<Next>1235564851</Next>
</Anchor>
</Meta>
</Item>
</Alert>
<Final/></SyncBody>
</SyncML>
13:27:31 GMT +1:00 [DEBUG] - Connecting to 10.234.16.84:80
13:27:31 GMT +1:00 [DEBUG] - Requesting resource /rpc.php
13:27:31 GMT +1:00 [DEBUG] - Sending data of size 848...
13:27:31 GMT +1:00 [DEBUG] - Message sent
13:27:31 GMT +1:00 [DEBUG] - Finished sending data of size 848.
13:27:31 GMT +1:00 [DEBUG] - Data sent succesfully to server. Server
responds OK
13:27:31 GMT +1:00 [DEBUG] - Header:
13:27:31 GMT +1:00 [DEBUG] - Reading response...
13:27:31 GMT +1:00 [DEBUG] - Content-length: 1220
13:27:31 GMT +1:00 [DEBUG] - Receiving data of size 1220...
13:27:31 GMT +1:00 [DEBUG] - Finished receiving data of size 1220.
13:27:31 GMT +1:00 [DEBUG] - Response read:
<SyncML><SyncHdr><VerDTD>1.1</VerDTD><VerProto>SyncML/1.1</VerProto><SessionID>1235564851</SessionID><MsgID>1</MsgID><Target><LocURI>fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg==</LocURI><LocName>robledoeduardo99r</LocName></Target><Source><LocURI>http://10.234.16.84/rpc.php</LocURI></Source></SyncHdr><SyncBody><Status><CmdID>1</CmdID><MsgRef>1</MsgRef><CmdRef>0</CmdRef><Cmd>SyncHdr</Cmd><TargetRef>http://10.234.16.84/rpc.php</TargetRef><SourceRef>fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg==</SourceRef><Data>212</Data></Status><Status><CmdID>2</CmdID><MsgRef>1</MsgRef><CmdRef>1</CmdRef><Cmd>Alert</Cmd><TargetRef>contacts</TargetRef><SourceRef>contact</SourceRef><Data>508</Data><Item><Data><Anchor xmlns="syncml:metinf"><Last>0</Last><Next>1235564851</Next></Anchor></Data></Item></Status><Alert><CmdID>3</CmdID><Data>201</Data><Item><Target><LocURI>contact</LocURI></Target><Source><LocURI>contacts</LocURI></Source><Meta><Anchor xmlns="syncml:metinf"><Last>0</Last><Next>1235564970</Next></Anchor></Meta></Item></Alert><Get><CmdID>4</CmdID><Meta><Type
xmlns="syncml:metinf">application/vnd.syncml-devinf+xml</Type></Meta><Item><Target><LocURI>./devinf11</LocURI></Target></Item></Get><Final></Final></SyncBody></SyncML>
13:27:31 GMT +1:00 [DEBUG] - Server requested syncmode "slow" for contact.
13:27:31 GMT +1:00 [DEBUG] - Checking for forced slow-sync...
13:27:31 GMT +1:00 [DEBUG] - Initialize COM library
13:27:31 GMT +1:00 [DEBUG] - Create Outlook.Application instance...
13:27:31 GMT +1:00 [DEBUG] - Logon to Outlook MAPI: default profile,
show-dialog = true, new-session = false
13:27:31 GMT +1:00 [DEBUG] - Creating Redemption.MAPIUtils instance...
13:27:31 GMT +1:00 [DEBUG] - Creating Redemption.RDOSession instance...
13:27:31 GMT +1:00 [INFO] - Outlook session opened successfully!
Using: Outlook 2003.
13:27:32 GMT +1:00 [DEBUG] - ---------------------- contact BEGIN
(mode "slow") ----------------------
13:27:32 GMT +1:00 [DEBUG] - beginSync of contact source: opening
Outlook session...
13:27:32 GMT +1:00 [DEBUG] - Reading ALL contacts from folder
'\\Carpetas personales\Contactos' (0 found)...
13:27:32 GMT +1:00 [INFO] - Total contact items to send: 0
13:27:32 GMT +1:00 [DEBUG] - Modification message: estimated size 150,
allowed size 250000, real size 3964 / estimated size 150 = 2642%
13:27:32 GMT +1:00 [DEBUG] - Modifications sent.
13:27:32 GMT +1:00 [DEBUG] - <?xml version="1.0" encoding="UTF-8"?>
<SyncML>
<SyncHdr><VerDTD>1.1</VerDTD>
<VerProto>SyncML/1.1</VerProto>
<SessionID>1235564851</SessionID>
<MsgID>2</MsgID>
<Target><LocURI>http://10.234.16.84/rpc.php</LocURI>
</Target>
<Source><LocURI>fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg==</LocURI>
</Source>
</SyncHdr>
<SyncBody><Status><CmdID>1</CmdID>
<MsgRef>1</MsgRef>
<CmdRef>0</CmdRef>
<Cmd>SyncHdr</Cmd>
<TargetRef>http://10.234.16.84/rpc.php</TargetRef>
<SourceRef>fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg==</SourceRef>
<Data>200</Data>
</Status>
<Status><CmdID>2</CmdID>
<MsgRef>1</MsgRef>
<CmdRef>3</CmdRef>
<Cmd>Alert</Cmd>
<TargetRef>contacts</TargetRef>
<SourceRef>contact</SourceRef>
<Data>200</Data>
<Item><Data><Anchor xmlns="syncml:metinf"><Next>1235564970</Next>
</Anchor>
</Data>
</Item>
</Status>
<Status><CmdID>4</CmdID>
<MsgRef>1</MsgRef>
<CmdRef>4</CmdRef>
<Cmd>Get</Cmd>
<Data>200</Data>
</Status>
<Results><CmdID>3</CmdID>
<MsgRef>1</MsgRef>
<CmdRef>4</CmdRef>
<Meta><Type xmlns="syncml:metinf">application/vnd.syncml-devinf+xml</Type>
</Meta>
<Item><Source><LocURI>./devinf11</LocURI>
</Source>
<Data><DevInf xmlns="syncml:devinf"><VerDTD>1.1</VerDTD>
<Man>Funambol</Man>
<Mod>Funambol Outlook Plug-in</Mod>
<SwV>7.0.7</SwV>
<DevID>fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg==</DevID>
<DevTyp>workstation</DevTyp>
<UTC/><SupportLargeObjs/><SupportNumberOfChanges/><DataStore><SourceRef>appointment</SourceRef>
<Rx-Pref><CTType>text/x-s4j-sife</CTType>
<VerCT>1.1</VerCT>
</Rx-Pref>
<Rx><CTType>text/x-s4j-sife</CTType>
<VerCT>1.0</VerCT>
</Rx>
<Rx><CTType>text/x-vcalendar</CTType>
<VerCT>1.0</VerCT>
</Rx>
<Tx-Pref><CTType>text/x-s4j-sife</CTType>
<VerCT>1.1</VerCT>
</Tx-Pref>
<Tx><CTType>text/x-s4j-sife</CTType>
<VerCT>1.0</VerCT>
</Tx>
<Tx><CTType>text/x-vcalendar</CTType>
<VerCT>1.0</VerCT>
</Tx>
<SyncCap><SyncType>2</SyncType>
<SyncType>1</SyncType>
<SyncType>5</SyncType>
<SyncType>3</SyncType>
<SyncType>6</SyncType>
<SyncType>4</SyncType>
</SyncCap>
</DataStore>
<DataStore><SourceRef>contact</SourceRef>
<Rx-Pref><CTType>text/x-vcard</CTType>
<VerCT>2.1</VerCT>
</Rx-Pref>
<Rx><CTType>text/x-s4j-sifc</CTType>
<VerCT>1.0</VerCT>
</Rx>
<Rx><CTType>text/x-vcard</CTType>
<VerCT>2.1</VerCT>
</Rx>
<Tx-Pref><CTType>text/x-vcard</CTType>
<VerCT>2.1</VerCT>
</Tx-Pref>
<Tx><CTType>text/x-s4j-sifc</CTType>
<VerCT>1.0</VerCT>
</Tx>
<Tx><CTType>text/x-vcard</CTType>
<VerCT>2.1</VerCT>
</Tx>
<SyncCap><SyncType>2</SyncType>
<SyncType>1</SyncType>
<SyncType>5</SyncType>
<SyncType>3</SyncType>
<SyncType>6</SyncType>
<SyncType>4</SyncType>
</SyncCap>
</DataStore>
<DataStore><SourceRef>note</SourceRef>
<Rx-Pref><CTType>text/x-s4j-sifn</CTType>
<VerCT>1.1</VerCT>
</Rx-Pref>
<Rx><CTType>text/x-s4j-sifn</CTType>
<VerCT>1.0</VerCT>
</Rx>
<Rx><CTType>text/x-vnote</CTType>
<VerCT>1.1</VerCT>
</Rx>
<Tx-Pref><CTType>text/x-s4j-sifn</CTType>
<VerCT>1.1</VerCT>
</Tx-Pref>
<Tx><CTType>text/x-s4j-sifn</CTType>
<VerCT>1.0</VerCT>
</Tx>
<Tx><CTType>text/x-vnote</CTType>
<VerCT>1.1</VerCT>
</Tx>
<SyncCap><SyncType>2</SyncType>
<SyncType>1</SyncType>
<SyncType>5</SyncType>
<SyncType>3</SyncType>
<SyncType>6</SyncType>
<SyncType>4</SyncType>
</SyncCap>
</DataStore>
<DataStore><SourceRef>task</SourceRef>
<Rx-Pref><CTType>text/x-s4j-sift</CTType>
<VerCT>1.1</VerCT>
</Rx-Pref>
<Rx><CTType>text/x-s4j-sift</CTType>
<VerCT>1.0</VerCT>
</Rx>
<Rx><CTType>text/x-vcalendar</CTType>
<VerCT>1.0</VerCT>
</Rx>
<Tx-Pref><CTType>text/x-s4j-sift</CTType>
<VerCT>1.1</VerCT>
</Tx-Pref>
<Tx><CTType>text/x-s4j-sift</CTType>
<VerCT>1.0</VerCT>
</Tx>
<Tx><CTType>text/x-vcalendar</CTType>
<VerCT>1.0</VerCT>
</Tx>
<SyncCap><SyncType>2</SyncType>
<SyncType>1</SyncType>
<SyncType>5</SyncType>
<SyncType>3</SyncType>
<SyncType>6</SyncType>
<SyncType>4</SyncType>
</SyncCap>
</DataStore>
</DevInf>
</Data>
</Item>
</Results>
<Sync><CmdID>5</CmdID>
<Target><LocURI>contacts</LocURI>
</Target>
<Source><LocURI>contact</LocURI>
</Source>
</Sync>
<Final/></SyncBody>
</SyncML>
13:27:32 GMT +1:00 [DEBUG] - Connecting to 10.234.16.84:80
13:27:32 GMT +1:00 [DEBUG] - Requesting resource /rpc.php
13:27:32 GMT +1:00 [DEBUG] - Sending data of size 3964...
13:27:33 GMT +1:00 [DEBUG] - Message sent
13:27:33 GMT +1:00 [DEBUG] - Finished sending data of size 3964.
13:27:33 GMT +1:00 [DEBUG] - HTTP server error: 500. Server failure.
13:27:33 GMT +1:00 [DEBUG] - ---------------------- END (mode "none")
----------------------
13:27:33 GMT +1:00 [DEBUG] - Server requested syncmode "none" for .
13:27:33 GMT +1:00 [DEBUG] - Error occurred in sync: code 3 = HTTP
server error: 500. Server failure.
13:27:33 GMT +1:00 [ERROR] - Error in syncing: HTTP server error: 500.
Server failure.
13:27:33 GMT +1:00 [INFO] -
============================================================
================ SYNCHRONIZATION REPORT ================
============================================================
SYNCHRONIZATION COMPLETED WITH ERRORS
-------------------------------------
Last error message = "HTTP server error: 500. Server failure."
Last error code = 2052
Contacts:
---------
Sync completed successfully!
Sync type: slow (requested by Server)
| on Client | on Server
--------|-----------|----------
New | 0/ 0 | 0/ 0
Updated | 0/ 0 | 0/ 0
Deleted | 0/ 0 | 0/ 0
13:27:33 GMT +1:00 [DEBUG] - Saving configuration to winRegistry
13:27:33 GMT +1:00 [DEBUG] - Writing configuration settings to the
management tree
13:27:33 GMT +1:00 [DEBUG] - Closing Outlook...
13:27:33 GMT +1:00 [DEBUG] - Deleting ClientApplication instance
13:27:33 GMT +1:00 [DEBUG] - Detaching IMAPIUtils object...
13:27:33 GMT +1:00 [INFO] - Outlook session closed successfully.
13:27:33 GMT +1:00 [DEBUG] - Closing COM library...
13:27:33 GMT +1:00 [DEBUG] - Releasing sync-mutex...
13:27:33 GMT +1:00 [DEBUG] - Sync-mutex released - closing handle.
13:27:33 GMT +1:00 [DEBUG] - Delete SyncSources...
13:27:33 GMT +1:00 [INFO] - Syncronization process completed with
errors (code = 2052).
------------------------------------------
In the server see logs info:
In horde.log
---------------------------------------------
Feb 25 13:27:18 HORDE [debug] [horde] SQL Query by
SessionHandler_mysql::read(): query = "SELECT session_data FROM
horde_sessionhandler WHERE session_id =
'syncmlfolU0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg1235564722' AND
session_lastmodified > 1235563398 FOR UPDATE" [on line 105 of
"/express/web/horde/lib/Horde/SessionHandler/mysql.php"]
Feb 25 13:27:18 HORDE [debug] [horde] SyncML: New session created:
syncmlfolU0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg1235564722 [on line 172 of
"/express/web/horde/lib/SyncML.php"]
Feb 25 13:27:18 HORDE [debug] [horde] SyncML: checking auth for
user=robledoeduardo99r [on line 261 of
"/express/web/horde/lib/SyncML/State.php"]
Feb 25 13:27:19 HORDE [debug] [imp] SQL Query by
Prefs_sql::retrieve(): SELECT pref_scope, pref_name, pref_value FROM
horde_prefs WHERE pref_uid = ? AND (pref_scope = ? OR pref_scope =
'horde') ORDER BY pref_scope [on line 137 of
"/express/web/horde/lib/Horde/Prefs/sql.php"]
Feb 25 13:27:19 HORDE [debug] [imp] SQL Query by
DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents
FROM horde_datatree WHERE datatree_name = ? AND group_uid = ? ORDER BY
datatree_id [on line 261 of
"/express/web/horde/lib/Horde/DataTree/sql.php"]
Feb 25 13:27:19 HORDE [debug] [imp] SQL Query by
DataTree_sql::_load(): SELECT c.datatree_id, c.datatree_name,
c.datatree_parents, c.datatree_order FROM horde_datatree c WHERE
c.group_uid = 'horde.perms' [on line 130 of
"/express/web/horde/lib/Horde/DataTree/sql.php"]
Feb 25 13:27:19 HORDE [debug] [imp] SQL Query by
Prefs_sql::retrieve(): SELECT pref_scope, pref_name, pref_value FROM
horde_prefs WHERE pref_uid = ? AND (pref_scope = ? OR pref_scope =
'horde') ORDER BY pref_scope [on line 137 of
"/express/web/horde/lib/Horde/Prefs/sql.php"]
Feb 25 13:27:19 HORDE [notice] [imp] Login success for
robledoeduardo99r [10.234.18.11] to {localhost:143} [on line 118 of
"/express/web/horde/imp/lib/api.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SyncML: authorized=1 version=1
msgid=1 source=fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg==
target=http://10.234.16.84/rpc.php user=robledoeduardo99r
charset=UTF-8 wbxml= [on line 226 of
"/express/web/horde/lib/SyncML.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SyncML: looking for sync for
contacts [on line 263 of
"/express/web/horde/lib/SyncML/Command/Alert.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SyncML: Create new sync for
contacts [on line 269 of
"/express/web/horde/lib/SyncML/Command/Alert.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SyncML: create for
syncType=contacts [on line 51 of
"/express/web/horde/lib/SyncML/Sync.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SQL Query by
DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents
FROM horde_datatree WHERE datatree_name = ? AND group_uid = ? ORDER BY
datatree_id [on line 261 of
"/express/web/horde/lib/Horde/DataTree/sql.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SQL Query by
DataTree_sql::_load(): SELECT c.datatree_id, c.datatree_name,
c.datatree_parents, c.datatree_order FROM horde_datatree c WHERE
c.group_uid = 'syncml' [on line 130 of
"/express/web/horde/lib/Horde/DataTree/sql.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SQL Query by
DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents
FROM horde_datatree WHERE datatree_name = ? AND group_uid = ? ORDER BY
datatree_id [on line 261 of
"/express/web/horde/lib/Horde/DataTree/sql.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SQL Query by
DataTree_sql::_load(): SELECT c.datatree_id, c.datatree_name,
c.datatree_parents, c.datatree_order FROM horde_datatree c WHERE
c.group_uid = 'syncml' [on line 130 of
"/express/web/horde/lib/Horde/DataTree/sql.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SyncML: SyncML: No info about
previous syncs found for id
robledoeduardo99r:fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg== and
database contacts [on line 96 of
"/express/web/horde/lib/SyncML/Command/Alert.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SyncML: SyncML: Anchor mismatch,
enforcing SlowSync [on line 119 of
"/express/web/horde/lib/SyncML/Command/Alert.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SyncML: SyncML: return message
completed [on line 513 of "/express/web/horde/lib/SyncML.php"]
Feb 25 13:27:19 HORDE [debug] [horde] SyncML: caught output=bool(true)
bool(true) [on line 116 of
"/express/web/horde/lib/Horde/RPC/syncml.php"]
Feb 25 13:27:20 HORDE [debug] [horde] SQL Query by
SessionHandler_mysql::read(): query = "SELECT session_data FROM
horde_sessionhandler WHERE session_id =
'syncmlfolU0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg1235564722' AND
session_lastmodified > 1235563400 FOR UPDATE" [on line 105 of
"/express/web/horde/lib/Horde/SessionHandler/mysql.php"]
Feb 25 13:27:20 HORDE [debug] [horde] SyncML: New session created:
syncmlfolU0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg1235564722 [on line 172 of
"/express/web/horde/lib/SyncML.php"]
Feb 25 13:27:20 HORDE [debug] [horde] SyncML: authorized= version=1
msgid=2 source=fol-U0NDMDIwMTNBOmNhbXBvc2VtaWxpbzc5Qg==
target=http://10.234.16.84/rpc.php user= charset=UTF-8 wbxml= [on line
226 of "/express/web/horde/lib/SyncML.php"]
Feb 25 13:27:20 HORDE [error] [horde] SyncML: No sync object found for
URI = contacts [on line 61 of
"/express/web/horde/lib/SyncML/Command/Sync.php"]
-------------------------------------------
In php.log
--------------------------------------------
[25-feb-2009 13:27:20] PHP Fatal error: Call to a member function
createSyncOutput() on a non-object in
/express/web/horde/lib/SyncML/Command/Sync.php on line 75
---------------------------------------------
The result: I can not sincronice contacts with outlook and horde.
Can you help meeee!!!?
THANKS
More information about the bugs
mailing list