Noisy Netty logs show up after adopting this library

[vemv]

Hi there,

this library works as intended. Kudos!

However I noticed this relatively minor nuisance at startup (e.g. lein repl):

18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.logging.InternalLoggerFactory:71] - Using SLF4J as the default logging framework
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent0:76] - java.nio.Buffer.address: available
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent0:76] - sun.misc.Unsafe.theUnsafe: available
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent0:71] - sun.misc.Unsafe.copyMemory: available
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent0:76] - java.nio.Bits.unaligned: true
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - Java version: 8
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.noUnsafe: false
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - sun.misc.Unsafe: available
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.noJavassist: false
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:71] - Javassist: available
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.tmpdir: /var/folders/2j/336sh1s13jv80nmvg2y5gyc80000gp/T (java.io.tmpdir)
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.bitMode: 64 (sun.arch.data.model)
18-12-22 01:10:57 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.noPreferDirect: false
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.logging.InternalLoggerFactory:71] - Using SLF4J as the default logging framework
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent0:76] - java.nio.Buffer.address: available
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent0:76] - sun.misc.Unsafe.theUnsafe: available
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent0:71] - sun.misc.Unsafe.copyMemory: available
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent0:76] - java.nio.Bits.unaligned: true
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - Java version: 8
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.noUnsafe: false
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - sun.misc.Unsafe: available
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.noJavassist: false
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:71] - Javassist: available
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.tmpdir: /var/folders/2j/336sh1s13jv80nmvg2y5gyc80000gp/T (java.io.tmpdir)
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.bitMode: 64 (sun.arch.data.model)
18-12-22 01:11:33 UnknownHost DEBUG [io.netty.util.internal.PlatformDependent:76] - -Dio.netty.noPreferDirect: false

...those lines didn't show up before slf4j-timbre adoption. From what I can see, Netty has the following static code which will run merely by being imported: https://github.com/netty/netty/blob/6464c98743779778e52db59522f269bfe47a46af/common/src/main/java/io/netty/util/internal/PlatformDependent.java#L92

So, in the average project that uses both Netty and Timbre, it's much more likely that Netty will be imported before Timbre is setup, which would be the place to silence this annoyance.

Is this a known scenario?

I tried solving it with :jvm-opts ["-Dorg.slf4j.simpleLogger.defaultLogLevel=WARN"], no luck. Another one was (-> (Logger/getLogger "io.netty.util.internal.PlatformDependent") (.setLevel Level/OFF)) in user.clj.

Thanks - Victor

[vemv]

Just tried export TIMBRE_LEVEL=":warn" as well... nope

[rufoa]

Thanks for the thorough report!

This looks similar to #21 (comment)

Strange that none of those things you tried worked. I assumed they would resolve this but I never actually checked at the time

[rufoa]

I think taoensso.timbre/-elide? and/or taoensso.timbre/may-log? might be misbehaving when used with our lib

This should cause our tests to fail but it doesn't:

$ TIMBRE_LEVEL=':warn' lein midje
Compile-time (elision) Timbre level: :warn
nil
All checks (114) succeeded.

[vemv]

Good that you post that, I was about to create a new issue (which would need a separate repo/repro):

logs that are successfully re-routed via slf4j-timbre are unconditionally logged, i.e. :min-level is ignored.

For proof I added <<<<level>>>> to a custom output-fn. It shows that Timbre is receiving correct level values, but ignoring them for some reason.

