Logging in gradle plugin

Can the logs provided using log4j/slf4j in a gradle plugin be visible when running from consumer project? We are facing some challenge here as these logs are not appearing when trying to consume as gradle plugin dependency but works fine in the standalone gradle plugin project. We are able to see the System.out.println statements but not the log4j or slf4j logs. Is there any specific configuration requiored to enable this?

2 Likes

You’ve just discovered the build tool equivalent of that unspeakable family secret that nobody here dares talk about :wink:

Tons of people have brought it up over a span of several years:

This answer goes out to all of them too :slight_smile:

When the Gradle Tooling API is on your classpath—as it is when you’re developing plugins— Gradle overrides the standard SLF4J API with its own internal SLF4J API plus its own internal implementation.

With those in your classpath, Gradle forbids you from using any other SLF4J API/implementation configuration when you’re developing plugins. Well, you could configure them. They just won’t work the way you expect them to work is all; as you, me and the others above have discovered.

Not the end of the world though. You could still do:

...
import org.gradle.api.logging.Logger;
import org.slf4j.LoggerFactory;
...
public class FooPlugin { 
	
    private static final Logger LOGGER = LoggerFactory.getLogger("FooPlugin");				
    ...				
    public void m(){
    ...
    LOGGER.quiet("...Which is more or less like Logger.debug()... ");
    ...
    }
    ...
}

Don’t you find it peculiar OP, that there’s no documentation anywhere that explains why Gradle’s logging is the way it is? I do. The user guide doesn’t explain it in enough detail. @Peter_Niederwieser? Would you happen to know of a blog post or anything that explains Gradle’s logging for plugins in detail?

3 Likes

So does that mean that I can’t enable the logs of my plugin (via configuration or xml) alone and disable all of the other logs that Gradle might output (processing, other plugins, etc…) during the development and testing of my plugin? If I want to verify that logging is correct in my plugin, my only option is to enable --info or --debug (or any level flag on the cmd line) and search for them inside all of the logs (about 100 lines or so) that come out?

I guess our only option is to convert all of my logs to use logger.quiet via a -DVAR option of some sort…right?

Yes. I think so. Based on my observations, that is my current understanding, anyway. If you eventually figure out how to do that configuration/disabling — which I haven’t figured out how to do yet — please don’t hesitate to correct my assumption.

Another option is to verify your plugin’s logging using a TestKit functional test. If you set the GradleRunner to forwardOutput( )…

    GradleRunner.create( )
            ...
            .forwardOutput( )
            ...

…and given you do some logging in your plugin, when you run your functional test, then you could assert that your plugin is logging whatever you’re expecting…

    ...
    result.output.contains( "whatever you're expecting" )
    ...

Whatever you end up going with, please share your eventual solution with the rest of us enquiring minds? TIA :+1:

Yeah I went out and did a simple solution. For me, logs is everything and I wanted to personally verify them (with my own eyes, that’s why 100s of log lines is just too much :stuck_out_tongue:) as I was developing, debugging and performing manual tests.

Of course I used the result.output.contains("string") in my functional tests. forwardOutput() was, without a question, a necessary for me. I even created a regex to search for the messages my plugin is outputting regardless of what log level or logging is done (such as multi-line messages). Samples below:

String buildOutputRegex(String output) {
    return "(?s).*" + output.replace("?", "\\?")
            .replace("{", "\\{")
            .replace("}", "\\}")
            .replace("(", "\\(")
            .replace(")", "\\)")
            .replace("[", "\\[")
            .replace("]", "\\]")
            .replace(".", "\\.")
            .replace("*", "\\*")
            .replace("\n", "\n.*") + ".*";
}

And in the test:

Assert.assertTrue(result.getOutput().matches(buildOutputRegex(
                messages.getString("multiline_message"))));

Where error_message in my messages.properties file is:

multiline_message=\
An example of a message in \n\
multi-line format

That way I was able to verify messages in errors and exceptions (I personally wouldn’t use it for verifying plugin logging, just the message verification is needed for the use case tests). It worked great with with output logs, even when --info or --debug is enabled.

As for the logging configuration, I created a wrapper for the Gradle org.gradle.api.logging.Logger class and added a config method that converts my plugin logs to use the QUIET level. It’s better (albeit even quicker) because then only your plugin is outputting logs and the gradle lifecycle/task names are being logged in the output which is a way smaller output than having to enable the --info or --debug and hence never having to search my plugin logs every time I perform some debugging. I’ve created a gist (Logger.java) for that, it’s still an initial implementation which could be improved even more but does the job well done. And in-case the config is disabled it’ll fallback to the default implementation (info to info, error to error, so on…) so we’re still following the standards that way when the plugin released. A nice way to configure the wrapper logger is using the Gradle StartParameter (-PENABLE_LOGS) passed as an argument to the gradle command and using a logic like the below:

Logger logger = Logger.getLogger(MyPlugin.class)
String enableLogs = project.getGradle().getStartParameter()
        .getProjectProperties().get("ENABLE_LOGS");
if (enableLogs != null) {
    logger.quiet("MyPlugin logs enabled");
    Logger.setUseQuietLogs(true);
}

logger.info("This log line will now show even if info level is disabled " + 
        "since it is using quiet method internally");

Hope it helps :smiley:

Is there even after 3 years, no way of running other slf4j implementations in a custom gradle plugin ?

I want to log a lot in debug level, but I don’t wanna see all that gradle internal debug stuff when switching log level to debug. Is there any way to configure it like one would do in a log4j or logback configuration like this ?

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <logger name="com.example" level="DEBUG" />

  <root level="INFO">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

No, there isn’t: User-customizable logging · Issue #2408 · gradle/gradle · GitHub.

You can only replace the whole logging and there decide on your own what to log and how: Gradle User Manual: Version 8.0.2

I already tried that, but that’s too much of a hassle so I discarded this workaround.
Thanks anyway.

Yes, it definitely is. :smiley:
Just wanted to mention the option for completeness. :slight_smile:

Thanks for the hint ! I watch this issue, maybe they enhance it sometime in the future.
As the workaround mentioned from ahasbini, does not work anymore, I now have another simple workaround:

I created this pseudo-logger :

import org.gradle.api.logging.LogLevel
import org.gradle.api.logging.Logger
import org.gradle.api.logging.Logging

class LoggerFascade {
    private Logger log

    private static LogLevel level

    LoggerFascade(Class clazz) {
        this.log = Logging.getLogger(clazz)

    }

    static LoggerFascade getLogger(Class clazz) {
        return new LoggerFascade(clazz)
    }

    static void setLevel(LogLevel newLevel) {
        if (newLevel != level) {
            level = newLevel
        }
    }

    static LogLevel getLevel() {
        return level
    }

    void lifecyle(String message) {
        log.lifecycle(message)
    }

    // eg. trace
    void quiet(String message) {
        if(LoggerFascade.level == LogLevel.QUIET) {
            log.lifecycle(message)
        }
    }

    void debug(String message) {
        if(LoggerFascade.level == LogLevel.DEBUG) {
            log.lifecycle(message)
        }
    }

    void error(String message) {
        log.error(message)
    }
}

and can now set the log level to “debug” and have all log messages from my custom plugin classes logged to the console:


class CustomPlugin implements Plugin<Project> {
    private static final LoggerFascade log = LoggerFascade.getLogger(CustomPlugin.class)

    @Override
    void apply(Project project) {
      LoggerFascade.setLevel(LogLevel.DEBUG)
      log.debug("watch out, I'm a debug message :)")
    }
}

this is far from optimal, but enough to keep me going. Maybe its helpful for some other people too.