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
On Wed, 9 Sep 2015, Nat Sincheler wrote:
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
[...] What does "Sync control : mode decoding error" mean? Any suggestions on next steps for troubleshooting?
See RFC4533 section 2.2 ... mode i.e. refreshOnly or refreshAndPersist.
blindly: I'm not familiar with the Perl module you reference, but perhaps you need to be explicitly specifying this value (i.e. perhaps your API has you sending some uninitialized, invalid value)?
methodically: packet sniffing, say using wireshark and/or slapd debugging facilities, and sit down and figure out if you're sending valid BER/mode value/etc. Or if your client API has some debugging options, but again, I'm not familiar with that side.
--On Thursday, September 10, 2015 9:39 AM -0400 Aaron Richton richton@nbcs.rutgers.edu wrote:
On Wed, 9 Sep 2015, Nat Sincheler wrote:
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
[...] What does "Sync control : mode decoding error" mean? Any suggestions on next steps for troubleshooting?
See RFC4533 section 2.2 ... mode i.e. refreshOnly or refreshAndPersist.
Well, the interesting bit is that it worked in 2.4.40 and previous, but broke in 2.4.41 or 2.4.42, where significant changes to the syncrepl code were made. It would be useful to know if it was 2.4.41 or 2.4.42. It would also be useful to have the full set of code, and I'd suggest using the latest Net::LDAPapi code (It's getting prepped for a new release):
https://github.com/quanah/net-ldapapi
--Quanah
--
Quanah Gibson-Mount Platform Architect Zimbra, Inc. -------------------- Zimbra :: the leader in open source messaging and collaboration
--On Thursday, September 10, 2015 10:57 AM -0700 Quanah Gibson-Mount quanah@zimbra.com wrote:
--On Thursday, September 10, 2015 9:39 AM -0400 Aaron Richton richton@nbcs.rutgers.edu wrote:
On Wed, 9 Sep 2015, Nat Sincheler wrote:
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
[...] What does "Sync control : mode decoding error" mean? Any suggestions on next steps for troubleshooting?
See RFC4533 section 2.2 ... mode i.e. refreshOnly or refreshAndPersist.
Well, the interesting bit is that it worked in 2.4.40 and previous, but broke in 2.4.41 or 2.4.42, where significant changes to the syncrepl code were made. It would be useful to know if it was 2.4.41 or 2.4.42. It would also be useful to have the full set of code, and I'd suggest using the latest Net::LDAPapi code (It's getting prepped for a new release):
Also, if you could send me the full script you are using, that would be helpful, thanks!
--Quanah
--
Quanah Gibson-Mount Platform Architect Zimbra, Inc. -------------------- Zimbra :: the leader in open source messaging and collaboration
On 9/10/2015 11:19 AM, Quanah Gibson-Mount wrote:
--On Thursday, September 10, 2015 10:57 AM -0700 Quanah Gibson-Mount quanah@zimbra.com wrote:
--On Thursday, September 10, 2015 9:39 AM -0400 Aaron Richton richton@nbcs.rutgers.edu wrote:
On Wed, 9 Sep 2015, Nat Sincheler wrote:
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
[...] What does "Sync control : mode decoding error" mean? Any suggestions on next steps for troubleshooting?
See RFC4533 section 2.2 ... mode i.e. refreshOnly or refreshAndPersist.
Well, the interesting bit is that it worked in 2.4.40 and previous, but broke in 2.4.41 or 2.4.42, where significant changes to the syncrepl code were made. It would be useful to know if it was 2.4.41 or 2.4.42. It would also be useful to have the full set of code, and I'd suggest using the latest Net::LDAPapi code (It's getting prepped for a new release):
Also, if you could send me the full script you are using, that would be helpful, thanks!
Here is a stripped-down version of the code:
use strict; use warnings;
use Net::LDAPapi;
sub make_connect { my $LDAP = ldap_connect(host => 'ldap-master0.example.com'); return $LDAP; }
sub ldap_connect { my %in = @_;
my $ldap;
if (($ldap = Net::LDAPapi->new($in{'host'})) == -1) { die "ERROR Connection to " . $in{'host'} . " failed."; } my $status; if ($in{'anonymous'}) { $status = $ldap->bind_s(); } else { $ldap->sasl_parms(-mech => "GSSAPI"); $status = $ldap->bind_s(-type => LDAP_AUTH_SASL); }
if ($status != LDAP_SUCCESS) { $ldap->unbind if $ldap; die 'ERROR Bind error connecting to ' . $in{'host'}; } return $ldap; }
sub listen_for_changes {
my $log_base_dn = 'cn=accesslog'; my $log_filter = 'objectclass=*'; my $log_cookie_file = '/var/run/ldap-sync-attributes.cookie';
# If the cookie file does not exist, create a new one. if (!(-e $log_cookie_file)) { open(my $FH, q{>}, $log_cookie_file); close($FH); }
my $LDAP = make_connect();
my $msgid = $LDAP->listen_for_changes(-basedn => $log_base_dn, -scope => LDAP_SCOPE_SUBTREE, -filter => $log_filter, -cookie => $log_cookie_file);
my %retry_list = ();
# Loop forever, listening for changes. Every time one is found, # iterate through each result, and make changes as needed.
while (1) { my @entries; while (@entries = $LDAP->next_changed_entries($msgid, 0, -1)) { foreach my $entry (@entries) {
# Find the dn of whatever changed my @reqdn = $LDAP->get_values('reqDN'); if (!@reqdn) { next; }
my $dn = $reqdn[0];
# Look at the changes my @mods = (); my $update_request = 0; if (@mods = $LDAP->get_values('reqMod')) { foreach my $val (@mods) { # Pick apart the result my $attr = my $action = my $value = q{}; if ($val =~ m{^(.+?):(.)\s+(.+)$}xsm) { $attr = $1; $action = $2; $value = $3; } elsif ($val =~ m{^(.+?):-}xsm) { $attr = $1; } elsif ($val =~ m{^([^:]+):=$}xsm) { $attr = $1; }
if (!$attr) { next; }
$update_request = 1; } }
if ($update_request) { # <update code here...> } }
$LDAP->msgfree; }
return; }
}
--On Monday, September 14, 2015 11:38 AM -0700 Nat Sincheler fai1107@macrotex.net wrote:
Ok, I've played around with this on some test servers, and I simply can't reproduce it. I'm not entirely sure what the motivations were here to post from an address unrelated to the organization you work for, particularly given that the organization has at least in the past, had close ties with the OpenLDAP project. When I ran the LDAP servers for your organization, one of the things we always had was a support contract with Symas. Assuming that rather sensical agreement has been maintained, I'd honestly advise making use of it. You're environment is rather unique, and the ability to debug your situation w/o access to the servers in question is extremely difficult.
--Quanah
--
Quanah Gibson-Mount Platform Architect Zimbra, Inc. -------------------- Zimbra :: the leader in open source messaging and collaboration
openldap-technical@openldap.org
-
Aaron Richton -
Nat Sincheler -
Quanah Gibson-Mount