Problem synchronizing LDAP addressbook

"David Hoover" <[email protected]> Wed, 18 Nov 2009 22:21:12 +0100
Newsgroups	gmane.comp.horde.sync
Message-ID	<[email protected]>
Hi,

Turba synchronization used to work for me. I recently did a reinstall of
my server, and I can't get it to work on the new config (with more
recent Horde webmail 1.2.4, openldap 2.4.19, php 5.2.11, etc.). LDAP
access works fine, and I can add LDAP addressbook entries manually with
imp. I am also able to synchronize with non-LDAP address books. But when
I try to synchronize with the LDAP address book, I get a strange error
message:
    HORDE [error] [horde] Error in adding client entry: Read failed: (0)
    Success [pid 20682 on line 282 of
    "/htdocs/horde/lib/SyncML/Sync.php"]

Anybody seen this before?  Thanks,

Dave.


horde.log
-------
Nov 18 20:19:15 HORDE [debug] [horde] Backend of class
SyncML_Backend_Horde created [pid 20682 on line 287 of
"/htdocs/horde/lib/SyncML/Backend.php"]
Nov 18 20:19:15 HORDE [debug] [horde] Started at 2009-11-18 20:19:15.
Packet logged in /tmp/sync/client_10.wbxml [pid 20682 on line 889 of
"/htdocs/horde/lib/SyncML/Backend.php"]
Nov 18 20:19:16 HORDE [debug] [horde] New session created:
a1b1c64dcb82fcb258ea5101bf2f0faa [pid 20682 on line 197 of
"/htdocs/horde/lib/SyncML/Command/SyncHdr.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Checking authentication for user
[email protected] [pid 20682 on line 606 of
"/htdocs/horde/lib/SyncML/Backend.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Guest user does not have READ
permission for turba [pid 20682 on line 814 of
"/htdocs/horde/lib/Horde/Registry.php"]
Nov 18 20:19:16 HORDE [error] [horde] Guest user is not authorised for
Address Book. [pid 20682 on line 1706 of "/htdocs/horde/lib/Horde.php"]
Nov 18 20:19:16 HORDE [error] [horde] Guest user is not authorised for
Address Book. [pid 20682 on line 791 of
"/htdocs/horde/lib/Horde/Prefs.php"]
Nov 18 20:19:16 HORDE [debug] [imp] Guest user does not have READ
permission for turba [pid 20682 on line 814 of
"/htdocs/horde/lib/Horde/Registry.php"]
Nov 18 20:19:16 HORDE [error] [imp] Guest user is not authorised for
Address Book. [pid 20682 on line 1706 of "/htdocs/horde/lib/Horde.php"]
Nov 18 20:19:16 HORDE [error] [imp] Guest user is not authorised for
Address Book. [pid 20682 on line 791 of
"/htdocs/horde/lib/Horde/Prefs.php"]
Nov 18 20:19:16 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 = ?, values: [email protected], horde [pid 20682 on
line 148 of "/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov 18 20:19:16 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 = ?, values: [email protected], imp [pid 20682 on
line 148 of "/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov 18 20:19:16 HORDE [debug] [imp] Hook _prefs_change_hook_last_login
in application horde not called. [pid 20682 on line 1713 of
"/htdocs/horde/lib/Horde.php"]
Nov 18 20:19:16 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 = ?, values: [email protected], ingo [pid 20682 on
line 148 of "/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov 18 20:19:16 HORDE [notice] [imp] Login success for
[email protected] [ipaddress] to {localhost:143 [imap/notls]} [pid
20682 on line 307 of "/htdocs/horde/imp/lib/Session.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Authenticated: yes; version: 1.2;
message ID: 1; source URI: IMEI:356795024387032; target URI:
https://www.domain.li:443/horde/rpc.php; user: [email protected];
charset: UTF-8; wbxml: yes [pid 20682 on line 441 of
"/htdocs/horde/lib/SyncML.php"]
Nov 18 20:19:16 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::readSyncAnchors(): SELECT syncml_clientanchor,
syncml_serveranchor FROM horde_syncml_anchors WHERE syncml_syncpartner =
? AND syncml_db = ? AND syncml_uid = ?, values: IMEI:356795024387032,
contacts, [email protected] [pid 20682 on line 621 of
"/htdocs/horde/lib/SyncML/Backend/Horde.php"]
Nov 18 20:19:16 HORDE [debug] [horde] No info about previous syncs found
for device IMEI:356795024387032 and database ./contacts [pid 20682 on
line 199 of "/htdocs/horde/lib/SyncML/Command/Alert.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Creating SyncML_Sync object for
database ./contacts; sync type 203 [pid 20682 on line 292 of
"/htdocs/horde/lib/SyncML/Command/Alert.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Received <Final> from client. [pid
20682 on line 50 of "/htdocs/horde/lib/SyncML/Command/Final.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Handle <Final> for state Init [pid
20682 on line 638 of "/htdocs/horde/lib/SyncML/Sync.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Sending <Final> to client [pid
20682 on line 511 of "/htdocs/horde/lib/SyncML.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Return message completed [pid
20682 on line 552 of "/htdocs/horde/lib/SyncML.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Finished at 2009-11-18 20:19:16.
Packet logged in /tmp/sync/server_10.wbxml [pid 20682 on line 897 of
"/htdocs/horde/lib/SyncML/Backend.php"]
Nov 18 20:19:16 HORDE [debug] [horde] Max memory usage: 9699328 bytes
[pid 20682 on line 339 of "/htdocs/horde/lib/Horde/Registry.php"]
Nov 18 20:19:16 HORDE [debug] [horde] IMAP errors: SECURITY PROBLEM:
insecure server advertised AUTH=PLAIN [pid 20682 on line 175 of
"/htdocs/horde/imp/lib/IMAP.php"]
Nov 18 20:19:16 HORDE [debug] [horde] SQL Query by Prefs_sql::store():
SELECT 1 FROM horde_prefs WHERE pref_uid = ? AND pref_name = ? AND
pref_scope = ?, values: [email protected], last_login, horde [pid 20682
on line 210 of "/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov 18 20:19:16 HORDE [debug] [horde] SQL Query by Prefs_sql::store():
UPDATE horde_prefs SET pref_value = ? WHERE pref_uid = ? AND pref_name =
? AND pref_scope = ?, values:
a:2:{s:4:"time";i:1258575556;s:4:"host";s:29:"address.ch";},
[email protected], last_login, horde [pid 20682 on line 244 of
"/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov 18 20:19:21 HORDE [debug] [horde] Backend of class
SyncML_Backend_Horde created [pid 20682 on line 287 of
"/htdocs/horde/lib/SyncML/Backend.php"]
Nov 18 20:19:21 HORDE [debug] [horde] Started at 2009-11-18 20:19:21.
Packet logged in /tmp/sync/client_11.wbxml [pid 20682 on line 889 of
"/htdocs/horde/lib/SyncML/Backend.php"]
Nov 18 20:19:21 HORDE [debug] [horde] Existing session continued:
a1b1c64dcb82fcb258ea5101bf2f0faa [pid 20682 on line 204 of
"/htdocs/horde/lib/SyncML/Command/SyncHdr.php"]
Nov 18 20:19:21 HORDE [debug] [horde] Authenticated: yes; version: 1.2;
message ID: 2; source URI: IMEI:356795024387032; target URI:
https://www.domain.li/horde/rpc.php; user: [email protected]; charset:
UTF-8; wbxml: yes [pid 20682 on line 441 of
"/htdocs/horde/lib/SyncML.php"]
Nov 18 20:19:21 HORDE [debug] [horde] Created device class
SyncML_Device_Nokia [pid 20682 on line 55 of
"/htdocs/horde/lib/SyncML/Device.php"]
Nov 18 20:19:21 HORDE [debug] [horde] Handling <Add> sent from client
[pid 20682 on line 211 of "/htdocs/horde/lib/SyncML/Sync.php"]
Nov 18 20:19:21 HORDE [debug] [horde] Created device class
SyncML_Device_Nokia [pid 20682 on line 55 of
"/htdocs/horde/lib/SyncML/Device.php"]
Nov 18 20:19:21 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 = ?, values:
[email protected], turba [pid 20682 on line 148 of
"/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov 18 20:19:21 HORDE [debug] [turba] Hook _horde_hook_share_init in
application horde not called. [pid 20682 on line 1713 of
"/htdocs/horde/lib/Horde.php"]
Nov 18 20:19:22 HORDE [debug] [turba] LDAP query by
Turba_Driver_ldap::_search(): user = [email protected], root =
[email protected],ou=personal_addressbook,dc=domain,dc=li
(localhost); filter = "(&(sn=*LastName*)(cn=*Firstname LastName*))";
attributes = "dn, uid, cn, sn"; deref = "0"  ; sizelimit = 0 [pid 20682
on line 191 of "/htdocs/horde/turba/lib/Driver/ldap.php"]
Nov 18 20:19:22 HORDE [error] [horde] Error in adding client entry: Read
failed: (0) Success [pid 20682 on line 282 of
"/htdocs/horde/lib/SyncML/Sync.php"]
Nov 18 20:19:22 HORDE [debug] [horde] Handling <Add> sent from client
[pid 20682 on line 211 of "/htdocs/horde/lib/SyncML/Sync.php"]
Nov 18 20:19:22 HORDE [debug] [horde] Created device class
SyncML_Device_Nokia [pid 20682 on line 55 of
"/htdocs/horde/lib/SyncML/Device.php"]
Nov 18 20:19:22 HORDE [debug] [turba] LDAP query by
Turba_Driver_ldap::_search(): user = [email protected], root =
[email protected],ou=personal_addressbook,dc=domain,dc=li
(localhost); filter = "(&(sn=*Lastname2*)(cn=*Firstname2 Lastname2*))";
attributes = "dn, uid, cn, sn"; deref = "0"  ; sizelimit = 0 [pid 20682
on line 191 of "/htdocs/horde/turba/lib/Driver/ldap.php"]
Nov 18 20:19:22 HORDE [error] [horde] Error in adding client entry: Read
failed: (0) Success [pid 20682 on line 282 of
"/htdocs/horde/lib/SyncML/Sync.php"]

... etc.

Nov 18 20:19:24 HORDE [debug] [horde] Received <Final> from client. [pid
20682 on line 50 of "/htdocs/horde/lib/SyncML/Command/Final.php"]
Nov 18 20:19:24 HORDE [debug] [horde] Handle <Final> for state Sync [pid
20682 on line 638 of "/htdocs/horde/lib/SyncML/Sync.php"]
Nov 18 20:19:24 HORDE [debug] [horde] Creating <Sync> output for server
changes in database ./contacts [pid 20682 on line 356 of
"/htdocs/horde/lib/SyncML/Sync.php"]
Nov 18 20:19:24 HORDE [debug] [horde] Sending <Final> to client [pid
20682 on line 511 of "/htdocs/horde/lib/SyncML.php"]
Nov 18 20:19:24 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::readSyncAnchors(): SELECT syncml_clientanchor,
syncml_serveranchor FROM horde_syncml_anchors WHERE syncml_syncpartner =
? AND syncml_db = ? AND syncml_uid = ?, values: IMEI:356795024387032,
contacts, [email protected] [pid 20682 on line 621 of
"/htdocs/horde/lib/SyncML/Backend/Horde.php"]
Nov 18 20:19:24 HORDE [debug] [horde] SQL Query by
SyncML_Backend_Horde::writeSyncAnchors(): INSERT INTO
horde_syncml_anchors (syncml_clientanchor, syncml_serveranchor,
syncml_syncpartner, syncml_db, syncml_uid) VALUES (?, ?, ?, ?, ?),
values: 20091118T201907Z, 1258575556, IMEI:356795024387032, contacts,
[email protected] [pid 20682 on line 591 of
"/htdocs/horde/lib/SyncML/Backend/Horde.php"]
Nov 18 20:19:25 HORDE [info] [horde] Finished sync of database
./contacts. Failures: 257; changes from client (Add, Replace, Delete,
AddReplaces): 0, 0, 0, 0; changes from server (Add, Replace, Delete): 0,
0, 0 [pid 20682 on line 722 of "/htdocs/horde/lib/SyncML/Sync.php"]
Nov 18 20:19:25 HORDE [debug] [horde] Session completed and closed [pid
20682 on line 546 of "/htdocs/horde/lib/SyncML.php"]
Nov 18 20:19:25 HORDE [debug] [horde] Finished at 2009-11-18 20:19:25.
Packet logged in /tmp/sync/server_12.wbxml [pid 20682 on line 897 of
"/htdocs/horde/lib/SyncML/Backend.php"]
Nov 18 20:19:25 HORDE [debug] [horde] Max memory usage: 10485760 bytes
[pid 20682 on line 339 of "/htdocs/horde/lib/Horde/Registry.php"]
Nov 18 20:19:25 HORDE [debug] [horde] SQL Query by Prefs_sql::store():
SELECT 1 FROM horde_prefs WHERE pref_uid = ? AND pref_name = ? AND
pref_scope = ?, values: [email protected], last_login, horde [pid 20682
on line 210 of "/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov 18 20:19:25 HORDE [debug] [horde] SQL Query by Prefs_sql::store():
UPDATE horde_prefs SET pref_value = ? WHERE pref_uid = ? AND pref_name =
? AND pref_scope = ?, values:
a:2:{s:4:"time";i:1258575556;s:4:"host";s:29:"address.ch";},
[email protected], last_login, horde [pid 20682 on line 244 of
"/htdocs/horde/lib/Horde/Prefs/sql.php"]



php.log
-------
PHP Warning:  Cannot modify header information - headers already sent by
(output started at /htdocs/horde/lib/SyncML/Backend.php:781) in
/htdocs/horde/templates/common-header.inc on line 4
PHP Warning:  Cannot modify header information - headers already sent by
(output started at /htdocs/horde/lib/SyncML/Backend.php:781) in
/htdocs/horde/templates/common-header.inc on line 5



/tmp/sync/log.txt
-------
DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Started at 2009-11-18 20:19:15. Packet logged in
/tmp/sync/client_10.wbxml
DEBUG:  New session created: a1b1c64dcb82fcb258ea5101bf2f0faa
DEBUG:  Checking authentication for user [email protected]
DEBUG:  Authenticated: yes; version: 1.2; message ID: 1; source URI:
IMEI:356795024387032; target URI:
https://www.domain.li:443/horde/rpc.php; user: [email protected];
charset: UTF-8; wbxml: yes
DEBUG:  SQL Query by SyncML_Backend_Horde::readSyncAnchors(): SELECT
syncml_clientanchor, syncml_serveranchor FROM horde_syncml_anchors WHERE
syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ?, values:
IMEI:356795024387032, contacts, [email protected]
DEBUG:  No info about previous syncs found for device
IMEI:356795024387032 and database ./contacts
DEBUG:  Creating SyncML_Sync object for database ./contacts; sync type
203
DEBUG:  Received <Final> from client.
DEBUG:  Handle <Final> for state Init
DEBUG:  Sending <Final> to client
DEBUG:  Return message completed
DEBUG:  Finished at 2009-11-18 20:19:16. Packet logged in
/tmp/sync/server_10.wbxml

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Started at 2009-11-18 20:19:21. Packet logged in
/tmp/sync/client_11.wbxml
DEBUG:  Existing session continued: a1b1c64dcb82fcb258ea5101bf2f0faa
DEBUG:  Authenticated: yes; version: 1.2; message ID: 2; source URI:
IMEI:356795024387032; target URI: https://www.domain.li/horde/rpc.php;
user: [email protected]; charset: UTF-8; wbxml: yes
DEBUG:  Created device class SyncML_Device_Nokia
DEBUG:  Handling <Add> sent from client
DEBUG:  Created device class SyncML_Device_Nokia
ERR:    Error in adding client entry: Read failed: (0) Success
DEBUG:  Handling <Add> sent from client
DEBUG:  Created device class SyncML_Device_Nokia
ERR:    Error in adding client entry: Read failed: (0) Success

etc.

ERR:    Error in adding client entry: Read failed: (0) Success
DEBUG:  Return message completed
DEBUG:  Finished at 2009-11-18 20:19:23. Packet logged in
/tmp/sync/server_11.wbxml

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Started at 2009-11-18 20:19:24. Packet logged in
/tmp/sync/client_12.wbxml
DEBUG:  Existing session continued: a1b1c64dcb82fcb258ea5101bf2f0faa
DEBUG:  Authenticated: yes; version: 1.2; message ID: 3; source URI:
IMEI:356795024387032; target URI: https://www.domain.li/horde/rpc.php;
user: [email protected]; charset: UTF-8; wbxml: yes
DEBUG:  Created device class SyncML_Device_Nokia
DEBUG:  Handling <Add> sent from client
DEBUG:  Created device class SyncML_Device_Nokia
ERR:    Error in adding client entry: Read failed: (0) Success
DEBUG:  Handling <Add> sent from client
DEBUG:  Created device class SyncML_Device_Nokia
ERR:    Error in adding client entry: Read failed: (0) Success
DEBUG:  Handling <Add> sent from client
DEBUG:  Created device class SyncML_Device_Nokia
ERR:    Error in adding client entry: Read failed: (0) Success
DEBUG:  Received <Final> from client.
DEBUG:  Handle <Final> for state Sync
DEBUG:  Creating <Sync> output for server changes in database ./contacts
DEBUG:  Sending <Final> to client
DEBUG:  SQL Query by SyncML_Backend_Horde::readSyncAnchors(): SELECT
syncml_clientanchor, syncml_serveranchor FROM horde_syncml_anchors WHERE
syncml_syncpartner = ? AND syncml_db = ? AND syncml_uid = ?, values:
IMEI:356795024387032, contacts, [email protected]
DEBUG:  SQL Query by SyncML_Backend_Horde::writeSyncAnchors(): INSERT
INTO horde_syncml_anchors (syncml_clientanchor, syncml_serveranchor,
syncml_syncpartner, syncml_db, syncml_uid) VALUES (?, ?, ?, ?, ?),
values: 20091118T201907Z, 1258575556, IMEI:356795024387032, contacts,
[email protected]
INFO:   Finished sync of database ./contacts. Failures: 257; changes
from client (Add, Replace, Delete, AddReplaces): 0, 0, 0, 0; changes
from server (Add, Replace, Delete): 0, 0, 0
DEBUG:  Session completed and closed
DEBUG:  Finished at 2009-11-18 20:19:25. Packet logged in
/tmp/sync/server_12.wbxml


slapd.conf
--------------
access to attrs=userPassword
  by self =xw
  by anonymous auth
  by * none

access to dn.subtree="ou=personal_addressbook,dc=domain,dc=li"
  by * write
  by * read


turba/config/sources.php
----------------
 //$_ldap_uid = Auth::getBareAuth();
 $_ldap_uid = Auth::getAuth();
 $_ldap_basedn = 'dc=domain,dc=li';
 $cfgSources['personal_ldap'] = array(
     'title' => _("My Address Book"),
     'type' => 'ldap',
     'params' => array(
         'server' => 'localhost',
         'tls' => false,
         'port' => 389,
         'root' => 'ou=' . $_ldap_uid . ',ou=personal_addressbook,' .
         $_ldap_basedn,
         'bind_dn' => 'uid=' . $_ldap_uid . ',ou=people,' .
         $_ldap_basedn,
         'bind_password' => Auth::getCredential('password'),
         'dn' => array('uid'),
         'objectclass' => array('top',
                                'person',
                                // 'turbaContact',
                                'inetOrgPerson',
                                // 'calEntry',
                                'organizationalPerson'
			),
         'scope' => 'sub',
         'charset' => 'utf-8',
         'version' => 3
     ),
     'map' => array(
         '__key' => 'dn',
         '__uid' => 'uid',

         'name' => 'cn',
         'lastname' => 'sn'
     ),
   'search' => array(
         'name'
     ),
     'strict' => array(
         'dn',
     ),
     'approximate' => array(
         'cn',
     ),
     'export' => true,
     'browse' => true,
 );

-- 
sync mailing list - Join the hunt: http://horde.org/bounties/#sync
Frequently Asked Questions: http://horde.org/faq/
To unsubscribe, mail: [email protected]