Logging via log4j backend doesn't work

uli-heller commented 9 years ago

I'm trying to get a webapp using log4j as logging backend up and running within gretty. I'm having the idea that this might be possible with gretty 1.1.9 or newer. Unfortunately, I don't have success on this.

Some more details:

my webapp uses slf4j
I'm linking this to log4j via slf4j-log4j12 and log4j-1.2.17
I do have a log4j.xml within my project
All of this works OK when I'm deploying the war file of the webapp to a standard tomcat container
- log4j loggers are created within the webapp
- log messages go into the log file configured within log4j.xml
When doing gradlew appRun to run the app within gretty, logback seems to be used for all the logging

The code is on github - https://github.com/uli-heller/uli-java-prototypes/tree/master/crash-webapp Unfortunately, most of this is in German at the moment. I'll translate it to English if needed.

But maybe I'm doing something that's not supposed to work at all? Please share your thoughts.

Thanks, Uli

akhikhl commented 9 years ago

I'm OK with German, since I live in Germany :smile: I'll have a look.

akhikhl commented 9 years ago

What I tried:

git clone git@github.com:uli-heller/uli-java-prototypes.git
cd uli-java-prototypes/crash-webapp
gradle appRun

What I got:

gradle appRun
Download https://repo1.maven.org/maven2/org/projectlombok/lombok/1.12.4/lombok-1.12.4.pom

FAILURE: Build failed with an exception.

* Where:
Build file '/home/ahi/Projects/temp/uli-java-prototypes/crash-webapp/build.gradle' line: 21

* What went wrong:
A problem occurred evaluating project ':crash-webapp'.
> Could not find method log4j12() for arguments [] on project ':crash-webapp'.

* Try:
Run with --stacktrace option to get the stack trace. Run with --info or --debug option to get more log output.

BUILD FAILED

Total time: 23.718 secs

uli-heller commented 9 years ago

Sorry, my fault. Should work now...

akhikhl commented 9 years ago

There is a bug in Gretty: log4j-over-slf4j slips into tomcat webapp configuration (although it should be excluded on the classloader level). I'll research this further and fix in the next version. In the meantime I can suggest a workaround: https://github.com/uli-heller/uli-java-prototypes/pull/1

uli-heller commented 9 years ago

Great! The workaround looks good to me. Thanks a lot for your help!

uli-heller commented 9 years ago

Quick test: For version 1.2.0, the issue still exists.

akhikhl commented 9 years ago

Could you, please, test it against version 1.2.3? The problem should be gone by now, because of improved classpath isolation.

uli-heller commented 9 years ago

Hi,

unfortunately, 1.2.3 has a very strange behavior for me. I'm trying to access org.apache.log4j.LogManager.getCurrentLoggers() and somehow I'm getting strange results when trying to iterate over the outcome:

java.lang.ClassCastException: java.util.Vector$1 cannot be cast to java.util.Iterator
    at org.codehaus.groovy.runtime.dgm$324.invoke(Unknown Source)
    at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMetho
...

With 1.2.2 and before, it used to be either an empty vector or a somehow populated vector (depending on the work around).

I have to stop looking at this for now, I'll be back within the next few days.

Thanks a lot for your support!

Best regards, Uli

uli-heller commented 9 years ago

I'm done now.

I've created a small demo project illustrating the issue - https://github.com/uli-heller/uli-gradle/tree/master/e02-gretty
Unfortunately, for gretty-1.2.3 the issue still exists
There might be a new issue related to using groovy scripts within the webapp - I'm verifying this within the next days and create another issue once I'm sure

Best regards, Uli

matthew-b-payne commented 9 years ago

I believe the groovy/conflict with logback slfj4 might be related. I posted the project here.

https://github.com/matthew-b-payne/gretty-logback-groovy-bug

akhikhl commented 9 years ago

Fixed in Gretty 1.2.4, please test.

uli-heller commented 9 years ago

Sorry, the issue still exists for me using gretty 1.2.4

tkent commented 9 years ago

+1, I'm also experiencing this issue with gretty 1.2.5-SNAPSHOT.

Btw, @akhikhl & @uli-heller, thanks for posting the workaround, it still works in 1.2.5-SNAPSHOT. That would have taken me forever to chase down.

mohamnag commented 8 years ago

I'm having same problem with gretty 1.2.4. I have a submodule which should be loaded as JNDI resource and therefore shall be added to Gretty class path. As soon as I add this line to gretty dependencies I'm unable to execute jettyRun:

gretty project(':sa_common')

the reason seems to be that subproject has this dependency:

compile group: 'org.slf4j', name: 'slf4j-api', version: '1.7.13'

