389-ds-base

Clone
Source Code
GIT

#49272 389 directory server is left out op number in access log
Closed: wontfix 7 years ago Opened 8 years ago by sjsong.

Closed: wontfix
Reopen Issue

Issue Description

389 directory server is left out op number in access log

op number 5 and 9.

I want to know this reason.

[29/May/2017:00:21:39.663445641 -0400] conn=4 fd=64 slot=64 connection from 192.168.29.1 to 192.168.29.225
[29/May/2017:00:21:39.666719211 -0400] conn=4 op=0 BIND dn="cn=directory manager" method=128 version=3
[29/May/2017:00:21:39.667859102 -0400] conn=4 op=0 RESULT err=0 tag=97 nentries=0 etime=0.001000 dn="cn=directory manager"
[29/May/2017:00:21:39.669855058 -0400] conn=4 op=1 SRCH base="dc=cae,dc=com" scope=1 filter="(objectClass=)" attrs="hasSubordinates"
[29/May/2017:00:21:39.671945219 -0400] conn=4 op=1 RESULT err=0 tag=101 nentries=5 etime=0.002000 notes=U
[29/May/2017:00:21:42.014076686 -0400] conn=4 op=2 SRCH base="ou=people,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[29/May/2017:00:21:42.015727962 -0400] conn=4 op=2 RESULT err=0 tag=101 nentries=1 etime=0.002000
[29/May/2017:00:21:42.664642611 -0400] conn=4 op=3 SRCH base="ou=Special Users,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[29/May/2017:00:21:42.666422976 -0400] conn=4 op=3 RESULT err=0 tag=101 nentries=1 etime=0.002000
[29/May/2017:00:21:45.454655247 -0400] conn=4 op=4 SRCH base="ou=Groups,dc=cae,dc=com" scope=1 filter="(objectClass=)" attrs="hasSubordinates"
[29/May/2017:00:21:45.456715004 -0400] conn=4 op=4 RESULT err=0 tag=101 nentries=4 etime=0.003000 notes=U
[29/May/2017:00:21:46.710095946 -0400] conn=4 op=6 SRCH base="ou=Groups,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[29/May/2017:00:21:46.712235857 -0400] conn=4 op=6 RESULT err=0 tag=101 nentries=1 etime=0.002000
[29/May/2017:00:21:48.449139737 -0400] conn=4 op=7 SRCH base="cn=HR Managers,ou=Groups,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[29/May/2017:00:21:48.451109107 -0400] conn=4 op=7 RESULT err=0 tag=101 nentries=1 etime=0.002000
[29/May/2017:00:22:02.052701703 -0400] conn=4 op=8 SRCH base="cn=QA Managers,ou=Groups,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[29/May/2017:00:22:02.057588276 -0400] conn=4 op=8 RESULT err=0 tag=101 nentries=1 etime=0.005000
[29/May/2017:00:22:03.826712190 -0400] conn=4 op=10 SRCH base="ou=people,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[29/May/2017:00:22:03.829878793 -0400] conn=4 op=10 RESULT err=0 tag=101 nentries=1 etime=0.003000

Package Version and Platform

389-ds-base 1.3.5.10-18
centos 7.3

@mreynolds Correct me if I'm wrong, but I think this is internal operations - they are done on the conn but don't show up in the access log.

For the record, this isn't really an issue with DS - our users list on 389-users@lists.fedoraproject.org, or our irc on freenode #389 might be a better place to ask questions like this.

Thanks!

Metadata Update from @firstyear:
- Custom field type adjusted to defect
8 years ago

@firstyear this case accesslog level is 256+131072.

if accesslog level is 4+256+131072, are internal operations appear in accesslog?
I am changing log level to 131332 but but yet, 389 directory server is left out op number in access log .
Edited 8 years ago by sjsong

389 directory server is not left out op number in 389-ds-base-1.3.4.0-21.el7_2.x86_64.
centos 7.2

