我们最近使用自定义过滤器向 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 中并不能解决问题
最佳答案
可能的死锁
查看源代码,我发现在记录事件时会在 Category
上获取锁定,然后在事件分派(dispatch)到的每个 AppenderSkeleton
上获取锁定。如果两个 Category
实例使用相同的附加程序(这很常见),则尝试从 Appender
(或附加到该附加程序的 Filter
)进行日志记录肯定会导致死锁。
例如,有两个 Category
对象,C1
和 C2
,以及一个 Appender
,A
。 Thread
T1
获取 C1
上的锁,然后获取 A
上的锁,然后开始处理 A
上的 Filter
链。
同时,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;
}
}
这可能不是您想要的,因为其他记录器上的事件不会“刷新”类别的“重复”消息。另一方面,它可能会更有效地压缩日志,因为相同的消息可能会在同一个记录器上重复。
关于java - 我的 log4j 过滤器出了什么问题? (这会让tomcat挂掉!),我们在Stack Overflow上找到一个类似的问题: https://stackoverflow.com/questions/2281719/