Раздельное логгирование методов в Java/logback

Задача

Допустим, нам захотелось логгировать каждый метод некого Java-класса по разному:

• Для каждого метода свой лог-файл,
• … свой формат лога,
• … свой минимальный уровень логгирования,
• формат лога расширяем собственными %переменными,
• возможность обновлять эту конфигурацию на лету.

Данная статья показывает как эти требования выполнить. В целях соблюдения простоты разделенем логгирования производится только по методам; в реальности может захотеться иметь иерархический уточнняющий конфиг, вроде Приложение → Компонент → Сервис → Метод… Ссылка на полный исходный код будет внизу.

Клиентский код

    class ThingService {         log = LoggerFactory.getLogger();         getThing() {             log.debug("getThing..."); // => one.log         }         listThings() {             log.debug("listThings..."); // => another.log         }     }

Logback

Для реализации выбрана добротная библиотека логгирования «logback», предоставляющая интересные возможности для кастомизации:

ch.qos.logback:logback-classic:1.2.3

Настраивается как из XML-конфига, так и напрямую из Джавы, подходы можно комбинировать:

    public void configureLogback() throws JoranException {         LoggerContext lc = LoggerFactory.getILoggerFactory();         lc.reset(); //  reset prev config         JoranConfigurator configurator = new JoranConfigurator();         configurator.setContext(lc);         configurator.doConfigure("config.xml"); // any data source         StatusPrinter.printInCaseOfErrorsOrWarnings(lc);          // а теперь комбинация:         Logger root = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);         root.setLevel(Level.INFO); // переопределение     }

Вкратце, о логгировании:

1. Программист дергает логгер,
2. Логгер дергает назначенные ему аппендеры,
3. Аппендер думает и вызывает энкодер,
4. Энкодер форматирует ровно одну строку лога,
5. Для этого он дёргает цепочку конвертеров, каждый из которых раскрывает свою %переменную,
6. Успех.

Для простоты была выбрана чистая джавиная конфигурация. Тут всё довольно очевидно если держать перед глазами XML-конфиг. Основная задача — создать свои собственные appender/encoder и зарегистрировать их — они будут вызываться логбэком из своих недр. Почти каждый создаваемый объект нужно не забыть запустить методом start(). Абстрактный пример:

    Logger rootLogger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);     LoggerContext lc = rootLogger.getLoggerContext();     lc.reset(); //  reset prev config      var encoder = new PatternLayoutEncoder();     encoder.setContext(lc);     encoder.setPattern("%-5level %message%n");     encoder.start();      var appender = new ConsoleAppender<ILoggingEvent>();     appender.setContext(lc);     appender.setEncoder(encoder);     appender.start();      rootLogger.setLevel(Level.DEBUG);     rootLogger.addAppender(appender);

Отделяем логгируемые методы друг от друга

Чтобы логбэк мог отличить один метод от другого, перед вызовом метода сохраняем его имя в ThreadLocal Mapped Diagnostic Context. Далее, при анализе, эти значения напрямую из класса MDC не достаём, так как логгирующий код будет исполняться уже в другом потоке и этих данных там не будет — достаём их через ILoggingEvent.getMDCPropertyMap().

    try {         MDC.put(MDC_KEY_METHOD, methodName);         // Вызов метода         // В реальности оборачивать лучше через AOP, конечно.     } finally {         MDC.put(remove);     }

Свой лог-файл на каждый метод

Создадим и не забудем зарегистрировать свой собственный аппендер:

    class MultiAppender extends AppenderBase<ILoggingEvent> {         @Override         protected void append(ILoggingEvent event) {             method = event.getMDCPropertyMap().get(MDC_KEY_METHOD);             Appender appender = getOrCreateAppender(method);             appender.doAppend(event);         }

Аппендер достаточно липовый, так как сам ничего не делает, а только делегирует логгирование пачке настоящих файловых аппендеров, по одному на каждый метод. Делегирует одному, самому подходящему. Создаются аппендеры по требованию, так:

    fileAppender = new FileAppender<ILoggingEvent>();     fileAppender.setContext(lc);     fileAppender.setAppend(false);     fileAppender.setEncoder(getOrCreateEncoderByMethod(lc, method));     fileAppender.setFile(logFileByMethod.get(method));     fileAppender.start();

Свой формат на каждый метод

Для этого держим кэш авто-создаваемых объектов типа Encoder:

    Map<String, String> patternByMethod = new HashMap<>();      // вызывается выше; упрощёно     Encoder getOrCreateEncoderByMethod(LoggerContext lc, String method) {         String pattern = patternByMethod.get(method);         encoder = new PatternLayoutEncoder();         encoder.setContext(lc);         encoder.setPattern(pattern);         encoder.start();         return encoder;     }

Каждому методу свой уровень логгирования

В класс MultiAppender добавим проверку: если уровень события преодолевает порог заданный для метода, только тогда логгируем его:

    Map<String, Level> levelByMethod = new HashMap<>();      protected void append(ILoggingEvent event) {         Level minLevel = levelByMethod.get(methodName);         if (event.getLevel().levelInt >= minLevel.levelInt) {             appender.doAppend(event);         }

В принципе, эту логику можно вынести в фильтр.

Расширение формата своими переменными

Чтобы не городить свой огород, а воспользоваться проверенной инфраструктурой логбэка, нужно определить свой класс конвертера, обязательно целиком публичный чтобы его могли инстанциировать извне. Если нужен MDC, берём его из эвента. Здесь заводится обработчик переменной %custom:

    public class CustomConverter extends ClassicConverter {         public String convert(ILoggingEvent event) {             // mdc = event.getMDCPropertyMap();             return "variable-expanded";         }     }

Во время общего процесса конфигурации зарегистрируем обработчик:

    void configurePatterns(LoggerContext lc) {         Map<String, String> rules                 = lc.getObject(CoreConstants.PATTERN_RULE_REGISTRY);         if (rules == null) {             rules = new HashMap<String, String>();             lc.putObject(CoreConstants.PATTERN_RULE_REGISTRY, rules);         }         rules.put("custom", CustomConverter.class.getName());     }

И будем использовать в качестве энкодера, например, PatternLayoutEncoder, который сам всё подхватит. В данном случае переменная %custom раскроется в строку "variable-expanded".

Обновление конфига на лету

Возможность такая есть из коробки: достаточно вызвать функцию-конфигуратор ещё раз, не забыв сделать там LoggerContext::reset() и очистку накопленного кэша.

Многопоточность

Если законфигурированный нами метод вызывает к жизни новые потоки, то на них, естественно, заданные правила логгирования распространяться не будут — в новом потоке thread local’ы сами собой не появятся. Так что, если хочется применить настройки метода к новому потоку, придётся скопировать туда MDC:

    Map<String, String> mdcOrig = MDC.getCopyOfContextMap();     ExecutorService es = Executors.newFixedThreadPool(1);     es.submit(() -> threadWorker(mdcOrig));      void threadWorker(Map<String, String> parentMdc) {         MDC.setContextMap(parentMdc);         log.error("expected to appear in method2*.log");     }

Пример целиком

https://github.com/zencd/logback-setup

Литература

Официальный мануал logback