@sjsong The reason it may not be left out in 1.3.4 is possibly different.

It looks like we change some log messages to be not logged if they are internal operations.

For example, in result.c we can see:

                else if ( !internal_op )
                {
                        ...
                        slapi_log_access( LDAP_DEBUG_STATS,
                                                          "conn=%" PRIu64 " op=%d RESULT err=%d"
                                                          " tag=%" BERTAG_T " nentries=%d etime=%s%s%s%s\n",
                                                          op->o_connid,
                                                          op->o_opid,
                                                          err, tag, nentries,
                                                          etime,
                                                          notes_str, csn_str, ext_str);
                         ....
                }
                else
                {
                         ....
                        slapi_log_access( LDAP_DEBUG_ARGS,
                                                          "conn=%s op=%d RESULT err=%d"
                                                          " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n",
                                                          LOG_INTERNAL_OP_CON_ID,
                                                          LOG_INTERNAL_OP_OP_ID,
                                                          err, tag, nentries,
                                                          etime,
                                                          notes_str, csn_str );

So when you set LDAP_DEBUG_ARGS, aka 0x4 to the access log level you should see internal operations which may be the source of the missing op numbers you are seeing.

@firstyear thnak you for reply. korean (고맙습니다.)

@firstyear
So when you set LDAP_DEBUG_ARGS, aka 0x4 to the access log level you should see internal operations which may be the source of the missing op numbers you are seeing.
-->
I did set access log level to 0x4. but yet, access log is missed op number.

hot can I resolve this problem?

current environment.
[root@myhost2 ~]# rpm -qa | grep 389
389-admin-console-doc-1.1.12-1.el7.noarch
389-ds-console-doc-1.2.16-1.el7.noarch
389-ds-console-1.2.16-1.el7.noarch
389-ds-base-1.3.5.10-18.el7_3.x86_64
389-ds-base-libs-1.3.5.10-18.el7_3.x86_64
389-ds-base-snmp-1.3.5.10-18.el7_3.x86_64
389-admin-console-1.1.12-1.el7.noarch
389-admin-1.1.46-1.el7.x86_64
389-console-1.1.18-1.el7.noarch
389-adminutil-1.1.21-2.el7.x86_64

access log
[01/Jun/2017:06:37:17.630832721 -0400] conn=1 fd=64 slot=64 connection from 127.0.0.1 to 127.0.0.1
[01/Jun/2017:06:37:17.670170836 -0400] conn=1 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[01/Jun/2017:06:37:17.672087581 -0400] conn=1 op=0 RESULT err=0 tag=97 nentries=0 etime=0.002000 dn="cn=directory manager"
[01/Jun/2017:06:37:17.674708295 -0400] conn=1 op=1 SRCH base="dc=cae,dc=com" scope=1 filter="(objectClass=)" attrs="objectClass"
[01/Jun/2017:06:37:17.687301255 -0400] conn=1 op=1 RESULT err=0 tag=101 nentries=5 etime=0.013000 notes=U
[01/Jun/2017:06:37:22.701170647 -0400] conn=1 op=2 SRCH base="ou=group,dc=cae,dc=com" scope=1 filter="(objectClass=)" attrs="objectClass"
[01/Jun/2017:06:37:22.708088815 -0400] conn=1 op=2 RESULT err=0 tag=101 nentries=2 etime=0.007000 notes=U
[01/Jun/2017:06:37:25.133827201 -0400] conn=1 op=3 SRCH base="ou=neworganizationalUnit,ou=group,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:37:25.137212272 -0400] conn=1 op=3 RESULT err=0 tag=101 nentries=1 etime=0.004000
[01/Jun/2017:06:37:26.373239480 -0400] conn=1 op=5 SRCH base="ou=autohome,ou=group,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:37:26.381610483 -0400] conn=1 op=5 RESULT err=0 tag=101 nentries=1 etime=0.008000
[01/Jun/2017:06:37:29.710407455 -0400] conn=1 op=6 SRCH base="ou=Special Users,dc=cae,dc=com" scope=0 filter="(objectClass=*)" attrs=ALL
[01/Jun/2017:06:37:29.718526981 -0400] conn=1 op=6 RESULT err=0 tag=101 nentries=1 etime=0.011000
[01/Jun/2017:06:37:43.123260877 -0400] conn=1 op=7 UNBIND
[01/Jun/2017:06:37:43.126888065 -0400] conn=1 op=7 fd=64 closed - U1

accessloglevel.png

try again.

missed op number is 6, 9, 15.
[01/Jun/2017:06:42:28.251079143 -0400] conn=1 op=5 ENTRY dn="ou=neworganizationalUnit,ou=group,dc=cae,dc=com"
[01/Jun/2017:06:42:28.256333149 -0400] conn=1 op=5 RESULT err=0 tag=101 nentries=1 etime=0.016000
[01/Jun/2017:06:42:32.991624844 -0400] conn=1 op=7 SRCH base="ou=autohome,ou=group,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:42:33.000982345 -0400] conn=1 op=7 ENTRY dn="ou=autohome,ou=group,dc=cae,dc=com"
[01/Jun/2017:06:42:33.007017853 -0400] conn=1 op=7 RESULT err=0 tag=101 nentries=1 etime=0.016000
[01/Jun/2017:06:42:37.296357189 -0400] conn=1 op=8 SRCH base="ou=Special Users,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:42:37.303037087 -0400] conn=1 op=8 ENTRY dn="ou=Special Users,dc=cae,dc=com"
[01/Jun/2017:06:42:37.306026968 -0400] conn=1 op=8 RESULT err=0 tag=101 nentries=1 etime=0.010000
[01/Jun/2017:06:42:38.684314587 -0400] conn=1 op=10 SRCH base="ou=Groups,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:42:38.693093662 -0400] conn=1 op=10 ENTRY dn="ou=Groups,dc=cae,dc=com"
[01/Jun/2017:06:42:38.699176217 -0400] conn=1 op=10 RESULT err=0 tag=101 nentries=1 etime=0.015000
[01/Jun/2017:06:42:39.854426975 -0400] conn=1 op=11 SRCH base="cn=Directory Administrators,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:42:39.865390909 -0400] conn=1 op=11 ENTRY dn="cn=Directory Administrators,dc=cae,dc=com"
[01/Jun/2017:06:42:39.869508042 -0400] conn=1 op=11 RESULT err=0 tag=101 nentries=1 etime=0.015000
[01/Jun/2017:06:42:41.123274211 -0400] conn=1 op=12 SRCH base="ou=Special Users,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:42:41.127628530 -0400] conn=1 op=12 ENTRY dn="ou=Special Users,dc=cae,dc=com"
[01/Jun/2017:06:42:41.129706328 -0400] conn=1 op=12 RESULT err=0 tag=101 nentries=1 etime=0.006000
[01/Jun/2017:06:42:42.239260131 -0400] conn=1 op=13 SRCH base="ou=people,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:42:42.252444183 -0400] conn=1 op=13 ENTRY dn="ou=people,dc=cae,dc=com"
[01/Jun/2017:06:42:42.259909826 -0400] conn=1 op=13 RESULT err=0 tag=101 nentries=1 etime=0.020000
[01/Jun/2017:06:42:43.353868867 -0400] conn=1 op=14 SRCH base="ou=group,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:42:43.362320379 -0400] conn=1 op=14 ENTRY dn="ou=group,dc=cae,dc=com"
[01/Jun/2017:06:42:43.364420439 -0400] conn=1 op=14 RESULT err=0 tag=101 nentries=1 etime=0.012000
[01/Jun/2017:06:42:44.451589493 -0400] conn=1 op=16 SRCH base="ou=autohome,ou=group,dc=cae,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[01/Jun/2017:06:42:44.457915677 -0400] conn=1 op=16 ENTRY dn="ou=autohome,ou=group,dc=cae,dc=com"
[01/Jun/2017:06:42:44.459534497 -0400] conn=1 op=16 RESULT err=0 tag=101 nentries=1 etime=0.008000
[01/Jun/2017:06:42:49.803845502 -0400] conn=1 op=17 UNBIND
[01/Jun/2017:06:42:49.809258389 -0400] conn=1 op=17 fd=64 closed - U1

how can I resolve this problem? @mreynolds @firstyear
thank you.

@sjsong - in order to help you at this point we need to be able to reproduce this in house. Do you have a reproducible test case that will show the access log op numbers missing?

To elaborate on what mark said: We need to see the sequence of searches and operations you are performing. If you have a development or testing system, can you show us a series of LDAPsearch commands that produce the error? Without this, it's hard for us to track down.

@sjsong - in order to help you at this point we need to be able to reproduce this in house. Do you have a reproducible test case that will show the access log op numbers missing?

@mreynolds ok. I'll organize it up.
thank you

@firstyear internal operations do have a separate conn and opid, they do not interfere with the increment of the ops of an external operation

@sjsong - in order to help you at this point we need to be able to reproduce this in house. Do you have a reproducible test case that will show the access log op numbers missing?

@mreynolds ok. I'll organize it up.
thank you

  1. install OS Centos 7.3

  2. install 389 package
    389-admin-console-doc-1.1.12-1.el7.noarch
    389-ds-console-doc-1.2.16-1.el7.noarch
    389-ds-console-1.2.16-1.el7.noarch
    389-ds-base-1.3.5.10-21.el7_3.x86_64
    389-ds-base-libs-1.3.5.10-18.el7_3.x86_64
    389-ds-base-snmp-1.3.5.10-18.el7_3.x86_64
    389-admin-console-1.1.12-1.el7.noarch
    389-admin-1.1.46-1.el7.x86_64
    389-console-1.1.18-1.el7.noarch
    389-adminutil-1.1.21-2.el7.x86_64

  3. setup directory server using 389-ds-admin.pl

  4. connect to directory server using LDAP browser.

  5. tail -F access
    lefting out op number is generated in access log.

image 8.jpg --> op number 3 is lefted out op number.

1.jpg
2.jpg
3.jpg
4.jpg
6.jpg
7.jpg

@mreynolds Could it be a failing op that's not being logged? We only are only logging SRCH and RESULT here, what if the op never progressed to a valid point? That could explain the odd gap in numbers?

@mreynolds Could it be a failing op that's not being logged? We only are only logging SRCH and RESULT here, what if the op never progressed to a valid point? That could explain the odd gap in numbers?

I do not see how it could happen, and I can not reproduce the problem either. Now I have not tried the "LDAP browser", but I'm not sure what it is or how to get it.

I was reinstall 389 directory server at centos 7.3. by yum install EPEL repo. but it was left out op number in access log.

case one connection multi operation. (ony SRCH)

op number 3, 7, 15 is missed.

[root@ldap slapd-ldap]# grep conn=12 access
[08/Jun/2017:05:01:50.197675404 -0700] conn=12 fd=65 slot=65 connection from 192.168.254.1 to 192.168.254.195
[08/Jun/2017:05:01:50.210778057 -0700] conn=12 op=0 BIND dn="cn=directory manager" method=128 version=3
[08/Jun/2017:05:01:50.211923718 -0700] conn=12 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[08/Jun/2017:05:01:50.214397813 -0700] conn=12 op=1 SRCH base="c=kr" scope=1 filter="(objectClass=)" attrs="hasSubordinates"
[08/Jun/2017:05:01:50.215407046 -0700] conn=12 op=1 RESULT err=0 tag=101 nentries=4 etime=0 notes=U
[08/Jun/2017:05:01:56.058347926 -0700] conn=12 op=2 SRCH base="ou=Groups,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:01:56.062178038 -0700] conn=12 op=2 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:01:57.268548433 -0700] conn=12 op=4 SRCH base="ou=People,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:01:57.276296240 -0700] conn=12 op=4 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:00.597000812 -0700] conn=12 op=5 SRCH base="ou=Groups,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:00.603062571 -0700] conn=12 op=5 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:01.781804443 -0700] conn=12 op=6 SRCH base="cn=Directory Administrators,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:01.785719563 -0700] conn=12 op=6 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:03.623376192 -0700] conn=12 op=8 SRCH base="ou=People,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:03.630266531 -0700] conn=12 op=8 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:04.183240967 -0700] conn=12 op=9 SRCH base="ou=Special Users,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:04.187006684 -0700] conn=12 op=9 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:04.792757730 -0700] conn=12 op=10 SRCH base="ou=Groups,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:04.797227078 -0700] conn=12 op=10 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:05.791141408 -0700] conn=12 op=11 SRCH base="ou=People,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:05.796499165 -0700] conn=12 op=11 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:06.815278807 -0700] conn=12 op=12 SRCH base="ou=Groups,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:06.820146215 -0700] conn=12 op=12 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:07.442975353 -0700] conn=12 op=13 SRCH base="cn=Directory Administrators,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:07.448080562 -0700] conn=12 op=13 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:08.172785709 -0700] conn=12 op=14 SRCH base="ou=Groups,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:08.177337477 -0700] conn=12 op=14 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:09.700133840 -0700] conn=12 op=16 SRCH base="ou=Special Users,c=kr" scope=0 filter="(objectClass=)" attrs=ALL
[08/Jun/2017:05:02:09.705076600 -0700] conn=12 op=16 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:12.504515268 -0700] conn=12 op=17 SRCH base="ou=Groups,c=kr" scope=1 filter="(objectClass=)" attrs="hasSubordinates"
[08/Jun/2017:05:02:12.510437870 -0700] conn=12 op=17 RESULT err=0 tag=101 nentries=4 etime=0 notes=U
[08/Jun/2017:05:02:13.191416500 -0700] conn=12 op=18 SRCH base="cn=HR Managers,ou=Groups,c=kr" scope=0 filter="(objectClass=*)" attrs=ALL
[08/Jun/2017:05:02:13.194930627 -0700] conn=12 op=18 RESULT err=0 tag=101 nentries=1 etime=0
[08/Jun/2017:05:02:15.921336542 -0700] conn=12 op=19 UNBIND
[08/Jun/2017:05:02:15.941632020 -0700] conn=12 op=19 fd=65 closed - U1

but 1.3.4.0-xx is not appeared.

Metadata Update from @mreynolds:
- Issue set to the milestone: 1.3.7.0
8 years ago

Hey there,

I'm not going to run some code that you provided in a zip sorry.

As it stands it looks like the issue is in your application not proceeding to create a valid search.

Sorry :(

Metadata Update from @firstyear:
- Custom field component adjusted to None
- Custom field origin adjusted to None
- Custom field reviewstatus adjusted to None
- Custom field version adjusted to None
- Issue close_status updated to: invalid
- Issue status updated to: Closed (was: Open)
7 years ago

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

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: invalid)
4 years ago

Log in to comment on this ticket.

Metadata
None
None
None
None
None
None
None
None
Attachments 9
accessloglevel.png
Attached 8 years ago View Comment
1.jpg
Attached 8 years ago View Comment
2.jpg
Attached 8 years ago View Comment
3.jpg
Attached 8 years ago View Comment
4.jpg
Attached 8 years ago View Comment
6.jpg
Attached 8 years ago View Comment
7.jpg
Attached 8 years ago View Comment
8.jpg
Attached 8 years ago View Comment
Gawor_ldapbrowser_282.zip
Attached 8 years ago View Comment
Powered by Pagure 5.14.1
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.