search

fzakaria / slf4j-timbre

SLF4J binding for Clojure's Timbre
Eclipse Public License 1.0
94 stars 23 forks source link

Noisy Netty logs show up after adopting this library #32

Closed vemv closed 4 years ago

vemv commented 5 years ago

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 commented 5 years ago

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

rufoa commented 5 years ago

Thanks for the thorough report!

This looks similar to https://github.com/fzakaria/slf4j-timbre/issues/21#issuecomment-233155008

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

rufoa commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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

This is because:

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

rufoa commented 5 years ago

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 https://github.com/fzakaria/slf4j-timbre/issues/32#issuecomment-449535327

$ 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 commented 4 years ago

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

runejuhl commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

Finally (sorry!) resolved in version "0.3.15"

Big thanks to everyone who helped sort this out