Open in app

Sign in

Write

Sign in

Spring Debugging Session: Adding Application Version To Logs With Gradle, Spring Boot and Logback

Anton Tkachenko
Duda
Published in
7 min readNov 7, 2022

--

By Duda

When your application is running in CI/CD processes, and production environment is updated frequently, it’s a good thing to know what version (build number) produced specific log — especially when investigating production incidents. Also, typical usage for log version is new version deploy monitoring: if new version generates too many warning/error logs, deploy should abort.

In some workflows, infrastructure itself is responsible for knowing from what server it grabbed logs and tags every log entry with version — but lets assume that we, developers, want to couple build version to every log we write on application level.

E.g., when invoking log.info(“Any random log”), we want to see something like this in actual logs

INFO -v 12345 {additional-log-meta} : Any random log

Initial project setup

Dependencies that we’ll need:

plugins {
    id 'org.springframework.boot' version '2.6.6'
}dependencies {
    compileOnly 'org.projectlombok:lombok'
    annotationProcessor 'org.projectlombok:lombok'
    implementation 'org.springframework.boot:spring-boot-starter'

    testCompileOnly 'org.projectlombok:lombok'
    testAnnotationProcessor 'org.projectlombok:lombok'
    testImplementation 'org.springframework.boot:spring-boot-starter-test'
}

Lombok is not necessary for this example, but its @Slf4j annotation is very convenient for logging.

org.springframework.boot:spring-boot-starter is a dependency that brings with it all we need to start Spring context, it also provides logging api and implementations via org.springframework.boot:spring-boot-starter-logging (default underlying framework is Logback)

Don’t forget to run gradle’s dependencies task to see what else is inside

Accessing build info on application level

For simplicity, let’s assume that application version is build id counter provided by our CI server (most likely, Jenkins) as env variable (let’s assume its name is ‘BUILD_NUMBER’)

It means that in gradle we can set project / artifact version property.
Value ‘latest’ is default fallback value for local dev env — since build number won’t be available

group 'examples.debuggingspring'
version = System.getProperty("BUILD_NUMBER", "latest")

In order to access project metainformation in runtime, we need to apply task spring-boot-plugin’s buildInfo task

springBoot {
    buildInfo()
}

Now, if we compile project, following tasks will run:

> Task :log-version:bootBuildInfo
> Task :log-version:compileJava
> Task :log-version:processResources
> Task :log-version:classes

And what’s important, /build/resources/main/META-INF folder will contain generated file build-info.properties that later will be used by spring-boot to create a bean of org.springframework.boot.info.BuildProperties that gives access to build information

build.artifact=log-version
build.group=examples.debuggingspring
build.name=log-version
build.time=2022-10-09T14\:51\:08.212010400Z
build.version=latest

Let’s create a simple sping-boot-application and a test to make sure that everything works as expected

package examples.debuggingspring.logversion;

import org.springframework.boot.autoconfigure.SpringBootApplication;

@SpringBootApplication
public class ArtifactVersionInLogsApplication {
}

And here is the test:

package examples.debuggingspring.logversion;import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.info.BuildProperties;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.boot.test.system.CapturedOutput;
import org.springframework.boot.test.system.OutputCaptureExtension;

import static org.assertj.core.api.Assertions.assertThat;

@SpringBootTest
@ExtendWith(OutputCaptureExtension.class)
@Slf4j
public class BuildInfoViaBuildPropertiesTest {

    @Autowired
    private BuildProperties buildProperties;

    @Test
    void buildPropertiesShouldBeAvailable(CapturedOutput output) {
        log.info("Build version is {}", buildProperties.getVersion());
        String out = output.getOut();
        assertThat(out).contains("Build version is latest");
    }

}

Actual log output:

2022-10-09 19:17:21.567 - INFO 1148 --- [Test worker] e.d.l.BuildInfoViaBuildPropertiesTest    : Build version is latest

Few comments about test setup:

  • @SpringBootTest is required because we need to run “real” process of context startup that picks up build info from meta-info
  • OutputCaptureExtension and CapturedOutput provide a mechanism to verify output generated by logging framework

Understanding logging pattern

Obviously, we don’t want to add build version to our log message manually or to create some dummy wrapper MyLogUtils.log(Logger logger, String message, Object… args). Instead, we need to configure logging framework to have version in all produced messages.

Spring boot provides very good documentation about it’s logging facade.

What we actually need from it — these two properties:

logging.pattern.file=...
logging.pattern.console=...

that allow us to define pattern for console/file output. Let’s assume that in local environment output goes to console and on staging & production — into a file on server, but we still want to use the same pattern for all envs.

In order to do so, we can use Spring’s feature of properties evaluation:

general.logging.pattern=... // our custom property in which we'll define pattern that will contain build version

logging.pattern.console=${general.logging.pattern}
logging.pattern.file=${general.logging.pattern}

Now, let’s find logging pattern that come out of the box with Spring Boot autoconfigure (ctrl-shift-F + search all places)

This is default value from search result:

%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}

Now, let’s adjust this pattern with version (a property from generated build-info.properties file) with manually defined fallback value

%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } -v ${build.version:UNKNOWN!!!} --- [%t] %-40.40logger{39} : %m%n ${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}

Let’s create a test to see what we get

package examples.debuggingspring.logversion;

import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.boot.test.system.CapturedOutput;
import org.springframework.boot.test.system.OutputCaptureExtension;

import static org.assertj.core.api.Assertions.assertThat;

