Bug 834075

Summary:	logconv.pl reporting unindexed search with different search base than shown in access logs
Product:	Red Hat Enterprise Linux 6	Reporter:	Nathan Kinder <nkinder>
Component:	389-ds-base	Assignee:	Rich Megginson <rmeggins>
Status:	CLOSED ERRATA	QA Contact:	Sankar Ramalingam <sramling>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	6.4	CC:	cww, jgalipea, klamb, mreynolds, sramling
Target Milestone:	rc
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:	389-ds-base-1.2.11.12-1.el6	Doc Type:	Bug Fix
Doc Text:	Cause: did not grab the correct search base Consequence: stats were invalid Fix: created a new hash to store conn/op numbers from search operations. This allows us to grab the correct stats Result: correct stats	Story Points:	---
Clone Of:		Environment:
Last Closed:	2013-02-21 08:19:51 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	782183

Description Nathan Kinder 2012-06-20 18:33:11 UTC

This bug is created as a clone of upstream ticket:
https://fedorahosted.org/389/ticket/292

https://bugzilla.redhat.com/show_bug.cgi?id=790081 (''Red Hat Directory Server'')

{{{
Description of problem:
logconv.pl's output of unindexed searches showed the search base a a different
search base that what the access logs showed for the search.


Version-Release number of selected component (if applicable):
rhds 8.2, current version

How reproducible:
happens very rarely.  Cust runs logconv.pl daily to look at server performance.
Cust noticed this only because the logconv output was very different on a known
entry

Steps to Reproduce:
1. run logconv.pl
2. check unindexed entries against access logs
3.

Actual results:
incorrect search base

Expected results:
correct search base

}}}

Comment 1 Nathan Kinder 2012-06-21 14:02:29 UTC

*** Bug 790081 has been marked as a duplicate of this bug. ***

Comment 2 RHEL Program Management 2012-07-10 06:17:06 UTC

This request was not resolved in time for the current release.
Red Hat invites you to ask your support representative to
propose this request, if still desired, for consideration in
the next release of Red Hat Enterprise Linux.

Comment 3 Sankar Ramalingam 2012-07-10 20:32:41 UTC

I am not sure how to reproduce this problem.

I ran logconv.pl script and found "Unindexed searches" as
Unindexed Search #1
  -  Date/Time:             10/Jul/2012:23:58:00
  -  Connection Number:     225
  -  Operation Number:      1

  Unindexed Search #2
  -  Date/Time:             10/Jul/2012:23:59:19
  -  Connection Number:     629
  -  Operation Number:      1

  Unindexed Search #3
  -  Date/Time:             10/Jul/2012:23:59:23
  -  Connection Number:     734
 -  Operation Number:      1

  Unindexed Search #4
  -  Date/Time:             11/Jul/2012:00:27:48
  -  Connection Number:     1128
  -  Operation Number:      1

In the access logs, I could see the same connections are marked as unidexed searches(notes=U).

Do I need to have a large number of entries to reproduce the problem?

Comment 4 Nathan Kinder 2012-07-10 21:09:26 UTC

