How to log repeated warnings only once

Question

There is a pattern that happens every now and then. I have a method called many times, and it contains this snippet:

Foo foo = getConfiguredFoo();
if (foo == null) {
  logger.warn("Foo not configured");
  foo = getDefaultFoo();
}

Then my log file is cluttered with this warning a hundred times. I know I can grep it out, but I wonder if there is a better way to see this warning only once.

Note: the duplication of messages is a correct behavior by default, so this is not about avoiding unintentional duplicate log message. I tagged my question as log4j, but I'm open to other java logging frameworks.

Answer 1

Here is what I can come up with: a class that accumulates warnings which can be dumped at the end. It's in groovy, but you can get the point. The dumping part can be customized to use a logger, of course.

class BadNews {
  static Map<String,List<Object>> warnings = [:];

  static void warn(String key, Object uniqueStuff) {
    def knownWarnings = warnings[key]
    if (! knownWarnings) {
      knownWarnings = []
      warnings[key] = knownWarnings
    }
    knownWarnings << uniqueStuff
  }

  static void dumpWarnings(PrintStream out) {
    warnings.each{key, stuffs ->
      out.println("$key: " + stuffs.size())
      stuffs.each{
        out.println("\t$it")
      }
    }
  }
}

class SomewhereElse {
  def foo(Bar bar) {
    if (! bar)
      BadNews.warn("Empty bar", this)
  }
}

Answer 2

I faced a similar problem sometime ago but could not find any way of dealing with this in Log4J. I finally did the following:

Foo foo = getConfiguredFoo();
if (foo == null) {
  if(!warningLogged)logger.warn("Foo not configured");
  warningLogged = true
  foo = getDefaultFoo();
}

This solution is OK if you have one or two log statements you don't want to see repeated in your logs but does not scale up with more log statements (you need a boolean for every message logged)

Answer 3

You could write a wrapper around your logging to store the last line logged. Depending on how you implement, you could add some sort of counter to log how many times it got logged or you may choose to subclass Logger instead of having an external wrapper. Could be configurable with a boolean suppressDuplicates if you needed that too.

public class LogWrapper{
    Logger logger = Logger.getLogger("your logger here");
    String lastLine = new String();

    public void warn(String s){
        if (lastLine.compareToIgnoreCase(s) == 0)
            return;
        else {
            lastLine = s;
            logger.warn(s);
        }
    }
}

Answer 4

If this is the only thing you want to print one time, then using a saved boolean would be your best bet. If you wanted something you could use throughout your project, I have created something that may be useful. I just created a Java class that uses a log4j logger instance. When I want to log a message, I just do something like this:

LogConsolidated.log(logger, Level.WARN, 5000, "File: " + f + " not found.", e);

Instead of:

logger.warn("File: " + f + " not found.", e);

Which makes it log a maximum of 1 time every 5 seconds, and prints how many times it should have logged (e.g. |x53|). Obviously, you can make it so you don't have as many parameters, or pull the level out by doing log.warn or something, but this works for my use case.

For you (if you only want to print one time, every time) this is overkill, but you can still do it by passing in something like: Long.MAX_LONG in as the 3rd parameter. I like the flexibility to be able to determine frequency for each specific log message (hence the parameter). For example, this would accomplish what you want:

LogConsolidated.log(logger, Level.WARN, Long.MAX_LONG, "File: " + f + " not found.", e);

Here is the LogConsolidated class:

import java.util.HashMap;

import org.apache.log4j.Level;
import org.apache.log4j.Logger;

public class LogConsolidated {

    private static HashMap<String, TimeAndCount> lastLoggedTime = new HashMap<>();

    /**
     * Logs given <code>message</code> to given <code>logger</code> as long as:
     * <ul>
     * <li>A message (from same class and line number) has not already been logged within the past <code>timeBetweenLogs</code>.</li>
     * <li>The given <code>level</code> is active for given <code>logger</code>.</li>
     * </ul>
     * Note: If messages are skipped, they are counted. When <code>timeBetweenLogs</code> has passed, and a repeat message is logged, 
     * the count will be displayed.
     * @param logger Where to log.
     * @param level Level to log.
     * @param timeBetweenLogs Milliseconds to wait between similar log messages.
     * @param message The actual message to log.
     * @param t Can be null. Will log stack trace if not null.
     */
    public static void log(Logger logger, Level level, long timeBetweenLogs, String message, Throwable t) {
        if (logger.isEnabledFor(level)) {
            String uniqueIdentifier = getFileAndLine();
            TimeAndCount lastTimeAndCount = lastLoggedTime.get(uniqueIdentifier);
            if (lastTimeAndCount != null) {
                synchronized (lastTimeAndCount) {
                    long now = System.currentTimeMillis();
                    if (now - lastTimeAndCount.time < timeBetweenLogs) {
                        lastTimeAndCount.count++;
                        return;
                    } else {
                        log(logger, level, "|x" + lastTimeAndCount.count + "| " + message, t);
                    }
                }
            } else {
                log(logger, level, message, t);
            }
            lastLoggedTime.put(uniqueIdentifier, new TimeAndCount());
        }
    }

    private static String getFileAndLine() {
        StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
        boolean enteredLogConsolidated = false;
        for (StackTraceElement ste : stackTrace) {
            if (ste.getClassName().equals(LogConsolidated.class.getName())) {
                enteredLogConsolidated = true;
            } else if (enteredLogConsolidated) {
                // We have now file/line before entering LogConsolidated.
                return ste.getFileName() + ":" + ste.getLineNumber();
            }
        }
        return "?";
    }       

    private static void log(Logger logger, Level level, String message, Throwable t) {
        if (t == null) {
            logger.log(level, message);
        } else {
            logger.log(level, message, t);
        }
    }

    private static class TimeAndCount {
        long time;
        int count;
        TimeAndCount() {
            this.time = System.currentTimeMillis();
            this.count = 0;
        }
    }
}