logback

I had one case where i need to send HTTP logs from Apache HTTP Client into console, the thing is this approach has a security impact since everything will be sent to console including credentials and authorization headers. This is one reason why we comes up with an approach to hide sensitive values based on specific pattern from Logback console logs.

Lets start with a simple Java project,

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>com.edw</groupId>
    <artifactId>logback-with-masked-credentials</artifactId>
    <version>1.0</version>

    <properties>
        <maven.compiler.source>17</maven.compiler.source>
        <maven.compiler.target>17</maven.compiler.target>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    </properties>

    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>3.0.4</version>
        <relativePath/>
    </parent>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>

        <dependency>
            <groupId>org.wiremock</groupId>
            <artifactId>wiremock</artifactId>
            <version>3.3.1</version>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>


</project>

And create a Java class for doing a simple HTTP outbound request to a simulator,

package com.edw;


import com.github.tomakehurst.wiremock.WireMockServer;
import org.apache.hc.client5.http.classic.methods.HttpGet;
import org.apache.hc.client5.http.impl.classic.CloseableHttpClient;
import org.apache.hc.client5.http.impl.classic.CloseableHttpResponse;
import org.apache.hc.client5.http.impl.classic.HttpClients;
import org.junit.jupiter.api.Assertions;
import org.junit.jupiter.api.DisplayName;
import org.junit.jupiter.api.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.test.context.SpringBootTest;

import java.io.IOException;
import java.io.InputStream;
import java.util.Scanner;

import static com.github.tomakehurst.wiremock.client.WireMock.aResponse;
import static com.github.tomakehurst.wiremock.client.WireMock.configureFor;
import static com.github.tomakehurst.wiremock.client.WireMock.get;
import static com.github.tomakehurst.wiremock.client.WireMock.getRequestedFor;
import static com.github.tomakehurst.wiremock.client.WireMock.stubFor;
import static com.github.tomakehurst.wiremock.client.WireMock.urlEqualTo;
import static com.github.tomakehurst.wiremock.client.WireMock.verify;

@SpringBootTest
public class MainTest {

    private WireMockServer wireMockServer = new WireMockServer();
    private CloseableHttpClient httpClient = HttpClients.createDefault();

    private Logger logger = LoggerFactory.getLogger(MainTest.class);

    @Test
    @DisplayName("01. Testing Hello World Page")
    public void indexTest() throws IOException {
        wireMockServer.start();

        configureFor("localhost", 8080);
        stubFor(
                get(
                    urlEqualTo("/"))
                        .willReturn(
                                aResponse()
                                        .withBody("Hello World")
                        ));

        HttpGet request = new HttpGet("http://localhost:8080/");
        request.addHeader("Accept-Encoding", "text/plain");
        request.addHeader("Accept-Charset", "utf-8");

        // authentication header --- this is a sample of sensitive value that we are going to masked
        request.addHeader("Authorization", "Bearer eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiS.jwt-sample.cpQcLckrTofjLZtCFFcMfThBNWD");

        CloseableHttpResponse httpResponse = httpClient.execute(request);
        String stringResponse = convertResponseToString(httpResponse);

        verify(getRequestedFor(urlEqualTo("/")));
        Assertions.assertEquals("Hello World", stringResponse);

        wireMockServer.stop();
    }

    private String convertResponseToString(CloseableHttpResponse response) throws IOException {
        InputStream responseStream = response.getEntity().getContent();
        Scanner scanner = new Scanner(responseStream, "UTF-8");
        String stringResponse = scanner.useDelimiter("\\Z").next();
        scanner.close();

        logger.debug("response is {}", stringResponse);

        return stringResponse;
    }

}

With below logback.xml configuration,

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

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

    <logger name="com.edw" level="DEBUG" additivity="false">
        <appender-ref ref="CONSOLE" />
    </logger>

    <logger name="org.apache.hc.client5.http.wire" level="DEBUG" additivity="false">
        <appender-ref ref="CONSOLE" />
    </logger>

    <root level="WARN">
        <appender-ref ref="CONSOLE" />
    </root>
</configuration>

This will generate this log files, and as we can see theres an Authorization header printed there

