Макросы, мета и ведение журнала
На протяжении многих лет управления Apache Tapestry я всегда делал упор на описательные исключения и сообщения журнала. Исключения и ведение журнала идут рука об руку: ведение журнала для определения общего состояния системы и исключения для предоставления подробных сведений, когда что-то пошло не так… а также для предоставления рекомендаций и подсказок разработчику, пытающемуся решить проблему.
Основная часть подхода Tapestry к исключениям и регистрации касается построения этих подробных сообщений об исключениях и регистрации. Например, вместо того, чтобы генерировать исключение NullPointerException после того, как ожидаемое значение отсутствует в HashMap, Tapestry обнаружит отсутствующий ключ и выдаст исключение, сообщение и дополнительные свойства которого будут определять, что ищется, а также какие возможные значения могут быть выбраны. . Запросите компонент и измените имя, и в сообщении об исключении четко указано: «Компонент TaxtField не найден». вместе со списком всех фактических типов компонентов.
Я по-прежнему придерживаюсь этого уровня проверки работоспособности, несмотря на то, что время выполнения очень короткое. Я потрачу несколько наносекунд на обработку (даже, если необходимо, на каждый запрос!), Чтобы сэкономить разработчику минуты или часы.
Точно так же, когда ведется журнал, я привык создавать сообщения журнала на удобочитаемом английском языке.
Но дискуссия со Стюартом Хэллоуэем немного раньше повела меня в другом направлении. Стюарт отстаивает идею «журналов как потоков данных», а не журналов как потоков текстовых сообщений.
Вы можете увидеть это в библиотеке io.pedestal / log. Выходные данные в рамках Пьедестала - это всегда данные. Каждое событие журнала представляет собой карту ключей и значений. Вот пример из пространства имен io.pedestal.interceptor.chain от Pedestal:
(log/debug :in 'leave-all :execution-id (::execution-id context))
Во время выполнения мы видим в консоли такие сообщения:
103741.182 DEBUG io.pedestal.interceptor.chain - {:in leave-all, :execution-id 9, :line 241}
Это то, что делает io.pedestal.log: он упаковывает эти пары ключ / значение, добавляет ключ :line
и записывает полученную карту в журнал в виде строки. Поскольку он находится в формате EDN, его можно легко проанализировать и интерпретировать.
Теперь, возможно, команда Pedestal могла бы зарегистрировать это более традиционным образом, с сообщением типа "Executing leave-all stage of interceptor execution #9."
. Но мое развитое мышление привело меня к выводу, что такой читабельный текст слишком многословен, слишком отвлекает, недостаточно единообразен и в конечном итоге менее полезен - как я больше работать с инструментами агрегирования журналов, такими как Splunk, мне нравится, когда мои данные как данные, которые я могу легко фильтровать и манипулировать.
Вернемся к клавише :line
. Это оказывается очень полезным; наличие номера строки (и пространства имен) для каждого зарегистрированного оператора делает работу в обратном направлении от вывода журнала к коду значительно быстрее и менее утомительна. Это одна из тех маленьких функций, о которых вы даже не подозреваете, чтобы требовать их заранее, но поймете, что они очень важны, как только они у вас появятся.
Макросы журналирования могут очень дешево определить номер строки, поскольку каждая форма, считываемая программой чтения Clojure, снабжена метаданными, которые описывают, откуда эта форма пришла, в терминах строки, столбца и файла.
Напротив, для Logback для определения номера строки требуются некоторые странные уловки JVM и достаточно дорого, чтобы они рекомендовали включать только номер строки в зарегистрированный вывод, где «скорость выполнения не является проблемой».
Но внутри log/debug
есть ахиллесова пята: предполагается, что ее будут использовать только изнутри обычного кода. Внутри макроса он не работает должным образом.
Я выяснил это на собственном горьком опыте. Для контекста я создаю код на основе Apache ZooKeeper и zookeeper-clj и пишу множество обратных вызовов.
Я обнаружил, что понимание и отладка приложения ZooKeeper требует большого ведения журнала; большая часть регистрации происходит внутри асинхронных функций обратного вызова, соответствующих каждому вызову API zookeeper-clj.
Каждый из обратных вызовов следует определенному шаблону:
log/trace
результат обратного вызова при вызове- Отправка с использованием
clojure.core/case
на основе кода результата ZooKeeper (со значениями, такими как:ok
или:connectionloss
) log/error
если нет совпадений
Например:
(let [callback (fn [result] (let [{:keys [return-code context stat] :as result'} (normalize-result result)] (log/trace :event :on-task-data :result result') (case return-code :ok (swap! *state assoc-in [:tasks context :created-at] (:ctime stat)) (log/error :event :on-task-data :result result'))))])
Это не просто много шаблонов, это много утомительных повторяющихся шаблонов. Церемония полностью перегружает суть, и у меня есть как минимум дюжина таких callback-функций.
Обычно я следую первому правилу написания макросов: не пишите макросы, но это кажется исключением из этого правила. Моя цель - создать макрос, который позволит мне более кратко описать сказанное выше:
(let [callback (result-callback :on-task-data {:keys [context stat]} :ok (swap! *state assoc-in [:tasks context :created-at] (:ctime stat)))])
Я думаю, что приведенная выше форма действительно позволяет нам сосредоточиться на сути.
Вот мой первый шаг в написании такого макроса:
(defn ^:private as-keyword [rc] (-> rc KeeperException$Code/get str str/lower-case keyword)) (defn normalize-result [result] (-> result (update :return-code as-keyword) (cond-> (-> result :data some?) (update :data to-string)))) (defmacro result-callback [tag sym & clauses] `(fn [result#] (let [normalized# (normalize-result result#) ~sym normalized#] (log/trace :event ~tag :result normalized#) (case (:return-code normalized#) ~@clauses ;; Otherwise: (log/error :event ~tag :result normalized#))) nil))
Таким образом, с result-callback
первый аргумент tag
становится ключом :event
в вызовах log/trace
и log/error
. sym
- это локальная переменная, которой будет назначен нормализованный результат (это может быть форма привязки), а предложения - это пары кодов возврата и совпадающих выражений.
Посмотрим, насколько хорошо это работает:
(def test-callback (result-callback :test result :ok (log/info :result result))) => #'user/test-callback (test-callback {:return-code KeeperException$Code/Ok}) => nil 132001.111 TRACE user - {:event :test, :result {:return-code :ok}, :line nil} 132001.111 INFO user - {:result {:return-code :ok}, :line 2}
result-callback
в основном работает правильно: обратный вызов регистрирует результат при входе и отправляет на основе версии ключевого слова кода возврата Ok
. Номер строки для кода внутри обратного вызова правильный, но номер строки для сгенерированного вызова трассировки равен нулю. Куда это делось?
Итак, краткий ответ заключается в том, что макросы потребляют и отбрасывают метаданные в формах, которые они преобразовывают. Код, созданный формой обратной ссылки, вообще не включает никаких метаданных.
Вот в чем уловка: мы собираемся получить метаданные формы (вызов result-callback
) и привязать их к двум вызовам журналирования. Для этого потребуется совсем немного гимнастики:
(defmacro result-callback [tag sym & clauses] (let [m (meta &form) normalized (gensym "normalized")] `(fn [result#] (let [~normalized (normalize-result result#) ~sym ~normalized] ~(with-meta `(log/trace :event ~tag :result ~normalized) m) (case (:return-code ~normalized) ~@clauses ;; Otherwise: ~(with-meta `(log/error :event ~tag :result ~normalized) m))) nil)))
&form
- это специальная переменная внутри макроса: это расширяемая форма, вызов самого result-callback
. Это достаточно хорошая ловушка для :line
метаданных. Заключение вызовов log/trace
и log/error
в with-meta
- это уже упомянутый выше прием; теперь, когда эти макросы рекурсивно раскрываются, они должны сообщить :line
:
(def test-callback (result-callback :test result :ok (log/info :result result))) => #'user/test-callback (test-callback {:return-code KeeperException$Code/Ok}) => nil 133922.258 TRACE user - {:event :test, :result {:return-code :ok}, :line 1} 133922.259 INFO user - {:result {:return-code :ok}, :line 2}
Итак, log/trace
придумал :line 1
, что имеет смысл для кода, вводимого непосредственно в REPL.
Обратите внимание, что вызов with-meta
находится внутри формы ~
: он выполняется во время раскрытия макроса, не во время выполнения кода. Простое использование (with-meta (log/trace ...))
не сработает, поскольку оно расширится до кода, который вызывает log/trace
, а затем применяет метаданные к его возвращаемому значению - нам нужны метаданные в форме log/trace
до log/trace
macro расширяется. Необходимость иметь дело с такого рода различиями - причина первого правила макросов!
В любом случае, теперь мы можем съесть свой пирог и тоже его съесть: мы получаем согласованное ведение журнала и другое поведение с помощью макроса, но мы также получаем точные отчеты о номерах строк. Я ожидал бы использовать эту технику в других местах при тех же условиях: сочетание ведения журнала в сочетании с подробным и повторяющимся шаблоном.
С Clojure всегда есть выход.