I get following exception:

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/mohamnag/.gradle/caches/modules-2/files-2.1/org.slf4j/slf4j-nop/1.7.12/8052427115f80679a17bd2af659c760df39829bd/slf4j-nop-1.7.12.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/mohamnag/.gradle/caches/modules-2/files-2.1/ch.qos.logback/logback-classic/1.1.3/d90276fff414f06cb375f2057f6778cd63c6082f/logback-classic-1.1.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.helpers.NOPLoggerFactory]
Exception in thread "main" org.codehaus.groovy.runtime.typehandling.GroovyCastException: Cannot cast object 'org.slf4j.helpers.NOPLoggerFactory@c267ef4' with class 'org.slf4j.helpers.NOPLoggerFactory' to class 'ch.qos.logback.classic.LoggerContext'
    at org.codehaus.groovy.runtime.typehandling.DefaultTypeTransformation.continueCastOnSAM(DefaultTypeTransformation.java:392)
    at org.codehaus.groovy.runtime.typehandling.DefaultTypeTransformation.continueCastOnNumber(DefaultTypeTransformation.java:306)
    at org.codehaus.groovy.runtime.typehandling.DefaultTypeTransformation.castToType(DefaultTypeTransformation.java:227)
    at org.codehaus.groovy.runtime.ScriptBytecodeAdapter.castToType(ScriptBytecodeAdapter.java:601)
    at org.akhikhl.gretty.Runner.initLogback(Runner.groovy:50)
    at org.akhikhl.gretty.Runner$initLogback$0.callStatic(Unknown Source)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallStatic(CallSiteArray.java:53)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callStatic(AbstractCallSite.java:157)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callStatic(AbstractCallSite.java:165)
    at org.akhikhl.gretty.Runner.run(Runner.groovy:117)
    at org.akhikhl.gretty.Runner.this$2$run(Runner.groovy)
    at org.akhikhl.gretty.Runner$this$2$run.call(Unknown Source)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:45)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:108)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:112)
    at org.akhikhl.gretty.Runner.main(Runner.groovy:46)
Exception in thread "Thread-16" org.gradle.process.internal.ExecException: Process 'command '/Library/Java/JavaVirtualMachines/jdk1.8.0_40.jdk/Contents/Home/bin/java'' finished with non-zero exit value 1
    at org.gradle.process.internal.DefaultExecHandle$ExecResultImpl.assertNormalExitValue(DefaultExecHandle.java:367)
    at org.gradle.process.internal.DefaultJavaExecAction.execute(DefaultJavaExecAction.java:31)
    at org.gradle.api.internal.file.DefaultFileOperations.javaexec(DefaultFileOperations.java:170)
    at org.gradle.api.internal.project.AbstractProject.javaexec(AbstractProject.java:833)
    at org.gradle.api.internal.project.AbstractProject.javaexec(AbstractProject.java:829)
    at org.gradle.api.Project$javaexec$9.call(Unknown Source)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:125)
    at org.akhikhl.gretty.DefaultLauncher.javaExec(DefaultLauncher.groovy:67)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:93)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:384)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1019)
    at org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(PogoMetaClassSite.java:69)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:52)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:154)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:166)
    at org.akhikhl.gretty.LauncherBase$_launchThread_closure4.doCall(LauncherBase.groovy:240)
    at org.akhikhl.gretty.LauncherBase$_launchThread_closure4.doCall(LauncherBase.groovy)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:93)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:294)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1019)
    at groovy.lang.Closure.call(Closure.java:426)
    at groovy.lang.Closure.call(Closure.java:420)
    at groovy.lang.Closure.run(Closure.java:507)
    at java.lang.Thread.run(Thread.java:745)

the workaround does not work, I tried to apply it to my Jetty 9 runner like this:

    gretty {
        configurations {
            grettyRunnerJetty9 {
                exclude group: 'org.slf4j', module: 'log4j-over-slf4j'
            }
        }
    }

xak2000 commented 7 years ago

This bug is still relevent on last version of Gretty (release 1.4.2 at 17 Mar 2017).

The presense of this line

compile "org.slf4j:slf4j-log4j12:1.7.25"

causes this error at startup:

SLF4J: Detected both log4j-over-slf4j.jar AND bound slf4j-log4j12.jar on the class path, preempting StackOverflowError.
SLF4J: See also http://www.slf4j.org/codes.html#log4jDelegationLoop for more details.
19:57:48 ERROR Exception sending context initialized event to listener instance of class org.springframework.web.context.ContextLoaderListener
java.lang.ExceptionInInitializerError: null
        at org.slf4j.impl.StaticLoggerBinder.<init>(StaticLoggerBinder.java:72) ~[logback-classic-1.1.2.jar:na]
        at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:45) ~[logback-classic-1.1.2.jar:na]
        at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150) ~[slf4j-api-1.7.7.jar:1.7.7]
        at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124) ~[slf4j-api-1.7.7.jar:1.7.7]
        at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:412) ~[slf4j-api-1.7.7.jar:1.7.7]
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:357) ~[slf4j-api-1.7.7.jar:1.7.7]
        at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:156) ~[jcl-over-slf4j-1.7.5.jar:1.2]
        at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:132) ~[jcl-over-slf4j-1.7.5.jar:1.2]
        at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:655) ~[commons-logging-1.2.jar:1.2]
        at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:302) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4728) [tomcat-embed-core-8.0.20.jar:8.0.20]
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5162) [tomcat-embed-core-8.0.20.jar:8.0.20]
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) [tomcat-embed-core-8.0.20.jar:8.0.20]
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1409) [tomcat-embed-core-8.0.20.jar:8.0.20]
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1399) [tomcat-embed-core-8.0.20.jar:8.0.20]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Caused by: java.lang.IllegalStateException: Detected both log4j-over-slf4j.jar AND bound slf4j-log4j12.jar on the class path, preempting StackOverflowError. See also http://www.slf4j.org/codes.html#log4jDelegationLoop for more details.
        at org.slf4j.impl.Log4jLoggerFactory.<clinit>(Log4jLoggerFactory.java:54) ~[slf4j-log4j12-1.7.25.jar:na]
        ... 20 common frames omitted
19:57:48 ERROR Error listenerStart
19:57:48 ERROR Context [/api] startup failed due to previous errors

What is weird, this message not appearing and all works if I use version 1.7.12 of slf4j-log4j12 library. Maybe this check in older slf4j-log4j12 version isn't present... But with 1.7.12 all works fine (no stackoverflow errors). Is this means, that the library is wrong detecting both libraries at classpath?

akhikhl / gretty

Logging via log4j backend doesn't work #145