How to become an author
Search
Write a publication
Pull to refresh

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

Reading time9 min
Views3.5K
Groovy & Grails*
- Псст, тут есть кто-нибудь?
- Это хаб 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 проектами.

Tags:
Hubs:
Total votes 4: ↑2 and ↓2+2
Comments8
-2
Karma
0
Rating
@antonpryamostanov

User

Send message

Articles

Your account

Sections

Information

Services

Support
© 2006–2024, Habr