Skip to content

Commit

Permalink
add warnOnce
Browse files Browse the repository at this point in the history
  • Loading branch information
bobjacobsen committed Mar 19, 2018
1 parent 299df88 commit e98afe3
Show file tree
Hide file tree
Showing 3 changed files with 70 additions and 36 deletions.
60 changes: 26 additions & 34 deletions help/en/html/doc/Technical/Logging.shtml
Expand Up @@ -133,10 +133,11 @@
As As


<p>The line:</p> <p>The line:</p>
<pre> <pre style="font-family: monospace;">
log4j.rootCategory= INFO, A1, T, R log4j.rootCategory= INFO, A1, T, R
</pre>controls where logging output goes. Later in the file, there </pre>
are "appenders" A1, T and R defined that write log messages to: controls where logging output goes. Later in the file, there
are "appenders" A1, T and R defined that write log messages to:


<ul> <ul>
<li>A1 - the console on the local computer, really <li>A1 - the console on the local computer, really
Expand All @@ -158,18 +159,15 @@ are "appenders" A1, T and R defined that write log messages to:


<p>The "default.lcf" file also determines the format of the <p>The "default.lcf" file also determines the format of the
output by setting the "layout" parameter(s).</p> output by setting the "layout" parameter(s).</p>
<pre> <pre style="font-family: monospace;">
<code>
log4j.appender.R.layout=org.apache.log4j.PatternLayout<br>log4j.appender.R.layout.ConversionPattern=%d{ISO8601} %-37.37c{2} %-5p - %m [%t]%n log4j.appender.R.layout=org.apache.log4j.PatternLayout<br>log4j.appender.R.layout.ConversionPattern=%d{ISO8601} %-37.37c{2} %-5p - %m [%t]%n
</code>
</pre> </pre>


<p>An example of the default format:</p> <p>An example of the default format:</p>
<pre> <pre style="font-family: monospace;">
<code>
2015-10-28 20:31:52,307 jmri.jmrit.powerpanel.PowerPane WARN - No power manager instance found, panel not active [AWT-EventQueue-0] 2015-10-28 20:31:52,307 jmri.jmrit.powerpanel.PowerPane WARN - No power manager instance found, panel not active [AWT-EventQueue-0]
</code> </pre>
</pre>The columns are: The columns are:


<ul> <ul>
<li><code>2015-10-28 20:31:52,307</code> - local time the <li><code>2015-10-28 20:31:52,307</code> - local time the
Expand All @@ -190,43 +188,33 @@ log4j.appender.R.layout=org.apache.log4j.PatternLayout<br>log4j.appender.R.layou


<h3>Coding</h3>To log messages from a class named MyClass, <h3>Coding</h3>To log messages from a class named MyClass,
add this to the bottom of the class's .java file: add this to the bottom of the class's .java file:
<pre> <pre style="font-family: monospace;">
<code>
private static final Logger log = LoggerFactory.getLogger(MyClass.class); private static final Logger log = LoggerFactory.getLogger(MyClass.class);
</code>
</pre> </pre>


<p>and add imports for org.slf4j.Logger and <p>and add imports for org.slf4j.Logger and
org.slf4j.LoggerFactory in your imports section:</p> org.slf4j.LoggerFactory in your imports section:</p>
<pre> <pre style="font-family: monospace;">
<code>
import org.slf4j.Logger;<br> import org.slf4j.Logger;<br>
import org.slf4j.LoggerFactory; import org.slf4j.LoggerFactory;
</code>
</pre>It's also OK to combine those into the fully-qualified form: </pre>It's also OK to combine those into the fully-qualified form:
<pre> <pre style="font-family: monospace;">
<code>
private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(MyClass.class); private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(MyClass.class);
</code>
</pre> </pre>


<p>(If logging is removed (e.g. commented out), it's OK to <p>(If logging is removed (e.g. commented out), it's OK to
comment out the log definition so that it can be easily added comment out the log definition so that it can be easily added
back later on.)</p> back later on.)</p>


<p>Then for each message to log insert a line like:</p> <p>Then for each message to log insert a line like:</p>
<pre> <pre style="font-family: monospace;">
<code>
log.debug("message"); log.debug("message");
</code>
</pre> </pre>


<p>Messages that are not just an explicit string should use <p>Messages that are not just an explicit string should use
this form instead for variables:</p> this form instead for variables:</p>
<pre> <pre style="font-family: monospace;">
<code>
log.debug("Found {}", numberEntries); log.debug("Found {}", numberEntries);
</code>
</pre> </pre>
<p>The string operations to build the actual error message (in <p>The string operations to build the actual error message (in
this case, combining "Found" and the numberEntries argument) are this case, combining "Found" and the numberEntries argument) are
Expand All @@ -242,21 +230,25 @@ log4j.appender.R.layout=org.apache.log4j.PatternLayout<br>log4j.appender.R.layou
does not waste time calculating parameters (in this case, does not waste time calculating parameters (in this case,
calling numberEntries() to get a value to pass to the calling numberEntries() to get a value to pass to the
function call):</p> function call):</p>
<pre> <pre style="font-family: monospace;">
<code>
if (log.isDebugEnabled()) { if (log.isDebugEnabled()) {
log.debug("Found {}", numberEntries()); log.debug("Found {}", numberEntries());
} }
</code>
</pre> </pre>

