It looks chaining backend has an issue. Some connection is established and used for operations without binding. Search is allowed, but delete is rejected as expected with the acl settings.
This is the snippet of the access log. conn=15 is established and used immediately for search without binding. The searches are from ldclt. Then, the same connection is used for ldclt delete, which fails since acl does not allow it to anonymous (no bind user).
[] conn=15 fd=64 slot=64 connection from 10.16.66.124 to 10.16.66.124 [] conn=15 op=0 SRCH base="o=farm1,o=cbrLD.com" scope=2 filter="(cn=monsieur14394)" attrs=ALL authzid="uid=buser,o=cbrld.com" [] conn=15 op=0 RESULT err=0 tag=101 nentries=0 etime=0 [] conn=15 op=1 SRCH base="o=farm1,o=cbrLD.com" scope=2 filter="(cn=monsieur22398)" attrs=ALL authzid="uid=buser,o=cbrld.com" [] conn=15 op=1 RESULT err=0 tag=101 nentries=0 etime=0 [] conn=15 op=2 SRCH base="o=farm1,o=cbrLD.com" scope=2 filter="(cn=monsieur12018)" attrs=ALL authzid="uid=buser,o=cbrld.com" ... [] conn=15 op=48176 DEL dn="cn=monsieur00000,o=farm1,o=cbrLD.com" authzid="uid=buser,o=cbrld.com" [] conn=15 op=48176 RESULT err=50 tag=107 nentries=0 etime=0 ... [] conn=15 op=48188 DEL dn="cn=monsieur00005,o=farm1,o=cbrLD.com" authzid="uid=buser,o=cbrld.com" [] conn=15 op=48188 RESULT err=50 tag=107 nentries=0 etime=1
On farm1, all the err=50 are associated with conn=15.
On farm2, all the err=50 are associated with conn=16.
This is the error log and access log of one delete op. It shows the binddn is empty.
# egrep "conn=15 op=48188" access errors access:[] conn=15 op=48188 DEL dn="cn=monsieur00005,o=farm1,o=cbrLD.com" authzid="uid=buser,o=cbrld.com" access:[] conn=15 op=48188 RESULT err=50 tag=107 nentries=0 etime=1 errors:[] NSACLPlugin - #### conn=15 op=48188 binddn="" errors:[] NSACLPlugin - #### conn=15 op=48188 binddn="" errors:[] NSACLPlugin - conn=15 op=48188 (main): Deny proxy on entry(cn=monsieur00005,o=farm1,o=cbrld.com).attr(NULL) to anonymous: no aci matched the subject by aci(19): aciname= "troot", acidn="o=cbrld.com" errors:[] NSACLPlugin - conn=15 op=48188 (main): Deny delete on entry(cn=monsieur00005,o=farm1,o=cbrld.com).attr(NULL) to proxy (uid=buser,o=cbrld.com): error occurred
I grepped BIND in the access log on Farm1. conn=13 and 15 are missing, which were running w/o bind.
# egrep BIND access | egrep -v UNBIND [] conn=2 op=0 BIND dn="cn=directory manager" method=128 version=3 [] conn=3 op=0 BIND dn="cn=directory manager" method=128 version=3 [] conn=4 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=5 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=6 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=7 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=8 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=9 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=10 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=11 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=12 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=14 op=0 BIND dn="uid=troot,o=cbrld.com" method=128 version=3 [] conn=16 op=0 BIND dn="cn=directory manager" method=128 version=3
Since chaining backend manages connections in the connection pool, once it's used without bound, it continues being used.
Interestingly, the connection with no bind occurs when the concurrent connection count reaches maxconnections (20, by default) and woken by receiving the notification from other thread. This case, conn=13 is unbound and closed, and conn=15 is established.
[] conn=13 op=80931 SRCH base="o=farm1,o=cbrLD.com" sc ope=2 filter="(cn=monsieur47560)" attrs=ALL authzid="uid=buser,o=cbrld.com" [] conn=13 op=80931 RESULT err=0 tag=101 nentries=0 etime=0 [] conn=13 op=80932 UNBIND [] conn=13 op=80932 fd=64 closed - U1 [] conn=15 fd=64 slot=64 connection from 10.16.66.124 to 10.16.66.124 [] conn=15 op=0 SRCH base="o=farm1,o=cbrLD.com" scope=2 filter="(cn=monsieur14394)" attrs=ALL authzid="uid=buser,o=cbrld.com" [] conn=15 op=0 RESULT err=0 tag=101 nentries=0 etime=0 ....
Only a suspicious code which could provide a connection without binding is the case that (pool->bindit == 0). But there is no place where 0 is setting to bindit. It should be always 1. But since we don't use the value we could get rid of the check (line 362) in the future.
158 int 159 cb_get_connection(cb_conn_pool * pool, 160 LDAP ** lld, 161 cb_outgoing_conn ** cc, 162 struct timeval * maxtime, 163 char **errmsg) 164 { ... 339 ld = slapi_ldap_init(hostname, port, secure, isMultiThread); ... 359 /* no controls and simple bind only */ 360 /* For now, bind even if no user to detect error */ 361 /* earlier */ 362 if (pool->bindit) { ... 397 /* Password-based client authentication */ 398 rc = slapi_ldap_bind(ld, binddn, plain, mech , NULL, &serverctrls, 399 &bind_to, NULL); 400 401 if ( ret == 0 ) slapi_ch_free_string(&plain) ; /* free plain only if it has been duplicated */ ...
Retested by Viktor and the test passed successfully. Closing this bug.
Metadata Update from @nhosoi: - Issue assigned to nhosoi - Issue set to the milestone: 1.3.6 backlog
389-ds-base is moving from Pagure to Github. This means that new issues and pull requests will be accepted only in 389-ds-base's github repository.
This issue has been cloned to Github and is available here: - https://github.com/389ds/389-ds-base/issues/559
If you want to receive further updates on the issue, please navigate to the github issue and click on subscribe button.
subscribe
Thank you for understanding. We apologize for all inconvenience.
Metadata Update from @spichugi: - Issue close_status updated to: wontfix (was: Fixed)
Login to comment on this ticket.