Trace with interceptors?

[evaogbe]

How would I use trace with an interceptor?

Interceptors are like the data-driven version of middleware. They separate entering the interceptor from leaving the interceptor and are used as a queue/stack, rather than a wrapping function. Example:

(defn interceptor [x]
  {:enter (fn [ctx] (println "enter " x) ctx)
   :leave (fn [ctx] (println "leave " x) ctx)})

Is it possible to do this with mulog? I could see how to do it with tracing libraries that have a span concept that can be entered and exited, but since mulog uses a binding, I wasn't sure how to make that work.

[BrunoBonacci]

Hi @eoogbe ,

In µ/log traces are just data, with no special feature. The trace coherence is maintained via the :mulog/root-trace and :mulog/parent-trace IDs.

In a traditional call stack you can imagine the trace being organised as:

(u/trace :this-is-the-root []                ;; assume `:mulog/trace-id "TR1"`
  (u/trace :this-is-level1 []                ;; assume `:mulog/trace-id "TR2"`
    (u/trace :this-is-level2 []              ;; assume `:mulog/trace-id "TR3"`
      (u/trace :this-is-level3 []            ;; assume `:mulog/trace-id "TR4"`
        (Thread/sleep 1000)))))

• :this-is-the-root is the root trace, its :mulog/trace-id (TR1) will be passed down as :mulog/root-trace to all nested traces
• :this-is-level1 has:mulog/root-trace "TR1", :mulog/parent-trace "TR1", :mulog/trace-id "TR2"
• :this-is-level2 has:mulog/root-trace "TR1", :mulog/parent-trace "TR2", :mulog/trace-id "TR3"
• :this-is-level3 has:mulog/root-trace "TR1", :mulog/parent-trace "TR3", :mulog/trace-id "TR4"

Notice as you go down in the nested traces, each trace uses the same :mulog/root-trace and the :mulog/parent-trace with the id of the level above.

If you have async operations, or operations which span process boundaries, all you need is to propagate the :mulog/root-trace and the :mulog/parent-trace to the next level.

So for example, if you want to nest under an existing span, all you need to do in your handler function is:

;; nest under the root-trace "foo" and the span "bar"
(u/with-context {:mulog/root-trace "foo" :mulog/parent-trace "bar"}
  (u/trace :nested-trace
  []
  (Thread/sleep 1000)))

in order to set the correct values for :mulog/root-trace and :mulog/parent-trace you can use the interceptors for example to grab the info from request headers and so on.

(def trace-interceptor
  (interceptor
    {:name ::mulog-trace-interceptor 
     :enter (fn [context]
              (assoc context :mulog/context (decode-trace-id-from-headers context))) 
     :leave identity}))

and handler

(defn handler [req]
  (u/with-context (get req :mulog/context {})
    (u/trace :nested-trace
    []
    (Thread/sleep 1000))))

I hope this help.

[evaogbe]

Thanks for the speedy response!

IIUC your example would require wrapping every handler in a function. Like if I had 2 handlers, it would look like:

(defn handler1 [req]
  (u/with-context (get req :mulog/context {})
    (u/trace :nested-trace
    []
    (Thread/sleep 1000))))

(defn handler2 [req]
  (u/with-context (get req :mulog/context {})
    (u/trace :nested-trace
    []
    (Thread/sleep 2000))))

And then I'd want to remove the duplication by doing something like:

(defn wrap-trace
  [handler]
  (fn [req]
  (u/with-context (get req :mulog/context {})
    (u/trace :nested-trace
    []
    (handler req))))

(def handler1
  (wrap-trace (fn [_req] (Thread/sleep 1000)))

But that's middleware again. It seems to add an interceptor to middleware instead of replacing middleware entirely. I like that it gives more flexibility in where the middleware can go.

Is there a way to do tracing completely without middleware?

[BrunoBonacci]

Hi @eoogbe

it is not required to wrap the handlers if you don't care about the nested traces which once the handler function is called they live on the stack and no longer in the interceptor.

in that case you can do as follow:

(ns mulog-interceptor.core
  (:require [io.pedestal.http :as http]
            [io.pedestal.http.route :as route]
            [io.pedestal.interceptor :as i]
            [com.brunobonacci.mulog :as u]
            [com.brunobonacci.mulog.core :as uc]
            [com.brunobonacci.mulog.flakes :as f])
  (:gen-class))

(def timing-interceptor
  (i/interceptor
    {:name ::timing
     :enter
     (fn [context]
       (let [tid (f/flake)]
         (assoc context :mulog
           {:mulog/root-trace tid
            :mulog/parent-trace nil
            :mulog/trace-id tid
            :mulog/timestamp (System/currentTimeMillis)
            :mulog/timer (System/nanoTime)})))

     :leave
     (fn [context]
       (let [timer-stop (System/nanoTime)
             mulog (:mulog context)
             timer-start (:mulog/timer mulog)
             mulog (-> mulog (dissoc :mulog/timer)
                     (assoc :mulog/duration (- timer-stop timer-start)))
             ;; logging request info
             request  (select-keys (:request context) [:path-info :request-method])
             ;; logggin response ingo
             response (select-keys (:response context) [:status])
             log-data (merge request response mulog)]
         (uc/log* uc/*default-logger* :http-request (mapcat seq log-data))
         (dissoc context :mulog)))}))

(defn respond-hello [context]
  (Thread/sleep ^long (rand-int 1000))
  {:status 200 :body "Hello, world!"})

(def routes
  (route/expand-routes
    #{["/greet" :get [timing-interceptor respond-hello] :route-name :greet]}))

(defn create-server []
  (http/create-server
    {::http/routes routes
     ::http/type :jetty
     ::http/join? false
     ::http/port 8890}))

(defn start []
  (http/start (create-server)))

(defn -main []
  (start)
  (u/start-publisher! {:type :console :pretty? true})
  (println "Server started at: http://localhost:8890/")
  @(promise))

if you start this and run: $ curl http://localhost:8890/greet then you'll get a event like:

{:mulog/event-name :http-request,
 :mulog/timestamp 1716914281020,
 :mulog/trace-id #mulog/flake "4xDoRHMvpqu2BWdisxaVQhtCqN61lqEN",
 :mulog/root-trace #mulog/flake "4xDoRHMvpqu2BWdisxaVQhtCqN61lqEN",
 :mulog/duration 660880208,
 :path-info "/greet",
 :request-method :get,
 :status 200}

This solution would track all the API requests where this interceptor is used. I hope this help.

[evaogbe]

Thank you! This helps me understand how tracing works better. I'm glad it's possible to do it as an interceptor. I think I will stick to middleware for logging since I can use with-context and the setup is less involved. Love this library though! Data-oriented Clojure libs are my jam

[BrunoBonacci]

Glad to help.