[sync] Problem synchronizing LDAP addressbook
David Hoover
spm at boiteauxlettres.sent.at
Wed Nov 18 21:21:12 UTC 2009
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
username at domain.li [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: username at domain.li, 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: username at domain.li, 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: username at domain.li, 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
username at domain.li [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: username at domain.li;
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, username at domain.li [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: username at domain.li, 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";},
username at domain.li, 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: username at domain.li; 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:
username at domain.li, 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 = username at domain.li, root =
ou=username at domain.li,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 = username at domain.li, root =
ou=username at domain.li,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, username at domain.li [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,
username at domain.li [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: username at domain.li, 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";},
username at domain.li, 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 username at domain.li
DEBUG: Authenticated: yes; version: 1.2; message ID: 1; source URI:
IMEI:356795024387032; target URI:
https://www.domain.li:443/horde/rpc.php; user: username at domain.li;
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, username at domain.li
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: username at domain.li; 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: username at domain.li; 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, username at domain.li
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,
username at domain.li
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,
);
More information about the sync
mailing list