Gradle logger does not log exceptions when using parameterized format string

Bugs
,
1

The gradle logger seems to be dropping the exception/stacktrace from log messages that include a Throwable.
build.gradle:

task test {
  println "Hello"
  logger.quiet("Hello {}, {}", "world", new Exception())
  logger.quiet("Hello {}", "world", new Exception())
  logger.quiet("Hello", new Exception())
}

Result:

$ gradle test
Hello
Hello world, java.lang.Exception
Hello world
Hello
java.lang.Exception
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at org.codehaus.groovy.reflection.CachedConstructor.invoke(CachedConstructor.java:80)
        at org.codehaus.groovy.runtime.callsite.ConstructorSite$ConstructorSiteNoUnwrapNoCoerce.callConstructor(ConstructorSite.java:105)
        at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallConstructor(CallSiteArray.java:60)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:235)
        at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:239)
        at build_bpqj3lk9iv7ovobn81oelqp74$_run_closure1.doCall(/Users/scarey/tmp/build.gradle:6)
        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:498)
        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:442)
        at org.gradle.api.internal.ClosureBackedAction.execute(ClosureBackedAction.java:67)
        at org.gradle.util.ConfigureUtil.configureSelf(ConfigureUtil.java:137)
        at org.gradle.api.internal.AbstractTask.configure(AbstractTask.java:522)
        at org.gradle.api.internal.project.AbstractProject.task(AbstractProject.java:927)
        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:498)
        at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:93)
        at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
        at org.gradle.internal.metaobject.BeanDynamicObject$MetaClassAdapter.invokeMethod(BeanDynamicObject.java:374)
        at org.gradle.internal.metaobject.BeanDynamicObject.invokeMethod(BeanDynamicObject.java:169)
        at org.gradle.internal.metaobject.CompositeDynamicObject.invokeMethod(CompositeDynamicObject.java:96)
        at org.gradle.internal.metaobject.MixInClosurePropertiesAsMethodsDynamicObject.invokeMethod(MixInClosurePropertiesAsMethodsDynamicObject.java:30)
        at org.gradle.internal.metaobject.AbstractDynamicObject.invokeMethod(AbstractDynamicObject.java:163)
        at org.gradle.groovy.scripts.BasicScript.methodMissing(BasicScript.java:79)
        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:498)
        at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:93)
        at groovy.lang.MetaClassImpl.invokeMissingMethod(MetaClassImpl.java:936)
        at groovy.lang.MetaClassImpl.invokePropertyOrMissing(MetaClassImpl.java:1259)
        at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1212)
        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:174)
        at build_bpqj3lk9iv7ovobn81oelqp74.run(/Users/scarey/tmp/build.gradle:2)
        at org.gradle.groovy.scripts.internal.DefaultScriptRunnerFactory$ScriptRunnerImpl.run(DefaultScriptRunnerFactory.java:91)
        at org.gradle.configuration.DefaultScriptPluginFactory$ScriptPluginImpl$2.run(DefaultScriptPluginFactory.java:177)
        at org.gradle.configuration.ProjectScriptTarget.addConfiguration(ProjectScriptTarget.java:77)
        at org.gradle.configuration.DefaultScriptPluginFactory$ScriptPluginImpl.apply(DefaultScriptPluginFactory.java:182)
        at org.gradle.configuration.project.BuildScriptProcessor.execute(BuildScriptProcessor.java:38)
        at org.gradle.configuration.project.BuildScriptProcessor.execute(BuildScriptProcessor.java:25)
        at org.gradle.configuration.project.ConfigureActionsProjectEvaluator.evaluate(ConfigureActionsProjectEvaluator.java:34)
        at org.gradle.configuration.project.LifecycleProjectEvaluator.evaluate(LifecycleProjectEvaluator.java:55)
        at org.gradle.api.internal.project.AbstractProject.evaluate(AbstractProject.java:540)
        at org.gradle.api.internal.project.AbstractProject.evaluate(AbstractProject.java:93)
        at org.gradle.execution.TaskPathProjectEvaluator.configureHierarchy(TaskPathProjectEvaluator.java:42)
        at org.gradle.configuration.DefaultBuildConfigurer.configure(DefaultBuildConfigurer.java:35)
        at org.gradle.initialization.DefaultGradleLauncher$2.run(DefaultGradleLauncher.java:124)
        at org.gradle.internal.Factories$1.create(Factories.java:22)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:91)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:53)
        at org.gradle.initialization.DefaultGradleLauncher.doBuildStages(DefaultGradleLauncher.java:121)
        at org.gradle.initialization.DefaultGradleLauncher.access$200(DefaultGradleLauncher.java:32)
        at org.gradle.initialization.DefaultGradleLauncher$1.create(DefaultGradleLauncher.java:98)
        at org.gradle.initialization.DefaultGradleLauncher$1.create(DefaultGradleLauncher.java:92)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:91)
        at org.gradle.internal.progress.DefaultBuildOperationExecutor.run(DefaultBuildOperationExecutor.java:63)
        at org.gradle.initialization.DefaultGradleLauncher.doBuild(DefaultGradleLauncher.java:92)
        at org.gradle.initialization.DefaultGradleLauncher.run(DefaultGradleLauncher.java:83)
        at org.gradle.launcher.exec.InProcessBuildActionExecuter$DefaultBuildController.run(InProcessBuildActionExecuter.java:99)
        at org.gradle.tooling.internal.provider.ExecuteBuildActionRunner.run(ExecuteBuildActionRunner.java:28)
        at org.gradle.launcher.exec.ChainingBuildActionRunner.run(ChainingBuildActionRunner.java:35)
        at org.gradle.launcher.exec.InProcessBuildActionExecuter.execute(InProcessBuildActionExecuter.java:48)
        at org.gradle.launcher.exec.InProcessBuildActionExecuter.execute(InProcessBuildActionExecuter.java:30)
        at org.gradle.launcher.exec.ContinuousBuildActionExecuter.execute(ContinuousBuildActionExecuter.java:81)
        at org.gradle.launcher.exec.ContinuousBuildActionExecuter.execute(ContinuousBuildActionExecuter.java:46)
        at org.gradle.launcher.exec.DaemonUsageSuggestingBuildActionExecuter.execute(DaemonUsageSuggestingBuildActionExecuter.java:51)
        at org.gradle.launcher.exec.DaemonUsageSuggestingBuildActionExecuter.execute(DaemonUsageSuggestingBuildActionExecuter.java:28)
        at org.gradle.launcher.cli.RunBuildAction.run(RunBuildAction.java:43)
        at org.gradle.internal.Actions$RunnableActionAdapter.execute(Actions.java:173)
        at org.gradle.launcher.cli.CommandLineActionFactory$ParseAndBuildAction.execute(CommandLineActionFactory.java:239)
        at org.gradle.launcher.cli.CommandLineActionFactory$ParseAndBuildAction.execute(CommandLineActionFactory.java:212)
        at org.gradle.launcher.cli.JavaRuntimeValidationAction.execute(JavaRuntimeValidationAction.java:35)
        at org.gradle.launcher.cli.JavaRuntimeValidationAction.execute(JavaRuntimeValidationAction.java:24)
        at org.gradle.launcher.cli.ExceptionReportingAction.execute(ExceptionReportingAction.java:33)
        at org.gradle.launcher.cli.ExceptionReportingAction.execute(ExceptionReportingAction.java:22)
        at org.gradle.launcher.cli.CommandLineActionFactory$WithLogging.execute(CommandLineActionFactory.java:205)
        at org.gradle.launcher.cli.CommandLineActionFactory$WithLogging.execute(CommandLineActionFactory.java:169)
        at org.gradle.launcher.Main.doAction(Main.java:33)
        at org.gradle.launcher.bootstrap.EntryPoint.run(EntryPoint.java:45)
        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:498)
        at org.gradle.launcher.bootstrap.ProcessBootstrap.runNoExit(ProcessBootstrap.java:55)
        at org.gradle.launcher.bootstrap.ProcessBootstrap.run(ProcessBootstrap.java:36)
        at org.gradle.launcher.GradleMain.main(GradleMain.java:23)