<p>If you want to emit a warning only the first time
it happens, there's a service method that will
handle that for you:
<pre style="font-family: monospace;">
Log4JUtil.warnOnce(log, "The warning with arguments {} {}", "A", "B");
</pre>

<p>Exceptions should be logged as:</p> <p>Exceptions should be logged as:</p>
<pre> <pre style="font-family: monospace;">
<code>
log.error("my local text"+exception.getLocalizedMessage(), exception); log.error("my local text"+exception.getLocalizedMessage(), exception);
</code>
</pre>to include the user readable description from the exception </pre>
itself, plus all its traceback information. to include the user readable description from the exception
itself, plus all its traceback information.
<!--#include virtual="/Footer" --> <!--#include virtual="/Footer" -->
</div><!-- closes #mainContent--> </div><!-- closes #mainContent-->
</div><!-- closes #mBody--> </div><!-- closes #mBody-->
Expand Down
24 changes: 22 additions & 2 deletions java/src/jmri/util/Log4JUtil.java
Expand Up @@ -5,8 +5,7 @@
import java.io.FileInputStream; import java.io.FileInputStream;
import java.io.IOException; import java.io.IOException;
import java.nio.file.Files; import java.nio.file.Files;
import java.util.Enumeration; import java.util.*;
import java.util.Properties;
import jmri.util.exceptionhandler.UncaughtExceptionHandler; import jmri.util.exceptionhandler.UncaughtExceptionHandler;
import org.apache.log4j.Appender; import org.apache.log4j.Appender;
import org.apache.log4j.BasicConfigurator; import org.apache.log4j.BasicConfigurator;
Expand Down Expand Up @@ -43,6 +42,27 @@ public class Log4JUtil {
private static final String jmriLog = "****** JMRI log *******"; private static final String jmriLog = "****** JMRI log *******";
private static final Logger log = LoggerFactory.getLogger(Log4JUtil.class); private static final Logger log = LoggerFactory.getLogger(Log4JUtil.class);


/**
* Emit a particular WARNING-level message just once.
* @return true if the log was emitted this time
*/
// Goal is to be lightweight and fast; this will only be used in a few places,
// and only those should appear in data structure.
static public boolean warnOnce(Logger log, String msg, Object... args) {
// the Map<String, Boolean> is just being checked for existence; it's never False
Map<String, Boolean> loggerMap = warnedOnce.get(log);
if (loggerMap == null) {
loggerMap = new HashMap<>();
warnedOnce.put(log, loggerMap);
} else {
if (loggerMap.get(msg) == Boolean.TRUE) return false;
}
loggerMap.put(msg, Boolean.TRUE);
log.warn(msg, args);
return true;
}
static private Map<Logger, Map<String, Boolean>> warnedOnce = new HashMap<>();

/** /**
* Initialize logging from a default control file. * Initialize logging from a default control file.
* <p> * <p>
Expand Down
22 changes: 22 additions & 0 deletions java/test/jmri/util/Log4JUtilTest.java
Expand Up @@ -20,9 +20,31 @@ public void testLog4JWarnMessage() {


log.debug("DEBUG message"); // should be suppressed see tests.lcf log.debug("DEBUG message"); // should be suppressed see tests.lcf


Assert.assertTrue(jmri.util.JUnitAppender.verifyNoBacklog());
}

public void testWarnOnceCounts() {
Assert.assertTrue(Log4JUtil.warnOnce(log, "WARN message")); // string has to be same until further notice
Assert.assertFalse(Log4JUtil.warnOnce(log, "WARN message"));
jmri.util.JUnitAppender.assertWarnMessage("WARN message");
Assert.assertTrue(jmri.util.JUnitAppender.verifyNoBacklog());

Logger log2 = LoggerFactory.getLogger("Log4JUtilTest-extra-logger");
Assert.assertTrue(Log4JUtil.warnOnce(log2, "WARN message"));
Assert.assertFalse(Log4JUtil.warnOnce(log2, "WARN message"));
jmri.util.JUnitAppender.assertWarnMessage("WARN message");
Assert.assertTrue(jmri.util.JUnitAppender.verifyNoBacklog()); Assert.assertTrue(jmri.util.JUnitAppender.verifyNoBacklog());

Assert.assertTrue(Log4JUtil.warnOnce(log, "WARN message 2")); // different string
jmri.util.JUnitAppender.assertWarnMessage("WARN message 2");
} }


public void testWarnOnceArguments() {
Assert.assertTrue(Log4JUtil.warnOnce(log, "Test {} {}", "A", "B"));
jmri.util.JUnitAppender.assertWarnMessage("Test A B");
Assert.assertTrue(jmri.util.JUnitAppender.verifyNoBacklog());
}

public void testSendJavaUtilLogInfoMessage() { public void testSendJavaUtilLogInfoMessage() {
// test that java.util.logging is getting to Log4J // test that java.util.logging is getting to Log4J
java.util.logging.Logger logger = java.util.logging.Logger logger =
Expand Down

0 comments on commit e98afe3

Please sign in to comment.