Allow usage of trace duration after trace is done

[MrEbbinghaus]

Hey,

I would like to use the duration that I already track in the Server-Timing header of a request.

(µ/trace :handle-request
  {:pairs [...]
   :capture (fn [{:keys [status]}] {:http-status status})
   :update (fn [response event]
             (update response :headers 
               assoc "Server-Timing" (str "handler;dur=" (/ (:µ/duration event) 1e6)))}
  (handle request))

Is this somehow possible? (This is somewhat related to: https://github.com/BrunoBonacci/mulog/issues/126)

Do you have a recommendation how this could be achieved?

---

Going further, it would be great if there was a way to get all the events that happened in some context. I think this needs to be approached by a publisher that captures the events, groups them by µ/root-trace like so: (alternatively, one could register a temporary publisher just for a trace, which is related to https://github.com/BrunoBonacci/mulog/issues/121)

(def trace-store* (atom {})

(deftype MyCustomPublisher [buffer transform]
  com.brunobonacci.mulog.publisher.PPublisher
  (agent-buffer [_] buffer)
  (publish-delay [_] 200)

  (publish [_ buffer]
    (doseq [event (rb/items buffer)
            :when (:capture-traces? event)]
      (when-some [root-trace-id (:µ/root-trace event)]
        (swap! trace-store* update root-trace-id conj event)))
    (rb/clear buffer)))

(defn my-custom-publisher
  [config]
  (let [config (update config :transform (fn [f] (or f identity)))]
    (MyCustomPublisher. config (rb/agent-buffer 10000))))

(defn pop-trace! [trace-id]
  (when-some [events (get @trace-store* trace-id)]
    (swap! trace-store* dissoc trace-id)
    events))

(defn format-entry [event]
  (str (name (:server-timing/name event)) ";dur=" (/ (:µ/duration event) 1e6)))

(defn query    [req]  (µ/trace :query    [:server-timing/name "query"] ...))
(defn process  [data] (µ/trace :process  [:server-timing/name "process"] ...))
(defn transact [data] (µ/trace :transact [:server-timing/name "transact"] ...))

(defn handle [req]
  (let [data               (query req)
        processed-data     (process data)
        transaction-result (transact processed-data)]
    {:status 200
     :headers {"Content-Type" "whatever"}
     :body ...}))

(µ/trace :some-request {}
  (let [response (µ/with-context {:capture-traces? true}
                   (handle request)
        events (pop-trace! (:µ/root-trace (µ/local-context)))
        server-timing-events (filter :server-timing/name events)]

    (->> server-timing-events
      (map format-entry)
      (str/join ", ")
      (update response assoc "Server-Timing")))

; => {:status 200
;     :headers {"Content-Type" "whatever"
;               "Server-Timing" "query;dur=23, process;dur=3, transact;dur=34.5"}
;     :body ...}

[BrunoBonacci]

Hi @MrEbbinghaus,

I've been reflecting on this request a bit, and here is my thoughts so far.

µ/log is designed to be as transparent as possible to the application flow. As one would expect it logging/tracing (or any type of metering) should not alter the application flow in any (significant) way. So you would expect that the application behaves the same whether the log is activated or not, or whether the logging is present or not.

Providing explicit access to the log event in the application flow would significantly break this assumption. The other consideration is that, as stated on the main page of the doc:

Event logs are useful, but not as important as process flow (therefore preferable to drop events rather than crashing the process)

logs (and traces) are not guaranteed. µ/log does its best to collect and dispatch the events to their destination, but it is not guaranteed that it will succeed. Therefore exposing events that might not even reach the final system of records would potentially cause non-guaranteed behavior in the application.

Not knowing why and how the trace duration would be used in your case, I would probably suggest that if you need to use the duration for any reason it is best that you record outside of µ/log and pass it as a value like you would do with any other values.

;; example
(let [start (System/nanoTime)
      result (do #_something)
      stop (System/nanoTime) 
      _ (µ/log ::my-event :duration (- stop start)]
  result)

If the purpose of retrieving the duration is to send it to another system then the publisher seems the right avenue.

Using the publisher to annotate a response from a server request, won't work because µ/log processing is entirely asynchronous so the only choice is to capture the information yourself.

Sorry, but I don't think this would be a good addition to the library, while this use case is certainly valid, it doesn't fit with the general design goals I have set out for µ/log.

[MrEbbinghaus]

@BrunoBonacci I agree, the code should run as if mulog wasn't there.

And I'm happy to have a library that prioritises good practices over convenience.

"Just because I could, doesn't mean I should."