SavePearlHarbor

Чёрный Ящик: забудьте о логировании

—

от автора

admin
- Псст, тут есть кто-нибудь? - Это хаб Groovy. - Теперь вообще не нужно писать код логирования! Он добавляется автоматически! - Круто, это сэкономит кучу времени и сил!

Привет!

В предыдущих статьях мы поговорили о логировании и о мета-программировании.

Теперь поговорим о мета-логировании.
Или о семантическом логировании — кому как нравится.

Логгер "Бобина" — это были цветочки. А вот и ягодки: Чёрный ящик.

Вступление

Я начал использовать Groovy в 2009 году.

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

Проблема

Существует методологический пробел в подходе и лучших практиках интеграции логирования в код программы.

Вкратце, нет общепринятого набора правил, помогающих программистам понять:

  • Какие данные логировать
  • Как структурировать логируемые данные
  • Когда логировать
  • Где размещать код логирования в коде программы
  • Как будут использованы созданные логи
  • Зачем вообще тратить время на написание кода логирования

Так же, казалось бы с существованием AST API (Groovy) и CGLIB (Java) — должны были уже появиться средства автоматизации логирования — но нет:

  • В Groovy есть пара аннотаций (@Slf4j, Log, и т.д.) которые лишь внедряют объявление и инициализацию переменной логгера.

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

  • Захламление кода приложения кодом логирования
  • Неструктурированный и захламлённый вывод логов
  • Человеческий фактор: легко упустить важный вывод в логе, неправильно расположив его логирование
  • Удорожание разработки и увеличение сроков

Решение

Теоретические изыскания привели к созданию концепции "семантического логирования" — похожей на функционал в JUL (sourceMethodName), но гораздо более продуманной:

Семантическое Логирование это техника написания кода, позволяющая отслеживать ход исполнения программы в соответствии с семантическими структурами её кода, такими как:

  • Начало и конец выполнения метода (включая конструкторы)
  • Аргументы и возвращаемое значение (результат) метода
  • Блоки, такие как if/then
  • Выражения, например присвоение значения переменной

Дело оставалось за малым: автоматизировать эту концепцию. И тут на помощь пришёл Groovy AST API.

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

"Чёрный ящик" помогает ответить на эти ключевые вопросы:

  • Что логировать:
    • 4 уровня детализации:
    • Исключения обработки методов (включая аргументы на которых метод выработал исключение)
    • Выполнение методов (аргументы, начало и конец выполнение, результат и исключения)
    • Блоки внутри методов (поддерживаются все блоки Groovy кода, такие как if, switch, for, и т.д.)
    • Вычисление выражений (все выражения Groovy поддерживаются) — с результирующим значением объекта и его классом
    • Мета-данные этапа компиляции:
    • Номера строк кода
    • Непосредственно сам исходный код
  • Как структурировать данные логирования
    • Данные автоматически структурируются в соответствии с форматом BlackBox, не оставляя пространства для неверной интерпретации
  • Где размещать код логирования в коде приложения
    • Просто добавьте аннотацию @BlackBox к методу (или даже ко всему классу) — и дело сделано. Не нужно захламлять основной код строчками с логированием.
  • Как будут использованы созданные логи
    • Расследование инцидентов и отладка
    • Профилирование быстродействие и оптимизация
    • Статистика
    • Аналитика
    • Мониторинг
    • Телеметрия
    • Журналирование
  • Зачем вообще тратить время на написание кода логирования
    • А и не нужно!

Назначение

Чёрный ящик — это решение для автоматической генерации кода Семантического Логирования на Groovy и добавления его в код приложения на этапе компиляции.

В результате это даёт возможность производить и анализировать исчерпывающие данные этапа выполнения приложения в форме логов, основанных на упрощённой классовой модели Groovy AST.

Вкратце

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

Детализация добавляемого логирования может быть настроена пользователем (программистом) до следующих уровней:

  • Исключения обработки методов (включая аргументы на которых метод выработал исключение)
  • Выполнение методов (аргументы, начало и конец выполнение, результат и исключения)
  • Блоки внутри методов (поддерживаются все блоки Groovy кода, такие как if, switch, for, и т.д.)
  • Вычисление выражений (все выражения Groovy поддерживаются) — с результирующим значением объекта и его классом

Чёрный ящик использует Slf4j-совместимый API логирования, позволяя использовать Ваш любимый логгер:

  • Log4j2
  • Logback
  • Бобина

Мы рекомендуем использовать Slf4j логгер Бобину вместе с Чёрным ящиком из-за её простоты и быстродействия.

Чёрный ящик доступен в Maven репозитории JCenter.

Функции

Чёрный ящик основан на инструменте AST трансформации "Карбюратор".

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

Здесь мы приводим только список дополнительных функций, присущих Чёрному ящику.

Функции этапа компиляции

Подавление исключений

Существуют сценарии, когда нужно залогировать исключение, но подавить его (проигнорировать) — без перебрасывания.

Например в пользовательских скриптах, в методах постоянно работающих потоков.

Для этого, аннотация @BlackBox поддерживает параметр suppressExceptions, который автоматически подавляет необработанные исключения в методе:

    @BlackBox(level = CarburetorLevel.ERROR, suppressExceptions = true)     void foo() {         bar()     }

