Что не так с моим фильтром log4j? (Это заставляет кота повесить трубку!) - PullRequest
Новая
       23

Что не так с моим фильтром log4j? (Это заставляет кота повесить трубку!)

1 голос
/ 17 февраля 2010

Недавно мы добавили фильтр в нашу конфигурацию 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 (...).но нам действительно нужно написать собственное сообщение (повторное время х).Мы пытались не использовать регистратор внутри фильтра, но мы не нашли способ.

Редактировать 2: Я использую версию 1.2.15 из log4j.

Редактировать 3: Что-то, что мы попробуем:

  • сделать весь наш appender вложенным в AsyncAppender

Edit 4: Обернуть каждый appender в asyncAppender делаетне решить вопрос

1 Ответ

1 голос
/ 17 февраля 2010

Возможный тупик

Глядя на исходный код, я вижу, что блокировка получается на Category при регистрации события, а затем блокировка получается на каждом AppenderSkeleton, для которого событиеотправляется.Если два экземпляра Category используют один и тот же appender (что является обычным), то попытка войти в систему с Appender (или Filter, подключенного к этому appender) может привести к тупику.

ДляНапример, есть два Category объекта, C1 и C2, и один Appender, A.Thread T1 получает блокировку на C1, затем A, затем начинает обработку цепочки Filter на A.

Одновременно Thread T2 получает блокировку на C2.Он не может получить блокировку на A, потому что он удерживается T1, поэтому он ждет.

Теперь предположим, что T1 направлено (фильтром) на запись сообщения в C2.Он не может получить блокировку на C2, потому что он удерживается T2.Deadlock.

Если вы опубликовали дополнительную информацию из дампа потока, должно быть возможно определить, является ли это истинным тупиком и, если да, какие объекты находятся в состоянии конфликта.

Возможное решение

Если это действительно то, что происходит, кажется, что проблемы можно избежать, регистрируя «повторное» сообщение только в «текущем» регистраторе, то есть регистраторе оцениваемого события.фильтромОдин из способов сделать это - отслеживать повторы для каждого регистратора. 

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;

  }

}

Это может быть не то, что вам нужно, потому что события в других регистраторах не будут «сбрасывать» сообщение «повторяется» категории.С другой стороны, он может сжимать журнал еще более эффективно, поскольку одно и то же сообщение, вероятно, будет повторяться на том же самом регистраторе.

...