search

389ds / 389-ds-base

The enterprise-class Open Source LDAP server for Linux
https://www.port389.org/
Other
211 stars 91 forks source link

389 directory server is left out op number in access log #2331

Closed 389-ds-bot closed 4 years ago

389-ds-bot commented 4 years ago

Cloned from Pagure issue: https://pagure.io/389-ds-base/issue/49272

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

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2017-05-29 07:21:32

@mreynolds389 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!

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2017-05-29 07:21:47

Metadata Update from @Firstyear:

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-05-29 08:32:03

@Firstyear this case accesslog level is 256+131072.

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-05-29 08:33:46

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 .

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-05-29 09:04:45

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

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2017-05-30 01:56:48

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

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-01 05:37:40

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

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-01 12:39:34

@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

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-01 12:45:19

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

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-01 12:54:55

how can I resolve this problem? @mreynolds389 @Firstyear thank you.

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2017-06-01 14:51:57

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

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2017-06-02 01:48:08

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.

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-02 08:51:41

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

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

389-ds-bot commented 4 years ago

Comment from lkrispen (@elkris) at 2017-06-02 17:17:45

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

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-05 08:43:47

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

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

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-05 08:50:52

image 8 8.jpg

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2017-06-06 00:53:29

@mreynolds389 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?

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2017-06-06 03:16:04

@mreynolds389 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.

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-08 14:04:42

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

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-08 14:05:51

but 1.3.4.0-xx is not appeared.

389-ds-bot commented 4 years ago

Comment from sjsong at 2017-06-08 14:07:24

this is ldapbrowser. Gawor_ldapbrowser_282.zip

389-ds-bot commented 4 years ago

Comment from mreynolds (@mreynolds389) at 2017-06-22 17:40:51

Metadata Update from @mreynolds389:

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2017-09-05 06:31:22

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

389-ds-bot commented 4 years ago

Comment from firstyear (@Firstyear) at 2017-09-05 06:31:22

Metadata Update from @Firstyear:

sjsong commented 2 months ago

thank you