Clojurians Log v2

@devurandom Hi Dennis! > However, during startup I still see DEBUG level messages from the OpenTelemetry Java agent. Just to confirm: is this output actually being generated by Timbre? (You should be able to tell by the format of the output)

Yes, we set OTEL_JAVAAGENT_LOGGING="application" so that the agent's logs would flow via SLF4J through Timbre. The output format matches between native Timbre logs from our app and those from the agent. Example (last log line of the agent before we call taoensso.timbre/merge-config! and first log line of our app):

2025-01-10T12:45:03.468Z 748cac9f51c0 DEBUG [io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener] - Transformed taoensso.encore$fn__8836$merge_with_STAR___8842$fn__8847 -- jdk.internal.loader.ClassLoaders$AppClassLoader@7e4c72d6
2025-01-10T12:45:03.481Z 748cac9f51c0 INFO [myns.logging:162] - Logging configured to [...]

So I’m not sure I fully understand your example output there, but in principle - if: 1. The relevant output is all being generated by Timbre handlers only, and 2. The output you’re seeing is at DEBUG level, and 3. You have TAOENSSO_TIMBRE_MIN_LEVEL_EDN set to :info for the relevant classes at the relevant time Then I would expect NO such output. Can’t think of any obvious reason why you’d still be seeing output, so I’d start by double checking that (1), (2), and (3) are all true. For (1) and (2) you could check by looking for the offending log call in your handler fn or via handler middleware. For (3) you could maybe try print the (get timbre/*config* :min-level) sometime before you call merge-config!. I.e. you want to confirm that your environmental config (min level) is being picked up correctly. You mentioned an uberjar, and I wonder if maybe that’s being compiled without the environmental config that you expect?

Thanks for taking the time to gives such detailed answer. Much appreciated! > The relevant output is all being generated by Timbre handlers only, and The OTel agent allegedly logs via SLF4J to the application when https://opentelemetry.io/docs/zero-code/java/agent/configuration/#java-agent-logging-output. Does com.taoensso/timbre-slf4j satisfy "output is all being generated by Timbre handlers"? > You mentioned an uberjar, and I wonder if maybe that’s being compiled without the environmental config that you expect? Does compiling the uberjar persist the value of TAOENSSO_TIMBRE_MIN_LEVEL_EDN into the JAR? Does that mean the value of TAOENSSO_TIMBRE_MIN_LEVEL_EDN at runtime is ignored? Or are both in effect: the value at compile time elides log calls from ever being made, but the value at runtime still omits the output if such calls are made?

Thanks for taking the time to gives such detailed answer. Much appreciated!

I printed timbre/*config* and found this in the the map: :compile-time-config {:min-level [:timbre/invalid-min-level {:value [[#{timbre-slf4j-otel-agent-mwe.*} :debug] [#{*} :info]], :type clojure.lang.PersistentVector}], :ns-pattern *}} However, I don't see the difference to the example in https://github.com/taoensso/timbre/blob/49c5de43e5bfe2e2d71dcdbace7ef0fa816e56d6/src/taoensso/timbre.cljc#L1140. I set it like this both during build and at runtime:

export TAOENSSO_TIMBRE_MIN_LEVEL_EDN='[[#{"timbre-slf4j-otel-agent-mwe.*"} :debug][#{"*"} :info]]'

Thanks for that, that was helpful! Looks like the compile-time min-level doesn’t currently support this kind of ns-specific syntax. That’s definitely not clear, and might not even be intentional. Will take a look at this tomorrow morning and come back to you!

If it’s an oversight, will get it fixed tomorrow morning. Otherwise will come back with an alternative suggestion 👍

Apologies for the trouble!

It’s also not ideal that this didn’t produce a clear error message right away.

I managed to create a minimal reproduction (https://github.com/devurandom/timbre-slf4j-otel-agent-mwe) and found some helpful knobs along the way which I documented on https://github.com/taoensso/timbre/wiki/4-Interop. • I managed to verify that (3) does not work as I expected it (`TAOENSSO_TIMBRE_MIN_LEVEL_EDN=[[,,,]]` as documented for taoensso.timbre/*config*). I adjusted it to what Timbre actually needs (`...=:info`) , but that did not change the behaviour. • I managed to verify (1) and (2) by abusing some odd behaviour of this specific MWE, where the Java agent's logs are not actually processed until I interact with SLF4J from my application, to delay processing of the OTel Java agent's log messages until after Timbre is initialized. Sadly that will not work for my actual implementation, where libraries already call SLF4J much earlier.

My hypothesis so far: To affect the Java agent's log output, I need a way to pass the min-level configuration to Timbre or com.taoensso.timbre.slf4j.TimbreServiceProvider right from the start, i.e. before we even enter -main, i.e. through some env var or Java system property. TAOENSSO_TIMBRE_MIN_LEVEL_EDN=:info appears to be ignored?

To affect the Java agent’s log output, I need a way to pass the min-level configuration to Timbre or com.taoensso.timbre.slf4j.TimbreServiceProvider right from the start, i.e. before we even enter -main, i.e. through some env var or Java system property.

Apologies for not getting back to you on Saturday, had some unexpected personal stuff come up. I’ve just pushed 2x commits related to this: • Throw on invalid compile-time level (https://github.com/taoensso/timbre/commit/a393582b5d90ef019f9e47e1f3fcb16c2c23ff3a) • Mention limitation on compile-time min-level (https://github.com/taoensso/timbre/commit/b97ad9826ffcb9446dea140c6852e599b553c20c) There’s more info in the commit messages.

> So to confirm: > 1. You’ve printed (get timbre/config :min-level) early in your application code - before any call to merge-config! and confirmed that you’re seeing :info? I moved the println in https://github.com/devurandom/timbre-slf4j-otel-agent-mwe in -main to before I even log/info the first time and got this:

>>> COMPILE-TIME CONFIG {:min-level :debug, :ns-filter #{*}, :middleware [], :timestamp-opts {:pattern :iso8601, :locale :jvm-default, :timezone :utc}, :output-fn #object[taoensso.timbre$default_output_fn 0x9a38c90 taoensso.timbre$default_output_fn@9a38c90], :appenders {:println {:enabled? true, :fn #object[taoensso.timbre.appenders.core$println_appender$fn__3477 0x245a06f4 taoensso.timbre.appenders.core$println_appender$fn__3477@245a06f4]}}, :_init-config {:loaded-from-source [:default], :compile-time-config {:min-level :info, :ns-pattern *}}}

Notice how -> :_init-config :compile-time-config :min-level and -> :min-level disagree.

I’ll note that the naming used (e.g. TAOENSSO_TIMBRE_MIN_LEVEL_EDN) doesn’t make this behaviour very clear! It’s a totally understandable confusion. Telemere improves on this by offering separate environmental config options for: • taoensso.telemere/ct-min-level ; compile-time min-level • taoensso.telemere/rt-min-level ; runtime min-level • etc.

BTW TAOENSSO_TIMBRE_CONFIG_EDN also provides an answer for how you can configure Timbre’s initial handlers, etc.

Thanks, that solved my problem! I should have read this part more carefully: > Its default value can be easily overridden by:| > • A JVM property, environment variable, or edn file on your resource path (see config docstring for details). > (https://github.com/taoensso/timbre/wiki/1-Getting-started#configuration) Fix for the minimal example: https://github.com/devurandom/timbre-slf4j-otel-agent-mwe/commit/6d2b3692e1551d80128d68a559af8fa07c98e20e

Excellent, thanks for the confirmation 🙏

Thanks a lot for your patience and help!