01.03.2019 09:59
antonpryamostanov 31 1400 Источник
Приветствую, дорогие друзья!

Хочу поделиться своими рассуждениями на тему логирования и тем к чему они привели.

Возможно по причине некоторого недостатка теоретических изысканий, логирование всегда было некой зоной турбулентности в Java мире. С течением времени, это вызвало появление нескольких библиотек для логирования, таких как:

  • Log4j
  • Java Util Logging
  • Commons Logging
  • Logback
  • Log4j2

Пытаясь сузить ограничения остальных, к сожалению каждая из них привносила свои недостатки.

И если с точки зрения стандартизации кода, ситуация улучшилась после появления Slf4j — как слоя абстракции для логирования, в существующих реализациях все еще присутствуют неразрешенные проблемы.

Как Open Source сообщество, мы предпринимаем инициативу чтобы придти к новому, революционному подходу — и создать легковесный (но в тоже время функционально-насыщенный) логгер, используя последние наработки, такие как скриптинг.

Проблемы


— Существующие реализации предоставляют лишь частичную поддержку скриптов в настройках


Это приводит к декларативному программированию в конфигурационных файлах логгера (XML, JSON, YAML), хотя гораздо проще было бы динамически интерпретировать конфигурационные значения во время исполнения, используя императивный скриптинг.

Возьмём пример конфигурации фильтра в Logback, для логирования только сообщений с уровнем логирования INFO:

<filter class="ch.qos.logback.classic.filter.LevelFilter">
  <level>INFO</level>
  <onMatch>ACCEPT</onMatch>
  <onMismatch>DENY</onMismatch>
</filter>

Это типичный пример декларативного XML программирования.

(да, Logback поддерживает фильтр использующий Groovy, но он применим только к конкретным аппендерам, а не к логгеру)

А вот поддержка скриптинга для форматирования строки отсутствует полностью.

— Усложнённая и переудлинённая конфигурация


Возьмём Logback и Log4j2:

Отсутствует возможность настроить уровень логирования для конкретного аппендера.

Аппендеры настраиваются отдельно от логгеров и логгеры ссылаются на аппендеры используя атрибут «AppenderRef» — при этом только логгеры поддерживают настройку уровня логирования и имён классов.

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

В Logback это возможно используя Groovy Script фильтр на аппендере — но если у нас есть множество аппендеров — размер конфигурации растёт экспоненциально.

— Каждому уровню логирования — отдельный файл!


Мы не смогли найти возможность такой настройки, при которой сообщения группируются в файлы по уровню сообщения (debug, info, и т.д.)

Существующие возможности требуют дупликации аппендеров на каждый уровень логирования.

— Настройка фильтрации по имени класса в самом Root логгере


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

— Существует концептуальное разъединение между тем, как производятся лог данные в приложении и тем, как эти данные потребляются логгером


Историческая практика такова, что логгеры (и их конфигурация) являются более классо-центричными, чем если бы файло-центричными.

Это противоречит человеческому восприятию, которое более логично воспринимает ожидания вокруг конечного содержимого лог файлов, а не беспокоится о настройке каждого отдельного класса.

На практике этот парадокс является причиной функциональных ограничений существующих реализаций:

  • Усложнённая конфигурация имён файлов
  • Иррациональная настройка логгера, например:

Logback поддерживает максимум 1 «discriminator» в «SiftingAppender».
SiftingAppender имеет ограничения в настройках полиси для архивирования
Переусложнённая настройка «RoutingAppender» в Log4j2

Решение


— Полная поддержка скриптинга в конфигурации


Bobbin (Бобина) использует конфигурацию как местодержатель для скриптов Groovy, которые определяют поведение логгера во времени исполнения приложения.

Вот так выглядит вышеприведенный пример «фильтра»:

{
  "levels": "['info'].contains(level)"
}

