I have Perl script that implements a syncrepl listener using the listen_for_changes method from Net::LDAPapi (3.0.3). The listener works well with OpenLDAP 2.4.40 but I am having trouble getting it to work consistently with 2.4.42.
The code looks something like this:
# $LDAP is bound using GSSAPI
my $msgid = $LDAP->listen_for_changes( -basedn => "cn=accesslog", -scope => LDAP_SCOPE_SUBTREE, -filter => "objectclass=*", -cookie => "/var/run/sync.cookie");
while (1) { my @entries; while (@entries = $LDAP->next_changed_entries($msgid, 0, -1))) { ... }
Most of the time (but not _all_ of the time) the listener fails to pick up any entries from the accesslog and I see these messages in my logs:
2015-09-09T08:32:20.926931-07:00 ldap-jessie0 slapd[631]: conn=1161 op=4 SEARCH RESULT tag=101 err=2 nentries=0 text=Sync control : mode decoding error 2015-09-09T08:32:20.927211-07:00 ldap-jessie0 slapd[631]: conn=1161 op=4 do_search: get_ctrls failed
(Fuller log output included below).
I know that the credentials can read the access log as I run a simple search against cn=accesslog before the list_for_changes just to be sure the issue is not related to my credentials.
What does "Sync control : mode decoding error" mean? Any suggestions on next steps for troubleshooting?
####################################################################
2015-09-09T08:32:20.902032-07:00 ldap-jessie0 slapd[631]: conn=1161 fd=14 ACCEPT from IP=171.67.214.66:39646 (IP=0.0.0.0:389) 2015-09-09T08:32:20.902108-07:00 ldap-jessie0 slapd[631]: conn=1161 op=0 SRCH base="" scope=0 deref=0 filter="(objectClass=*)" 2015-09-09T08:32:20.902207-07:00 ldap-jessie0 slapd[631]: conn=1161 op=0 SRCH attr=supportedSASLMechanisms 2015-09-09T08:32:20.902262-07:00 ldap-jessie0 slapd[631]: conn=1161 op=0 SEARCH RESULT tag=101 err=0 nentries=1 text= 2015-09-09T08:32:20.910842-07:00 ldap-jessie0 slapd[631]: conn=1161 op=1 BIND dn="" method=163 2015-09-09T08:32:20.914261-07:00 ldap-jessie0 slapd[631]: conn=1161 op=1 RESULT tag=97 err=14 text=SASL(0): successful result: mech EXTERNAL is too weak 2015-09-09T08:32:20.917754-07:00 ldap-jessie0 slapd[631]: conn=1161 op=2 BIND dn="" method=163 2015-09-09T08:32:20.917798-07:00 ldap-jessie0 slapd[631]: conn=1161 op=2 RESULT tag=97 err=14 text=SASL(0): successful result: mech EXTERNAL is too weak 2015-09-09T08:32:20.918060-07:00 ldap-jessie0 slapd[631]: conn=1161 op=3 BIND dn="" method=163 2015-09-09T08:32:20.918102-07:00 ldap-jessie0 slapd[631]: conn=1161 op=3 BIND authcid="service/ldap-jessie0@stanford.edu" authzid="service/ldap-jessie0@stanford.edu" 2015-09-09T08:32:20.918188-07:00 ldap-jessie0 slapd[631]: conn=1161 op=3 BIND dn="cn=ldap-jessie0,cn=service,cn=applications,dc=stanford,dc=edu" mech=GSSAPI sasl_ssf=56 ssf=56 2015-09-09T08:32:20.918240-07:00 ldap-jessie0 slapd[631]: conn=1161 op=3 RESULT tag=97 err=0 text= 2015-09-09T08:32:20.926931-07:00 ldap-jessie0 slapd[631]: conn=1161 op=4 SEARCH RESULT tag=101 err=2 nentries=0 text=Sync control : mode decoding error 2015-09-09T08:32:20.927211-07:00 ldap-jessie0 slapd[631]: conn=1161 op=4 do_search: get_ctrls failed