Affects: 6.0.15, 6.1.3
This property is necessary for collecting metrics via Micrometer.
In the org.springframework.http.server.observation.DefaultServerRequestObservationConvention class, the protected KeyValue uri(ServerRequestObservationContext context) method tries to get context.getPathPattern() but it is always null.
Comment From: bclozel
We have tests that check for this case. Can you elaborate? What's the endpoint? Can your provide a minimal sample application that reproduces the problem?
Comment From: bergerdenes
Repro repository: https://github.com/bergerdenes/metrics-repro Similar issue reported (and others referenced within): https://github.com/spring-projects/spring-framework/issues/31028
Comment From: bclozel
I'm sorry I can't reproduce the problem. I ran many requests on my local machine, including using benchmarking tools and I'm seeing:
$ curl localhost:8080/metrics | grep ^http_server_requests_seconds
http_server_requests_seconds{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/metrics",quantile="0.5",} 0.0
http_server_requests_seconds{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/metrics",quantile="0.95",} 0.0
http_server_requests_seconds_count{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/metrics",} 5.0
http_server_requests_seconds_sum{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/metrics",} 0.066770067
http_server_requests_seconds{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",quantile="0.5",} 0.007856128
http_server_requests_seconds{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",quantile="0.95",} 0.016769024
http_server_requests_seconds_count{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",} 30016.0
http_server_requests_seconds_sum{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",} 256.0871663
http_server_requests_seconds_max{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/metrics",} 0.007237065
http_server_requests_seconds_max{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",} 0.054313366
Thoughts?
Comment From: bergerdenes
My output for the same:
http_server_requests_active_seconds_max{exception="none",method="GET",outcome="SUCCESS",status="200",uri="UNKNOWN",} 0.038592375
http_server_requests_active_seconds{exception="none",method="GET",outcome="SUCCESS",status="200",uri="UNKNOWN",quantile="0.5",} 0.0385395
http_server_requests_active_seconds{exception="none",method="GET",outcome="SUCCESS",status="200",uri="UNKNOWN",quantile="0.95",} 0.038592375
http_server_requests_active_seconds_active_count{exception="none",method="GET",outcome="SUCCESS",status="200",uri="UNKNOWN",} 1.0
http_server_requests_active_seconds_duration_sum{exception="none",method="GET",outcome="SUCCESS",status="200",uri="UNKNOWN",} 0.038580208
http_server_requests_seconds{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",quantile="0.5",} 0.001409024
http_server_requests_seconds{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",quantile="0.95",} 0.01622016
http_server_requests_seconds_count{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",} 3.0
http_server_requests_seconds_sum{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",} 0.018441751
http_server_requests_seconds_max{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/test",} 0.016043917
Comment From: bclozel
I'm only seeing "UNKNOWN" tags for the http_server_requests_active metric, which is expected. For each observation, the Micrometer metrics handler creates a long task timer that measures ongoing requests. This tag value is expected for those, as tags are collected as soon as the observation starts; at this stage, the instrumentation cannot know on which controller handler the request will be mapped.
That is an interesting point, though. If you believe that this is confusing, or if you'd like to have an option to disable those long task timers, please raise a Micrometer issue in order to discuss this matter with the team. The metrics handler code is managed by Micrometer directly.
In light of that, I'm closing this issue. Thanks!
Comment From: bergerdenes
@bclozel please reopen the issue. I have updated the repro project with explanation.
If one calls the "metrics" endpoint first then later you will see UNKNOWN for all of the API endpoints.
Comment From: bclozel
That's an entirely different setup now! The application is not using Spring MVC but it's using Jersey. In this case, the Spring instrumentation cannot know about the URI pattern mapped to the JAX-RS endpoint. Please use the Jersey instrumentation for your application.
Comment From: bergerdenes
Then what is the explanation for this:
If you change the order (i.e. call a Jersey endpoint first), $ curl localhost:8080/jersey/test $ curl localhost:8080/metrics | grep ^http_server_requests then the metrics are good.
Comment From: bclozel
@bergerdenes I don't know. That's probably a bug to be reported to the Jersey instrumentation? The Spring instrumentation is not being used here. Tags are created by the io.micrometer.core.instrument.binder.jersey.server.DefaultJerseyTagsProvider.
Edit: Apologies, in this case the instrumentation is done by Micrometer directly. I was confused because it's also been contributed to Jersey directly.
Comment From: bergerdenes
I have debugged into DefaultJerseyTagsProvider and the JerseyTags.uri(event) returns the correct value in both cases (i.e. when the "metrics" endpoint is called first and when the "test" endpoint is called first)
So I don't know how to progress forward.
I have also placed breakpoint inside DefaultServerRequestObservationConvention#uri but the context.getPathPattern() is null most of the times.
Comment From: bclozel
I think you should try disabling the Spring MVC instrumentation by excluding the org.springframework.boot.actuate.autoconfigure.observation.web.servlet.WebMvcObservationAutoConfiguration. If this works, this means that instrumentations are somehow overstepping each other.
You can do so by updating your application with:
@SpringBootApplication(exclude=WebMvcObservationAutoConfiguration.class)
If this solves the problem, you can create a Spring Boot issue to better figure out this can be better addressed.
Comment From: bergerdenes
@SpringBootApplication(exclude=WebMvcObservationAutoConfiguration.class)
solved the issue, thanks for the hint.
I hope it is adequate if I just create a SpringBoot issue and reference this issue here...