16:41:35.164 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "GET / HTTP/1.1[\r][\n]"
16:41:35.165 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Accept-Encoding: text/plain[\r][\n]"
16:41:35.165 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Accept-Charset: utf-8[\r][\n]"
16:41:35.165 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Authorization: Bearer eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiS.jwt-sample.cpQcLckrTofjLZtCFFcMfThBNWD[\r][\n]"
16:41:35.165 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Host: localhost:8080[\r][\n]"
16:41:35.165 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Connection: keep-alive[\r][\n]"
16:41:35.165 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "User-Agent: Apache-HttpClient/5.1.4 (Java/17.0.6)[\r][\n]"
16:41:35.165 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "[\r][\n]"
16:41:35.175 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]"
16:41:35.176 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "Matched-Stub-Id: 584bed8e-a120-46c4-9139-ce3837b47ef6[\r][\n]"
16:41:35.176 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "Transfer-Encoding: chunked[\r][\n]"
16:41:35.176 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "[\r][\n]"
16:41:35.176 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "b[\r][\n]"
16:41:35.176 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "Hello World[\r][\n]"
16:41:35.179 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "0[\r][\n]"
16:41:35.179 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "[\r][\n]"

For hiding Authorization header, we can leverage Logback.xml replace function and use something like this.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="CONSOLE"
              class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>
    <appender name="CUSTOM-HTTP-CONSOLE"
              class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %replace(%msg){"(Authorization.*$)", "Authorization: xxxxx"}%n</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>
    <logger name="com.edw" level="DEBUG" additivity="false">
        <appender-ref ref="CONSOLE" />
    </root>
</configuration>

Which will eventually generates logs like this,

08:56:23.046 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "GET / HTTP/1.1[\r][\n]"
08:56:23.046 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Accept-Encoding: text/plain[\r][\n]"
08:56:23.047 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Accept-Charset: utf-8[\r][\n]"
08:56:23.047 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Authorization: xxxxx"
08:56:23.047 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Host: localhost:8080[\r][\n]"
08:56:23.047 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "Connection: keep-alive[\r][\n]"
08:56:23.047 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "User-Agent: Apache-HttpClient/5.1.4 (Java/17.0.6)[\r][\n]"
08:56:23.047 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 >> "[\r][\n]"
08:56:23.064 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]"
08:56:23.064 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "Matched-Stub-Id: eccc2faf-5b55-4850-981e-a0ef26219c87[\r][\n]"
08:56:23.064 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "Transfer-Encoding: chunked[\r][\n]"
08:56:23.064 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "[\r][\n]"
08:56:23.069 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "b[\r][\n]"
08:56:23.069 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "Hello World[\r][\n]"
08:56:23.069 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "0[\r][\n]"
08:56:23.069 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "[\r][\n]"

Code for this article can be found here,

https://github.com/edwin/logback-with-masked-credentials

There are times where we want to create a dynamic configuration for our logging level. Lets say for most of cases, logger with level INFO is sufficient enough, but we want a much more detail logger such as DEBUG or TRACE for debugging purpose.

We can achieve that condition by using a dynamic configuration in Logback. This is how we do it, we’ll start with using a specific logging library called Logback.

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>com.edw</groupId>
    <artifactId>springboot-and-logback-xml</artifactId>
    <version>1.0-SNAPSHOT</version>

    <properties>
        <maven.compiler.source>17</maven.compiler.source>
        <maven.compiler.target>17</maven.compiler.target>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    </properties>

    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>3.0.4</version>
        <relativePath/>
    </parent>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>

</project>

And create a file called logback.xml,

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <property name="APP_LOG_LEVEL" value="${APP_LOG_LEVEL:-INFO}" />
    <property name="ROOT_LOG_LEVEL" value="${ROOT_LOG_LEVEL:-WARN}" />
    
    <appender name="CONSOLE"
              class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>

    <logger name="com.edw" level="${APP_LOG_LEVEL}" additivity="false">
        <appender-ref ref="CONSOLE" />
    </logger>

    <root level="${ROOT_LOG_LEVEL}">
        <appender-ref ref="CONSOLE" />
    </root>
