[sync] Authentication problems

Karsten Fourmont fourmont at gmx.de
Tue Apr 26 10:09:35 PDT 2005 

Hi,

the authentication seems to be fine (authorized=1), it's more of a 
session handling issue.

Your logs indicate that the for the second message sent from the client, 
horde SyncML creates a new session:

Apr 26 18:03:17 HORDE [debug] [horde] SyncML: New session created:
syncmlscpimoutlook1 [on line 162 of "/usr/share/pear/Horde/SyncML.php"]

This is wrong: it should say something like "SyncML: Existing session 
continued: syncml scpimoutlook1..."

Without the session information, the SyncML code does not know 
user/password (client sends this only for 1st msg) and so the backend 
produces the "not authorized error".

Try fiddling around with your horde session handling config.

My php.ini says something like:

session.save_handler = files
session.save_path = /mydirforsessioninfo

which results in files sess_syncml... files being created in that dir 
during syncing. (The files get deleted after succesful sync)

Hope this helps,
  Karsten



Roel Gloudemans wrote:


> My Horde installation uses LDAP for authentication. Syncing using 
> sync4j fails each and every time with the message that no password has 
> been provided for LDAP authentication.
> 
> Where should I look to debug this?
> 
> Cheers,
> Roel.
> 
> ---- horde log -------
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: New session created: 
> syncmlscpimoutlook1 [on line 162 of "/usr/share/pear/Horde/SyncML.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] 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 132 of 
> "/usr/share/pear/Horde/Prefs/sql.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: authorized=1 version=1 
> msgid=1 source=sc-pim-outlook target=http://lancer.gloudemans.info 
> user=lancer charset=ISO-8859-1 [on line 216 of 
> "/usr/share/pear/Horde/SyncML.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: looking for sync for 
> contacts [on line 260 of 
> "/usr/share/pear/Horde/SyncML/Command/Alert.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: Create new sync for 
> contacts [on line 266 of 
> "/usr/share/pear/Horde/SyncML/Command/Alert.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SQL Query by 
> DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents 
>>FROM horde_datatree WHERE datatree_name = 'contacts' AND group_uid = 
> 'syncml' ORDER BY datatree_id [on line 257 of 
> "/usr/share/pear/Horde/DataTree/sql.php"]
> Apr 26 18:03:17 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 118 of 
> "/usr/share/pear/Horde/DataTree/sql.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: SyncML: No info about 
> previous syncs found for id lancer:sc-pim-outlookand database contacts 
> [on line 99 of "/usr/share/pear/Horde/SyncML/Command/Alert.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: SyncML: Anchor mismatch, 
> enforcing SlowSync [on line 121 of 
> "/usr/share/pear/Horde/SyncML/Command/Alert.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: SyncML: return message 
> completed [on line 486 of "/usr/share/pear/Horde/SyncML.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: New session created: 
> syncmlscpimoutlook1 [on line 162 of "/usr/share/pear/Horde/SyncML.php"]
> Apr 26 18:03:17 HORDE [emergency] [horde] No password provided for LDAP 
> authentication. [on line 94 of "/usr/share/pear/Horde/Auth/ldap.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: New session created: 
> syncmlscpimoutlook1 [on line 162 of "/usr/share/pear/Horde/SyncML.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] 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 132 of 
> "/usr/share/pear/Horde/Prefs/sql.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: authorized=1 version=1 
> msgid=1 source=sc-pim-outlook target=http://lancer.gloudemans.info 
> user=lancer charset=ISO-8859-1 [on line 216 of 
> "/usr/share/pear/Horde/SyncML.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: looking for sync for 
> calendar [on line 260 of 
> "/usr/share/pear/Horde/SyncML/Command/Alert.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: Create new sync for 
> calendar [on line 266 of 
> "/usr/share/pear/Horde/SyncML/Command/Alert.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SQL Query by 
> DataTree_sql::_buildParentIds(): SELECT datatree_id, datatree_parents 
>>FROM horde_datatree WHERE datatree_name = 'calendar' AND group_uid = 
> 'syncml' ORDER BY datatree_id [on line 257 of 
> "/usr/share/pear/Horde/DataTree/sql.php"]
> Apr 26 18:03:17 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 118 of 
> "/usr/share/pear/Horde/DataTree/sql.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: SyncML: No info about 
> previous syncs found for id lancer:sc-pim-outlookand database calendar 
> [on line 99 of "/usr/share/pear/Horde/SyncML/Command/Alert.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: SyncML: Anchor mismatch, 
> enforcing SlowSync [on line 121 of 
> "/usr/share/pear/Horde/SyncML/Command/Alert.php"]
> Apr 26 18:03:17 HORDE [debug] [horde] SyncML: SyncML: return message 
> completed [on line 486 of "/usr/share/pear/Horde/SyncML.php"]
> Apr 26 18:03:18 HORDE [debug] [horde] SyncML: New session created: 
> syncmlscpimoutlook1 [on line 162 of "/usr/share/pear/Horde/SyncML.php"]
> Apr 26 18:03:18 HORDE [emergency] [horde] No password provided for LDAP 
> authentication. [on line 94 of "/usr/share/pear/Horde/Auth/ldap.php"]
> 
> 
> ---- sync4j log -------
> 18:03:15:578 [INFO] - Initializing
> 18:03:15:578 [INFO] - **********  CONTACTS SYNC  ************
> 18:03:15:578 [DEBUG] - initialization-message:
> 18:03:15:578 [DEBUG] - <?xml version="1.0" encoding="UTF-8"?><SyncML>
> <SyncHdr>
> <VerDTD>1.1</VerDTD>
> <VerProto>SyncML/1.1</VerProto>
> <SessionID>1</SessionID>
> <MsgID>1</MsgID>
> <Target><LocURI>http://lancer.gloudemans.info</LocURI></Target>
> <Source><LocURI>sc-pim-outlook</LocURI></Source>
> <Cred>
> <Meta><Format xmlns='syncml:metinf'>b64</Format><Type 
> xmlns='syncml:metinf'>syncml:auth-basic</Type></Meta>
> <Data>[DATA REMOVED]</Data>
> </Cred>
> </SyncHdr>
> <SyncBody>
> <Alert>
> <CmdID>1</CmdID>
> <Data>201</Data>
> <Item>
> <Target><LocURI>contacts</LocURI></Target>
> <Source><LocURI>contact</LocURI></Source>
> <Meta><Anchor xmlns="syncml:metinf">
> <Last>0</Last>
> <Next>1114531395</Next>
> </Anchor></Meta>
> </Item>
> </Alert>
> 
> <Final/>
> </SyncBody>
> </SyncML>
> 18:03:15:578 [DEBUG] - Connecting to lancer.gloudemans.info:80
> 18:03:15:593 [DEBUG] - Requesting resource /horde/rpc.php
> 18:03:15:890 [DEBUG] - Message sent
> 18:03:15:906 [DEBUG] - Reading response...
> 18:03:15:906 [DEBUG] - Content-length: 940
> 18:03:15:906 [DEBUG] - Response read
> 18:03:15:906 [INFO] - Initialization done
> 18:03:15:906 [DEBUG] - response to inizialization-message:
> 18:03:15:906 [DEBUG] - 
> <SyncML><SyncHdr><VerDTD>1.1</VerDTD><VerProto>SyncML/1.1</VerProto><SessionID>1</SessionID><MsgID>1</MsgID><Target><LocURI>sc-pim-outlook</LocURI></Target><Source><LocURI>http://lancer.gloudemans.info</LocURI></Source></SyncHdr><SyncBody><Status><CmdID>1</CmdID><MsgRef>1</MsgRef><CmdRef>0</CmdRef><Cmd>SyncHdr</Cmd><SourceRef>sc-pim-outlook</SourceRef><TargetRef>http://lancer.gloudemans.info</TargetRef><Data>212</Data></Status><Status><CmdID>2</CmdID><MsgRef>1</MsgRef><CmdRef>1</CmdRef><Cmd>Alert</Cmd><SourceRef>contact</SourceRef><TargetRef>contacts</TargetRef><Data>508</Data><Item><Data><Anchor><Next>1114531395</Next><Last>0</Last></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>1114531397</Next></Anchor></Meta></Item></Alert><Final></Final></SyncBody></SyncML>
> 18:03:15:906 [INFO] - The server alert code for contacts is 201
> 18:03:15:906 [DEBUG] - url from response to inizialization-message:
> 18:03:15:937 [INFO] - Synchronizing contacts
> 18:03:15:937 [INFO] - Preparing slow sync for contacts
> 18:03:15:937 [INFO] - Detected 0 items
> 18:03:15:937 [DEBUG] - Preparing slow sync for contact
> 18:03:15:937 [DEBUG] - modification-message:
> 18:03:15:937 [DEBUG] - <?xml version="1.0" encoding="UTF-8"?><SyncML><SyncHdr>
> <VerDTD>1.1</VerDTD>
> <VerProto>SyncML/1.1</VerProto>
> <SessionID>1</SessionID>
> <MsgID>2</MsgID>
> <Target><LocURI>http://lancer.gloudemans.info</LocURI></Target>
> <Source><LocURI>sc-pim-outlook</LocURI></Source>
> </SyncHdr>
> <SyncBody>
> <Status>
> <CmdID>1</CmdID>
> <MsgRef>1</MsgRef>
> <CmdRef>0</CmdRef>
> <Cmd>SyncHdr</Cmd>
> <TargetRef>http://lancer.gloudemans.info</TargetRef>
> <SourceRef>sc-pim-outlook</SourceRef>
> <Data>200</Data>
> </Status>
> <Status>
> <CmdID>2</CmdID>
> <MsgRef>1</MsgRef><CmdRef>1</CmdRef><Cmd>Alert</Cmd>
> <TargetRef>contacts</TargetRef>
> <SourceRef>contact</SourceRef>
> <Data>200</Data>
> <Item>
> <Data>
> <Anchor xmlns='syncml:metinf'><Next>1114531395</Next></Anchor>
> </Data>
> </Item>
> </Status>
> <Sync><CmdID>3</CmdID>
> <Target><LocURI>contacts</LocURI></Target>
> <Source><LocURI>contact</LocURI></Source>
> 
> </Sync><Final/>
> </SyncBody>
> </SyncML>
> 18:03:15:937 [INFO] - Sending modifications
> 18:03:15:937 [DEBUG] - Connecting to lancer.gloudemans.info:80
> 18:03:15:937 [DEBUG] - Requesting resource /horde/rpc.php
> 18:03:16:062 [DEBUG] - Message sent
> 18:03:16:062 [DEBUG] - Reading response...
> 18:03:16:062 [DEBUG] - Content-length: 269
> 18:03:16:062 [DEBUG] - Response read
> 18:03:16:062 [DEBUG] - response to modification-message:
> 18:03:16:062 [DEBUG] - <html>
> <head><title>Horde :: Fatal Error</title></head>
> <body style="background-color: white; color: black;"><h1>A fatal error 
> has occurred</h1><h3>No password provided for LDAP 
> authentication.</h3><h3>Details have been logged for the 
> administrator.</h3></body>
> </html>
> 18:03:16:078 [INFO] - **********  CALENDAR SYNC  ************
> 18:03:16:078 [DEBUG] - initialization-message:
> 18:03:16:093 [DEBUG] - <?xml version="1.0" encoding="UTF-8"?><SyncML>
> <SyncHdr>
> <VerDTD>1.1</VerDTD>
> <VerProto>SyncML/1.1</VerProto>
> <SessionID>1</SessionID>
> <MsgID>1</MsgID>
> <Target><LocURI>http://lancer.gloudemans.info</LocURI></Target>
> <Source><LocURI>sc-pim-outlook</LocURI></Source>
> <Cred>
> <Meta><Format xmlns='syncml:metinf'>b64</Format><Type 
> xmlns='syncml:metinf'>syncml:auth-basic</Type></Meta>
> <Data>[DATA REMOVED]</Data>
> </Cred>
> </SyncHdr>
> <SyncBody>
> <Alert>
> <CmdID>1</CmdID>
> <Data>201</Data>
> <Item>
> <Target><LocURI>calendar</LocURI></Target>
> <Source><LocURI>calendar</LocURI></Source>
> <Meta><Anchor xmlns="syncml:metinf">
> <Last>0</Last>
> <Next>1114531396</Next>
> </Anchor></Meta>
> </Item>
> </Alert>
> 
> <Final/>
> </SyncBody>
> </SyncML>
> 18:03:16:093 [DEBUG] - Connecting to lancer.gloudemans.info:80
> 18:03:16:093 [DEBUG] - Requesting resource /horde/rpc.php
> 18:03:16:296 [DEBUG] - Message sent
> 18:03:16:296 [DEBUG] - Reading response...
> 18:03:16:296 [DEBUG] - Content-length: 942
> 18:03:16:296 [DEBUG] - Response read
> 18:03:16:296 [INFO] - Initialization done
> 18:03:16:296 [DEBUG] - response to inizialization-message:
> 18:03:16:296 [DEBUG] - 
> <SyncML><SyncHdr><VerDTD>1.1</VerDTD><VerProto>SyncML/1.1</VerProto><SessionID>1</SessionID><MsgID>1</MsgID><Target><LocURI>sc-pim-outlook</LocURI></Target><Source><LocURI>http://lancer.gloudemans.info</LocURI></Source></SyncHdr><SyncBody><Status><CmdID>1</CmdID><MsgRef>1</MsgRef><CmdRef>0</CmdRef><Cmd>SyncHdr</Cmd><SourceRef>sc-pim-outlook</SourceRef><TargetRef>http://lancer.gloudemans.info</TargetRef><Data>212</Data></Status><Status><CmdID>2</CmdID><MsgRef>1</MsgRef><CmdRef>1</CmdRef><Cmd>Alert</Cmd><SourceRef>calendar</SourceRef><TargetRef>calendar</TargetRef><Data>508</Data><Item><Data><Anchor><Next>1114531396</Next><Last>0</Last></Anchor></Data></Item></Status><Alert><CmdID>3</CmdID><Data>201</Data><Item><Target><LocURI>calendar</LocURI></Target><Source><LocURI>calendar</LocURI></Source><Meta><Anchor 
> xmlns="syncml:metinf"><Last>0</Last><Next>1114531397</Next></Anchor></Meta></Item></Alert><Final></Final></SyncBody></SyncML>
> 18:03:16:296 [INFO] - The server alert code for calendar is 201
> 18:03:16:296 [DEBUG] - url from response to inizialization-message:
> 18:03:16:359 [INFO] - Synchronizing calendar
> 18:03:16:359 [INFO] - Preparing slow sync for calendar
> 18:03:16:359 [INFO] - Detected 0 items
> 18:03:16:359 [DEBUG] - Preparing slow sync for calendar
> 18:03:16:359 [DEBUG] - modification-message:
> 18:03:16:359 [DEBUG] - <?xml version="1.0" encoding="UTF-8"?><SyncML><SyncHdr>
> <VerDTD>1.1</VerDTD>
> <VerProto>SyncML/1.1</VerProto>
> <SessionID>1</SessionID>
> <MsgID>2</MsgID>
> <Target><LocURI>http://lancer.gloudemans.info</LocURI></Target>
> <Source><LocURI>sc-pim-outlook</LocURI></Source>
> </SyncHdr>
> <SyncBody>
> <Status>
> <CmdID>1</CmdID>
> <MsgRef>1</MsgRef>
> <CmdRef>0</CmdRef>
> <Cmd>SyncHdr</Cmd>
> <TargetRef>http://lancer.gloudemans.info</TargetRef>
> <SourceRef>sc-pim-outlook</SourceRef>
> <Data>200</Data>
> </Status>
> <Status>
> <CmdID>2</CmdID>
> <MsgRef>1</MsgRef><CmdRef>1</CmdRef><Cmd>Alert</Cmd>
> <TargetRef>calendar</TargetRef>
> <SourceRef>calendar</SourceRef>
> <Data>200</Data>
> <Item>
> <Data>
> <Anchor xmlns='syncml:metinf'><Next>1114531396</Next></Anchor>
> </Data>
> </Item>
> </Status>
> <Sync><CmdID>3</CmdID>
> <Target><LocURI>calendar</LocURI></Target>
> <Source><LocURI>calendar</LocURI></Source>
> 
> </Sync><Final/>
> </SyncBody>
> </SyncML>
> 18:03:16:359 [INFO] - Sending modifications
> 18:03:16:359 [DEBUG] - Connecting to lancer.gloudemans.info:80
> 18:03:16:359 [DEBUG] - Requesting resource /horde/rpc.php
> 18:03:16:843 [DEBUG] - Message sent
> 18:03:16:875 [DEBUG] - Reading response...
> 18:03:16:875 [DEBUG] - Content-length: 269
> 18:03:16:875 [DEBUG] - Response read
> 18:03:16:890 [DEBUG] - response to modification-message:
> 18:03:16:890 [DEBUG] - <html>
> <head><title>Horde :: Fatal Error</title></head>
> <body style="background-color: white; color: black;"><h1>A fatal error 
> has occurred</h1><h3>No password provided for LDAP 
> authentication.</h3><h3>Details have been logged for the 
> administrator.</h3></body>
> </html>
> 
>

More information about the sync mailing list