Fork me on GitHub
#timbre
<
2023-12-12
>
Eric Dvorsak15:12:52

In my project I am using Timbre and I noticed that manifold exceptions are not being logged. This is what it looks like in a barebone project:

Dec 12, 2023 3:31:40 PM clojure.tools.logging$eval9363$fn__9366 invoke
SEVERE: error in stream handler
java.lang.Exception: Boom
	at manifold.experiment$eval12645$fn__12648.invoke(experiment.clj:16)
	at manifold.stream$map$fn__12300.invoke(stream.clj:624)
	at manifold.stream.Callback.put(stream.clj:457)
	at manifold.stream.graph$async_send.invokeStatic(graph.clj:85)
	at manifold.stream.graph$async_send.invoke(graph.clj:79)
	at manifold.stream.graph$sync_connect$f__10142__auto____11466.invoke(graph.clj:289)
	at clojure.lang.AFn.run(AFn.java:22)
	at io.aleph.dirigiste.Executor$3.run(Executor.java:320)
	at io.aleph.dirigiste.Executor$Worker$1.run(Executor.java:62)
	at manifold.executor$thread_factory$reify__9466$f__9467.invoke(executor.clj:70)
	at clojure.lang.AFn.run(AFn.java:22)
	at java.base/java.lang.Thread.run(Thread.java:829)
Any idea why it doesn't log anything when I have Timbre set up?

1
Peter Taoussanis15:12:51

Hi Eric, as mentioned before - please try to include relevant context with your questions. For example- 1. What version of Timbre are you using? 2. What appender are you using? 3. Have you ruled out the usual things like an insufficient log level, namespace filtering, etc.? Assuming you’re using the println appender on the latest version of Timbre and have ruled out other config issues (for example, by confirming that other standard exceptions log fine with the same config) - I’d check: 1. Do str and println work normally against an example Manifold exception? 2. Does (timbre/default-output-error-fn {:?err <ex>}) work against an example Manifold exception? If not, what error is thrown? If it’s not a config issue, my first guess would be that there’s something in your Manifold exceptions that could be tripping up the default stacktrace rendering (`default-output-error-fn`).

Eric Dvorsak15:12:45

Sorry I was about to submit an example project

Eric Dvorsak15:12:30

I use this code to reproduce:

@(->> (stream/->source [1 2 3])
      (stream/map (fn [x] (println :x-before x) (throw (Exception. "Boom")) (inc x)))
      (stream/consume (fn [x] (println x))))

Eric Dvorsak15:12:37

Version of timbre is latest 6.3.1

Eric Dvorsak15:12:07

And I don't have any config for Timbre in the project so it seems like some lib might be impacting it, I'm adding them one by one to the barebone project to see which one

Eric Dvorsak15:12:12

ok it's fulcro com.fulcrologic/fulcro {:git/url "https://github.com/fulcrologic/fulcro.git" :sha "11a75f8957ec8984559769eca76c2130595e7648"}

Eric Dvorsak16:12:38

