Макросы, мета и ведение журнала

На протяжении многих лет управления 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/tracemacro расширяется. Необходимость иметь дело с такого рода различиями - причина первого правила макросов!

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

С Clojure всегда есть выход.