@SpringBootTest
@ExtendWith(OutputCaptureExtension.class)
@Slf4j
public class ArtifactVersionInAllLogsTest {

    @Test
    void allLogsShouldHaveBuildVersion(CapturedOutput output) {
        log.info("Any random log");
        String out = output.getOut();
        assertThat(out).contains("-v latest");
    }

}

But with given setup, test fails — this is what we get in output

2022-10-09 18:19:11.494 - INFO 11060 -v UNKNOWN!!! --- [Test worker] e.d.l.ArtifactVersionInAllLogsTest       : Any random log

Debugging Spring Boot’s internals

In this section we’ll set some breakpoint in Spring & Spring Boot sources to understand the reasons why test fails and how to fix it.

The problem with build.version property is that logger-configuration happens early in context startup, before props from build-info.properties are loaded and transformed into BuildProperties bean.

If we check how BuildProperties are created (e.g. check constructor usage)

public BuildProperties(Properties entries) {
   super(processEntries(entries));
}

we’ll find that is invoked in this configuration class: org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration

@ConditionalOnResource(resources = "${spring.info.build.location:classpath:META-INF/build-info.properties}")
@ConditionalOnMissingBean
@Bean
public BuildProperties buildProperties() throws Exception {
   return new BuildProperties(
         loadFrom(this.properties.getBuild().getLocation(), "build", this.properties.getBuild().getEncoding()));
}

This also indicates that properties from build-info.properties can’t even be accessed via Environment / PropertyResolver:

@Autowired
org.springframework.core.env.PropertyResolver propertyResolver;@Test
void buildInfoPropertyIsNotAvailable() {
    assertThat(propertyResolver.getProperty("build.version"))
            .isNull();
}

Now let’s get back to usage of logging.pattern.file property in Spring Boot’s sources: it can be found via search in org.springframework.boot.logging.LoggingSystemProperties

public static final String FILE_LOG_PATTERN = "FILE_LOG_PATTERN";setSystemProperty(resolver, FILE_LOG_PATTERN, "logging.pattern.file");

We can see that it’s used to set properties for logback that will later be used by org.springframework.boot.logging.logback.LogbackLoggingSystem

If we put a breakpoint, we’ll see that log-pattern value is indeed resolved without data that we need

Tweaking Environment to contain build-properties

What we actually need to do — is to add properties from build-info as early as possible during context startup so that PropertyResolver could access it.

Creating some configuration with @PropertySource won’t help because configuration beans are created later after logger configuration.

Spring Boot has an interface org.springframework.boot.env.EnvironmentPostProcessor that is invoked before most actions , but after Spring Boot initialized all properties according to it’s own rules. Implementing this interface allows us to register “custom” properties manually:

package examples.debuggingspring.logversion;

import lombok.extern.slf4j.Slf4j;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.env.EnvironmentPostProcessor;
import org.springframework.core.env.ConfigurableEnvironment;
import org.springframework.core.env.PropertiesPropertySource;
import org.springframework.core.io.ClassPathResource;
import org.springframework.core.io.support.PropertiesLoaderUtils;

import java.io.IOException;
import java.util.Properties;

@Slf4j
public class BuildVersionEnvironmentPostprocessor implements EnvironmentPostProcessor {

    /**
     * Will be added by spring-boot-gradle plugin into runtime classpath
     * <a href="https://docs.spring.io/spring-boot/docs/current/gradle-plugin/api/org/springframework/boot/gradle/tasks/buildinfo/BuildInfo.html">see docs</a>
     */
    private static final String BUILD_INFO_PROPS = "META-INF/build-info.properties";

    @Override
    public void postProcessEnvironment(ConfigurableEnvironment environment, SpringApplication application) {
        try {
            ClassPathResource buildProperties = new ClassPathResource(BUILD_INFO_PROPS);
            Properties props = PropertiesLoaderUtils.loadProperties(buildProperties);
            environment.getPropertySources()
                    .addLast(new PropertiesPropertySource(
                            "build-info", props
                    ));
        } catch (IOException ignore) {
            log.warn("Can't read properties from build-info file {}. Logs will not be enriched with build number",
                    BUILD_INFO_PROPS);
        }
    }
}

Notice that EnvironmentPostProcessor is not a bean — it shouldn’t be annotated as @Component — instead, according to documentation, it must be registered in spring.factories file in META-INF resources folder:

org.springframework.boot.env.EnvironmentPostProcessor=examples.debuggingspring.logversion.BuildVersionEnvironmentPostprocessor

And if we use same breakpoint during log configuration phase, we’ll see that now pattern is initialized with expected version (and it’s avso available via ProperyResolver directly)

Finally, let’s run the test that we created earlier — it will be green now and produce following output:

2022-10-09 18:53:54.936 - INFO 5452 -v latest --- [Test worker] e.d.l.ArtifactVersionInAllLogsTest       : Any random log

Log4j usage instead of Logback

BTW, if you choose to use Log4j instead of Logback as your logging framework, test will still be green thanks to Spring-logging abstraction over underlying “worker”

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-log4j2'
}

configurations {
    all {
        exclude group: 'org.springframework.boot', module: 'spring-boot-starter-logging'
    }
}

Source code

Available here: https://github.com/tkachenkoas/debugging-spring

Spring Boot
Logging And Monitoring
Logback
Engineering
Software Engineering

--

--

Anton Tkachenko
Duda

Written by Anton Tkachenko

29 Followers
Writer for

Help

Status

About

Careers

Press

Blog

Privacy

Terms

Text to speech

Teams