Bug 1657635

Summary: Random number generate for internal access logs without the sequence.
Product: Red Hat Enterprise Linux 8 Reporter: Amita Sharma <amsharma>
Component: 389-ds-baseAssignee: mreynolds
Status: CLOSED NOTABUG QA Contact: RHDS QE <ds-qe-bugs>
Severity: medium Docs Contact:
Priority: low    
Version: 8.0CC: cpelland, lkrispen, nkinder, rmeggins, spichugi, tbordaz, vashirov
Target Milestone: rc   
Target Release: 8.0   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-07-31 17:14:21 UTC Type: Bug
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: 1683259    
Bug Blocks:    
Attachments:
Description Flags
internal server access logs none

Description Amita Sharma 2018-12-10 08:08:59 UTC
Created attachment 1512958 [details]
internal server access logs

Description of problem:
Random number generate for internal access logs without the sequence.

Version-Release number of selected component (if applicable):
389-ds-base-1.4.0.19-2.module+el8+1+36e60e1d.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Configure access log level to 260 (4 + 256)
dsconf -D "cn=Directory Manager" slapd-localhost config replace nsslapd-accesslog-level=260

2. Restart the server
dsctl slapd-localhost restart

3. Check the access logs - It has random number generated for the access log, look for "conn=Internal(0) op=0(174)(1)"

[10/Dec/2018:07:58:23.236168537 +0000] conn=1 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0000228213 dn="cn=Directory Manager"
[10/Dec/2018:07:58:23.236497131 +0000] conn=1 op=1 MOD dn="cn=config"
[10/Dec/2018:07:58:23.242442496 +0000] conn=1 op=1 RESULT err=0 tag=103 nentries=0 etime=0.0006057640
[10/Dec/2018:07:58:23.242664859 +0000] conn=1 op=2 UNBIND
[10/Dec/2018:07:58:23.242675880 +0000] conn=1 op=2 fd=64 closed - U1
[10/Dec/2018:07:58:35.842422218 +0000] conn=Internal(0) op=0(174)(1) MOD dn="cn=uniqueid generator,cn=config"
[10/Dec/2018:07:58:35.844357335 +0000] conn=Internal(0) op=0(174)(1) RESULT err=0 tag=48 nentries=0 etime=0.0001955328
[10/Dec/2018:07:58:39.241484658 +0000] conn=Internal(0) op=0(1)(1) SRCH base="cn=mapping tree,cn=config" scope=1 filter="(&(objectclass=nsMappingTree)(!(nsslapd-parent-suffix=*)))" attrs=ALL
[10/Dec/2018:07:58:39.241605324 +0000] conn=Internal(0) op=0(1)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000127719
[10/Dec/2018:07:58:39.241644087 +0000] conn=Internal(0) op=0(2)(1) ADD dn=""
[10/Dec/2018:07:58:39.241692963 +0000] conn=Internal(0) op=0(2)(1) RESULT err=68 tag=48 nentries=0 etime=0.0000051243

Please find attachment for the complete access logs.

NOTE - I observed every-time it is same operation which comes up with random number - "MOD dn="cn=uniqueid generator,cn=config"

Comment 1 mreynolds 2018-12-11 02:05:09 UTC
Upstream ticket:
https://pagure.io/389-ds-base/issue/50080

Comment 2 mreynolds 2019-07-31 17:14:21 UTC
Actually the server is working correctly.  What happens is that the "random" number was from before the server was restarted.  After the server starts up the last internal operation is:

[31/Jul/2019:13:10:09.005210233 -0400] conn=Internal(0) op=0(237)(1) MOD dn="cn=uniqueid generator,cn=config"
[31/Jul/2019:13:10:09.017457233 -0400] conn=Internal(0) op=0(237)(1) RESULT err=0 tag=48 nentries=0 etime=0.0017452450

It is NOT the first operation, but with log buffering it's easy to misinterpret the order of events.  Closing as not a bug