Каждый аспект логгера поддерживает настройку, используя скрипты:

  • Уровни логирования
  • Имена классов
  • Формат сообщения
  • Имена файлов

— Простая и краткая настройка


Bobbin не требует Энкодеры, Паттерны, Фильтры, Дискриминаторы и много других лишних вещей.

Он настраивается всего-лишь несколькими основными параметрами:

  • Уровни
  • Классы
  • Файлы
  • Формат строки

Отдельные файлы для каждого уровня логирования: просто разместите "${level}" в маску имени файла в Bobbin.json (файл настройки).

Пример файла настройки:

{
  "levels": "['debug', 'info', 'warn', 'error'].contains(level)",
  "destinations": [
    {
      "name": "io.infinite.bobbin.destinations.FileDestination",
      "properties": {
        "fileName": "\"./LOGS/PLUGINS/INPUT/${className}/${level}/${className}_${level}.log\""
      },
      "classes": "className.contains('conf.plugins.input')"
    },
    {
      "name": "io.infinite.bobbin.destinations.FileDestination",
      "properties": {
        "fileName": "\"./LOGS/PLUGINS/OUTPUT/${className}/${level}/${threadName}_${level}_${date}.log\""
      },
      "classes": "className.contains('conf.plugins.output')"
    },
    {
      "name": "io.infinite.bobbin.destinations.FileDestination",
      "properties": {
        "fileName": "\"./LOGS/THREADS/${threadGroupName}/${threadName}/${level}/${threadName}_${level}_${date}.log\""
      },
      "classes": "className.contains('io.infinite.')"
    },
    {
      "name": "io.infinite.bobbin.destinations.FileDestination",
      "properties": {
        "fileName": "\"./LOGS/ALL/WARNINGS_AND_ERRORS_${date}.log\""
      },
      "levels": "['warn', 'error'].contains(level)"
    },
    {
      "name": "io.infinite.bobbin.destinations.ConsoleDestination",
      "levels": "['warn', 'error'].contains(level)"
    }
  ]
}

Попробуйте Bobbin сейчас:

Gradle: compile "io.infinite:bobbin:2.0.0"

*Bobbin является Open Source проектом под лицензией Apache.

