Print traces waterfall style to the console

[cjohansen]

When you have multiple levels of tracing telemere's default console logger prints them in the order they are started, which results in traces printing in the reverse order they appear in source code. Maybe telemere could provide a buffering handler that could print traces in a waterfall like how tools such as Jaeger print nested spans in traces?

Here's some code I just wrote:

(defn receive [ctx req]
  (tel/trace!
   ::receive-command
   (let [command (prepare-command req)
         res (validate-command req command)]
     (tel/trace!
      {:id ::validated-command
       :data res}
      (if (:valid? res)
        (let [execution (process-command ctx (:state req) command)]
          (tel/trace!
           {:id ::executed-command
            :data execution}
           (if (:execution/success? execution)
             (:execution/result execution)
             (render-error req 500))))
        (render-error req (:status res)))))))

This prints like so:

14:59:49 INFO TRACE pairsmith.commands[97,6] ::executed-command ...
14:59:49 INFO TRACE pairsmith.commands[97,6] ::validated-command ...
14:59:49 INFO TRACE pairsmith.commands[93,3] ::receive-command ...

I'd like them to print something like this:

14:59:49 INFO TRACE pairsmith.commands[93,3] ::receive-command ...
   14:59:49 INFO TRACE pairsmith.commands[97,6] ::validated-command ...
      14:59:49 INFO TRACE pairsmith.commands[97,6] ::executed-command ...

I'm not exactly sure about the details - e.g. where to indent etc, but seeing them in the order they appear in the code would be helpful, and some visual clues that they are part of the same flow would also be nice.

[ptaoussanis]

@cjohansen Thanks Christian!

I believe this should be pretty easy to add as a generic handler wrapper if anyone felt like submitting a PR.

Basic idea:

1. Take a handler-fn (fn [signal]) -> output
2. Returns a modified handler-fn (fn [signal]) -> output that:
3. Inspects incoming signals to identify "inner" signals (will have :parent and :root keys)
4. Keep a {<root-id> [<signal1> ...]} buffer
5. Once the root signal comes in, flush the buffer by calling the original handler-fn (1) with all signals (4) in reverse order

As a safety might also want to handle the case where (5) never happens by using a max timeout before force flushing. If doing this please use Encore's timer service which is very efficient.

Might be a fun little exercise for a first-time committer, otherwise I'll aim to take care of this myself next time I'm on batched Telemere work.

[cjohansen]

Thanks for the detailed sketch. You're right, it was fairly easy 😊 Here's one attempt:

(defn hold-for-root-trace [handler]
  (let [buffer (volatile! {})]
    (fn [signal]
      (if (:parent signal)
        (vswap! buffer update (:uid (:root signal)) conj signal)
        (handler signal))
      (when-let [buffered (get @buffer (:uid signal))]
        (doseq [signal buffered]
          (handler signal))))))

The hardest part was finding a good name, which I failed to do. This doesn't have the timeout on it, I'll have a look at that.

I wonder if you have thoughts about indenting the output? Since the handlers are side-effecting, I can't really assume anything, so probably the best option would be to pass indent/level information to the handler(?) I did have a go at assuming the handler prints, and this does work when all the stars align:

(defn find-level [id->parent signal]
  (loop [id (:uid (:parent signal))
         level 0]
    (if-let [parent-id (id->parent id)]
      (recur parent-id (inc level))
      level)))

