6.0.0-alpha14
7/3/25

[#8032] Error with funambol outlook plugin and horde rpc.php
Summary Error with funambol outlook plugin and horde rpc.php
Queue Synchronization
Type Enhancement
State No Feedback
Priority 2. Medium
Owners
Requester emilio.campos.martin (at) gmail (dot) com
Created 02/25/2009 (5972 days ago)
Due 02/25/2009 (5972 days ago)
Updated 03/09/2009 (5960 days ago)
Assigned
Resolved 03/09/2009 (5960 days ago)
Milestone
Patch No

History
03/09/2009 12:46:54 AM Chuck Hagenbuch State ⇒ No Feedback
 
02/25/2009 03:19:27 PM Jan Schneider Comment #2
State ⇒ Feedback
Reply to this comment
Please try a more recent groupware version.
02/25/2009 12:32:27 PM emilio (dot) campos (dot) martin (at) gmail (dot) com Comment #1
Priority ⇒ 2. Medium
Patch ⇒ No
Milestone ⇒
Queue ⇒ Synchronization
Due ⇒ 02/25/2009
Summary ⇒ Error with funambol outlook plugin and horde rpc.php
Type ⇒ Enhancement
State ⇒ New
Reply to this comment
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




Saved Queries