On 25/02/07, Pierangelo Masarati ando@sys-net.it wrote:

Michael Cassaniti wrote:

...

Hi, I have followed the OpenLDAP v2.3 Software Administrators Guide to using Sync Replication. I have the following snippets for my LDAP servers.

[provider] overlay syncprov syncprov-checkpoint 10 60 syncprov-sessionlog 100

[consumer] syncrepl rid=101 provider=ldap://192.168.0.4 type=refreshOnly interval=00:00:30:00 retry="05 +" searchbase="dc=home,dc=net" bindmethod=simple binddn="uid=ldap,ou=Users,dc=home,dc=net" credentials=secret

I have checked that I can authenticate using simple authentication as user ldap (via ldapwhoami) against the sync provider server. This was successful. I also know that the credentials information, which is in SSHA form is correct.

The problem is that there is a bind issue. In particular it returns the following error in the log on the consumer: do_syncrep1: ldap_sasl_bind_s failed (49)

On the provider, there is not much information to determine the error. I extracted the following: Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: activity on 1 descriptor Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: activity on: Feb 24 22:13:14 Home-Server4 slapd[3749]: Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: listen=7, new connection on 12 Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: added 12r (active) listener=(nil) Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: epoll: listen=7 active_threads=1 tvp=zero Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: activity on 1 descriptor Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: activity on: Feb 24 22:13:14 Home-Server4 slapd[3749]: 12r Feb 24 22:13:14 Home-Server4 slapd[3749]: Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: read active on 12 Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: epoll: listen=7 active_threads=1 tvp=zero Feb 24 22:13:14 Home-Server4 slapd[3749]: => access_allowed: auth access to "uid=ldap,ou=Users,dc=home,dc=net" "userPassword" requested Feb 24 22:13:14 Home-Server4 slapd[3749]: => acl_get: [1] attr userPassword Feb 24 22:13:14 Home-Server4 slapd[3749]: => slap_access_allowed: no res from state (userPassword) Feb 24 22:13:14 Home-Server4 slapd[3749]: => acl_mask: access to entry "uid=ldap,ou=Users,dc=home,dc=net", attr "userPassword" requested Feb 24 22:13:14 Home-Server4 slapd[3749]: => acl_mask: to value by "", (=0) Feb 24 22:13:14 Home-Server4 slapd[3749]: <= check a_dn_pat: self Feb 24 22:13:14 Home-Server4 slapd[3749]: <= check a_dn_pat: cn=root,dc=home,dc=net Feb 24 22:13:14 Home-Server4 slapd[3749]: <= check a_dn_pat: uid=ldap,ou=users,dc=home,dc=net Feb 24 22:13:14 Home-Server4 slapd[3749]: <= check a_dn_pat: anonymous Feb 24 22:13:14 Home-Server4 slapd[3749]: <= acl_mask: [4] applying auth(=xd) (stop) Feb 24 22:13:14 Home-Server4 slapd[3749]: <= acl_mask: [4] mask: auth(=xd) Feb 24 22:13:14 Home-Server4 slapd[3749]: => slap_access_allowed: auth access granted by auth(=xd) Feb 24 22:13:14 Home-Server4 slapd[3749]: => access_allowed: auth access granted by auth(=xd) Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: activity on 1 descriptor Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: activity on: Feb 24 22:13:14 Home-Server4 slapd[3749]: 12r Feb 24 22:13:14 Home-Server4 slapd[3749]: Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: read active on 12 Feb 24 22:13:14 Home-Server4 slapd[3749]: connection_read(12): input error=-2 id=0, closing. Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: epoll: listen=7 active_threads=1 tvp=zero Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: activity on 1 descriptor Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: activity on: Feb 24 22:13:14 Home-Server4 slapd[3749]: Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: epoll: listen=7 active_threads=1 tvp=zero Feb 24 22:13:14 Home-Server4 slapd[3749]: daemon: removing 12

