Spring Music является приложением для использования сервиса базы данных среды Cloud Foundry совместно со Spring Framework и Spring Boot. Оно создано для сохранения одних и тех же доменных объектов в одном из множества различных хранилищ – объектно-реляционном, документно-ориентированном или распределенном (key-value store).
Двумя наиболее распространенными логгерами, которые используются совместно со Spring / Spring Boot, являются Logback и Log4j2. Еще недавно разработчик имел большую свободу действий в отношении формата логов и самих файлов, используемых для ведения журнала. Однако в современном мире внедрения контейнеров и масштабирования логирование обычно предлагает корпоративные решения, требующие определенного уровня стандартизации.
Одна из самых больших проблем заключается в том, что исключения Java обычно приводят к большой многострочной трассировке стека в журналах. Из-за этого вместо одного события журнала, указывающего на исключение, или сообщение об ошибке, у вас возникает более 100 различных логов, по одному на каждую строку трассировки стека, перемежающихся другими событиями журнала, поступающими от других служб или экземпляров служб.
В этой статье рассказывается, как настроить приложение Spring Boot для свертывания исключений в одну строку как для логгера Logback, так и для Log4j2. Это позволяет рассматривать логирование исключения и трассировку стека как один лог событий.
Классы ошибок Error и исключений Exception в JAVA
Проверяемые Checked и непроверяемые Unchecked исключения Exception в JAVA
Приложение Spring Music
В этой статье для специализированного логирования используется кастомная версия приложения spring-music, необходимая для работы логгеров Logback и Log4j2. Для начала нужно убедиться, что мы сможем воссоздать ее из источника. Проект требует наличия Java8, поэтому первым шагом является установка Java8 на ваш хост Ubuntu.
Затем мы берем исходный код проекта с github и создаем сборку с использованием встроенных скриптов системы сборки Gradle:
Свертывание многострочных исключений с использованием Logback
Двинемся дальше и создадим Java-архив проекта jar с реализацией логгера Logback с помощью стандартной команды Gradle:
Файл “build/libs/spring-music.jar” является самоисполняемым и содержит встроенный Tomcat, который привязан к localhost:8080. Вызов jar-файла осуществляется с помощью команды:
Вызов http://localhost:8080 в браузере покажет вам страницу со списком Альбомов, а в консоль будет выведена строка лога, выглядящая таким образом:
Этот синтаксис строки лога определен в “src/main/resources/logback-spring.xml” с использованием пользовательского шаблона:
Переменные ${…} извлекаются из application.properties и system properties, которые можно просмотреть на странице по адресу http://localhost:8080/env. Однако нужная нам часть кода находится сразу после сообщения (%m).
Слово ‘MULTIEXCEPTION’ не имеет особого значения, это просто уникальный строковый маркер, который позволяет нам узнать, где заканчивается сообщение (%m) и начинается исключение. Если хотите, то можете оставить этот маркер.
Далее, вместо того, чтобы просто вставлять заполнитель %xException, который выводил бы большую трассировку стека с символами новой строки, мы преобразуем значение при помощи функции %replace и заменяем все символы новой строки на выражение “\u2028”, которое является представлением разделителя строк Unicode.
Удаление символов "\n" из трассировки стека означает, что теперь трассировка стека теперь будет отправляться в однострочном виде. Чтобы доказать это, перейдите по ссылке http://localhost:8080/errors/throw, где имеется Error Controller, который намеренно отбрасывает NullPointerException с помощью следующего кода:
Это создает в консоли строку лога, показанную ниже:
Здесь видно, что выражение «u2028» отделяет то, что раньше было переводом строки в трассировке стека. Теперь сообщение об исключении и трассировка стека будут отправлены как единое целое.
Свертывание многострочных исключений с использованием Log4j2
Чтобы переопределить сценарий сборки по умолчанию и использовать Log4j2 в качестве резервной реализации данного проекта, нужно использовать файл “build-log4j2.gradle”.
Файл “build/libs/spring-music.jar” является самоисполняемым и использует встроенный Tomcat, который привязан к localhost:8080. Как и в предыдущем примере, вызов jar-файла осуществляется с помощью команды:
Вызов http://localhost:8080 с помощью браузера отобразит страницу со списком Альбомов с выводом на консоль строки лога, которая выглядит следующим образом:
Этот синтаксис строки журнала определен в “src/main/resources/log4j2.xml” с использованием кастомного шаблона:
Переменные ${…} извлекаются из application.properties и system properties, которые можно просмотреть на странице по адресу http://localhost:8080/env. Однако нужная нам часть кода находится сразу после сообщения (%m).
Слово ‘MULTIEXCEPTION’ не имеет специального значения, это просто уникальный строковый маркер по нашему выбору, который позволяет узнать, где заканчивается сообщение (%m) и начинается исключение. Если хотите, то можете его оставить.
Но после этого вместо того, чтобы просто вставлять заполнитель %xException, который выводил бы большую трассировку стека с символами новой строки, мы преобразуем значение при помощи функции %replace, которая заменяет все символы новой строки выражением “\u2028”, которое является представлением разделителя строк Unicode.
Удаление символов "\n" из трассировки стека означает, что теперь трассировка стека теперь будет отправляться в виде одной строки. Чтобы доказать это, перейдите по ссылке http://localhost:8080/errors/throw, где имеется Error Controller, который намеренно отбрасывает NullPointerException с помощью следующего кода:
Это создает в консоли строку лога, показанную ниже:
Как можно увидеть, здесь выражение «u2028» отделяет то, что раньше было переводом строки в трассировке стека. Теперь сообщение об исключении и трассировка стека будут отправляться как единое целое.
Выводы
Возможность свертывания многострочной трассировки стека Java в одну строку означает, что данный прием можно рассматривать как единое централизованное решение логирования.
Не существует никаких причин тратить вычислительные и человеческие ресурсы на восстановление трассировки стека на стороне назначения с помощью идентификаторов корреляции, больших размеров стека, высокой загрузки процессора и «умного» парсинга, если гораздо эффективнее выполнить это свертывание на стороне источника.
При этом символ Unicode всегда может быть заменен на стороне сбора логов (например, на стороне конвейера для сбора, фильтрации и нормализации логов Logstash) для восстановления сообщения в исходном формате.
Ссылочный материал
- https://docs.cloudfoundry.org/loggregator/architecture.html#metron (архитектура CF логирования)
docs.pivotal.io/pivotalcf/2-0/devguide/deploy-apps/streaming-logs.html#format (типы потоковых логов) - https://docs.pivotal.io/tiledev/2-0/nozzle.html#examples (формат лога для компонентов CF =<${PRI}>${VERSION} ${TIMESTAMP} ${HOST_IP} ${APP_NAME} ${PROD_ID} ${MSG_ID} ${SD-ELEMENT-instance} ${MESSAGE})
- http://grokconstructor.appspot.com/do/construction (онлайн версия шаблонов Grok)
- https://github.com/cloudfoundry/dropsonde-protocol (протокол сериализации структурированных данных Cloud Foundry Dropsonde Protocol)
- https://logback.qos.ch/manual/layouts.html (форматы компонентов преобразования входящего сообщения в строку)
- https://www.elastic.co/guide/en/logstash/current/plugins-codecs-protobuf.html (ввод logstash protobuf)
- https://github.com/cloudfoundry-community/firehose-to-syslog (отправка событий firehose из Cloud Foundry в системный журнал)
- http://schd.ws/hosted_files/cfsummit2016/f7/MonitoringCloudFoundry-LearningAboutTheFirehose.pdf (отображение частей UDP и TCP системы логирования CF)
- https://github.com/cloudfoundry-community/logsearch-for-cloudfoundry (ELK стек для CF)
- https://discuss.pivotal.io/hc/en-us/articles/223207207-Why-Loggregator-may-lose-logs (прогнозирование потерь для msgs/sec)
- http://scottfrederick.cfapps.io/blog/2014/02/20/cloud-foundry-and-logstash (как разделить на части событие syslog 5424)
- https://logz.io/blog/cloud-foundry-elk-stack/ (разделение на части 5424 syslog, встроенный сервис типа платформы для визуализации и анализа данных Kibana)
- https://docs.cloudfoundry.org/loggregator/cli-plugin.html (CF CLI плагин для просмотра firehost)
- https://github.com/cloudfoundry/loggregator-release/blob/develop/docs/java-multi-line-work-around.md (обход logback для многострочного исключения)
- https://stackoverflow.com/questions/23096129/make-logback-include-the-t-between-date-and-time-in-its-date-format-for-str (формат даты и времени logback)
- http://cloud.rohitkelapure.com/2016/06/multi-line-java-stack-traces-out-of.html (формат строки logback для свертывания исключения)
- https://discuss.elastic.co/t/match-and-replace-unicode-characters/56656 (идея использования Ruby для замены Unicode в случаях, когда Mutate не срабатывает)
- https://www.diycode.cc/projects/cloudfoundry/loggregator (логирование и манифест BOSH)
- https://www.elastic.co/guide/en/logstash/5.0/breaking-changes.html (критическое изменение event.get() для Ruby)
- https://medium.com/@martatatiana/aws-lambda-in-java-8-log4j2-and-scattered-stacktrace-in-cloudwatch-a4aea2e7bf2a (LogEventPatternConverter — кастомный конвертер логгера log4j2)
- https://springframework.guru/using-log4j-2-spring-boot/ (использование log4j2 в Spring Boot)
- https://www.quickprogrammingtips.com/spring-boot/using-log4j2-with-spring-boot.html (совместное использование log4j2 и Spring Boot )
- https://logging.apache.org/log4j/2.x/manual/layouts.html (шаблоны log4j2)
- http://www.codepreference.com/2016/04/configurable-thread-context-tags-log4j2.html (контекстная переменная потокового логирования)
- https://docs.spring.io/spring-boot/docs/current/reference/html/boot-features-external-config.html (внешние настройки конфигурации Spring Boot)
- http://logging.apache.org/log4j/2.x/manual/configuration.html#PropertySubstitution (замена свойств log4j2)
Немного рекламы :)
Спасибо, что остаётесь с нами. Вам нравятся наши статьи? Хотите видеть больше интересных материалов? Поддержите нас, оформив заказ или порекомендовав знакомым, облачные VPS для разработчиков от $4.99, уникальный аналог entry-level серверов, который был придуман нами для Вас: Вся правда о VPS (KVM) E5-2697 v3 (6 Cores) 10GB DDR4 480GB SSD 1Gbps от $19 или как правильно делить сервер? (доступны варианты с RAID1 и RAID10, до 24 ядер и до 40GB DDR4).
Dell R730xd в 2 раза дешевле в дата-центре Equinix Tier IV в Амстердаме? Только у нас 2 х Intel TetraDeca-Core Xeon 2x E5-2697v3 2.6GHz 14C 64GB DDR4 4x960GB SSD 1Gbps 100 ТВ от $199 в Нидерландах! Dell R420 — 2x E5-2430 2.2Ghz 6C 128GB DDR3 2x960GB SSD 1Gbps 100TB — от $99! Читайте о том Как построить инфраструктуру корп. класса c применением серверов Dell R730xd Е5-2650 v4 стоимостью 9000 евро за копейки?
Комментарии (9)
schroeder
05.01.2020 16:02вы решили проблему не с той стороны: не проще ли писать логи в json формате, как собственно и положено делать в 2020 году?
ladutsko
05.01.2020 17:25Спорное заявление!
Json избыточен. Форматирование отнимает ресурсы у биснеса. Логирование в консоль нечитаемое. Как то так …endymion
05.01.2020 17:34Вот ни разу не спорное. json per line формат широко распространен и супер-удобен при централизации логов. Настроить логирование в json в том-же spring-boot — дело двух минут:
build.gradle.kts:
configurations { all { exclude("org.springframework.boot", "spring-boot-starter-logging") } } dependencies { implementation("org.springframework.boot:spring-boot-starter-log4j2") }
log4j2-spring.xml:
<?xml version="1.0" encoding="UTF-8"?> <Configuration status="WARN"> <Appenders> <Console name="Console" target="SYSTEM_OUT" follow="true"> <JsonLayout compact="true" eventEol="true" properties="false" stacktraceAsString="true"> <!-- Zipkin <KeyValuePair key="trace" value="$${ctx:X-B3-TraceId:-}"/> <KeyValuePair key="span" value="$${ctx:X-B3-SpanId:-}"/> <KeyValuePair key="parent" value="$${ctx:X-B3-ParentSpanId:-}"/> <KeyValuePair key="exportable" value="$${ctx:X-Span-Export:-}"/> --> </JsonLayout> </Console> </Appenders> <Loggers> <Logger name="io.micrometer" level="warn"/> <Logger name="org.apache.kafka" level="warn"/> <Logger name="org.hibernate.validator" level="warn"/> <Logger name="org.springframework" level="warn"/> <Root level="info"> <AppenderRef ref="Console"/> </Root> </Loggers> </Configuration>
ladutsko
05.01.2020 17:39Имхо, полумера т.к. не только стектрейсы многострочные. Переводы строк могут вылезти откуда угодна – пользовательский ввод, сторонние библиотеки и т.д. Замарачиваться с разбором многострочных логов все равно придется.
Urgen
06.01.2020 00:28Системы сбора логов умеют их «склеивать» таким образом, что несколько строк отображаются в итоге как одно событие
+ многострочное событие порой выглядит намного читабельнее
rmuskovets
В названии опечатка — Spring, не Sprnig.
foxyrus
Ctrl+Enter