(defn hold-for-root-trace [handler & [{:keys [indent]}]]
  (let [!buffer (volatile! {})
        !id->parent (volatile! {})
        indent (or indent 0)]
    (fn [signal]
      (if (:parent signal)
        (do
          (vswap! !buffer update (:uid (:root signal)) conj signal)
          (vswap! !id->parent assoc (:uid signal) (:uid (:parent signal))))
        (handler signal))
      (when-let [buffered (get @!buffer (:uid signal))]
        (doseq [signal buffered]
          (let [indent-s (apply str (repeat (* indent (find-level @!id->parent signal)) " "))]
            (->> (with-out-str
                   (handler signal))
                 str/split-lines
                 (map #(str indent-s %))
                 (str/join "\n")
                 println)))
        (vswap! !buffer dissoc (:uid signal))
        (vswap! !id->parent (fn [id->parent]
                              (apply dissoc id->parent (:uid signal) (map :uid buffered))))))))

But it's very brute force. Other suggestions?

[ptaoussanis]

You're very welcome!

Some feedback on your implementation (just commenting on hold-for-root-trace):

1. I'd use atom here instead of volatile!. Handlers may be simultaneously called from >1 thread, and there's practically no performance difference - especially relative to the cost of handling a signal.

2. It looks like you're not actually draining the buffer anywhere, so your buffer will grow without bounds. Where you do (let [buffered (get @buffer (:uid signal))] ...) you want to make sure that you actually atomically remove the uid key. You can do that with reset-vals! or (faster) encore/pull-val!.

probably the best option would be to pass indent/level information to the handler(?)

Yes, that's a good idea. If this is a generic handler wrapper, it shouldn't assume anything about the handler - including whether or not the handler even outputs strings. I like your idea of including something like :indent :nest-level in the signal calls, ∈ [0, 1, ...] with 0 for the root uid.

You could then make a higher-level wrapper if you wanted that added string-style indenting based on the nest value.

The hardest part was finding a good name

Something like wrap-handler:parent->child-signals might work. (Telemere already uses the handler:x pattern for handler constructors).

[cjohansen]

It looks like you're not actually draining the buffer anywhere

Ah, my bad. The second longer example does drain the buffer, but I seem to have forgotten it in the trivial example.

Yes, that's a good idea. If this is a generic handler wrapper, it shouldn't assume anything about the handler - including whether or not the handler even outputs strings. I like your idea of including something like :indent :nest-level in the signal calls, ∈ [0, 1, ...] with 0 for the root uid.

Should I just assoc on :nest-level on the signal? Does telemere need to make this "an official thing", or is it fine as part of the handler's contract?

Here's an updated proposal:

(defn find-level [id->parent signal]
  (loop [id (or (:uid (:parent signal))
                (:uid (:root signal)))
         level 0]
    (if-let [parent-id (id->parent id)]
      (recur parent-id (inc level))
      (+ level (if (contains? id->parent id) 1 0)))))

(defn wrap-handler:parent->child-signals [handler]
  (let [!buffer (atom {})
        !id->parent (atom {})]
    (fn [signal]
      (swap! !id->parent assoc (:uid signal) (:uid (:parent signal)))
      (if (:parent signal)
        (swap! !buffer update (:uid (:root signal)) conj signal)
        (handler (assoc signal :nest-level 0)))
      (when-let [buffered (get @!buffer (:uid signal))]
        (doseq [signal buffered]
          (handler (assoc signal :nest-level (find-level @!id->parent signal))))
        (swap! !buffer dissoc (:uid signal))
        (swap! !id->parent (fn [id->parent]
                              (apply dissoc id->parent (:uid signal) (map :uid buffered))))))))

This can be combined with another handler to hack the indentation in place for something that prints to stdout:

(defn indent [n s]
  (->> (str/split-lines s)
       (map #(str (apply str (repeat n " ")) %))
       (str/join "\n")
       println)
  (flush))

(defn wrap-handler:indent-output [handler & [{:keys [indent-w]}]]
  (let [indent-w (or indent-w 4)]
    (fn [signal]
      (->> (with-out-str (handler signal))
           (indent (* indent-w (:nest-level signal 0)))))))

Now this gives me what I originally wanted:

(def handler
  (-> (tel/handler:console
       {:output-fn
        (telutils/format-signal-fn
         {:preamble-fn
          (telutils/signal-preamble-fn
           {:format-inst-fn
            (telutils/format-inst-fn {:formatter hh:mm:ss})})})})
      wrap-handler:indent-output
      wrap-handler:parent->child-signals))

I'd be happy to polish this up and provide a PR, but where should it live? It would also need a timeout.