:test UP-TO-DATE

BUILD SUCCESSFUL

Total time: 1.292 secs

The Exception is only logged when the format string does not contain parameters. The exceptions are logged when running the same logger statements from Groovy or Java.

Gradle Version: 2.14
Operating System: Mac OS X, Ubuntu
Is this a regression? If yes, which version of Gradle do you know it last worked for?

1 Like
2

This works as expected in Gradle 2.3 and stops working in Gradle 2.4

3

I’m quite certain this has always been the case with Logger. The difference is not with the format string, it’s with the arguments passed. Notice the two quiet() methods.

This one takes a string and variable argument list. These arguments are used in the format string.

void quiet(String message, Object... objects);

This one takes a string and a Throwable. In this case, the Throwable's stacktrace is included in the logging output.

void quiet(String message, Throwable throwable);

The reason for the different behavior is not due to the content of the string being passed. It is due to the type and number of arguments. Basically, there is no method which supports a format string and exception. If you want to do this I’d combine with String.format() with this method.

logger.quiet(String.format("Hello %s", "world"), new Exception());
4

SLF4J supports varags with exception as the last parameter. See http://slf4j.org/faq.html#paramException

It works in Java and it worked in Gradle until version 2.4.

5

Ah yes, it looks like perhaps something changes under the hood here. I have confirmed this does work in 2.3. I’ve created GRADLE-3504 to track this. Thanks for reporting this.

6

I’ve tracked down the issue here and have committed a fix that will be included in Gradle 3.0.

1 Like
7

Thanks for following up, Mark!