Clojurians Log v2

@lorddoig has joined the channel

afternoon channel. I’m having a pretty awful time trying to pump immutant logs through timbre. My deps are set up like so:

[com.taoensso/timbre "4.7.4"]
    [org.slf4j/slf4j-api "1.7.21"]
    [com.fzakaria/slf4j-timbre "0.3.5"]
    [org.slf4j/log4j-over-slf4j "1.7.14"]
    [org.immutant/web "2.1.5"
     :exclusions [ch.qos.logback/logback-classic]]

@lorddoig can you gist the xnio output? It may be writing to stdout in some cases

Sure

Jun 06, 2017 6:21:51 PM org.xnio.Xnio <clinit>
INFO: XNIO version 3.3.6.Final
Jun 06, 2017 6:21:51 PM org.xnio.nio.NioXnio <clinit>
INFO: XNIO NIO Implementation Version 3.3.6.Final

That’s it until requests start hitting

if you comment out your timbre & logging deps (and just use the default) does the output from xnio change?

I can’t really comment out timbre as the app won’t boot, but with these:

[com.taoensso/timbre "4.7.4"]
    ;[org.slf4j/slf4j-api "1.7.21"]
    ;[com.fzakaria/slf4j-timbre "0.3.5"]
    ;[org.slf4j/log4j-over-slf4j "1.7.14"]
    [org.immutant/web "2.1.5"
     :exclusions [ch.qos.logback/logback-classic]]

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See  for further details.
Jun 07, 2017 12:46:02 PM org.xnio.Xnio <clinit>
INFO: XNIO version 3.3.6.Final
Jun 07, 2017 12:46:02 PM org.xnio.nio.NioXnio <clinit>
INFO: XNIO NIO Implementation Version 3.3.6.Final

ie the SLF4J warnings are added

I'm playing with it locally to see what I can figure out

I’ve skimmed the source of xnio and see that it delegates to jboss for logging. Have also tried manually setting org.jboss.logging.provider to both log4j and slf4j—makes no difference.

I hate logging, btw :)

yeah, what's interesting is if you go with the default config, you don't see any messages from XNIO at startup

so something is shipping a config to suppress XNIO's INFO messages I think

but that's not the issue here

java isn’t my forte, java logging seems especially mystical

it's terrible

so I hear. and experience.

just noticed i’m on immutant 2.1.5, will try bumping to latest

I've already tried 2.1.7, same thing unfortunately

Indeed same thing

is the end goal here to get the log messages to a file that you set up via timbre?

It’s to get it into a timbre appender function so that I can log to file/stdout/kibana and instrument error counts with riemann

gotcha

jboss-logging is supposed to recognize that slf4j is available, and designate to that, but it looks like that's not happening

well interestingly, I do get this coming through timbre when I start the server:

INFO [org.projectodd.wunderboss.web.Web:145] - Registered web context /

yeah, that's from wunderboss, which doesn't use jboss-logging, and writes directly to slf4j

aha

It’s odd that when I manually set jboss to use slf4j (have checked it is set properly) it doesn’t make a difference. Perhaps it’s not detecting log4j/slf4j but, in the absence of logback, is just writing directly to stdout

But when I include log4j I get errors about multiple bindings and a warning about a missing config file

how are you setting jboss to use slf4j? by setting org.jboss.logging.provider?

Yeah

dangit, I was just about to try that

😞

I'm at a loss - @jcrossley3 should be in soon, he may have some more insight

Thanks for your help dude

I'm stepping through jboss-logging in a debugger now

so I guess I'm not completely lost yet :)

awesome 😀

weird. it's failing because something in clojure-land is throwing an AssertionError: "Assert failed: (nil? arg-array)", but with no stacktrace

hmmmm that is odd. elide asserts?

i have no insight. i always defer to James Perkins for jboss logging problems.

I suspect it's a pre-condition on a fn somewhere, can those be suppressed?

(set! *assert* false) i think

although we’re having trouble with that…

if you’re using lein you can do it via :global-vars in project.clj

in a meeting atm, but will look after

@lorddoig I'm back. It looks like this the culprit: https://github.com/fzakaria/slf4j-timbre/tree/master/src/slf4j_timbre/adapter.clj#L95

it doesn't expect (and doesn't allow) the .log method to be called with an arg array, and that's happening somewhere

Aha. But would that explain why the xnio logs are diverting to stdout?

I think so, since jboss-logging fails to init slf4j (that assert fails when jboss-logging makes a debugf call to the slf4j logger it found during init, and jboss-logging swallows the exception and assumes slf4j failed to init, and moves on to other logging methods)

I'm playing with it a bit more to confirm

Brilliant! I will investigate too

Hopefully we can just modify slf4j-timbre and be done. Happy days.

if I comment out that assert, the XNIO messages do make it to timbre

🙏 thank you so much

happy to help! though messages that come through that -log fn won't have the arg-array included in the message, it is just ignored

so this is something that should probably be fixed in slf4j-timbre for real at some point

I’ll fork for new and open an issue/PR. Unless you’re planning on doing that? you seem to know more than me

@tcrawley nice catch!

Indeed! It would have taken me a while to find that, if ever

The team here at http://style.com are extremely grateful. Thanks so much guys.

@lorddoig you're welcome to file the issue and fix it if you like, and I'm happy to assist.

and it's our pleasure!

I’ll give you a nod on GH, is your username the same?

no, I'm tobias on gh

👍

@tcrawley I’ve just tried commenting that assert out but I’m seeing the same thing happening. What deps are you using?

Scratch that, got it working by setting org.jboss.logging.provider=slf4j

ah, good deal. I was just checking my deps :)

Finally. I’ve tried to get this working on and off for about 18 months now. Thanks again, just about to file an issue

my pleasure!

https://github.com/fzakaria/slf4j-timbre/issues/25 for reference

right on