I don't think, though I could be wrong, that this has anything to do with poor ACLs being set. I also tried the bind using the rootdn, but this also failed. The output log from the provider gave the folllowing: Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: activity on 1 descriptor Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: activity on: Feb 24 22:16:03 Home-Server4 slapd[4083]: Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: listen=7, new connection on 12 Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: added 12r (active) listener=(nil) Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: epoll: listen=7 active_threads=1 tvp=zero Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: activity on 1 descriptor Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: activity on: Feb 24 22:16:03 Home-Server4 slapd[4083]: 12r Feb 24 22:16:03 Home-Server4 slapd[4083]: Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: read active on 12 Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: epoll: listen=7 active_threads=1 tvp=zero Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: activity on 1 descriptor Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: activity on: Feb 24 22:16:03 Home-Server4 slapd[4083]: 12r Feb 24 22:16:03 Home-Server4 slapd[4083]: Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: read active on 12 Feb 24 22:16:03 Home-Server4 slapd[4083]: connection_read(12): input error=-2 id=0, closing. Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: epoll: listen=7 active_threads=1 tvp=zero Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: activity on 1 descriptor Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: activity on: Feb 24 22:16:03 Home-Server4 slapd[4083]: Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: epoll: listen=7 active_threads=1 tvp=zero Feb 24 22:16:03 Home-Server4 slapd[4083]: daemon: removing 12

As you can see, none of this is very forthcoming for information. Log level is set to 28904, so there should be a high amount of logging done to show any/all errors. Modifying the ACLs on the provider to: access to * by * write still returned this error.

you're logging at: conns + filter + config + acl + sync + some undefined level (slapd.conf(5): loglevel; if you read the manual, you would have found that log level can now be specified in frinedly form, instead of numbers); since you already worked out (by setting "access to * by * write") that's not an ACL issue, the rest of the logging you selected, apart from sync, which would come into play later, after authentication succeeds, makes little sense with respect to the issue you're trying to address. I'd rather log at: stats + args + trace + sync, increasing the log level in this order, to work out what's going on (note that stats should be pointless, but it's good to get an overview of what the server is doing in relation to external stimuli)

...

What suprises me is that this is an SASL error, when SASL is not used for a simple bind. Like I have already stated, this is a configuration straight from the OpenLDAP Guide, so what have I done wrong.

How did you get to that conclusion? ldap_sasl_bind_s() is a catchall for any type of bind (see ldap_sasl_bind_s(3)), and 49 indicates "invalid credentials", which is the only error you'll get from the server in case the bind failed. It could be anything: wrong DN, wrong password, no auth access to password, ...

It is apparent, from the logs you show, that password fetching goes just fine at the producer, but fails later on for some reason. You should definitely provide more meaningful logging, instead of making conjectures on SASL errors... http://www.openldap.org/faq/data/cache/231.html

p.

Ing. Pierangelo Masarati OpenLDAP Core Team

SysNet s.n.c. Via Dossi, 8 - 27100 Pavia - ITALIA http://www.sys-net.it

---

Office: +39.02.23998309 Mobile: +39.333.4963172 Email: pierangelo.masarati@sys-net.it

---

I wasnt sure whether the log levels you specified should be used just for the consumer, or for both the consumer and provider. I have attached (hope that isn't a problem) the logs for both the consumer and provider with different log levels set. In the case where everything was logged, I omitted the details before the line 'slapd starting' as this information is mainly about indexing and configuration file parsing.

The only thing interesting besides the error 49 (comes with SASL bind problem) is an error 11 about resource temporarily unavailable. I don't know that much about OpenLDAP's error codes, or how to go looking for information on them. I am still stuck on how to rectify my issue with OpenLDAP.

I have also attached a copy of the configuration files for both the provider and consumer. You may have noticed that the ip address of the provider has changed. This is due to a processor failure with one of my computers. I moved the database with slapcat/slapadd. I found that I am missing the overlay syncprov section in my configuration file for this new setup. The original server did have it. This does not explain however why there is difficulty with the bind.

Just so we are clear, the passwords in the configuration file are not the passwords I am using. They are written originally like so: {SSHA}......

Thanks again for your help. Pierangelo, your feedback is much appreciated. Michael Cassaniti