Clojure: RingでTodoアプリを作る - logging

Advent Calendar 2024 Day 17

昨日でTodoアプリのベースが完成しました。
今日はHttpログを出せるようにしていきます

目標

以下ログを出せるようにしたいと思います

• リクエストログ
  • type("request")
  • timestamp
  • request_uri
  • request_method
• レスポンスログ
  • type("response")
  • timestamp
  • status code
  • request_uri
  • request_method
  • response_time

SLF4J・logback

SLF4J（Simple Logging Facade for Java）は、Javaアプリケーション向けのロギングAPIの統一インターフェースです。

今回は clojure.tools.logging を使うつもりですが、
こちらがSLF4Jに依存しているため、プロジェクトに依存を追加します。

SLF4Jを実装しているバックエンドとして、logback をproject.clj に追加していきます

project.clj

  :dependencies [[org.clojure/clojure "1.11.1"]
                 [...]
                 [ch.qos.logback/logback-classic "1.4.11"]]

これでprojectにlogbackを追加できました

次にlogbackの設定ファイル resources/logback.xml を作成します

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level - %msg%n</pattern>
        </encoder>
    </appender>
    <root level="info">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

2020-01-01 12:00:00 INFO - {"type": "request", ... }

この設定で↑のような形で出力できるはずです

clojure.tools.logging

次にlogを出力するために、clojure.tools.logging を追加します

project.clj

  :dependencies [[org.clojure/clojure "1.11.1"]
                 [...]
                 [ch.qos.logback/logback-classic "1.4.11"]
                 [org.clojure/tools.logging "1.3.0"]]

これでログを出す準備ができました。

ミドルウェアで実装

リクエストログ

もう一度リクエストログの目標を確認します

• リクエストログ
  • type("request")
  • timestamp
  • request_uri
  • request_method

以上を実現するためのミドルウェアを作成してみました。

core.clj

(ns todo.core
  (:require [ring.adapter.jetty :as jetty]
            [ring.util.response :as res]
            [ring.middleware.json :refer [wrap-json-response wrap-json-body]]
            [...]
            [clojure.data.json :as json]
            [clojure.tools.logging :as log]))

(defn- wrap-log-request
  [handler]
  (fn [req]
    (let [current-timestamp (-> (java.time.Instant/now)
                                (.toString))]
      (log/info (json/write-str {:type "request"
                                 :timestamp current-timestamp
                                 :request_uri (:uri req)
                                 :request_method (:request-method req)})))
    (handler req)))

(def handler
  (-> handler'
      (wrap-json-response)
      (wrap-json-body {:keywords? true})
      (wrap-log-request)))

logを出力する部分は clojure.tools.loggingを使用し、
jsonに変換する部分は ring.middleware.json を使いました。

実際にリクエストを送ってみます

$ lein run
2024-12-14 23:50:55 INFO  - {"type":"request","timestamp":"2024-12-14T14:50:55.825355298Z","request_uri":"\/v1\/todos","request_method":"get"

うまくログを出力することができました

レスポンスログ

レスポンスログも一度目標を確認しておきます

• レスポンスログ
  • type("response")
  • timestamp
  • status code
  • request_uri
  • request_method
  • response_time

こちらのログを実現するために先ほど作成したミドルウェアを修正します

core.clj

(ns todo.core
  (:require [ring.adapter.jetty :as jetty]
            [ring.util.response :as res]
            [ring.middleware.json :refer [wrap-json-response wrap-json-body]]
            [...]
            [clojure.data.json :as json]
            [clojure.tools.logging :as log]))

(defn- wrap-log-response
  [handler]
  (fn [req]
    (let [start-time (System/nanoTime)
          response (handler req)
          end-time (System/nanoTime)
          response-time (/ (- end-time start-time) 1e6)
          current-timestamp (-> (java.time.Instant/now)
                                (.toString))]
      (log/info (json/write-str {:type "response"
                                 :timestamp current-timestamp
                                 :status (:status response)
                                 :request_uri (:uri req)
                                 :request_method (:request-method req)
                                 :response_time response-time}))
      response)))

(def handler
  (-> handler'
      (wrap-log-response)
      (wrap-json-response)
      (wrap-json-body {:keywords? true})
      (wrap-log-request)))

こんな感じで実装してみました。

こちらも実際にリクエストを送ってみます

$ lein run
2024-12-15 00:09:09 INFO  - {"type":"response","timestamp":"2024-12-14T15:09:09.195763764Z","status":200,"request_uri":"\/v1\/todos","request_method":"get","response_time":108.078736}

いい感じで出力できました

ライブラリを使う

このライブラリを使っても簡単に実装できます

core.clj

(ns todo.core
  (:require [ring.adapter.jetty :as jetty]
            [ring.util.response :as res]
            [ring.middleware.json :refer [wrap-json-response wrap-json-body]]
            [compojure.core :refer [defroutes GET POST PUT DELETE]]
            [compojure.route :as route]
            [todo.handler :as handler]
            [ring.logger :as logger]))

(def handler
  (-> handler'
      (logger/wrap-log-response)
      (wrap-json-body {:keywords? true})
      (wrap-json-response)
      (logger/wrap-log-request-start)))

(defn -main []
  (jetty/run-jetty handler {:port 3000}))

これでリクエストを送ってみます

$ lein run
2024-12-16 12:13:38 INFO  - {:request-method :get, :uri "/v1/todos", :server-name "localhost", :ring.logger/type :starting}
2024-12-16 12:13:38 INFO  - {:request-method :get, :uri "/v1/todos", :server-name "localhost", :ring.logger/type :finish, :status 200, :ring.logger/ms 126}

いい感じですね

自分で作ってカスタマイズしてもいいし、ライブラリを使っても良さそうです