Комментарии (31)


  1. valery1707
    01.03.2019 14:10
    #19824128
    +1

    Попробуйте Bobbin сейчас: Gradle: compile "io.infinite:bobbin:2.0.0"

    А в каком репозитории находятся артефакты? В Maven Central, на сколько я вижу, их пока нет.


    *Bobbin является Open Source проектом под лицензией Apache.

    Может стоило дать ссылку на исходники?
    Я правильно понимаю что вот его репозиторий: https://github.com/INFINITE-TECHNOLOGY/BOBBIN


    1. valery1707
      01.03.2019 14:32
      #19824284

      В статье ни одной необходимой ссылки нет, а жаль.


      Если перейти с найденного на GitHub репозитория, то можно найти и домашнюю страницу проекта, а там и документацию и уже в самом конце документации есть указание на то, что библиотеки лежат на отдельном репозитории внутри Bintray: https://dl.bintray.com/infinite-technology/m2


      И этот репозиторий, естественно, нужно прописывать и в Maven и в Gradle проектах, без этого простое добавление зависимости приведёт к ошибке сборки.


      1. antonpryamostanov Автор
        01.03.2019 20:18
        #19826168
        -1

        если честно, я очень боялся что лишние ссылки будут выглядеть как само-PR (очень хочу чтобы этот проект стал «народным»). Поэтому понадеялся на авось, что у всех JCenter прописан. Прошу прощения!
        Пожалуйста, пропишите репозиторий JCenter и попробуйте собрать.


        PS: m2 репозиторий это внутренний репозиторий для m2, артефакты из него автоматически привязываются к JCenter.


    1. antonpryamostanov Автор
      01.03.2019 20:12
      #19826152

      Приветствую valery1707!


      Спасибо за комментарий! Репозиторий JCenter. Можете попробовать пожалуйста?


      1. valery1707
        02.03.2019 00:27
        #19826980

        Проект на Gradle вроде собирается, но лучше не смотреть в вашу документацию и jcenter подключать как положено через repositories {jcenter()} вместо repositories {maven {url "https://dl.bintray.com/infinite-technology/m2" }}


        А вот с maven всё ещё веселее:


        1. Тоже проблемы в документации: там сказано что нужно указать jcenter в pom.xml, но пример конфига указывает на изменения в setting.xml
        2. Ваша либа зависит от org.codehaus.groovy:groovy-all:2.5.4:jar, а такого файла нет ни в Maven central ни в JCenter в результате Maven не находит зависимость и сборка падает


        1. antonpryamostanov Автор
          02.03.2019 09:48
          #19827732

          Приветсвую, valery1707! Огромное спасибо за комментарии и pull request’ы!
          Документация на вики проекта в github обновленная, пожалуйста используйте ее:
          github.com/INFINITE-TECHNOLOGY/BOBBIN/wiki

          Сайт (не буду указывать ссылку дабы избежать рекламы) немного отстает и будет скоро обновлен!


  1. aleksandy
    01.03.2019 14:14
    #19824148

     "fileName": "\"./LOGS/ALL/WARNINGS_AND_ERRORS_${date}.log\""

    Мои глаза! Зачем в имени файла дополнительные кавычки?


    1. zagayevskiy
      01.03.2019 16:09
      #19824938

      Затонеиксемель!


      1. antonpryamostanov Автор
        01.03.2019 20:40
        #19826250

        изначально этот логгер был зависимостью более крупного проекта Blackbox — Груви аннотации для контроллируемого обогащения кода стейтментами с логированием.
        При этом вывод планировался в XML. Так что мы любим и уважаем XML и XSD.
        Просто пока есть только конфиг использующий Jackson databind.
        Я буду рад добавить фичу! Делать XML конфиг? (будем рады сослаться на Ваш профиль в Хабре в описании issue на Гитхабе!)


    1. antonpryamostanov Автор
      01.03.2019 20:36
      #19826230

      приветствую, aleksandy!

      Отличный вопрос! и я рад продемонстрировать гибкость скриптовой настройки, можно настроить без escape characters:

      "fileName": "'./LOGS/'+level+'/'+className+'/'+threadName+'/log.txt'"


      Выглядит тоже не очень! Но идея в скриптах — возможно кто-то из пользователей найдет идеальный вариант. Каждый может использовать свой подход к написанию скрипта.
      Ограничение вызвано интерпретацией кода в GString на этапе компиляции Груви класса, при использовании «$переменная».


      1. aleksandy
        02.03.2019 09:05
        #19827608

        идея в скриптах

        Это я понял, я не понял почему
             "fileName": "./LOGS/ALL/WARNINGS_AND_ERRORS_${date}.log"

        нельзя на этапе разбора json-объекта предобработать (то же закавычивание значения), чтобы для пользователя это было прозрачно.


        1. antonpryamostanov Автор
          02.03.2019 09:52
          #19827738

          вопрос ясен! И я тоже имел такую идею!
          Но опыт показывает, что иногда пользователю может наоборот помешать доп. обработка — поэтому пока было сделано так. Пример:

          "fileName": "threadName"

          В этом случае имя лог файла равно имени треда. Но если взять насильно это в кавычки (за пределами JSON), смысл потеряется и переменная станет константой.


          1. aleksandy
            02.03.2019 10:54
            #19827916

            В этом случае имя лог файла равно имени треда.

            Это ни разу не очевидно. Для консистентного поведения в таком случае настройка должна выглядеть так:
            "fileName": "\"${threadName}\""


            При таком подходе даже человеку незнакомому с Вашей библиотекой будет понятно, что это не просто строка, но какой-то плэйсхолдер.


            1. antonpryamostanov Автор
              02.03.2019 11:00
              #19827934

              хехе, это классический парадокс! И решение пока существует наверное одно — dsl.
              Но dsl имеет другие недостатки — а именно непрозрачный синтексис.


    1. MrMango
      01.03.2019 20:36
      #19826232

      похоже каждая стринга в конфиге потом парсится в груви


      1. antonpryamostanov Автор
        01.03.2019 20:43
        #19826262

        всё верно! Создаётся класс и компилируется используя GroovyClassloader.
        Весь код использует только статическую компиляцию (через Groovy Enterprise Plugin).
        Это сочетание обеспечивает наилучшую производительность (протестировали все возможности изначально).


  1. Faenor
    01.03.2019 20:36
    #19826234

    А для maven планируется этот логгер?


    1. antonpryamostanov Автор
      01.03.2019 20:46
      #19826280

      Приветсвтую, Faenor!
      Попробуйте из репозитория Jcenter:

      <dependency>
  <groupId>io.infinite</groupId>
  <artifactId>bobbin</artifactId>
  <version>2.0.0</version>
  <type>pom</type>
