Задача

Допустим, нам захотелось логгировать каждый метод некого 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().

В общем случае, как верно заметил vooft, нужно поддерживать стек вызовов и не затирать MDC-значение, а возвращать его к предыдущему фрейму, что делается через введение нового ThreadLocal. Схематический пример:

    try {
        MDC.put(MDC_KEY_METHOD, currentMethod);
        // 1. Сохранить currentMethod в стек вызовов
        // 2. Вызвать сам метод
        // 3. В реальности оборачивать вызовы лучше через AOP, конечно.
    } finally {
        String previousMethod = // Достаётся из стека вызовов
        MDC.put(previousMethod);
    }

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

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

    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