что становится эквивалентно:

    void foo() {         try {             bar()         } catch (Exception e) {             log.error(e) //log exception without re-throwing         }     }

Функции этапа выполнения программы

Чёрный ящик реализует обработку событий времени выполнения API Карбюратора — логируя их с помощью Slf4j API.

Вот примеры того, как логируется выполнение с помощью Чёрного ящика:

2019-02-20 18:29:43:121|debug|http-nio-8089-exec-2|conf.plugins.input.rest.SelfTest|METHOD RESULT: 2019-02-20 18:29:43:121|debug|http-nio-8089-exec-2|conf.plugins.input.rest.SelfTest|org.springframework.http.ResponseEntity 2019-02-20 18:29:43:121|debug|http-nio-8089-exec-2|conf.plugins.input.rest.SelfTest|<200 OK OK,io.infinite.pigeon.springdatarest.CustomResponse(response:[message:Self test started (2019-02-20 18-29-43-090), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550672982945, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550672983042]),{}> 2019-02-20 18:29:43:121|debug|http-nio-8089-exec-2|conf.plugins.input.rest.SelfTest|METHOD END: applyPlugin.conf.plugins.input.rest.SelfTest(20,1,62,2) 2019-02-21 15:43:51:128|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2) 2019-02-21 15:43:51:154|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD RESULT: 2019-02-21 15:43:51:154|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|org.apache.groovy.json.internal.LazyMap 2019-02-21 15:43:51:155|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|[message:Self test started (2019-02-21 15-43-51-148), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550749431056, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550749431124] 2019-02-21 15:43:51:155|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD END: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2) 2019-02-21 15:48:34:536|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2) 2019-02-21 15:48:34:571|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD RESULT: 2019-02-21 15:48:34:571|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|org.apache.groovy.json.internal.LazyMap 2019-02-21 15:48:34:572|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|[message:Self test started (2019-02-21 15-48-34-564), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550749714444, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550749714530] 2019-02-21 15:48:34:572|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD END: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2) 2019-02-21 15:53:58:299|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2) 2019-02-21 15:53:58:326|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD RESULT: 2019-02-21 15:53:58:326|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|org.apache.groovy.json.internal.LazyMap 2019-02-21 15:53:58:327|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|[message:Self test started (2019-02-21 15-53-58-318), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550750038217, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550750038295] 2019-02-21 15:53:58:328|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD END: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2) 2019-02-21 15:58:35:032|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2) 2019-02-21 15:58:35:061|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD RESULT: 2019-02-21 15:58:35:061|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|org.apache.groovy.json.internal.LazyMap 2019-02-21 15:58:35:062|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|[message:Self test started (2019-02-21 15-58-35-052), financialMessages:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550750314954, otpMessage:http://localhost:8089/pigeon/outputMessages/search/searchByInputExternalIdAndSourceName?sourceName=SELF_TEST_PLUGIN&externalId=1550750315028] 2019-02-21 15:58:35:063|debug|http-nio-8089-exec-1|conf.plugins.input.rest.SelfTest|METHOD END: getResponseJson.conf.plugins.input.rest.SelfTest(71,1,79,2)

2019-02-21 15:54:11:486|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|EXCEPTION (first occurrence): 2019-02-21 15:54:11:492|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|a64aceed-8e4c-4d4b-8030-0c23bc3b3f0d 2019-02-21 15:54:11:493|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|java.lang.NullPointerException     at io.infinite.pigeon.threads.SenderThread.sendMessage(SenderThread.groovy:98)     at io.infinite.pigeon.threads.SenderThread.run(SenderThread.groovy:44)  2019-02-21 15:54:11:493|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|METHOD EXCEPTION: sendMessage.io.infinite.pigeon.threads.SenderThread(60,5,100,6) 2019-02-21 15:54:11:493|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|EXCEPTION (additional occurrence): 2019-02-21 15:54:11:494|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|a64aceed-8e4c-4d4b-8030-0c23bc3b3f0d 2019-02-21 15:54:11:494|error|SELF_TEST_RETRY_OUTPUT_RETRY_SENDER_1_RETRY|io.infinite.pigeon.threads.SenderThread|METHOD EXCEPTION: run.io.infinite.pigeon.threads.SenderThread(40,5,50,6)

Использование

Чёрный ящик размещён в репозитории JCenter:

Download

Gradle

... repositories {     jcenter() } ... compile 'io.infinite:blackbox:1.0.21' ...

Аннотация @BlackBox применима к классам, методам и конструкторам:

import io.infinite.blackbox.BlackBox import io.infinite.carburetor.CarburetorLevel  @BlackBox(level = CarburetorLevel.EXPRESSION) String foobar(String foo) {     String bar = "bar"     String foobar = foo + bar     return foobar }  foobar("foo")

Заключение

Чёрный ящик — это новое секретное оружие Groovy, а также фундамент открытой экосистемы i-t.io.

По нашим оценкам, использование Чёрного ящика экономит до 25% ресурсов на этапе написания программного кода и от 20% до 500% при поддержке программ.

Это уникальная реализация инновационной концепции, подкреплённая научным подходом к её разработке.

Забудьте о логировании — теперь Чёрный ящик сделает его за вас.

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

ссылка на оригинал статьи https://habr.com/ru/post/490056/

Комментарии

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *