Red Hat Bugzilla – Bug 1301097
logconv.pl displays negative operation speeds
Last modified: 2016-11-03 16:38:57 EDT
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
This is a bug, using "access*" should work correctly. What are your steps to reproduce? How many logs do you have?
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) ... ... ...
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)
Upstream ticket: https://fedorahosted.org/389/ticket/48446
Fixed upstream
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune@redhat.com with any questions
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.
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