log/*config* with fulcro

{:min-level :debug,
 :ns-filter #{"*"},
 :middleware [],
 :timestamp-opts
 {:pattern :iso8601, :locale :jvm-default, :timezone :utc},
 :output-fn #function[taoensso.timbre/default-output-fn],
 :appenders
 {:println
  {:enabled? true,
   :fn
   #function[taoensso.timbre.appenders.core/println-appender/fn--26619]}},
 :_init-config
 {:loaded-from-source [:default],
  :compile-time-config {:min-level nil, :ns-pattern "*"}}}

Eric Dvorsak16:12:00

log/**config** without fulcro

{:min-level :debug,
 :ns-filter #{"*"},
 :middleware [],
 :timestamp-opts
 {:pattern :iso8601, :locale :jvm-default, :timezone :utc},
 :output-fn #function[taoensso.timbre/default-output-fn],
 :appenders
 {:println
  {:enabled? true,
   :fn
   #function[taoensso.timbre.appenders.core/println-appender/fn--16458]}},
 :_init-config
 {:loaded-from-source [:default],
  :compile-time-config {:min-level nil, :ns-pattern "*"}}}

Eric Dvorsak16:12:40

They look exactly the same to me

Eric Dvorsak17:12:20

using clojure -Stree I narroed down to com.taoensso/sente 1.16.2 (it was a transitive dep of fulcro)

Eric Dvorsak17:12:27

So I guess it is that sl4j-api lib

clojure -Stree
org.clojure/clojure 1.11.1
  . org.clojure/spec.alpha 0.3.218
  . org.clojure/core.specs.alpha 0.2.62
com.taoensso/timbre 6.3.1
  . com.taoensso/encore 3.68.0
    . org.clojure/tools.reader 1.3.6 :newer-version
    . com.taoensso/truss 1.11.0
  . io.aviso/pretty 1.4.4
com.taoensso/sente 1.16.2
  . org.clojure/core.async 1.3.610
    . org.clojure/tools.analyzer.jvm 1.1.0
      . org.clojure/tools.analyzer 1.0.0
      . org.clojure/core.memoize 1.0.236
        . org.clojure/core.cache 1.0.207
          . org.clojure/data.priority-map 1.0.0
      . org.ow2.asm/asm 5.2
      X org.clojure/tools.reader 1.3.2 :older-version
  X com.taoensso/encore 3.12.1 :older-version
  . org.java-websocket/Java-WebSocket 1.5.1
    . org.slf4j/slf4j-api 1.7.25
  X org.clojure/tools.reader 1.3.5 :superseded
  X com.taoensso/timbre 5.1.2 :use-top
manifold/manifold 0.4.1
  . org.clojure/tools.logging 1.2.4
  . org.clj-commons/dirigiste 1.0.3
  . riddley/riddley 0.2.0
  . potemkin/potemkin 0.4.6
    . clj-tuple/clj-tuple 0.2.2
    X riddley/riddley 0.1.12 :older-version
```

Eric Dvorsak17:12:41

No timbre:

Dec 12, 2023 6:22:18 PM clojure.tools.logging$eval8532$fn__8535 invoke
SEVERE: error in stream handler
java.lang.Exception: Boom
	at manifold.experiment$eval12890$fn__12893.invoke(experiment.clj:16)
	at manifold.stream$map$fn__11469.invoke(stream.clj:624)
	at manifold.stream.Callback.put(stream.clj:457)
	at manifold.stream.graph$async_send.invokeStatic(graph.clj:85)
	at manifold.stream.graph$async_send.invoke(graph.clj:79)
	at manifold.stream.graph$sync_connect$f__9311__auto____10635.invoke(graph.clj:289)
	at clojure.lang.AFn.run(AFn.java:22)
	at io.aleph.dirigiste.Executor$3.run(Executor.java:320)
	at io.aleph.dirigiste.Executor$Worker$1.run(Executor.java:62)
	at manifold.executor$thread_factory$reify__8630$f__8636.invoke(executor.clj:70)
	at clojure.lang.AFn.run(AFn.java:22)
	at java.base/java.lang.Thread.run(Thread.java:829)
With timbre:
Dec 12, 2023 6:23:22 PM clojure.tools.logging$eval9352$fn__9355 invoke
SEVERE: error in stream handler
java.lang.Exception: Boom
	at manifold.experiment$eval12645$fn__12648.invoke(experiment.clj:16)
	at manifold.stream$map$fn__12300.invoke(stream.clj:624)
	at manifold.stream.Callback.put(stream.clj:457)
	at manifold.stream.graph$async_send.invokeStatic(graph.clj:85)
	at manifold.stream.graph$async_send.invoke(graph.clj:79)
	at manifold.stream.graph$async_connect$this__11451.invoke(graph.clj:220)
	at manifold.stream.graph$async_connect$this__11451.invoke(graph.clj:199)
	at clojure.core$trampoline.invokeStatic(core.clj:6345)
	at clojure.core$trampoline.invoke(core.clj:6334)
	at manifold.stream.graph$async_connect.invokeStatic(graph.clj:194)
	at manifold.stream.graph$async_connect.invoke(graph.clj:133)
	at manifold.stream.graph$connect.invokeStatic(graph.clj:345)
	at manifold.stream.graph$connect.invoke(graph.clj:317)
	at manifold.stream$connect.invokeStatic(stream.clj:333)
	at manifold.stream$connect.invoke(stream.clj:303)
	at manifold.stream$connect_via.invokeStatic(stream.clj:518)
	at manifold.stream$connect_via.invoke(stream.clj:503)
	at manifold.stream$map.invokeStatic(stream.clj:622)
	at manifold.stream$map.invoke(stream.clj:618)
	at manifold.experiment$eval12645.invokeStatic(experiment.clj:16)
	at manifold.experiment$eval12645.invoke(experiment.clj:1)
	at clojure.lang.Compiler.eval(Compiler.java:7194)
	at clojure.lang.Compiler.load(Compiler.java:7653)
	at user$eval9014.invokeStatic(NO_SOURCE_FILE:1)
	at user$eval9014.invoke(NO_SOURCE_FILE:1)
	at clojure.lang.Compiler.eval(Compiler.java:7194)
	at clojure.lang.Compiler.eval(Compiler.java:7149)
	at clojure.core$eval.invokeStatic(core.clj:3215)
	at clojure.core$eval.invoke(core.clj:3211)
	at nrepl.middleware.interruptible_eval$evaluate$fn__1265$fn__1266.invoke(interruptible_eval.clj:87)
	at clojure.lang.AFn.applyToHelper(AFn.java:152)
	at clojure.lang.AFn.applyTo(AFn.java:144)
	at clojure.core$apply.invokeStatic(core.clj:667)
	at clojure.core$with_bindings_STAR_.invokeStatic(core.clj:1990)
	at clojure.core$with_bindings_STAR_.doInvoke(core.clj:1990)
	at clojure.lang.RestFn.invoke(RestFn.java:425)
	at nrepl.middleware.interruptible_eval$evaluate$fn__1265.invoke(interruptible_eval.clj:87)
	at clojure.main$repl$read_eval_print__9206$fn__9209.invoke(main.clj:437)
	at clojure.main$repl$read_eval_print__9206.invoke(main.clj:437)
	at clojure.main$repl$fn__9215.invoke(main.clj:458)
	at clojure.main$repl.invokeStatic(main.clj:458)
	at clojure.main$repl.doInvoke(main.clj:368)
	at clojure.lang.RestFn.invoke(RestFn.java:1523)
	at nrepl.middleware.interruptible_eval$evaluate.invokeStatic(interruptible_eval.clj:84)
	at nrepl.middleware.interruptible_eval$evaluate.invoke(interruptible_eval.clj:56)
	at nrepl.middleware.interruptible_eval$interruptible_eval$fn__1298$fn__1302.invoke(interruptible_eval.clj:152)
	at clojure.lang.AFn.run(AFn.java:22)
	at nrepl.middleware.session$session_exec$main_loop__1368$fn__1372.invoke(session.clj:218)
	at nrepl.middleware.session$session_exec$main_loop__1368.invoke(session.clj:217)
	at clojure.lang.AFn.run(AFn.java:22)
	at java.base/java.lang.Thread.run(Thread.java:829)

Eric Dvorsak17:12:41

Timbre+Sente

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See  for further details.
:x-before 1

Eric Dvorsak17:12:24

Sente with excluded timbre same as above

Eric Dvorsak18:12:19

Fixed by adding org.java-websocket/Java-WebSocket {:mvn/version "1.5.1" :exclusions [org.slf4j/slf4j-api] :comment "fix "} to my project

Peter Taoussanis13:12:26

I’m sorry Eric, but I’m finding it a bit difficult to understand the context here. From your example project, it looks like you’ve got Timbre and Manifold in a project and you’re calling this block of code-

@(->> (stream/->source [1 2 3])
      (stream/map (fn [x] (println :x-before x) (throw (Exception. "Boom")) (inc x)))
      (stream/consume (fn [x] (println x))))
Is that right so far? Then you seem to have Timbre configured with a :debug log level, and Timbre’s println appender. Is that right? So what behaviour are you expecting from the above code block, and what behaviour are you actually seeing? Are you expecting the above code block to log something with Timbre? If so, why would you expect that to happen? I’m not familiar with Manifold but it doesn’t seem to use Timbre. So if you’d want Manifold to do its logging with Timbre, it looks like you’d need to use Timbre’s tools.logging https://github.com/taoensso/timbre/blob/2547283c025173144c1233753960da16b6bac42b/src/taoensso/timbre/tools/logging.clj#L36.

Eric Dvorsak14:12:30

@UASETR481 thanks I'll try that to sum up what I've been doing: • I tried a barebone project with only manifold and made it throw an exception, which got logged • then I added Timbre, it was still logging an exception, better formatted (so Timbre worked out, without any changes at all to config) • then I added Sente, and nothing was logged anymore but there was a WARN about slf4j using NOP, Timbre still had everything default • so I added the JavaWebsocket lib that Sente is using and excluded slf4j-api which it introduced and it got me back to point 2

Eric Dvorsak14:12:07

but I suppose that with your suggestion I potentially don't have to be extra careful about transitive deps introducing slf4j?

Peter Taoussanis14:12:24

then I added Timbre, it was still logging an exception, better formatted (so Timbre worked out, without any changes at all to config)This part doesn’t sound right to me. Manifold https://github.com/clj-commons/manifold/blob/c3fc69066f3abba0b5ab0f4c2b1c4338bcc61d19/project.clj#L7 tools.logging for its logging, so it’s not obvious to me how just adding Timbre as a dependency would cause Manifold to log using Timbre. Timbre doesn’t integrate with tools.logging automatically, so if Timbre’s somehow getting involved - my guess would be that you’ve got some other (possibly transitive) dependency that’s somehow involving Timbre. Anyway, to summarise my current understanding: 1. You want Manifold to do its internal error logging using Timbre 2. It seems that some set of (possibly transitive) dependencies was somehow making that happen automatically 3. But the behaviour seems to be fragile and can be messed up by adding other (possibly transitive) dependencies If that’s accurate, then I’d recommend checking Manifold’s docs to understand how it decides what tool to use for logging. There might be some way to explicitly choose. And it might be that it (or tools.logging) is using some kind of heuristic to try auto select (possibly explaining point 3). You might have luck with explicitly calling https://github.com/taoensso/timbre/blob/2547283c025173144c1233753960da16b6bac42b/src/taoensso/timbre/tools/logging.clj#L36 I linked to before, that’ll cause tools.logging calls to go via Timbre. But I’d also check Manifold’s docs to see what it says about logging.

Eric Dvorsak15:12:51

@UASETR481 so I think you might be right and Timbre is not involved at all. 1. that would be nice since I'm using Timbre in my main project, although my priority is to not lose logs 2 .Sente transitive dependencies were definitely triggering that:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See  for further details.
and as a consequence Manifold was not logging anymore 3. yes exactly

Eric Dvorsak16:12:58

Right so Timbre wasn't really part of the equation, it's really just that Sente was pulling a transitive dependency that brought slf4j in so the bare clojure.logging of manifold stopped working because slf4j was using the NOP logger implementation

👍 1
Eric Dvorsak16:12:39

and use-timbre fixes that 👍 thanks @UASETR481

👍 1
Peter Taoussanis08:12:10

Happy to hear that helped, thanks for following up 👍 Cheers!