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

    Bart writing some logs


    Задача


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

    Поделиться публикацией
    AdBlock похитил этот баннер, но баннеры не зубы — отрастут

    Подробнее
    Реклама

    Комментарии 6

      0
      Надо сохранять старое значение и восстанавливать его в finally, иначе после вызова другого метода внутри этой конструкции все сломается. В идеале стоит сделать какую-нибудь структуру, реализующую AutoCloseable, которая спрячет весь этот бойлерплейт.
        0

        Спасибо! Везде добавил поддержку вложенных вызовов.

        0

        Я уж подумал, что то оригинальное (автоматом имя вызова контекста).
        Потом увидел:


        Чтобы логбэк мог отличить один метод от другого, перед вызовом метода сохраняем его имя в ThreadLocal Mapped Diagnostic Context.

        А при таком подходе это, по моему, любой логе делает.
        Вот например, для log4j2


        import org.apache.logging.log4j.ThreadContext;
        ..
        ThreadContext.put("LOG_SUFFIX", "blabalProcName");

        <RollingFile name="Rolling-${ctx:LOG_SUFFIX}" fileName="${log-path}/xxxxx${ctx:LOG_SUFFIX}"
                                         filePattern="${log-path}/xxxx${ctx:LOG_SUFFIX}-%d{yyyy-MM-dd}.gz">
                                <PatternLayout pattern="%d{dd MMM HH:mm:ss.SSS}:%c:tid [%t]:%p: %m %X{SID}%n" charset="UTF-8"/>
        ...

        Хотя задача, по моему, высосана из пальца.


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

        Логирование нити или группы нитей или подобное — понятно. А отдельных вызовов…
        Даже не знаю зачем это может понадобится.

          0

          Мы как-то однажды в древнем проекте делали


          import org.jboss.logging.MDC;
          
          // ...
          MDC.put("job", " [Job: " + job.getId() + ']');
          // ... всякий рефлексивный вызов фактического тела задачи
          
          MDC.remove("job");

          Там, кажется, ThreadLocal-подобная переменная, которая наследуется по дочерним потокам.


          Но это была задача логирования целой группы потоков, как mmMike сверху сказал.
          Наверное, это похоже на логирование одного метода, особенно если он крупный.


          Спасибо, что собрали материал в одном месте. :)

            +1

            Если есть аспекты в проекте, то это решается аннотацией методов, которые хочется логгировать и аспектом, который это делает. Тогда совершенно пофиг какой у вас логер. Туда же можно запихнуть алертинг, трассировку… и черта лымого, который проходит через весь проект… что суть аспектов

              0

              Или без анотаций можно точку среза указать так, что логироваться вообще будет все.

            Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

            Самое читаемое