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
Log Level: Stats Feb 25 19:54:35 Home-Server1 slapd[13502]: do_syncrep1: ldap_sasl_bind_s failed (49) Log Level: Stats + Args Feb 25 19:53:48 Home-Server1 slapd[13274]: do_syncrep1: ldap_sasl_bind_s failed (49) Log Level: Stats + Args + Trace Feb 25 19:55:20 Home-Server1 slapd[13730]: do_syncrep1: ldap_sasl_bind_s failed (49) Log Level: Stats + Args + Trace + Sync Feb 25 19:56:52 Home-Server1 slapd[13968]: do_syncrep1: ldap_sasl_bind_s failed (49) Log Level: -1 (Log everything) Feb 25 20:07:20 Home-Server1 slapd[14811]: slapd starting Feb 25 20:07:20 Home-Server1 slapd[14811]: daemon: added 4r listener=(nil) Feb 25 20:07:20 Home-Server1 slapd[14811]: daemon: added 7r listener=0x8194140 Feb 25 20:07:20 Home-Server1 slapd[14811]: daemon: epoll: listen=7 active_threads=0 tvp=zero Feb 25 20:07:20 Home-Server1 slapd[14811]: =>do_syncrepl Feb 25 20:07:20 Home-Server1 slapd[14811]: do_syncrep1: ldap_sasl_bind_s failed (49)
Log Level: Stats
Feb 25 19:32:47 Home-Server2 slapd[25634]: conn=3 fd=11 ACCEPT from IP=159.255.36.1:2611 (IP=0.0.0.0:389)
Feb 25 19:32:47 Home-Server2 slapd[25634]: conn=3 op=0 BIND dn="uid=ldap,ou=Users,dc=home,dc=net" method=128
Feb 25 19:32:47 Home-Server2 slapd[25634]: conn=3 op=0 RESULT tag=97 err=49 text=
Feb 25 19:32:47 Home-Server2 slapd[25634]: conn=3 op=1 UNBIND
Feb 25 19:32:47 Home-Server2 slapd[25634]: conn=3 fd=11 closed
Log Level: Stats + Args
Feb 25 19:37:53 Home-Server2 slapd[25919]: conn=1 fd=11 ACCEPT from IP=159.255.36.1:4978 (IP=0.0.0.0:389)
Feb 25 19:37:53 Home-Server2 slapd[25919]: conn=1 op=0 BIND dn="uid=ldap,ou=Users,dc=home,dc=net" method=128
Feb 25 19:37:53 Home-Server2 slapd[25919]: conn=1 op=0 RESULT tag=97 err=49 text=
Feb 25 19:37:53 Home-Server2 slapd[25919]: conn=1 op=1 UNBIND
Feb 25 19:37:53 Home-Server2 slapd[25919]: conn=1 fd=11 closed
Log Level: Stats + Args + Trace
Feb 25 19:40:06 Home-Server2 slapd[26049]: >>> slap_listener(ldap:///)
Feb 25 19:40:06 Home-Server2 slapd[26049]: conn=1 fd=11 ACCEPT from IP=159.255.36.1:4981 (IP=0.0.0.0:389)
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_get(11)
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_get(11): got connid=1
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_read(11): checking for input on id=1
Feb 25 19:40:06 Home-Server2 slapd[26049]: ber_get_next on fd 11 failed errno=11 (Resource temporarily unavailable)
Feb 25 19:40:06 Home-Server2 slapd[26049]: do_bind
Feb 25 19:40:06 Home-Server2 slapd[26049]: >>> dnPrettyNormal: <uid=ldap,ou=Users,dc=home,dc=net>
Feb 25 19:40:06 Home-Server2 slapd[26049]: <<< dnPrettyNormal: <uid=ldap,ou=Users,dc=home,dc=net>, <uid=ldap,ou=users,dc=home,dc=net>
Feb 25 19:40:06 Home-Server2 slapd[26049]: do_bind: version=3 dn="uid=ldap,ou=Users,dc=home,dc=net" method=128
Feb 25 19:40:06 Home-Server2 slapd[26049]: conn=1 op=0 BIND dn="uid=ldap,ou=Users,dc=home,dc=net" method=128
Feb 25 19:40:06 Home-Server2 slapd[26049]: ==> bdb_bind: dn: uid=ldap,ou=Users,dc=home,dc=net
Feb 25 19:40:06 Home-Server2 slapd[26049]: bdb_dn2entry("uid=ldap,ou=users,dc=home,dc=net")
Feb 25 19:40:06 Home-Server2 slapd[26049]: send_ldap_result: conn=1 op=0 p=3
Feb 25 19:40:06 Home-Server2 slapd[26049]: send_ldap_result: err=49 matched="" text=""
Feb 25 19:40:06 Home-Server2 slapd[26049]: send_ldap_response: msgid=1 tag=97 err=49
Feb 25 19:40:06 Home-Server2 slapd[26049]: conn=1 op=0 RESULT tag=97 err=49 text=
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_get(11)
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_get(11): got connid=1
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_read(11): checking for input on id=1
Feb 25 19:40:06 Home-Server2 slapd[26049]: ber_get_next on fd 11 failed errno=0 (Success)
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_closing: readying conn=1 sd=11 for close
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_close: deferring conn=1 sd=-1
Feb 25 19:40:06 Home-Server2 slapd[26049]: do_unbind
Feb 25 19:40:06 Home-Server2 slapd[26049]: conn=1 op=1 UNBIND
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_resched: attempting closing conn=1 sd=11
Feb 25 19:40:06 Home-Server2 slapd[26049]: connection_close: conn=1 sd=-1
Feb 25 19:40:06 Home-Server2 slapd[26049]: conn=1 fd=11 closed
Log Level: Stats + Args + Trace + Sync
Nothing!!!
Log Level: -1 (Log everything)
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: activity on 1 descriptor
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: activity on:
Feb 25 20:04:30 Home-Server2 slapd[27307]:
Feb 25 20:04:30 Home-Server2 slapd[27307]: >>> slap_listener(ldap:///)
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: listen=7, new connection on 11
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: added 11r (active) listener=(nil)
Feb 25 20:04:30 Home-Server2 slapd[27307]: conn=2 fd=11 ACCEPT from IP=159.255.36.1:3397 (IP=0.0.0.0:389)
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: epoll: listen=7 active_threads=1 tvp=zero
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: activity on 1 descriptor
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: activity on:
Feb 25 20:04:30 Home-Server2 slapd[27307]: 11r
Feb 25 20:04:30 Home-Server2 slapd[27307]:
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: read active on 11
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_get(11)
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_get(11): got connid=2
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_read(11): checking for input on id=2
Feb 25 20:04:30 Home-Server2 slapd[27307]: ber_get_next on fd 11 failed errno=11 (Resource temporarily unavailable)
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: epoll: listen=7 active_threads=1 tvp=zero
Feb 25 20:04:30 Home-Server2 slapd[27307]: do_bind
Feb 25 20:04:30 Home-Server2 slapd[27307]: >>> dnPrettyNormal: <uid=ldap,ou=Users,dc=home,dc=net>
Feb 25 20:04:30 Home-Server2 slapd[27307]: <<< dnPrettyNormal: <uid=ldap,ou=Users,dc=home,dc=net>, <uid=ldap,ou=users,dc=home,dc=net>
Feb 25 20:04:30 Home-Server2 slapd[27307]: do_bind: version=3 dn="uid=ldap,ou=Users,dc=home,dc=net" method=128
Feb 25 20:04:30 Home-Server2 slapd[27307]: conn=2 op=0 BIND dn="uid=ldap,ou=Users,dc=home,dc=net" method=128
Feb 25 20:04:30 Home-Server2 slapd[27307]: ==> bdb_bind: dn: uid=ldap,ou=Users,dc=home,dc=net
Feb 25 20:04:30 Home-Server2 slapd[27307]: bdb_dn2entry("uid=ldap,ou=users,dc=home,dc=net")
Feb 25 20:04:30 Home-Server2 slapd[27307]: => access_allowed: auth access to "uid=ldap,ou=Users,dc=home,dc=net" "userPassword" requested
Feb 25 20:04:30 Home-Server2 slapd[27307]: => acl_get: [1] attr userPassword
Feb 25 20:04:30 Home-Server2 slapd[27307]: => slap_access_allowed: no res from state (userPassword)
Feb 25 20:04:30 Home-Server2 slapd[27307]: => acl_mask: access to entry "uid=ldap,ou=Users,dc=home,dc=net", attr "userPassword" requested
Feb 25 20:04:30 Home-Server2 slapd[27307]: => acl_mask: to value by "", (=0)
Feb 25 20:04:30 Home-Server2 slapd[27307]: <= check a_dn_pat: self
Feb 25 20:04:30 Home-Server2 slapd[27307]: <= check a_dn_pat: cn=root,dc=home,dc=net
Feb 25 20:04:30 Home-Server2 slapd[27307]: <= check a_dn_pat: uid=ldap,ou=users,dc=home,dc=net
Feb 25 20:04:30 Home-Server2 slapd[27307]: <= check a_dn_pat: anonymous
Feb 25 20:04:30 Home-Server2 slapd[27307]: <= acl_mask: [4] applying auth(=xd) (stop)
Feb 25 20:04:30 Home-Server2 slapd[27307]: <= acl_mask: [4] mask: auth(=xd)
Feb 25 20:04:30 Home-Server2 slapd[27307]: => slap_access_allowed: auth access granted by auth(=xd)
Feb 25 20:04:30 Home-Server2 slapd[27307]: => access_allowed: auth access granted by auth(=xd)
Feb 25 20:04:30 Home-Server2 slapd[27307]: send_ldap_result: conn=2 op=0 p=3
Feb 25 20:04:30 Home-Server2 slapd[27307]: send_ldap_result: err=49 matched="" text=""
Feb 25 20:04:30 Home-Server2 slapd[27307]: send_ldap_response: msgid=1 tag=97 err=49
Feb 25 20:04:30 Home-Server2 slapd[27307]: conn=2 op=0 RESULT tag=97 err=49 text=
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: activity on 1 descriptor
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: activity on:
Feb 25 20:04:30 Home-Server2 slapd[27307]: 11r
Feb 25 20:04:30 Home-Server2 slapd[27307]:
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: read active on 11
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_get(11)
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_get(11): got connid=2
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_read(11): checking for input on id=2
Feb 25 20:04:30 Home-Server2 slapd[27307]: ber_get_next on fd 11 failed errno=0 (Success)
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_read(11): input error=-2 id=2, closing.
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_closing: readying conn=2 sd=11 for close
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_close: deferring conn=2 sd=-1
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: epoll: listen=7 active_threads=1 tvp=zero
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: activity on 1 descriptor
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: activity on:
Feb 25 20:04:30 Home-Server2 slapd[27307]:
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: epoll: listen=7 active_threads=1 tvp=zero
Feb 25 20:04:30 Home-Server2 slapd[27307]: do_unbind
Feb 25 20:04:30 Home-Server2 slapd[27307]: conn=2 op=1 UNBIND
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_resched: attempting closing conn=2 sd=11
Feb 25 20:04:30 Home-Server2 slapd[27307]: connection_close: conn=2 sd=-1
Feb 25 20:04:30 Home-Server2 slapd[27307]: daemon: removing 11
Feb 25 20:04:30 Home-Server2 slapd[27307]: conn=2 fd=11 closed
Attachment:
consumer.conf
Description: Binary data
Attachment:
provider.conf
Description: Binary data