1

我们最近使用自定义过滤器向我们的 log4j 配置添加了一个过滤器。目标是停止一次又一次地重复相同的日志,但将其替换为:

日志 +“最后一行重复 x 次”

我们编写了以下过滤器,效果很好。但是后来,我们开始评论奇怪的死锁并挂断了tomcat5.5。

当我们删除此过滤器时,错误停止发生。(是的,我们对此非常确定)。

除了这个经验观察之外,JVM 的堆堆栈有许多 log4j 线程被阻塞并等待 tomcat 监视器被释放。

这是我们过滤器的代码。很基本。它出什么问题了 ?

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

}

编辑:是的,当我们在过滤器中使用记录器时,它们是一个递归。事实上,服务器在 lastLogger.log(... ) 行之后挂起。但我们确实需要编写自定义消息(重复 x 次)。我们尝试在过滤器中不使用记录器,但我们还没有找到方法。

编辑 2:我使用 log4j 的 1.2.15 版本。

编辑3:我们将尝试的东西:

  • 使我们所有的 appender 嵌套在 AsyncAppender 中

编辑 4:将每个附加程序包装在 asyncAppender 中并不能解决问题

4

1 回答 1

1

可能的死锁

查看源代码,我看到在Category记录事件时获得了锁,然后在AppenderSkeleton将事件分派到的每个上都获得了锁。如果两个Category实例使用相同的附加程序(这很常见),那么尝试从一个Appender(或Filter附加到该附加程序的)记录肯定会导致死锁。

例如,有两个Category对象,C1C2,和一个AppenderAThread T1获取锁,C1然后A开始处理FilterA

同时,Thread T2获取对 的锁定C2。它无法获得锁,A因为它被 持有T1,所以它等待。

现在假设T1(由过滤器)指示将消息记录到C2. 它无法获得锁定,C2因为它由 持有T2。僵局。

如果您从线程转储中发布了更多信息,则应该可以判断它是否是真正的死锁,如果是,则哪些对象处于争用状态。

可能的解决方案

如果确实发生了这种情况,似乎可以通过将“重复”消息仅记录到“当前”记录器(即过滤器正在评估的事件的记录器)来避免问题。一种方法是在每个记录器的基础上跟踪重复。

public class RepeatFilter
  extends Filter
{

  private final Map<Category, Repeat> repeats = 
    new HashMap<Category, Repeat>();

  @Override
  public int decide(LoggingEvent event)
  {
    String message = event.getRenderedMessage();
    if ((message == null) || message.startsWith("Last message repeated "))
      return Filter.NEUTRAL;
    Category logger = event.getLogger();
    Repeat r = repeats.get(logger);
    if (r == null)
      repeats.put(logger, r = new Repeat());
    if (message.equals(r.message)) {
      ++r.count;
      return Filter.DENY;
    }
    if (r.count > 0) {
      logger.log(r.level, "Last message repeated " + r.count + " time(s).");
      r.count = 0;
    }
    r.message = message;
    r.level = event.getLevel();
    return Filter.NEUTRAL;
  }

  private final class Repeat
  {

    Priority level;

    String message;

    int count;

  }

}

这可能不是您想要的,因为其他记录器上的事件不会“刷新”该类别的“重复”消息。另一方面,它可能更有效地压缩日志,因为相同的消息很可能在同一个记录器上重复出现。

于 2010-02-17T15:29:31.703 回答