Fork me on GitHub
#immutant
<
2017-06-07
>
lorddoig11:06:21

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]]
With this I get logs from org.projectodd.wunderboss.web.Web coming through timbre, but logs from xnio and from when an error is thrown mid-request are sent in some default-looking format to stdout. If I add log4j-core I get the same thing but in a slightly different format. Does anyone know the incantation to make this work? Google suggests it’s possible (https://twitter.com/statonjr/status/541250845300768768)

tcrawley11:06:00

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

lorddoig11:06:40

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

lorddoig11:06:51

That’s it until requests start hitting

tcrawley11:06:06

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

lorddoig11:06:26

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]]
I get
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

lorddoig11:06:49

ie the SLF4J warnings are added

tcrawley11:06:15

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

lorddoig12:06:19

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.

tcrawley12:06:33

I hate logging, btw :)

tcrawley12:06:01

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

tcrawley12:06:21

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

tcrawley12:06:26

but that's not the issue here

lorddoig12:06:51

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

tcrawley12:06:11

it's terrible

lorddoig12:06:24

so I hear. and experience.

lorddoig12:06:36

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

tcrawley12:06:55

I've already tried 2.1.7, same thing unfortunately

lorddoig12:06:11

Indeed same thing

tcrawley12:06:29

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

lorddoig12:06:10

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

tcrawley12:06:17

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

lorddoig12:06:49

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

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

tcrawley12:06:19

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

lorddoig12:06:39

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

lorddoig12:06:58

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

tcrawley12:06:13

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

tcrawley12:06:30

dangit, I was just about to try that

tcrawley12:06:10

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

lorddoig12:06:24

Thanks for your help dude

tcrawley12:06:35

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

tcrawley12:06:46

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

lorddoig12:06:08

awesome 😀

tcrawley12:06:05

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

lorddoig12:06:23

hmmmm that is odd. elide asserts?

jcrossley312:06:08

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

tcrawley12:06:35

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

lorddoig13:06:30

(set! *assert* false) i think

lorddoig13:06:47

although we’re having trouble with that…

lorddoig13:06:07

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

tcrawley13:06:41

in a meeting atm, but will look after

tcrawley13:06:22

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

lorddoig13:06:06

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

tcrawley13:06:51

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)

tcrawley13:06:04

I'm playing with it a bit more to confirm

lorddoig13:06:48

Brilliant! I will investigate too

lorddoig13:06:16

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

tcrawley13:06:58

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

lorddoig13:06:36

🙏 thank you so much

tcrawley13:06:14

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

tcrawley13:06:33

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

lorddoig13:06:02

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

lorddoig13:06:31

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

lorddoig13:06:39

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

tcrawley13:06:14

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

tcrawley13:06:31

and it's our pleasure!

lorddoig13:06:09

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

tcrawley13:06:22

no, I'm tobias on gh

lorddoig14:06:37

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

lorddoig14:06:26

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

tcrawley14:06:50

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

lorddoig14:06:41

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

tcrawley14:06:27

my pleasure!