Логгирование и телеметрия в Clojure
@MikeAnanevСпециально для @ParensC решил написать небольшую заметку по практике логгирования и сбору метрик. Все нижеследующее – мой частный взгляд на проблему и возможно, кто-то найдет его полезным для себя.
Введение
Исходные утверждения, которые я ставлю как проблематику:
- Любой программный код содержит ошибки
- Ошибки происходят на: аппаратном, системном, платформенном, прикладном уровне
- Ошибки существуют несмотря на системы типов в языках программирования и наличие тестов
- Самые дорогие ошибки – в Production среде
- Для поиска и исправления ошибки необходимо знать или воссоздать состояние программы (state) во время работы (Runtime)
- В распределенной среде (в отличие от монолитного приложения) поиск ошибок многократно усложняется
Поэтому бизнес целью внедрения практики логгирования и телеметрии я вижу: максимально снизить операционные расходы на поддержку ПО.
Идея логгирования
Логгирование (журналирование) рассматривается как долгосрочные инвестиции в сокращение издержек по поддержке и обслуживанию ПО. Журналы работы ПО (или просто логи) являются важным источником информации для аналитики поведения системы в производственной среде. Отсюда первый вывод: писать логи как попало - нельзя (см. бизнес-цель). Поэтому в команде важно выработать общую культуру ведения логов.
При разработке общей культуры ведения логов важно дать новичкам в команде базовые принципы или идеи, руководствуясь которыми в различных ситуациях они будут правильно оценивать, что и как нужно логгировать.
Вот первая идея: при ведении журналов на системном, платформенном и прикладном уровне – ПО должно сообщать о себе достаточно информации , чтобы подразделения поддержки и разработчиков могли понять, что именно происходит в Runtime.
На основе этой идеи можно прийти к следующим размышлениям: в зависимости от типа нагрузки и задач системы виды логов и их структура будут меняться. Для одних задач может понадобится активный вывод системных логов, для других достаточно будет только прикладных. Чтобы понять, что происходит в Runtime важно выбрать узловые точки и логгируемые данные, при взгляде на которые сразу станет ясно, что не так.
Вторая идея: логи должны быть структурированными. Писать логи как простой String это значит лишать себя возможности анализировать логи программно. Как только вы поместили любые данные в String, вы тут же похоронили все достоинства работы данными, структурами данных, лишились data driven подхода. Вот кстати чем не удобен SQL в виде строк, но это уже другая история... Строковые данные могут анализировать только люди, глазами, как в 80-е. Сейчас все больше анализом логов занимаются машины (машины следят за машинами, в этом что-то есть...) Для того, чтобы помочь машинам люди пишут парсеры логов. Поэтому желательно сразу писать логи в human readable & machine readable виде, с общей структурой и тогда не придется писать парсеры (ну или почти не придется).
Третья идея: не пишите логи только в локальные файлы, т.к. на проде их потом придется собирать. Лучше сразу предусмотрите механизм отправки логов по сети в место сбора и анализа. Например, мы для этих целей используем Apache Kafka.
Общая рекомендация – развивайте идеи логгирования внутри ваших команд, в контексте ваших задач и профиля нагрузок.
Настройка логов и метрик в проекте
До недавнего времени я активно использовал базовую библиотеку логгирования в Clojure – org.clojure/tools.logging. Однако в последнее время стал использовать библиотеку логгирования от pedestal, которая позволяет удобнее логгировать в структурированном виде.
В качестве низлежащего логгера использую logback (существенно улучшенный аналог log4j от того же автора).
Вот так я импортирую библиотеки по логгированию и сбору метрик в project.clj:
;;metrics support [io.dropwizard.metrics/metrics-core "3.2.2"][io.dropwizard.metrics/metrics-jvm "3.2.2"][io.dropwizard.metrics/metrics-healthchecks "3.2.2"] [com.readytalk/metrics3-statsd "4.2.0" :exclusions [io.dropwizard.metrics/metrics-core]] ;;logging support [io.pedestal/pedestal.log "0.5.2" :exclusions [io.dropwizard.metrics/metrics-core]] [com.github.danielwegener/logback-kafka-appender "0.1.0"] [ch.qos.logback/logback-classic "1.2.3" :exclusions [org.slf4j/slf4j-api]] [org.slf4j/jul-to-slf4j "1.7.25"] [org.slf4j/jcl-over-slf4j "1.7.25"] [org.slf4j/log4j-over-slf4j "1.7.25"]
Для корректной работы логгеров необходима настройка аппендеров. Аппендеры это управляющие механизмы, которые задают разные параметры для логгирования:
- куда писать логи (экран, файл, бд, сеть,...),
- уровень логгирования (log level), ниже которого логи не будут записаны
- максимальный размер файла.
- ...
Для настройки аппендеров я создаю в папке resources файл logback.xml. Ниже приведено его содержимое.
<configuration debug="false" scan="true" scanPeriod="30 seconds">
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"><filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<!-- minimum level which we emit on console-->
<level>WARN</level>
</filter>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<!-- minimum level which we emit to file-->
<level>INFO</level>
</filter>
<file>${VERITA_LOG_DIR}/verita.log</file>
<append>true</append>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<!-- rollover daily -->
<fileNamePattern>${VERITA_LOG_DIR}/verita-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<!-- or whenever the file size reaches 100 MB -->
<maxFileSize>100MB</maxFileSize>
</rollingPolicy>
</appender>
<!-- This is the kafkaAppender -->
<appender name="kafkaAppender" class="com.github.danielwegener.logback.kafka.KafkaAppender">
<!-- This is the default encoder that encodes every log message to an utf8-encoded string -->
<encoder class="com.github.danielwegener.logback.kafka.encoding.LayoutKafkaMessageEncoder">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</layout>
</encoder>
<topic>${KAFKA_LOG_TOPIC}</topic>
<keyingStrategy class="com.github.danielwegener.logback.kafka.keying.RoundRobinKeyingStrategy"/>
<deliveryStrategy class="com.github.danielwegener.logback.kafka.delivery.AsynchronousDeliveryStrategy"/>
<!-- each <producerConfig> translates to regular kafka-client config (format: key=value) -->
<!-- producer configs are documented here: https://kafka.apache.org/documentation.html#newproducerconfigs -->
<!-- bootstrap.servers is the only mandatory producerConfig -->
<producerConfig>bootstrap.servers=${KAFKA_SERVERS}</producerConfig>
<!-- this is the fallback appender if kafka is not available. -->
<!--<appender-ref ref="FILE"/>-->
</appender>
<!--If all brokers are not reachable when the logging context starts, or all brokers become unreachable for a longer
time period (> metadata.max.age.ms), your appender will eventually block. This behavior is undesirable in
general and can be migitated with wrapping the KafkaAppender with logback's own AsyncAppender-->
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
<queueSize>500</queueSize>
<discardingThreshold>0</discardingThreshold>
<neverBlock>true</neverBlock>
<appender-ref ref="kafkaAppender"/>
</appender>
<logger name="verita" level="INFO"/>
<root level="WARN"> <!-- all other classes minimum level-->
<appender-ref ref="CONSOLE"/>
<appender-ref ref="FILE"/>
<appender-ref ref="ASYNC"/>
</root>
</configuration>
В данном примере используются аппендеры для вывода логов на консоль, в файл и Kafka. Конфигурация некоторых параметров задана через переменные окружения. Это очень удобно для DevOps'a. Минимальный уровень логгирования задан как WARN. (не забудьте переименовать в примере название приложения verita на имя вашего приложения).
FILE аппендер автоматически делает logrotate или по размеру файла 100МБ или по истечению суток (что раньше настанет)
ASYNC апендер используется здесь для того, что если сервера Kafka не доступны (или у вас их нет вообще), то это никак не скажется на работе приложения.
Вот переменные окружения из project.clj, которые используются для логгирования и телеметрии:
:jvm-opts ^:replace ["-Xmx256m"
"-DVERITA_HOST=0.0.0.0" "-DVERITA_PORT=8080"
"-DVERITA_HOME=." "-DVERITA_LOG_DIR=logs"
"-DVERITA_CONF_DIR=conf"
"-DKAFKA_LOG_TOPIC=verita_logs"
"-DKAFKA_SERVERS=127.0.0.1:9092"
"-DVERITA_REPORTER=statsd"
"-DVERITA_REPORT_PERIOD=5"
"-DSTATSD_SERVER=127.0.0.1"
"-DSTATSD_PORT=8125"]
Логгируем
В коде делаем стандартный импорт библиотеки логгирования (require '[io.pedestal.log :as logger]) и пишем логи в зависимости уровня важности. Обычно я использую уровни logger/debug, logger/info, logger/warn, logger/error (уровни приведены в порядке возрастания важности).
Частенько при отладке возникает необходимость посмотреть промежуточное значение в каком-нибудь let, для этого я использую logger/spy, которая выводит в логи значение наблюдаемой величины и возвращает его как есть.
(let [a1 (logger/spy (+ 2 3)) b (+ a1 5)] b)
В данном примере, значение a1 будет выведено в том случае, если в аппендере задан минимальный уровень логгирования DEBUG или ниже. В приведенном выше примере logback.xml задан минимальный уровень INFO для файлов и WARN для консоли и поэтому spy промолчит в логах.
При старте программы, где-нибудь в начале main, по рекомендации авторов необходимо вызвать (logger/maybe-init-java-util-log), чтобы перенаправить все логи от java.util.logging через SLF4J. Это полезно, чтобы какой-нибудь логгер вдруг не начал сыпать на экран ненужные данные.
Пример кода, по формированию структурированных логов:
(logger/info :msg "got request" :request-body {:a 1 :b "hello" :c [1]})
В результате чего, в файле с логами появится следующее сообщение:
2017-06-15 15:17:40.502 [nREPL-worker-8] INFO verita.app - {:msg "got request", :request-body {:a 1, :b "hello", :c [1]}, :line 55}
Как видно, структура сообщения имеет строгий формат:
- первая часть формата записи задана в logback.xml: дата, время, процесс, уровень лога, namespace из которого был эммитирован лог.
- вторая часть задается самим программистом начиная с {:msg...} и представляет собой EDN структуру данных. Заметим, что pedestal.log любезно подставил номер строки в исходных файлах, откуда был брошен лог.
В логах можно сохранить дополнительный контекст ситуации, который сильнее раскроет проблему. В отдельных случаях можно логгировать все приходящие запросы и соответствующие им ответы из того или иного модуля. Тогда можно увидеть весь поток данных (flow) через все приложение и результаты преобразований на каждом этапе.
У Стюарта Сиерры подсмотрел полезную функцию, которую стоит однократно запускать, в самом начале программы:
(defn set-global-exception-hook "set global exception hook. here we catch any uncaught exceptions and log it." [] (Thread/setDefaultUncaughtExceptionHandler (reify Thread$UncaughtExceptionHandler (uncaughtException [_ thread ex] (logger/error :msg "uncaught exception" :thread (.getName thread) :descr ex) (println ex)))))
Данная функция регистрирует в JVM общий хук, который будет перехватывать все необработанные вами Exception и логгировать их. Очень полезно, когда код вдруг поломался в неожиданном месте, где мы не ставили try-catch.
Рекомендую везде использовать set-global-exception-hook.
Метрики aka телеметрия
Помимо логов, очень важно собирать и анализировать метрики приложений. Метрики более легковесны чем логи. Под метриками (телеметрией) я понимаю сбор и передачу мгновенных показателей работы приложения. В отличие от логов, метрики показывают текущее поведение приложения на проде, их легко визуализировать, что дает возможность DevOps инженерам предсказывать поведение системы видя графики.
Примерами метрик могут быть:
- число запросов в сек (req/sec);
- текущее количество активных сессий;
- время доступа к базе;
- среднее время выполнения запросов, min, max, дисперсия;
- 50,75, 90,99 персентали (чего-бы то ни было);
- расход памяти JVM;
- нагрузка на CPU;
- и так далее.
Вот пример графика сбора метрик по нагрузке на CPU и JVM, отображаемый в Grafana.
Базовые понятия и инструменты сбора метрик
Для организации сбора метрик я использую библиотеку Metrics http://metrics.dropwizard.io/3.2.2/ В приведенном выше project.clj все необходимые зависимости уже присутствуют.
На youtube есть несколько презентаций по этой библиотеке. Их вы легко найдете с помощью поиска.
На рисунке ниже изображена верхнеуровневая архитектура.
Registry (реестр) – некий класс, который хранит все типы метрик и производит необходимые вычисления, в зависимости от типа метрики.
Reporter – другой класс, который периодически опрашивает реестр и отправляет метрики туда, куда ему было указано.
В при старте приложения (Main App code), необходимо создать Реестр и запустить Репортер, после чего можно начинать регистрировать метрики.
Метрики бывают следующих видов:
- Gauge - простейшая метрика. Просто мгновенное значение, какой-либо измерямой величины на текущий момент. logger/gauge в качестве параметра принимает функцию, которая будет вызвана в момент опроса реестра для расчета наблюдаемой величины. (logger/gauge statsd-reporter "verita.current-sessions-number" (fn [] (common/max-jvm-memory)))
- Counter - мгновенная величина (64 bit Integer) наблюдаемой характеристики, которая может быть уменьшена или увеличена: текущее значение пользователей, количество задач в очереди и т.п. В качестве аргумента счетчика всегда указывается дельта на которую изменится текущее значение счетчика. Дельта может быть как положительной так и отрицательной. Например (logger/counter statsd-reporter "verita.uniq-user-counter" 1). В данном случае 1 это дельта, на которую увеличится текущее значение счетчика уникальных пользователей.
- Histogram - измерение распределения величины в потоке данных и измерение частоты события. Для Histogram считаются: общее количество поступивших значений наблюдаемой величины, минимальные и максимальные значения величины, среднее значение величины за наблюдаемый период, а также от 50 до 99 персентали. Передаваемый аргумент - мгновенное значение величины. Например (logger/histogram statsd-reporter "verita.db-req" 234)
- Meter - измеряет частоту с которой происходит событие. функция mark помечает, что событие произошло
- Timer - это измерение количества времени, которое занимает выполнение какого-либо операции или куска кода.
Graphite - принимает метрики по UDP и хранит их в timeseries базе данных. Может отображать метрики, но это удобнее делать в Grafana.
Установка Graphite производится одной командой:
docker run -d --name graphite --restart=always -p 80:80 -p 2003-2004:2003-2004 -p 2023-2024:2023-2024 -p 8125:8125/udp -p 8126:8126 hopsoft/graphite-statsd
Для остановки я использую: docker stop graphite. Для удаления контейнера (не образа): docker rm graphite Для повторного запуска ранее остановленного контейнера docker run graphite.
Grafana – очень хорошо рисует дашборды. Установка Grafana производится одной командой:
docker run -d --name grafana -i -p 3000:3000 -e "GF_SERVER_ROOT_URL=http://localhost" -e "GF_SECURITY_ADMIN_PASSWORD=mypwd01" grafana/grafana
По аналогии с Graphite, остановка, удаление или запуск ранее остановленного контейнера производится:
- docker stop grafana
- docker rm grafana
- docker run grafana
Далее я привожу просто кусок кода, который
- далает необходимую инициализацию Реестра и Репортеров
- запускает тот или иной репортер
- регистрирует метрики, которые были приведены на рисунке выше
Raw Clojure code
(ns verita.util.metrics
(:gen-class)
(:require [clojure.spec.alpha :as spec]
[io.pedestal.log :as logger]
[mount.core :refer [defstate] :as mount]
[environ.core :refer [env]]
[verita.util.common :as common])
(:import (java.util.concurrent TimeUnit)
(org.slf4j LoggerFactory)
(com.codahale.metrics Slf4jReporter Gauge MetricRegistry
ConsoleReporter ScheduledReporter MetricFilter)
(com.codahale.metrics.health HealthCheck)
(com.readytalk.metrics StatsDReporter)))
;; enable asserts
(spec/check-asserts true)
(def ^:dynamic *config*
{:reporter-type (-> env :verita-reporter keyword)
:report-period (or (common/safe (Integer. ^String (:verita-report-period env))) 2)
:statsd-server (or (:statsd-server env) "127.0.0.1")
:statsd-port (or (common/safe (Integer. ^String (:statsd-port env))) 8125)})
(spec/def ::registry #(instance? MetricRegistry %))
(spec/def ::time-unit #(instance? TimeUnit %))
(spec/def ::rate-unit ::time-unit)
(spec/def ::duration-unit ::time-unit)
(spec/def ::report-period pos-int?)
(spec/def ::report-timeunit ::time-unit)
(spec/def ::logger-name string?)
(spec/def ::prefix string?)
(spec/def ::reporter-type #{:console :slf4j :statsd})
(spec/def ::host string?)
(spec/def ::port pos-int?)
(spec/def ::max-size-bytes pos-int?)
(spec/def ::max-latency-ms pos-int?)
(defmulti reporter-type ::reporter-type)
(defmethod reporter-type :console [_]
(spec/keys :req [::registry
::rate-unit
::duration-unit
::report-period
::report-timeunit]))
(defmethod reporter-type :slf4j [_]
(spec/keys :req [::registry
::rate-unit
::duration-unit
::report-period
::report-timeunit
::logger-name]))
(defmethod reporter-type :statsd [_]
(spec/keys :req [::registry
::host
::port
::rate-unit
::duration-unit
::report-period
::report-timeunit]))
(spec/def ::reporter-params (spec/multi-spec reporter-type ::reporter-type))
(defn console-reporter
"create console reporter for given registry and start it. return nil."
[params]
(spec/assert ::reporter-params params)
(doto (some-> (ConsoleReporter/forRegistry (::registry params))
(.outputTo System/out)
(.convertRatesTo (::rate-unit params))
(.convertDurationsTo (::duration-unit params))
(.build))
(.start (::report-period params) (::report-timeunit params))))
(defn slf4j-reporter
"create SLF4j reporter for given registry and start it. return nil."
[params]
(spec/assert ::reporter-params params)
(doto (some-> (Slf4jReporter/forRegistry (::registry params))
(.outputTo (LoggerFactory/getLogger ^String (::logger-name params)))
(.convertRatesTo (::rate-unit params))
(.convertDurationsTo (::duration-unit params))
(.build))
(.start (::report-period params) (::report-timeunit params))))
(defn statsd-reporter
"create StatsD reporter for given registry and start it. return nil."
[params]
(spec/assert ::reporter-params params)
(doto (some-> (StatsDReporter/forRegistry (::registry params))
(.convertRatesTo (::rate-unit params))
(.convertDurationsTo (::duration-unit params))
(.build (::host params) (::port params)))
(.start (::report-period params) (::report-timeunit params))))
(defn init-metric-reporter
"return initialzed MetricRegistry object."
[reporter-type]
(case (spec/assert ::reporter-type reporter-type)
:console (logger/metric-registry #(console-reporter {::reporter-type :console
::registry %
::rate-unit TimeUnit/SECONDS
::duration-unit TimeUnit/MILLISECONDS
::report-period (:report-period *config*)
::report-timeunit TimeUnit/SECONDS}))
:slf4j (logger/metric-registry #(slf4j-reporter {::reporter-type :slf4j
::registry %
::rate-unit TimeUnit/SECONDS
::duration-unit TimeUnit/MILLISECONDS
::report-period (:report-period *config*)
::report-timeunit TimeUnit/SECONDS
::logger-name "verita"}))
:statsd (logger/metric-registry #(statsd-reporter {::reporter-type :statsd
::host (:statsd-server *config*)
::port (Integer. (:statsd-port *config*))
::registry %
::rate-unit TimeUnit/SECONDS
::duration-unit TimeUnit/MILLISECONDS
::report-period (:report-period *config*)
::report-timeunit TimeUnit/SECONDS}))))
;; Defines reporter to be passed to metrics functions
(defonce custom-reporter (init-metric-reporter (:reporter-type *config*)))
(logger/gauge custom-reporter "verita.jvm.max" (fn [] (common/max-jvm-memory)))
(logger/gauge custom-reporter "verita.jvm.free" (fn [] (common/free-jvm-memory)))
(logger/gauge custom-reporter "verita.jvm.total" (fn [] (common/total-jvm-memory)))
(logger/gauge custom-reporter "verita.jvm.used" (fn [] (common/used-jvm-memory)))
(logger/gauge custom-reporter "verita.cpu.system" (fn [] (common/system-cpu-load)))
(logger/gauge custom-reporter "verita.cpu.jvm-proc" (fn [] (common/process-cpu-load)))
(logger/gauge custom-reporter "verita.file.max-descr" (fn [] (common/max-file-descriptor)))
(logger/gauge custom-reporter "verita.file.open-descr" (fn [] (common/open-file-descriptor)))
(logger/gauge custom-reporter "verita.swap.total" (fn [] (common/total-swap-size)))
(logger/gauge custom-reporter "verita.swap.free" (fn [] (common/free-swap-size)))
Как видно из примера, параметры репортеров задаются из переменных окружения, что также удобно для DevOps.
Послесловие
Когда пишите прототип, код для себя и т.д, словом любой код – вырабатывайте привычку логгировать правильно. Этот навык быстро прививается и в дальнейшем он не заметен для разработчика, а качество кода становится выше. Я очень часто вижу коде, который писался "по быстрому", чтобы проверить гипотезу операторы типа System.out.println ("никому непонятное сообщение с сокращ."). И часто такие куски кода потом попадают в реальный код систем. Тех поддержке ничего не остается как копипастить стектрейсы и невнятные фразы и отправлять их назад разработчикам. Если разработчики отделены от прода, то они тоже частенько гадают, что же выдал им их собственный лог.
State приложения в проде – самая ценная информация. Постарайтесь его донести в логах так, чтобы сразу было понятно - вот она бага, попалась!
Метрики глубже помогают понять поведение системы или отдельных ее модулей под нагрузкой.
Что вы измеряете, то вы можете анализировать и улучшать, соответственно, что вы не измеряете, вы точно улучшать не сможете.
Описанный в этой заметке подход предлагает "выталкивание" метрик и логов из приложения. Это очень удобно в cloud среде, где наблюдается высокая частота переезда процессов с машины на машину.
К приложению в проде бывает довольно сложно подключиться, в силу административных барьеров. Выталкивание метрик из приложения помогает преодолеть эти барьеры.