log4j: Standard way to prevent repetitive log mess

Question

Our production application logs an error when it fails to establish a TCP/IP connection. Since it is constantly retrying the connection, it logs the same error message over and over. And similarly, other running components in the application can get into an error loop if some realtime resource is unavailable for a period of time.

Is there any standard approach to controlling the number of times the same error gets logged? (We are using log4j, so if there is any extension for log4j to handle this, it would be perfect.)

Answer 1

It would be fairly simple to control this by recording a timestamp each time you log the error, and then only logging it next time if a certain period has elapsed.

Ideally this would be a feature within log4j, but coding it within your app isn't too bad, and you could encapsulate it within a helper class to avoid boilerplate throughout your code.

Clearly, each repetitive log statement would need some kind of unique ID so that you could merge statements from the same source.

Answer 2

I just created a Java class that solves this exact problem using log4j. 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 ever 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.

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;
        }
    }
}