Bug 1019677

Summary: Events on TRACE severity level are included to the total number of events
Product: [JBoss] JBoss Operations Network Reporter: jvlasak
Component: Monitoring - EventsAssignee: RHQ Project Maintainer <rhq-maint>
Status: CLOSED NOTABUG QA Contact: Mike Foley <mfoley>
Severity: medium Docs Contact:
Priority: unspecified    
Version: JON 3.2CC: ahovsepy, jshaughn, loleary, lzoubek, mkoci
Target Milestone: ---   
Target Release: JON 3.3.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-11-19 13:55:28 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:    
Bug Blocks: 1017214    
Attachments:
Description Flags
Also TRACE events are included into the total number of events although they shouldn't be. none

Description jvlasak 2013-10-16 08:52:30 UTC
Created attachment 812830 [details]
Also TRACE events are included into the total number of events although they shouldn't be.

Description of problem:
Events on TRACE severity level are included to the total number of events anytime when at least DEBUG severity level is considered although there is no support in the UI for events on this level.

Version-Release number of selected component (if applicable):
Version: 3.2.0.ER2
Build Number: 9bf6f76:371eac0

How reproducible:
always

Steps to Reproduce:
1. Start JBoss ON 3.2 system.
2. Import RHQ Agent and RHQ Server into inventory.
3. Modify RHQ Agent resource configuration Event Report Max Per Source and Event Report Max Total to 1000 and 10000.
4. Add 16 event logging sources to RHQ Server resource using generated log files /tmp/file-00.log, /tmp/file-01.log, /tmp/file-02.log, ..., /tmp/file-15.log
5. Restart agent with DEBUG logging enabled.
6. Create /tmp/generateLog using the script below.
7. Then run /tmp/generateLog to generate our random log data:
    
    a) chmod +x /tmp/generateLog
    b) for i in $(seq -w 0 15); do /tmp/generateLog /tmp/file-${i}.log 2>/dev/null & done

8. Let started processes in the previous step generate messages into log files for some time and then stop them (use kill -STOP {P1..P16}).
9. Go to /tmp folder of your machine and then run command: 

wc -l file-*

to found out the count of all events in the log files including messages on TRACE level.

10. Then click on Inventory, choose Servers - Top Level Imports under Resources, click on EAP and choose its tab Events and compare the total number of events in the UI with the count of events in the log files.
 


File: /tmp/generateLog
------------------------------------------------------------------------
#!/bin/sh
#

maxSleepTimePerSleep=2
maxEntriesPerSleep=5
maxEntries=1000000
maxSleepTime=3600





logLevels=("FATAL"
"ERROR"
"WARN "
"INFO "
"DEBUG"
"TRACE")

logThreads=(main
$(echo Thread-{0..99})
$(echo Fake-{0..9}))

logCategories=(apache.cassandra.db.commitlog.CommitLogReplayer
org.jboss.as.server.deployment 
org.jboss.as.messaging 
org.some.other.category)

logMessages=("A log message"
"Another log message"
"A log message with some meaning"
"A log message without any meaning"
"To be a log message or not to be"
"To infinity and beyond"
"Every rose has its throne"
"Come out and pay"
"That thing wasn't supposed to do that."
"Now that's what I'm talking about"'!'
"Friends don't let friends eat grapefruit")

function printRandomLogLevel() {
    numLogLevels=${#logLevels[*]}
    echo -n ${logLevels[$((RANDOM%numLogLevels))]}
}

function printRandomLogThread() {
    numLogThreads=${#logThreads[*]}
    echo -n ${logThreads[$((RANDOM%numLogThreads))]}
}

function printRandomLogCategory() {
    numLogCategories=${#logCategories[*]}
    echo -n ${logCategories[$((RANDOM%numLogCategories))]}
}

function printRandomLogMessage() {
    numLogMessages=${#logMessages[*]}
    echo -n ${logMessages[$((RANDOM%numLogMessages))]}
}


function printLogTimestamp() {
    timestamp=$(date +"%F %T|%N")
    ms="$(printf "%03d" $(( 10#${timestamp#*|}/1000000 )))"
    echo -n "${timestamp%|*},${ms}"
}

function printRandomLogEntry() {
    echo "$(printLogTimestamp) $(printRandomLogLevel) [$(printRandomLogThread)] ($(printRandomLogCategory)) $(printRandomLogMessage)"
}

function printRandomLogEntries() {
    totalSleepTime=0
    totalEntries=0

    while [ true ]; do
        randomSleep=$((RANDOM%${maxSleepTimePerSleep}))
        [ $((${maxSleepTime}-(${totalSleepTime}+${randomSleep}))) -lt 0 ] && randomSleep=$((${randomSleep} +(${maxSleepTime}-(${totalSleepTime}+${randomSleep}))))
        echo >&2 Sleeping for ${randomSleep} seconds...
        sleep ${randomSleep}s
        totalSleepTime=$((totalSleepTime+$randomSleep))
        randomNumEntries=$((RANDOM%${maxEntriesPerSleep}))
        [ $((${maxEntries}-(${totalEntries}+${randomNumEntries}))) -lt 0 ] && randomNumEntries=$((${randomNumEntries} +(${maxEntries}-(${totalEntries}+${randomNumEntries}))))
        echo >&2 Printing ${randomNumEntries} log entries...
        for ((i=0; i<randomNumEntries; i++)); do
            [ $# -gt 0 ] && {
                echo $(printRandomLogEntry) >>"$1"
            } || {
                echo $(printRandomLogEntry)
            }
        done
        totalEntries=$((totalEntries+${randomNumEntries}))
        [ ${totalEntries} -ge ${maxEntries} -o ${totalSleepTime} -ge ${maxSleepTime} ] && break
    done
    echo >&2 Total entries is ${totalEntries} and total sleep time was ${totalSleepTime} seconds.
}

printRandomLogEntries $@
------------------------------------------------------------------------

Actual results:
Also TRACE events are counted to the total number of events although they shouldn't be. See attached screenshot.

Expected results:
Events on all levels except for TRACE level should be counted to the total number of rows (events).


Additional info:
If in severity filter in the UI is not DEBUG level the number of events is counted correctly according to our chosen severity levels.

Comment 2 Mike Foley 2013-11-11 16:31:39 UTC
moving to JON 3.2.1 per BZ Triage 11/11/2013.  loleary, heute, santos, foley, yarboro

Comment 6 Jay Shaughnessy 2014-09-04 19:13:05 UTC
This was the suspicion for why Bug 1017214 was reported (and why it should probably be closed as Not a Bug).  I think this boils down to wanting TRACE level support in the Event Source, Even filtering, Alerting etc.  It may or may not even be doable, given the semantics of the logging subsystem.

Unless this is linked to a customer RFE I don't think the priority will be high enough to provide this distinction.

Comment 7 Libor Zoubek 2014-11-19 13:55:28 UTC
Closing as not a bug. Given screenshot and reprosteps does not prove, there are at least some messages on TRACE level. Even if it was. Current UI works as expected = it puts "unknown" severity levels into Debug bucket, those events are visible and can be filtered using "Debug" severity filter. This is actually very good solution, so we don't need to support FINE, FINER, FINEST etc. If we did proper severity filtering in UI, all events with unknown severity would never show up.