</dependency>


      1. valery1707
        02.03.2019 00:33
        #19826996

        Почему предлагаете в зависимости указывать <type>pom</type>?
        У вас же библиотека — значит должен быть jar, а он идёт по-умолчанию так что тэг typeможно не указывать вовсе.


        1. antonpryamostanov Автор
          02.03.2019 09:55
          #19827750

          спасибо! поправлю и изучу вопрос лучше.


  1. antonpryamostanov Автор
    01.03.2019 20:49
    #19826292

    Огромное спасибо всем за комментарии! Если честно это был не очень подготовленный ход разместить статью сейчас. Дело в том что я сейчас в Бангладеше (идея привлечь студентов из развивающихся стран в Open Source проекты), тут дожди и у меня температура. Очень рад что пока позитивный feedback! (я боялся наихудшего!)


  1. mikaakim
    02.03.2019 10:00
    #19827760

    полиси для политик архивирования


    1. antonpryamostanov Автор
      02.03.2019 11:25
      #19828030

      отлично подмеченный момент! Пока подход такой: исключить эту функциональность, и позднее разработать отдельную независимую библиотеку для Housekeeping — в которой будут правила обращения с лог файлами и прочими файлами (например архивировать обработанные пакетные файлы с транзакциями).
      Причина такая на мой взгляд: иначе получается смешение функциональностей и выходит супер библиотека, делающая всё.

      А независимая библиотека априори более функциональная и качественная.

      Да, так сделано в других логгерах. Например в Logback эти настройки применимы только к FileAppender, но в случае SiftingAppender появляются ограничения: jira.qos.ch/browse/LOGBACK-1442

      Поэтому настало время принять правду — в Logback это архитектурно неправильно реализовано… Как Вы думаете?


  1. mikaakim
    02.03.2019 10:05
    #19827776

    Может использовать конфигурацию на груви или yaml, чтобы убрать кавычки?


    1. antonpryamostanov Автор
      02.03.2019 11:41
      #19828072

      Груви конфигурация точно отпугнёт некоторых Java пользователей.
      А вот yaml отличная идея. Добавил заявку: github.com/INFINITE-TECHNOLOGY/BOBBIN/issues/17

      Спасибо!


      1. mikaakim
        02.03.2019 11:54
        #19828096
        +1

        возможности пока никого не отпугивали, а только делали больше удобств, особенно в конфигурировании логов


        1. antonpryamostanov Автор
          02.03.2019 12:31
          #19828158

          тут есть такой момент, каждая фича должна быть покрыта тестами и документацией.
          Так что фичи должны быть востребованы, иначе получается мертвый груз затрудняющий рефакторинг.
          В идеале набор опций таков:
          — xml, json, yaml конфиги
          — groovy конфиг
          — dsl конфиг

          Начнем с yaml добавлять! По остальным проведем небольшой анализ и опрос.


  1. ads83
    02.03.2019 15:31
    #19828536

    От системы логирования хочется не только гибкой настройки, но и производительности, и надежности.
    Расскажите, пожалуйста, тестировали ли вы производительность? По каким сценариям? С чем сравнивали?
    Насколько хорошо ваш логгер работает с огромными логами? Как ведет себя под длительной (больше суток) нагрузкой?


    1. antonpryamostanov Автор
      02.03.2019 16:54
      #19828760

      производительность была одним из основных требований к этому логгеру.
      Расскажу как производилась оптимизация footprint этого логерра по отношению к CPU, RAM и влиянию на GC, а также как выбиралась архитектура и принципы разработки исходя из общей производительности:
      — Тестовый стенд представляет собой гибридное Spring Boot приложение, имеющее около 150 постоянных потоков, как синхронизированных, так и постоянно работающих в фоне.
      Он использует JPA, Hibernate, Groovy, REST. Стенд нагружался до степени, которая позволила выявить большое количество багов по потокобезопасности.
      Влючалось логирование SQL и binding в JPA/Hibernate. Ну и самое главное — стенд использовал Blackbox, который логировал буквально каждый expression в коде бизнес логики. Т.е. вывод примерно 25Мб/с логов. Около 400 одновременно записываемых файлов.
      — Была произведена первоначальная оптимизация при помощи нашего другого проекта Speedometer (пока на стадии разработки) — AST профайлер.
      — Затем производился последовательный анализ вносимых изменений используя Java Visual VM. Анализировалось потребление CPU и особенно памяти и эффективности GC.
      Как результат были выработаны и внедрены следующин принципы:
      1-статическая компиляция всех классов (мы используем новый Groovy Enterprise Plugin)
      2-отказ от использования синтаксиса форматирования аргументов, использованного в Slf4j (это кошмарная идея была изначальнл в Slf4j)
      3-полное отсутствие synchronized блоков и методов
      4-отказ от MDC/ThreadLocal — это вызывает проблемы для GC (тем не менее мы оставили поддержку встроенного MDC из Slf4j)
      5-минимизация использования коллекций и особенно потокобезопасных коллекций. Это в первую очередь касается “@Memoized” — он очень сильно замедляет работу.
      6-для замены Memoized была разработана другая аннотация “@CacheFieldInit”
      7-минимизация создания экземпляров классов. По возможности используются только аргументы методов. Это очень сильно помогает GC, и непонятно почему этим пренебрегли в Logback.
      8-скрипты из файла настройки статически компилируются в Груви класс используя GroovyClassLoader — это дает наилучшую производительность
      9-потокобезопасность строится на принципе потоковой изоляции стеков операндов вызовов методов, избегая необходимость какой-либо синхронизации

      Анализировались Heap Dumps, профайлер и разные статистики. Искались memory leaks.
      Это был очень стрессовый процесс с пересиживаниями в ночь на протяжении 1.5 месяца. Иногда руки опускались и казалось что все напрасно.

      Но конечный итог оправдал все надежды — у меня не было времени сохранить конкретные значения, но скажу так: по Java Visual VM logback выглядел… жирно — по сравнению с нашем логгером.

      Если коротко — Bobbin быстрый. Очень быстрый. И экономит память.

      Так же есть список todo: посмотреть как влияет opcodes.FINAL на GC в применении к операндам методов; протестировать производительность на других платформах кроме Windows.


      1. ads83
        02.03.2019 17:25
        #19828830

        Спасибо за развернутый ответ


        1. antonpryamostanov Автор
          03.03.2019 08:47
          #19830182
          +1

          и Вас спасибо за отличный вопрос!
          Кстати, забыл ответить на счёт «выносливости»: также тестировали на предмет деградации производительности при длительном использовании.


          И ещё один момент: нужно будет повторить тесты под раздными JVM, пока не делали этого.