</configuration>

We can test by using below Java code where we create two different logging line with different log level,

package com.edw.controller;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.HashMap;

@RestController
public class IndexController {

    private static final Logger logger = LoggerFactory.getLogger(IndexController.class);

    @GetMapping("/")
    public HashMap getIndexPage() {
        logger.debug("we are at index page using {}", "DEBUG");
        logger.info("we are at index page using {}", "INFO");

        return new HashMap() {{
            put("hello", "world");
        }};
    }
}

We can run the project using default command and see default log outputs

$  java -jar springboot-and-logback-xml-1.0-SNAPSHOT.jar

  .   ____          _            __ _ _    
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \   
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \  
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) ) 
  '  |____| .__|_| |_|_| |_\__, | / / / /  
 =========|_|==============|___/=/_/_/_/   
 :: Spring Boot ::                (v3.0.4) 

14:12:49.321 [main] INFO  com.edw.Main - Starting Main v1.0-SNAPSHOT using Java 17.0.6 with PID 13480 
14:12:49.326 [main] INFO  com.edw.Main - No active profile set, falling back to 1 default profile: "default" 
14:12:51.122 [main] INFO  com.edw.Main - Started Main in 2.283 seconds (process running for 2.983) 
14:13:02.489 [http-nio-8080-exec-1] INFO  com.edw.controller.IndexController - we are at index page using INFO 

However for a much more detail outputs, we can use below command with configured “APP_LOG_LEVEL” and “ROOT_LOG_LEVEL”

$ java -DAPP_LOG_LEVEL=DEBUG -DROOT_LOG_LEVEL=INFO -jar springboot-and-logback-xml-1.0-SNAPSHOT.jar

  .   ____          _            __ _ _    
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \   
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \  
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) ) 
  '  |____| .__|_| |_|_| |_\__, | / / / /  
 =========|_|==============|___/=/_/_/_/   
 :: Spring Boot ::                (v3.0.4) 
 
14:15:40.353 [main] INFO  com.edw.Main - Starting Main v1.0-SNAPSHOT using Java 17.0.6 with PID 9004 
14:15:40.356 [main] DEBUG com.edw.Main - Running with Spring Boot v3.0.4, Spring v6.0.6                      
14:15:40.357 [main] INFO  com.edw.Main - No active profile set, falling back to 1 default profile: "default" 
14:15:41.774 [main] INFO  o.s.b.w.e.tomcat.TomcatWebServer - Tomcat initialized with port(s): 8080 (http) 
14:15:41.788 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-8080"] 
14:15:41.789 [main] INFO  o.a.catalina.core.StandardService - Starting service [Tomcat]
14:15:41.789 [main] INFO  o.a.catalina.core.StandardEngine - Starting Servlet engine: [Apache Tomcat/10.1.5]
14:15:41.903 [main] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring embedded WebApplicationContext 
14:15:41.905 [main] INFO  o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 1449 ms 
14:15:42.365 [main] INFO  o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-8080"] 
14:15:42.404 [main] INFO  o.s.b.w.e.tomcat.TomcatWebServer - Tomcat started on port(s): 8080 (http) with context path '' 
14:15:42.425 [main] INFO  com.edw.Main - Started Main in 2.604 seconds (process running for 3.422) 
14:17:29.454 [http-nio-8080-exec-1] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring DispatcherServlet 'dispatcherServlet' 
14:17:29.455 [http-nio-8080-exec-1] INFO  o.s.web.servlet.DispatcherServlet - Initializing Servlet 'dispatcherServlet' 
14:17:29.456 [http-nio-8080-exec-1] INFO  o.s.web.servlet.DispatcherServlet - Completed initialization in 1 ms
14:17:29.490 [http-nio-8080-exec-1] DEBUG com.edw.controller.IndexController - we are at index page using DEBUG 
14:17:29.492 [http-nio-8080-exec-1] INFO  com.edw.controller.IndexController - we are at index page using INFO 

For Kubernetes delployments, we can also use below environment variables

  env:
	- name: APP_LOG_LEVEL
	  value: DEBUG
	- name: ROOT_LOG_LEVEL
	  value: INFO