When enabling structured logging with the ECS format in a Spring Boot 3.4.2 (also occurs with 3.4.0 and 3.4.1) application, log statements inside catch blocks are completely missing from both the console and file outputs. Consider the following snippet:
public void mymethod() {
log.atInfo()
.addKeyValue("operation", "mymethod")
.log("Start processing data message");
try {
// Some code here that throws an exception
} catch (final Exception e) {
log.atInfo()
.addKeyValue("operation", "mymethod")
.log("Unable to process the message.");
}
}
Expected Behavior
- Both log statements should appear in the console and log file.
- The first log message ("Start processing data message") appears as expected.
- The second log message ("Unable to process the message.") inside the catch block should also be logged.
Actual Behavior
- The first log message appears as expected.
- The log message inside the catch block never appears in the console or log file.
- Other logs in the application continue to be logged normally.
Observations & Confirmations
- The exception is definitely thrown (verified using e.printStackTrace(), which prints the stack trace correctly).
- Disabling structured logging restores normal behavior—logs inside the catch block appear as expected.
- The issue occurs with formats ecs and logstash but not with gelf
- The application continues logging normally for other requests—only log statements that follow an exception are missing.
- We got the same behaviour using version 3.4.0 and 3.4.1
Comment From: wilkinsona
I can't reproduce the described behavior. I tried to do so using the following code:
package com.example.gh_44048;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
@RestController
@SpringBootApplication
public class Gh44048Application {
private static final Logger log = LoggerFactory.getLogger(Gh44048Application.class);
public static void main(String[] args) {
SpringApplication.run(Gh44048Application.class, args);
}
@GetMapping
public void mymethod() {
log.atInfo()
.addKeyValue("operation", "mymethod")
.log("Start processing data message");
try {
throw new RuntimeException();
} catch (final Exception e) {
log.atInfo()
.addKeyValue("operation", "mymethod")
.log("Unable to process the message.");
}
}
}
and application.properties:
spring.application.name=gh-44048
logging.structured.format.console=ecs
Starting the application and making a request to http://localhost:8080 produces the following output:
{"@timestamp":"2025-02-03T09:36:22.329424Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"com.example.gh_44048.Gh44048Application","message":"Starting Gh44048Application using Java 17.0.13 with PID 71204 (\/Users\/aw036093\/dev\/temp\/gh-44048\/bin\/main started by aw036093 in \/Users\/aw036093\/dev\/temp\/gh-44048)","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:22.332526Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"com.example.gh_44048.Gh44048Application","message":"No active profile set, falling back to 1 default profile: \"default\"","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:22.738305Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","message":"Tomcat initialized with port 8080 (http)","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:22.745812Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"org.apache.catalina.core.StandardService","message":"Starting service [Tomcat]","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:22.746063Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"org.apache.catalina.core.StandardEngine","message":"Starting Servlet engine: [Apache Tomcat\/10.1.34]","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:22.772324Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[\/]","message":"Initializing Spring embedded WebApplicationContext","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:22.773063Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext","message":"Root WebApplicationContext: initialization completed in 416 ms","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:22.932317Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","message":"Tomcat started on port 8080 (http) with context path '\/'","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:22.938011Z","log.level":"INFO","process.pid":71204,"process.thread.name":"main","service.name":"gh-44048","log.logger":"com.example.gh_44048.Gh44048Application","message":"Started Gh44048Application in 0.789 seconds (process running for 0.959)","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:32.950884Z","log.level":"INFO","process.pid":71204,"process.thread.name":"http-nio-8080-exec-1","service.name":"gh-44048","log.logger":"org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[\/]","message":"Initializing Spring DispatcherServlet 'dispatcherServlet'","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:32.951147Z","log.level":"INFO","process.pid":71204,"process.thread.name":"http-nio-8080-exec-1","service.name":"gh-44048","log.logger":"org.springframework.web.servlet.DispatcherServlet","message":"Initializing Servlet 'dispatcherServlet'","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:32.951941Z","log.level":"INFO","process.pid":71204,"process.thread.name":"http-nio-8080-exec-1","service.name":"gh-44048","log.logger":"org.springframework.web.servlet.DispatcherServlet","message":"Completed initialization in 0 ms","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:32.969738Z","log.level":"INFO","process.pid":71204,"process.thread.name":"http-nio-8080-exec-1","service.name":"gh-44048","log.logger":"com.example.gh_44048.Gh44048Application","message":"Start processing data message","operation":"mymethod","ecs.version":"8.11"}
{"@timestamp":"2025-02-03T09:36:32.970241Z","log.level":"INFO","process.pid":71204,"process.thread.name":"http-nio-8080-exec-1","service.name":"gh-44048","log.logger":"com.example.gh_44048.Gh44048Application","message":"Unable to process the message.","operation":"mymethod","ecs.version":"8.11"}
Note the final entry in the log, produced by the log statement in the catch block.
If you would like us to spend some more time investigating, please spend some time providing a complete yet minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.