views:

440

answers:

1

Hi,

We recently add a filter to our log4j configuration with a custom filter. The goal is to stop repeating the same log again and again, but replace it by :

the log + "last line repeated x times"

We have write the following filter, who works fine. But then, we have beggin to remark strange deadlock and hang up of tomcat5.5.

When we remove this filter, the error stop to occurs. ( Yes, we are pretty sure of that ).

Beside this empirical observation, the Heap Stack of the JVM has many log4j thread blocked and waiting to a tomcat monitor to be realeased.

Here is the code of our filter. Pretty basic. What's wrong with it ?

public class RepeatFilter extends Filter {
String lastMessage;
Category lastLogger;
int repeatCount = 0;

@Override
public int decide(LoggingEvent event) {
    // get the rendered (String) form of the message
    String msg = event.getRenderedMessage();

    if(msg == null || msg.startWith("Last message repeated "){
        return Filter.NEUTRAL;
    }

    if(msg.equals(lastMessage)) {
        repeatCount++;
        return Filter.DENY;
    } else {
        if(repeatCount>0){
            String msgToLog = "Last message repeated " + repeatCount + " time(s).";
            repeatCount = 0;
            lastLogger.log(event.getLevel(), msgToLog);
        }
    }

    lastLogger = event.getLogger();
    lastMessage = msg;
    return Filter.NEUTRAL;
}

}

EDIT : Yes, theire is a recursion when we use a logger inside the filter. In fact, the server hang after the line lastLogger.log(... ). but we really need to writte a custom message ( the repeated x time ). We have try not to use a logger inside the filter, but we havent find a way.

Edit 2 : I use the version 1.2.15 of log4j.

Edit 3 : Something we will try :

  • make all our appender nested in a AsyncAppender

Edit 4 : Wrap each appender in a asyncAppender does not solve the issue

+1  A: 
erickson
log4j must lock a file before writting it at some point, no ?. Indeed, lastLogger and lastMessage are corrupted in a multithreaded environnement. We have try to synchronise the part where they are modified : without succes.
Antoine Claval
It's not necessarily true that log4j will acquire a lock before writing to a file. Many operating systems allow the same file to be opened for writing by multiple threads (and indeed, I've seen this happen with log4j). However, I believe that log4j is probably using a lock on a per-appender basis; I'd have to check the source to make sure.
erickson
Thanks for the precision erickson. I think our problem is that the same appender is used by several thread of our application.
Antoine Claval