Document limitations of Servlet Filter observations

[jonatan-ivanov]

Affects: 6.0.0-SNAPSHOT

If micrometer-observation is set-up and if I throw an exception from a controller:

@GetMapping("/trouble")
String trouble() {
    LOGGER.info("3,2,1... Boom!");
    throw new IllegalArgumentException("Noooooo!");
}

The ERROR log entry does not contain the traceID/spanId, see [boot3-sample,,] (log correlation does not work):

2022-10-28T12:37:16.647-07:00  INFO [boot3-sample,635c2f6c8cb895fa15f922f7cacc6954,15f922f7cacc6954] 96088 --- [nio-8080-exec-1] i.m.boot3.samples.SampleController       : 3,2,1... Boom!
2022-10-28T12:37:16.660-07:00 ERROR [boot3-sample,,] 96088 --- [nio-8080-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.lang.IllegalArgumentException: Noooooo!] with root cause

java.lang.IllegalArgumentException: Noooooo!
...

I think the issue is either the error logging is not "observed" or it is not "in-Scope".

[bclozel]

Hey @jonatan-ivanov

From what I understand, this is being logged from an org.apache.catalina class? In this case, it's called outside of the observation scope of the Servlet filter so it's expected at this stage not to have the log correlation anymore.

I don't think Framework can do anything about that.

[jonatan-ivanov]

Yes, it is definitely out of the scope of the Observation.
I'm not sure if it is purely Catalina or a component that we provide to Catalina (dispatcherServlet in the name of the logger).

@marcingrzejszczak might have more details, in Sleuth, we fixed it with a Valve: TraceValve

[bclozel]

I'm not sure if it is purely Catalina or a component that we provide to Catalina (dispatcherServlet in the name of the logger).

I guess Tomcat is logging the name of the Servlet.

I did discuss the Valve possibility with Marcin, and while it would bring better measurements in general, I don't think it's the right approach for Framework:

• we don't ship container specific API and we usually stick to the Servlet API
• we would need to implement the same feature for Jetty, Undertow and others - containers would need to offer the same features and apply it at the same phase during the request lifecycle

Taking a step back, I think the Servlet filter is enough to instrument the application behavior.

[jonatan-ivanov]

I think having traceId/spanId on error logs is a vital feature.
Errors are the events where users most likely want to look into, with missing traceId/spanId they are unable to do so out of the box.

[bclozel]

I think that the main issue here is that exceptions unhandled by the web framework are not logged by Spring and bubble up to the Servlet container, which chooses to log them at the ERROR level. If Spring web frameworks logged those exceptions, this user experience issue would be solved. Considering a custom valve here would only work for Tomcat and would not address the issues listed in my previous comment.

DispatcherServlet is not logging those at the moment, maybe a dedicated logger and/or a configuration setting would help. This is a fundamental part of the logging experience, and it's been like this for a very long time so changing this behavior is likely to bother a lot of Spring developers out there.

Note that exceptions handled by Spring MVC are logged by the Framework, not by the container. For example here, using the new Problem Detail support (this would also work for any exception handler in general).

@Controller
public class SomeController {

	private static final Log logger = LogFactory.getLog(SomeController.class);

	@GetMapping("/test")
	public String test() {
		logger.info("test() is called");
		throw new IllegalStateException("the request has an invalid state");
	}

	@ExceptionHandler(IllegalStateException.class)
	ProblemDetail handleIllegalState(IllegalStateException exc) {
		ProblemDetail problemDetail = ProblemDetail.forStatus(HttpStatus.BAD_REQUEST);
		problemDetail.setTitle("Illegal State");
		return problemDetail;
	}

}

$ http localhost:8080/test

HTTP/1.1 400
Connection: close
Content-Type: application/problem+json
Transfer-Encoding: chunked

{
    "instance": "/test",
    "status": 400,
    "title": "Illegal State",
    "type": "about:blank"
}

INFO [,ec159f78ffd24972f83a88a093fd16dc,b23d770731d64cb8]  28380 --- [nio-8080-exec-1] com.example.error.SomeController         : test() is called
WARN [,ec159f78ffd24972f83a88a093fd16dc,b23d770731d64cb8]  28380 --- [nio-8080-exec-1] .m.m.a.ExceptionHandlerExceptionResolver : Resolved [java.lang.IllegalStateException: the request has an invalid state]

[jonatan-ivanov]

I only used the valve as an example (Tomcat), I'm not saying we should use it or that would be a universal solution. I'm only saying that out of the box this does not work and this is a rather important functionality.

I guess the question for me is: can we do anything with this in the 6.0 timeline or in 6.1? I.e.: brainstorming about it with the whole team?

If this can't be fixed in 6.0, can we document it? I guess other options should work too, like having a ControllerAdvice or using a custom ObservationHandler.