viesti / timbre-json-appender

JSON appender for Timbre
MIT License
44 stars 11 forks source link

Extra stack trace lines when using ex-info #28

Closed NoahTheDuke closed 1 year ago

NoahTheDuke commented 1 year ago

Hey there!

When using ex-info, the first couple lines of the stack trace are from this line.

Example:

(let [ex (ex-info "asdf" {})]
  (timbre/error ex "asdf"))

{"dd.trace_id":"0","dd.span_id":"0","ns":"example.config","file":"/home/noah/personal/demo/src/example/config.clj","err":{"via":[{"type":"clojure.lang.ExceptionInfo","message":"asdf","data":{},"at":["timbre_json_appender.core$process_ex_data_map","invokeStatic","core.clj",100]}],"trace":[["timbre_json_appender.core$process_ex_data_map","invokeStatic","core.clj",100],["timbre_json_appender.core$process_ex_data_map","invoke","core.clj",97],["clojure.core$partial$fn__5908","invoke","core.clj",2641],["timbre_json_appender.core$json_appender$fn__29908","invoke","core.clj",125],["taoensso.timbre$_log_BANG_fn__24565","invoke","timbre.cljc",684],["clojure.lang.PersistentArrayMap","kvreduce","PersistentArrayMap.java",429],["clojure.core$fn__8525","invokeStatic","core.clj",6908],["clojure.core$fn__8525","invoke","core.clj",6888],["clojure.core.protocols$fn__8257$G__8252__8266","invoke","protocols.clj",175],["clojure.core$reduce_kv","invokeStatic","core.clj",6919],["clojure.core$reduce_kv","invoke","core.clj",6910],["taoensso.timbre$_log_BANG_","invokeStatic","timbre.cljc",628],["taoensso.timbre$_log_BANG_","invoke","timbre.cljc",540],["example.config$eval80065","invokeStatic","form-init17595965402220594328.clj",118],["example.config$eval80065","invoke","form-init17595965402220594328.clj",117],

That's a lot of stack to get through before reaching the place where I've thrown the exception. Compare this to using an Exception.:

{"dd.trace_id":"0","dd.span_id":"0","ns":"example.config","file":"/home/noah/personal/demo/src/example/config.clj","err":{"via":[{"type":"java.lang.Exception","message":"asdf","at":["example.config$eval80069","invokeStatic","form-init17595965402220594328.clj",117]}],"trace":[["example.config$eval80069","invokeStatic","form-init17595965402220594328.clj",117],["example.config$eval80069","invoke","form-init17595965402220594328.clj",117],

(My apologies, if I make it a code block, there are no line breaks :sob:)

This comes from creating a new ex-info when passed an ex-info. A solution is to overwrite the stack trace with the one from the passed-in ex:

(defn- process-ex-data-map [ex-data-field-fn ex]
  (if (and ex (instance? ExceptionInfo ex))
    (let [cause (process-ex-data-map ex-data-field-fn (ex-cause ex))
          new-ex (ex-info (ex-message ex)
                          (into {} (map (fn [[k v]] {k (ex-data-field-fn v)}) (ex-data ex)))
                          cause)]
      (.setStackTrace ^ExceptionInfo new-ex (.getStackTrace ^ExceptionInfo ex))
      new-ex)
    ex))

Nothing else changes, which I think is pretty cool. I don't know a lot about how Java's nested exceptions work, but given the quality of life improvement here, I feel like making this change is worth it.

If you agree, I can open a PR with this fix.

viesti commented 1 year ago

Oof! An excellent find! In hindsight, it should have been obvious that when re-creating an Exception, the original stack trace should have been kept intact, doh! Thank you! :)