Re: Sync Replication issues with bindmethod=simple

[Pierangelo Masarati <ando@sys-net.it>]

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
------------------------------------------