(In reply to comment #3)
> I am not sure how to reproduce this problem.

There is an access log attached to the original bug report (bug 790081) logged by the customer against RHDS 8.2.  Please download it and use longconv.pl against it to reproduce the problem and verify the fix.

Comment 5 RHEL Program Management 2012-07-10 23:02:40 UTC

This request was erroneously removed from consideration in Red Hat Enterprise Linux 6.4, which is currently under development.  This request will be evaluated for inclusion in Red Hat Enterprise Linux 6.4.

Comment 6 Sankar Ramalingam 2012-07-11 15:04:42 UTC

(In reply to comment #4)
> (In reply to comment #3)
> > I am not sure how to reproduce this problem.
> 
> There is an access log attached to the original bug report (bug 790081)
> logged by the customer against RHDS 8.2.  Please download it and use
> longconv.pl against it to reproduce the problem and verify the fix.
I downlaoded the access logs from the bug attachment and ran logconv.pl with -V option.
What I see here is... 
Unindexed searches are having "notes=U" at the end of the line. Where as the 
"conn=1304041 op=386" doesn't end with "notes=U". If the line ends with "notes=U" and logconv.pl doesn't find it, then its an issue in the tool. 

Is this the problem in access log reporting? or logconv.pl tool?

Comment 7 Nathan Kinder 2012-07-12 15:19:32 UTC

(In reply to comment #6)
> (In reply to comment #4)
> > (In reply to comment #3)
> > > I am not sure how to reproduce this problem.
> > 
> > There is an access log attached to the original bug report (bug 790081)
> > logged by the customer against RHDS 8.2.  Please download it and use
> > longconv.pl against it to reproduce the problem and verify the fix.
> I downlaoded the access logs from the bug attachment and ran logconv.pl with
> -V option.
> What I see here is... 
> Unindexed searches are having "notes=U" at the end of the line. Where as the 
> "conn=1304041 op=386" doesn't end with "notes=U". If the line ends with
> "notes=U" and logconv.pl doesn't find it, then its an issue in the tool. 
> 
> Is this the problem in access log reporting? or logconv.pl tool?

The bug was in the logconv.pl tool.  The access log itself is correct.

Comment 9 Sankar Ramalingam 2013-02-04 10:21:03 UTC

I ran logconv.pl tool on the access logs and I observed that the Search base shown in the result is relevant to the access logs. Hence marking the bug as Verified.

  Unindexed Search #152
  -  Date/Time:             04/Feb/2013:05:10:10
  -  Connection Number:     5
  -  Operation Number:      1
  -  Etime:                 0
  -  Nentries:              1
  -  IP Address:            10.16.65.106
  -  Bind DN:               cn=directory manager
  -  Bind DN:               cn=replication manager,cn=config
  -  Search Base:           cn=account uids,cn=distributed numeric assignment plugin,cn=plugins,cn=config
  -  Search Base:           cn=posix user4,ou=people,o=dna.net
  -  Search Base:           cn=posix user3,ou=people,o=dna.net
  -  Search Base:           cn=dna user3,ou=people,o=dna.net
  -  Search Base:           cn=posix user2,ou=people,o=dna.net
  -  Search Base:           cn=posix user2,ou=people,o=dna.net
  -  Search Base:           cn=posix user3,ou=people,o=dna.net
  -  Search Base:           cn=group1,ou=groups,o=dna.net



From access logs:
[04/Feb/2013:04:56:52 -0500] conn=20 fd=65 slot=65 connection from 10.16.65.106 to 10.16.65.106
[04/Feb/2013:04:56:52 -0500] conn=20 op=0 BIND dn="cn=directory manager" method=128 version=3
[04/Feb/2013:04:56:52 -0500] conn=20 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[04/Feb/2013:04:56:52 -0500] conn=20 op=1 SRCH base="dnaHostname=dell-pe2800-01.rhts.eng.bos.redhat.com+dnaPortNum=24204,cn=Account UIDs,ou=Ranges,o=dna.net" scope=2 filter="(objectClass=*)" attrs=ALL
[04/Feb/2013:04:56:52 -0500] conn=20 op=1 RESULT err=0 tag=101 nentries=1 etime=0 notes=U
[04/Feb/2013:04:56:52 -0500] conn=20 op=2 UNBIND
[04/Feb/2013:04:56:52 -0500] conn=20 op=2 fd=65 closed - U1
[04/Feb/2013:04:56:52 -0500] conn=21 fd=66 slot=66 connection from 10.16.65.106 to 10.16.65.106
[04/Feb/2013:04:56:52 -0500] conn=21 op=0 BIND dn="cn=directory manager" method=128 version=3
[04/Feb/2013:04:56:52 -0500] conn=21 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=directory manager"
[04/Feb/2013:04:56:52 -0500] conn=21 op=1 SRCH base="dnaHostname=dell-pe2800-01.rhts.eng.bos.redhat.com+dnaPortNum=24204,cn=Account UIDs,ou=Ranges,o=dna.net" scope=2 filter="(objectClass=*)" attrs=ALL
[04/Feb/2013:04:56:52 -0500] conn=21 op=1 RESULT err=0 tag=101 nentries=1 etime=0 notes=U

Comment 10 errata-xmlrpc 2013-02-21 08:19:51 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2013-0503.html