Bug 1301097

Summary: logconv.pl displays negative operation speeds
Product: Red Hat Enterprise Linux 7 Reporter: Viktor Ashirov <vashirov>
Component: 389-ds-baseAssignee: Noriko Hosoi <nhosoi>
Status: CLOSED ERRATA QA Contact: Viktor Ashirov <vashirov>
Severity: low Docs Contact:
Priority: low    
Version: 7.3CC: mreynolds, nkinder, rmeggins
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 389-ds-base-1.3.5.2-1.el7 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-11-03 20:38:57 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:
Attachments:
Description Flags
access logs none

Description Viktor Ashirov 2016-01-22 15:11:03 UTC 
Description of problem:
When I run logconv.pl on access* logs (as man page says), operation speeds are negative:
$ logconv.pl access*

Searches:                     2             (-0.01/sec)  (-0.42/min)
Modifications:                1             (-0.00/sec)  (-0.21/min)
Adds:                         0             (-0.00/sec)  (-0.00/min)
Deletes:                      0             (-0.00/sec)  (-0.00/min)
Mod RDNs:                     0             (-0.00/sec)  (-0.00/min)
Compares:                     0             (-0.00/sec)  (-0.00/min)
Binds:                        2             (-0.01/sec)  (-0.42/min)


But when I run it as:
$ logconv.pl access.* access

