timbre
timbre copied to clipboard
taoensso
Printing a stack trace should show details for the "cause" Exceptions too
The following neatly formatted stack trace printed by Timbre shows no trace of my own code, which makes it useless for figuring out where an error is happening.
java.lang.Thread.run Thread.java: 834
java.util.concurrent.ThreadPoolExecutor$Worker.run ThreadPoolExecutor.java: 628
java.util.concurrent.ThreadPoolExecutor.runWorker ThreadPoolExecutor.java: 1128
jdk.internal.net.http.Http1Exchange.lambda$cancelImpl$9 Http1Exchange.java: 473
java.util.concurrent.CompletableFuture.completeExceptionally CompletableFuture.java: 2088
java.util.concurrent.CompletableFuture.postComplete CompletableFuture.java: 506
java.util.concurrent.CompletableFuture$UniHandle.tryFire CompletableFuture.java: 907
java.util.concurrent.CompletableFuture.uniHandle CompletableFuture.java: 930
jdk.internal.net.http.MultiExchange.lambda$responseAsyncImpl$7 MultiExchange.java: 339
jdk.internal.net.http.MultiExchange.getExceptionalCF MultiExchange.java: 412
jdk.internal.net.http.MultiExchange.toTimeoutException MultiExchange.java: 463
java.net.ConnectException: HTTP connect timed out
java.net.http.HttpConnectTimeoutException: HTTP connect timed out
java.net.http.HttpConnectTimeoutException: HTTP connect timed out
But when I call a normal Java .printStackTrace, I see my own code in the details for one of the java.net.http.HttpConnectTimeoutExceptions
@peterlindstrom123 Hi there!
Could you please try provide a minimum reproducible example?
With the default config in v4.10.0 I'm seeing causes displayed as expected:
(timbre/error (ex-info "Ex.1" {} (ex-info "Ex.2" {} (ex-info "Ex.3" {}))) "Foo") ; =>
Sep 12 15:49 Schrebermann.local ERROR [taoensso.timbre:804] - Foo
nrepl.middleware.interruptible-eval/evaluate/fn interruptible_eval.clj: 91
clojure.core/eval core.clj: 3214
...
taoensso.timbre/eval14635 REPL Input
taoensso.timbre/-log! timbre.clj: 358
clojure.core/deref core.clj: 2320
...
taoensso.timbre/eval14635/fn REPL Input
clojure.lang.ExceptionInfo: Ex.3
clojure.lang.ExceptionInfo: Ex.2
clojure.lang.ExceptionInfo: Ex.1
Thanks!
Hi,
I'm not sure what you mean.
Is all of this output related to Ex.3?
nrepl.middleware.interruptible-eval/evaluate/fn interruptible_eval.clj: 91
clojure.core/eval core.clj: 3214
...
taoensso.timbre/eval14635 REPL Input
taoensso.timbre/-log! timbre.clj: 358
clojure.core/deref core.clj: 2320
...
taoensso.timbre/eval14635/fn REPL Input
?
If that's correct, then as far as I can tell, my problem was that no source files or line numbers are mentioned for Ex.2 or Ex.1. A normal Java stack trace would show them all.
Obviously the details for all of the source exceptions are relevant?
Yeah, hiding the chain of traces is a big mistake. I believe https://github.com/AvisoNovate/pretty is the culprit really. To deal with this I had to create my own :output-fn which basically uses clojure.stacktrace/print-cause-trace.
Just to follow-up on this- I'm still not completely clear on what's being requested here.
It'd be helpful to have the following:
- An example that I can run at the REPL
- What output you're seeing
- What output you'd rather see
Thanks!
Of course this is pointless here in this example, but in other cases the exception and the cause traces are both actually needed. Compare:
user> (clojure.stacktrace/print-cause-trace (Exception. "hi" (Exception. "cause")))
java.lang.Exception: hi
at user$eval11357.invokeStatic (NO_SOURCE_FILE:1)
user$eval11357.invoke (NO_SOURCE_FILE:1)
clojure.lang.Compiler.eval (Compiler.java:7194)
clojure.lang.Compiler.eval (Compiler.java:7149)
clojure.core$eval.invokeStatic (core.clj:3215)
clojure.core$eval.invoke (core.clj:3211)
nrepl.middleware.interruptible_eval$evaluate$fn__1245$fn__1246.invoke (interruptible_eval.clj:87)
clojure.lang.AFn.applyToHelper (AFn.java:152)
clojure.lang.AFn.applyTo (AFn.java:144)
clojure.core$apply.invokeStatic (core.clj:667)
clojure.core$with_bindings_STAR_.invokeStatic (core.clj:1990)
clojure.core$with_bindings_STAR_.doInvoke (core.clj:1990)
clojure.lang.RestFn.invoke (RestFn.java:425)
nrepl.middleware.interruptible_eval$evaluate$fn__1245.invoke (interruptible_eval.clj:87)
clojure.main$repl$read_eval_print__9206$fn__9209.invoke (main.clj:437)
clojure.main$repl$read_eval_print__9206.invoke (main.clj:437)
clojure.main$repl$fn__9215.invoke (main.clj:458)
clojure.main$repl.invokeStatic (main.clj:458)
clojure.main$repl.doInvoke (main.clj:368)
clojure.lang.RestFn.invoke (RestFn.java:1523)
nrepl.middleware.interruptible_eval$evaluate.invokeStatic (interruptible_eval.clj:84)
nrepl.middleware.interruptible_eval$evaluate.invoke (interruptible_eval.clj:56)
nrepl.middleware.interruptible_eval$interruptible_eval$fn__1278$fn__1282.invoke (interruptible_eval.clj:152)
clojure.lang.AFn.run (AFn.java:22)
nrepl.middleware.session$session_exec$main_loop__1348$fn__1352.invoke (session.clj:218)
nrepl.middleware.session$session_exec$main_loop__1348.invoke (session.clj:217)
clojure.lang.AFn.run (AFn.java:22)
java.lang.Thread.run (Thread.java:833)
Caused by: java.lang.Exception: cause
at user$eval11357.invokeStatic (NO_SOURCE_FILE:1)
user$eval11357.invoke (NO_SOURCE_FILE:1)
clojure.lang.Compiler.eval (Compiler.java:7194)
clojure.lang.Compiler.eval (Compiler.java:7149)
clojure.core$eval.invokeStatic (core.clj:3215)
clojure.core$eval.invoke (core.clj:3211)
nrepl.middleware.interruptible_eval$evaluate$fn__1245$fn__1246.invoke (interruptible_eval.clj:87)
clojure.lang.AFn.applyToHelper (AFn.java:152)
clojure.lang.AFn.applyTo (AFn.java:144)
clojure.core$apply.invokeStatic (core.clj:667)
clojure.core$with_bindings_STAR_.invokeStatic (core.clj:1990)
clojure.core$with_bindings_STAR_.doInvoke (core.clj:1990)
clojure.lang.RestFn.invoke (RestFn.java:425)
nrepl.middleware.interruptible_eval$evaluate$fn__1245.invoke (interruptible_eval.clj:87)
clojure.main$repl$read_eval_print__9206$fn__9209.invoke (main.clj:437)
clojure.main$repl$read_eval_print__9206.invoke (main.clj:437)
clojure.main$repl$fn__9215.invoke (main.clj:458)
clojure.main$repl.invokeStatic (main.clj:458)
clojure.main$repl.doInvoke (main.clj:368)
clojure.lang.RestFn.invoke (RestFn.java:1523)
nrepl.middleware.interruptible_eval$evaluate.invokeStatic (interruptible_eval.clj:84)
nrepl.middleware.interruptible_eval$evaluate.invoke (interruptible_eval.clj:56)
nrepl.middleware.interruptible_eval$interruptible_eval$fn__1278$fn__1282.invoke (interruptible_eval.clj:152)
clojure.lang.AFn.run (AFn.java:22)
nrepl.middleware.session$session_exec$main_loop__1348$fn__1352.invoke (session.clj:218)
nrepl.middleware.session$session_exec$main_loop__1348.invoke (session.clj:217)
clojure.lang.AFn.run (AFn.java:22)
java.lang.Thread.run (Thread.java:833)
i.e. both traces vs.
2022-03-23T05:54:54.850Z bullseyeclub-5006 DEBUG [user:61] -
nrepl.middleware.interruptible-eval/evaluate/fn interruptible_eval.clj: 87
...
clojure.core/with-bindings* core.clj: 1990 (repeats 2 times)
clojure.core/apply core.clj: 667
...
nrepl.middleware.interruptible-eval/evaluate/fn/fn interruptible_eval.clj: 87
clojure.core/eval core.clj: 3215
...
user$eval11359.invoke NO_SOURCE_FILE: 61
user$eval11359.invokeStatic NO_SOURCE_FILE: 61
taoensso.timbre/-log! timbre.cljc: 534
clojure.core/deref core.clj: 2337
...
user$eval11359$fn__11360.invoke NO_SOURCE_FILE: 61
java.lang.Exception: cause
java.lang.Exception: hi
..which has only one of the traces.
@lnostdal Hi Lars, thanks for the clear example! Apologies for the delay replying. This does indeed appear to be the current behaviour of https://github.com/AvisoNovate/pretty.
A couple possibilities:
- [Immediate workaround]
alter-var-rootcould be used to change the defaultstacktracefn. - [Future Timbre version]
default-output-fncould be given an option to specify a different/custom stacktrace fn.
How does (2) sound? Would also be open to ideas re: alternative stracktrace implementations!
Cheers :-)
Hi there! I'm doing something similar to nr. 1 now - but nr. 2 seems like a better idea.
I don't know about alternatives to the pretty printing done by aviso, but this stacktrace stuff was so important to me I wanted all the details and even noise no matter what - so I just ended up doing: (with-out-str (clojure.stacktrace/print-cause-trace err))
Great, thanks for the feedback @lnostdal.
@lnostdal @peterlindstrom123 An :error-output-fn option will be added to default-output-fn in a forthcoming release. This'll allow one to easily swap in an alternative stacktrace implementation 👍