Running in Open Liberty drops the Logbook logging

[berndgoetz]

Description

I have a simple Spring Boot 3.2.8 application, a couple of REST API endpoints.

The Logbook configuration is the following:

    @Bean
    public Logbook logbookForLogstash() {
        var jsonHttpLogFormatter = new JsonHttpLogFormatter();
        var sink = new DefaultSink(jsonHttpLogFormatter, new DefaultHttpLogWriter());
        return Logbook.builder()
                .condition(Conditions.requestTo("/test1")
                        .or(Conditions.requestTo("/test2"))
                        .or(Conditions.requestTo("/log")))
                .sink(sink)
                .build();
    }

The REST endpoint /log is defined as follows:

    @Operation(summary = "Logging testing", tags = "Testing")
    @GetMapping("/log")
    public String log() {
        log.info("Logging testing - info message");
        log.warn("Logging testing - warning message");
        log.error("Logging testing - error message");
        log.trace("Logging testing - trace message");
        return "Messages logged";
    }

Parts of the application.yml:

...
logging:
  level:
    root: info
    # set to trace for request/response logging:
    org.zalando.logbook: trace
    # testing
    com.swissre.pcss.tt: trace

logbook:
  filter.enabled: true
...

logback-spring.xml:

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

    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>

    <property name="CONSOLE_LOG_PATTERN"
              value="${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%15.15t] %8X{user} %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>

    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>

    <springProperty name="logstashUrl" source="laas.url" scope="context"/>

    <springProfile name="logstash">
        <appender name="logstash" class="net.logstash.logback.appender.LogstashAccessTcpSocketAppender">
            <destination>${logstashUrl}</destination>
            <reconnectionDelay>1 second</reconnectionDelay>
            <writeBufferSize>16384</writeBufferSize>
            <ssl/>
            <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
                <providers>
                    <timestamp>
                        <timeZone>UTC</timeZone>
                    </timestamp>
                    <pattern>
                        <pattern>
                            {
                            "type": "liberty_message",
                            "serverName": "${CONTAINER_NAME}",
                            "hostName": "${INSTANCE_GUID}",
                            "loggerName": "%logger{35}",
                            "severity": "%-5.5level",
                            "threadId": "%thread",
                            "message": "%message %ex",
                            "userId": "%mdc{user}",
                            "callerId": "%mdc{callerId}",
                            "traceId": "%X{X-B3-TraceId:-}",
                            "spanId": "%X{X-B3-SpanId:-}"
                            }
                        </pattern>
                    </pattern>
                </providers>
            </encoder>
        </appender>

    </springProfile>

    <springProfile name="logstash">
        <root level="INFO">
            <appender-ref ref="logstash"/>
            <appender-ref ref="stdout"/>
        </root>
    </springProfile>
    <root level="INFO">
        <appender-ref ref="stdout"/>
    </root>
</configuration>

When I run the service in the embedded Tomcat mode locally, everything works fine, Logbook is logging request and response details correctly:

:: Spring Boot ::                (v3.2.8)

 INFO 25940 --- [           main]          com.swissre.pcss.tt.Application          : Starting Application using Java 21.0.2 with PID 25940 (C:\srdev\projects\pcss\pcss-tt\build\classes\java\main started by SRZGOB in C:\srdev\projects\pcss\pcss-tt)
 INFO 25940 --- [           main]          com.swissre.pcss.tt.Application          : The following 1 profile is active: "local"
 INFO 25940 --- [           main]          o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port 8080 (http)
 INFO 25940 --- [           main]          o.apache.catalina.core.StandardService   : Starting service [Tomcat]
 INFO 25940 --- [           main]          o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.26]
 INFO 25940 --- [           main]          o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
 INFO 25940 --- [           main]          w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1521 ms
 INFO 25940 --- [           main]          com.swissre.pcss.tt.web.CallerIdFilter   : Caller id filter enforcement: false
 INFO 25940 --- [           main]          o.s.b.a.w.s.WelcomePageHandlerMapping    : Adding welcome page template: index
 INFO 25940 --- [           main]          o.s.b.a.e.web.EndpointLinksResolver      : Exposing 4 endpoint(s) beneath base path '/actuator'
 INFO 25940 --- [           main]          o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port 8080 (http) with context path ''
 INFO 25940 --- [           main]          com.swissre.pcss.tt.Application          : Started Application in 3.991 seconds (process running for 4.933)
 INFO 25940 --- [           main]          com.swissre.pcss.tt.Application          : Application ready
 INFO 25940 --- [nio-8080-exec-2]          o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
 INFO 25940 --- [nio-8080-exec-2]          o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
 INFO 25940 --- [nio-8080-exec-2]          o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
TRACE 25940 --- [nio-8080-exec-2]          org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"c78f09c8868e7daa","protocol":"HTTP/1.1","remote":"127.0.0.1","method":"GET","uri":"http://localhost:8080/log","host":"localhost","path":"/log","scheme":"http","port":"8080","headers":{"accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"],"accept-encoding":["gzip, deflate, br"],"accept-language":["en-US,en;q=0.5"],"connection":["keep-alive"],"cookie":["Idea-c5807970=0e094b9b-54f5-424f-8cd7-6c80baba8ff2; mmsa-hosted=e8f139b37b4ebde165991ba937d19cae-20240702; user-device=667e5644e90df4317a3b9734"],"host":["localhost:8080"],"sec-fetch-dest":["document"],"sec-fetch-mode":["navigate"],"sec-fetch-site":["none"],"sec-fetch-user":["?1"],"upgrade-insecure-requests":["1"],"user-agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:109.0) Gecko/20100101 Firefox/115.0"]}}
 INFO 25940 --- [nio-8080-exec-2]          com.swissre.pcss.tt.MainController       : Logging testing - info message
 WARN 25940 --- [nio-8080-exec-2]          com.swissre.pcss.tt.MainController       : Logging testing - warning message
ERROR 25940 --- [nio-8080-exec-2]          com.swissre.pcss.tt.MainController       : Logging testing - error message
TRACE 37344 --- [nio-8080-exec-1]          com.swissre.pcss.tt.MainController       : Logging testing - trace message
TRACE 25940 --- [nio-8080-exec-2]          org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"c78f09c8868e7daa","duration":3849,"protocol":"HTTP/1.1","status":200,"headers":{"Connection":["keep-alive"],"Content-Length":["15"],"Content-Type":["text/html;charset=UTF-8"],"Date":["Mon, 19 Aug 2024 23:08:15 GMT"],"Keep-Alive":["timeout=60"]},"body":"Messages logged"}

We are using Open Liberty in a CloudFoundry PaaS. All other logback based logging, including logging to logstash, works fine. I find all logs in stdout and in Kibana. Just the Logbook logs are not there when running remotely in the Open Liberty container.

Any obvious thing I'm missing here? Maybe some class loader issues? Any ideas on what else I could try and test?

I tried the LogstashLogbackSink but also no success.

Expected Behavior

The regular log.trace(.) statements in DefaultHttpLogWriter should send this log entry to the according appenders (stdout and logstash), but the the request/response log entries are visible in neither sinks.

Actual Behavior

The request/response log entries are not visible anywhere.

Possible Fix

Unknown.

Steps to Reproduce

1. Setup a local Open Liberty version 24.+ server
2. Deploy a simple Spring Boot 3.2.8 with a few REST endpoints, and Logbook included as configured above

Context

I want to use Logbook as the request/response logging framework for all our Spring Boot based services.

Your Environment

• Java 21.+
• Open Liberty 24.+
• Logbook 3.9.0
• logstash-logback-encoder 7.4