Searches:                     2             (0.01/sec)  (0.40/min)
Modifications:                1             (0.00/sec)  (0.20/min)
Adds:                         0             (0.00/sec)  (0.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        2             (0.01/sec)  (0.40/min)

Issue is with the order of new and old access log files that are passed to logconv.pl.
In order to display right numbers, I need to run it with the list of files starting from the oldest one to the newest one.
We might as well fix the man page to explicitly mention that. 

Version-Release number of selected component (if applicable):
389-ds-base-1.3.4.0-25.el7_2.x86_64
Comment 2 mreynolds 2016-01-22 17:12:54 UTC 
This is a bug, using "access*" should work correctly.  

What are your steps to reproduce?  How many logs do you have?
Comment 3 mreynolds 2016-01-22 17:29:44 UTC 
Works for me:


# logconv.pl /var/log/dirsrv/slapd-localhost/access*
Access Log Analyzer 8.1
Command: logconv.pl /var/log/dirsrv/slapd-localhost/access /var/log/dirsrv/slapd-localhost/access.20160122-122207 /var/log/dirsrv/slapd-localhost/access.20160122-122424 /var/log/dirsrv/slapd-localhost/access.20160122-122438 /var/log/dirsrv/slapd-localhost/access.20160122-122603 /var/log/dirsrv/slapd-localhost/access.20160122-122608 /var/log/dirsrv/slapd-localhost/access.rotationinfo
Processing 6 Access Log(s)...

[006] /var/log/dirsrv/slapd-localhost/access.20160122-122207	size (bytes):      1148884

[005] /var/log/dirsrv/slapd-localhost/access.20160122-122424	size (bytes):      1048598

[004] /var/log/dirsrv/slapd-localhost/access.20160122-122438	size (bytes):      1379760

[003] /var/log/dirsrv/slapd-localhost/access.20160122-122603	size (bytes):      1572685

[002] /var/log/dirsrv/slapd-localhost/access.20160122-122608	size (bytes):      1142625

[001] /var/log/dirsrv/slapd-localhost/access	size (bytes):       555981


Total Log Lines Analysed:  79854


----------- Access Log Output ------------

Start of Logs:    22/Jan/2016:12:22:10
End of Logs:      22/Jan/2016:12:26:15

Processed Log Time:  0 Hours, 4 Minutes, 5 Seconds

Restarts:                     1
Total Connections:            11310
 - LDAP Connections:          11310
 - LDAPI Connections:         0
 - LDAPS Connections:         0
 - StartTLS Extended Ops:     0
Peak Concurrent Connections:  6
Total Operations:             22952
Total Results:                22951
Overall Performance:          100.0%

Searches:                     11526         (47.04/sec)  (2822.69/min)
Modifications:                6             (0.02/sec)  (1.47/min)
Adds:                         107           (0.44/sec)  (26.20/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        11312         (46.17/sec)  (2770.29/min)
...
...
...
Comment 4 Viktor Ashirov 2016-01-22 17:39:38 UTC 
Created attachment 1117311 [details]
access logs

[root@rhel7ds slapd-rhel7ds]# pwd
/var/log/dirsrv/slapd-rhel7ds
[root@rhel7ds slapd-rhel7ds]# logconv.pl /var/log/dirsrv/slapd-rhel7ds/access*
Access Log Analyzer 8.1
Command: logconv.pl /var/log/dirsrv/slapd-rhel7ds/access /var/log/dirsrv/slapd-rhel7ds/access.20160122-182552 /var/log/dirsrv/slapd-rhel7ds/access.20160122-182653 /var/log/dirsrv/slapd-rhel7ds/access.rotationinfo
Processing 3 Access Log(s)...

[003] /var/log/dirsrv/slapd-rhel7ds/access.20160122-182552	size (bytes):          485

[002] /var/log/dirsrv/slapd-rhel7ds/access.20160122-182653	size (bytes):       132687

[001] /var/log/dirsrv/slapd-rhel7ds/access	size (bytes):        45234


Total Log Lines Analysed:  2069


----------- Access Log Output ------------

Start of Logs:    22/Jan/2016:18:25:57
End of Logs:      22/Jan/2016:18:28:07

Processed Log Time:  0 Hours, 2 Minutes, 10 Seconds

Restarts:                     2
Total Connections:            13
 - LDAP Connections:          13
 - LDAPI Connections:         0
 - LDAPS Connections:         0
 - StartTLS Extended Ops:     0
Peak Concurrent Connections:  10
Total Operations:             1017
Total Results:                1017
Overall Performance:          100.0%

Searches:                     2             (0.02/sec)  (0.92/min)
Modifications:                1             (0.01/sec)  (0.46/min)
Adds:                         1001          (7.70/sec)  (462.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        13            (0.10/sec)  (6.00/min)

...
Looks good, but, when I do the same without the full path, speeds are zeros:

[root@rhel7ds slapd-rhel7ds]# logconv.pl access*
Access Log Analyzer 8.1
Command: logconv.pl access access.20160122-182552 access.20160122-182653 access.rotationinfo
Processing 3 Access Log(s)...

[003] access                        	size (bytes):        45234

[002] access.20160122-182552        	size (bytes):          485

[001] access.20160122-182653        	size (bytes):       132687


Total Log Lines Analysed:  2069


----------- Access Log Output ------------

Start of Logs:    22/Jan/2016:18:27:33
End of Logs:      22/Jan/2016:18:27:33

Processed Log Time:  0 Hours, 0 Minutes, 0 Seconds

Restarts:                     2
Total Connections:            13
 - LDAP Connections:          13
 - LDAPI Connections:         0
 - LDAPS Connections:         0
 - StartTLS Extended Ops:     0
Peak Concurrent Connections:  0
Total Operations:             1017
Total Results:                1017
Overall Performance:          100.0%

Searches:                     2             (0.00/sec)  (0.00/min)
Modifications:                1             (0.00/sec)  (0.00/min)
Adds:                         1001          (0.00/sec)  (0.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        13            (0.00/sec)  (0.00/min)


And when the wrong order is used:

[root@rhel7ds slapd-rhel7ds]# logconv.pl access.20160122-182653 access.20160122-182552
Access Log Analyzer 8.1
Command: logconv.pl access.20160122-182653 access.20160122-182552
Processing 2 Access Log(s)...

[002] access.20160122-182653        	size (bytes):       132687

[001] access.20160122-182552        	size (bytes):          485


Total Log Lines Analysed:  1541


----------- Access Log Output ------------

Start of Logs:    22/Jan/2016:18:26:34
End of Logs:      22/Jan/2016:18:25:57

Processed Log Time:  0 Hours, 0 Minutes, -37 Seconds

Restarts:                     2
Total Connections:            12
 - LDAP Connections:          12
 - LDAPI Connections:         0
 - LDAPS Connections:         0
 - StartTLS Extended Ops:     0
Peak Concurrent Connections:  10
Total Operations:             766
Total Results:                756
Overall Performance:          98.7%

Searches:                     1             (-0.03/sec)  (-1.62/min)
Modifications:                1             (-0.03/sec)  (-1.62/min)
Adds:                         752           (-20.32/sec)  (-1219.46/min)
Deletes:                      0             (-0.00/sec)  (-0.00/min)
Mod RDNs:                     0             (-0.00/sec)  (-0.00/min)
Compares:                     0             (-0.00/sec)  (-0.00/min)
Binds:                        12            (-0.32/sec)  (-19.46/min)
Comment 5 mreynolds 2016-01-29 15:01:21 UTC 
Upstream ticket:
https://fedorahosted.org/389/ticket/48446
Comment 6 mreynolds 2016-01-29 16:57:30 UTC 
Fixed upstream
Comment 7 Mike McCune 2016-03-28 23:13:32 UTC 
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune with any questions
Comment 9 Viktor Ashirov 2016-06-08 14:01:22 UTC 
Build tested:
389-ds-base-1.3.5.4-1.el7.x86_64

I tried different orders of files passed to logconv, it correctly shows speeds:

Searches:                     2             (0.02/sec)  (0.92/min)
Modifications:                1             (0.01/sec)  (0.46/min)
Adds:                         1001          (7.70/sec)  (462.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        13            (0.10/sec)  (6.00/min)

Marking as VERIFIED.
Comment 11 errata-xmlrpc 2016-11-03 20:38:57 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.

https://rhn.redhat.com/errata/RHSA-2016-2594.html