18-12-22 15:37:36 INFO <<<<<:info>>>>>[datomic.process-monitor:43] - {:MetricsReport {:lo 1, :hi 1, :sum 1, :count 1}, :AvailableMB 6360.0, :event :metrics, :pid 30261, :tid 56}
18-12-22 15:37:36 DEBUG <<<<<:debug>>>>>[datomic.process-monitor:44] - {:event :metrics/report, :phase :begin, :pid 30261, :tid 56}
18-12-22 15:37:36 DEBUG <<<<<:debug>>>>>[datomic.process-monit...

[rufoa]

It looks like Timbre's compile-time elision is not working with slf4j-timbre.

This is because:

• Logging calls are elided at macro-expansion time based on the value of TIMBRE_LEVEL
• Because slf4j-timbre is AOT compiled, macro-expansion of slf4j-timbre.adapter occured when I compiled my project (using my value of TIMBRE_LEVEL), rather than when you compile your project

Unfortunately this project requires AOT. I will try to find another solution.

[rufoa]

So when TIMBRE_LEVEL is set at compile-time (of slf4j-timbre), our tests fail properly, as expected. The value of TIMBRE_LEVEL at runtime is ignored. This explains #32 (comment)

$ lein clean

$ TIMBRE_LEVEL=':warn' lein compile
Compiling slf4j-timbre.adapter
Compile-time (elision) Timbre level: :warn
Compiling slf4j-timbre.factory
Compiling slf4j-timbre.static-logger-binder
Compiling slf4j-timbre.static-marker-binder
Compiling slf4j-timbre.static-mdc-binder

$ lein midje
FAIL at (t_adapter.clj:43)
...

[ivarref]

Any progress on this? I figure an improvement would at least be to set the AOT compiled default level to info?

[runejuhl]

It should be possible to filter out Jetty (and other noisy libraries) using the :ns-blacklist option in timbre: https://github.com/ptaoussanis/timbre#configuration

One of my projects has the following in an :ns-blacklist config option, loaded at runtime:

{:ns-blacklist ["com.zaxxer.hikari.pool.*"
                "io.netty.*"
                "org.apache.http.*"
                "org.eclipse.jgit.util.FS"]}

Seems to work fine. It's quite heavy handed, but that particular blacklist is used only for some configurations -- it's probably not something that should be enabled globally...

[ivarref]

My problem is that loads of logging happen during execution of tools.deps plugins such as deps-ancient and pack.alpha where I do not have the option to set anything at runtime.

[runejuhl]

Ah, gotcha. Then I'm not of much use, sorry. I'm not even sure how I'd go about it... Hope you find a solution!

[ivarref]

Thanks -- and thanks for trying to help!

I'm not very ventured in slf4j-implementation land, but I figure that it would be possible to set the default timbre log level to :info (or what is present in TIMBRE_LEVEL).

Personally when binding slf4j I would like the default level to be :info.

[ivarref]

I updated factory.clj to be:

(ns slf4j-timbre.factory
	(:gen-class
		:name com.github.fzakaria.slf4j.timbre.TimbreLoggerFactory
		:implements [org.slf4j.ILoggerFactory]
		:state state
		:init init)
	(:require slf4j-timbre.adapter
						[taoensso.timbre :as timbre])
	(:import
		(com.github.fzakaria.slf4j.timbre TimbreLoggerFactory TimbreLoggerAdapter)))

(defonce bootstrapped (atom false))

(defn -init
	[]
	(when-not @bootstrapped
	  (reset! bootstrapped true)
		(let [lvl (System/getProperty "TIMBRE_LEVEL" ":info")]
			(timbre/set-level! (keyword (subs lvl 1)))))
	[[] (atom {})])

This seems to work fine for me. I will make a pull request.

[runejuhl]

Personally when binding slf4j I would like the default level to be :info.

That seems like a good compromise IMO, but I'd make sure it was possible to override the default log level easily. That way it'd avoid the worst of too verbose logs, and users that want to see everything can adjust it to their needs.

[ivarref]

Thanks for the input @runejuhl. I've added a pull request now which respects TIMBRE_LEVEL and defaults to :info.

The reason for defaulting to :info is that so many java libraries adds tons of debug output, and I would rather not have to specify -J-DTIMBRE_LEVEL=:info when running all my tools.deps plugins.

Thanks for the library @rufoa and hope you have time to review the pull request.

[rufoa]

Finally (sorry!) resolved in version "0.3.15"

Big thanks to everyone who helped sort this out