gretty icon indicating copy to clipboard operation
gretty copied to clipboard
verified publisher icon akhikhl

Logging via log4j backend doesn't work

Open uli-heller opened this issue 10 years ago • 15 comments

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

uli-heller avatar Mar 04 '15 06:03 uli-heller

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

akhikhl avatar Mar 04 '15 08:03 akhikhl

What I tried:

git clone [email protected]: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

akhikhl avatar Mar 04 '15 08:03 akhikhl

Sorry, my fault. Should work now...

uli-heller avatar Mar 04 '15 08:03 uli-heller

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

akhikhl avatar Mar 04 '15 09:03 akhikhl

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

uli-heller avatar Mar 04 '15 10:03 uli-heller

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

uli-heller avatar Mar 10 '15 05:03 uli-heller

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

akhikhl avatar May 18 '15 18:05 akhikhl

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 avatar May 20 '15 18:05 uli-heller

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

uli-heller avatar May 22 '15 04:05 uli-heller

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

matthew-b-payne avatar Jun 02 '15 16:06 matthew-b-payne

Fixed in Gretty 1.2.4, please test.

akhikhl avatar Jun 02 '15 21:06 akhikhl

Sorry, the issue still exists for me using gretty 1.2.4

uli-heller avatar Jun 06 '15 12:06 uli-heller

+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.

tkent avatar Jun 13 '15 22:06 tkent

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'
            }
        }
    }

mohamnag avatar Jul 12 '16 15:07 mohamnag

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?

xak2000 avatar Jun 15 '17 17:06 xak2000