SpringFW 6 / SpringBoot 3.1.4 http_server_requests_seconds_count metrics incorrectly reports outcome=UNKNOWN for success requests and not reporting exception/errors for client cancel #31365
Comments
spring-projects-issues
added
the
status: waiting-for-triage
|
Thanks for the report, but it's not clear from this issue what is the main ask. |
bclozel
added
the
status: waiting-for-feedback
|
Note the following comment: #29720 (comment) We are getting cancel signals from the HTTP library and we are reporting those as best as we can. The response status was indeed "200", as what's being sent by the server. It could be that the client cancelled before receiving the response or right after, racing with the normal closure of the channel. We can only assume "UNKNOWN" as the status since we cannot know whether the response as been received. |
|
Anyway Spring Boot 2.3 is out of support, so we can't change anything there. I'm closing this issue as a result. Thanks! |
bclozel
added
in: web
|
Sorry typo in version, should be 3.1.4 |
jtorkkel
changed the title
|
Should I create new one |
jtorkkel
changed the title
|
I created new one #31367 with correct version number |
|
No need to create a new one. |
|
Why not reopen, it is latest Spring Framework 6.x and springBoot 3.1.4 |
|
There are 3 main issues in http_server_requests_seconds_count/sum/max/bucket metrics in SpringBoot 3.x/Springframework 6.x
Thus success, client cancel and random extra false doOnCancel events contribute up to 10% of the unknown metrics. This cause false alerts when errors. Thus http_server_requests_seconds_count/sum/max/bucket metrics are random and useless. |
|
I'll review this issue on Monday.
This is an open source project and we expect from our community constructive feedback and actionable issues. |
|
Thanks for opening the error. Sorry for stating that metrics are now useless due this regression. We have been successfully using spring metrics metrics for years, they have been super reliable and accurate. They can pinpoint the issue into single requests. We are just migrating from 2.7 to 3.1 and finding this kind of "regression" late, and finding same issues being reported earlier but because not actionable not progressing. Sounds that metrics are not "tested" systemically, and because of that issues are not seen in automated tests. I admit that they are not always easy to reproduce, and probably require proper end to end setup or use of customizable mock server, with large number of requests and test automation. Because of that we also see this issue when analyzing production or performance environment metrics against test results. We also missed these in our unit tests. I tried to create detailed description of the error and detailed repro steps, due randomness it might not happen in all test setup so changing setup slightly might bring issue visible. I also linked two separate issue to same case as I think they are related, and another is not reported earlier But the issue is real, once again sorry for non constructive feedback. |
snicoll
added
status: waiting-for-triage
After this comment #29720 (comment), I'm actually tempted to change our instrumentation and ignore cancellations if the response is already committed. In this case, it is very likely that the response was sent but the client closed the connection before we had a chance to complete the exchange. I've opened #31387 as an enhancement, as we can't change this behavior in a maintenance release. It's not really possible to know for sure here, since we're setting status "UNKNOWN" if the client has disconnected. This one looks strange and I think this is a bug, I've opened #31388 (please check that one and let me know if the described behavior sounds sane).
I don't think those are duplicate calls to and check whether you have a consistent pairs of
Issues created above could improve the situation here. We changed things from Spring Boot 2.5 since the reported exceptions were either completely artificial (and not thrown anywhere in the code really), or they could change at any time depending on the server implementation. As for the "outcome" tag, we thought about "CANCELLED" but went with UNKNOWN at the time. You can check whether improvements made here will be helpful by setting up a custom convention on the filter, like this one: public class CustomServerObservationConvention extends DefaultServerRequestObservationConvention {
private static final KeyValue HTTP_OUTCOME_UNKNOWN = KeyValue.of(ServerHttpObservationDocumentation.LowCardinalityKeyNames.OUTCOME, "UNKNOWN");
@Override
protected KeyValue status(ServerRequestObservationContext context) {
return (context.getResponse() != null && context.getResponse().getStatusCode() != null) ?
KeyValue.of(ServerHttpObservationDocumentation.LowCardinalityKeyNames.STATUS, Integer.toString(context.getResponse().getStatusCode().value())) :
KeyValue.of(ServerHttpObservationDocumentation.LowCardinalityKeyNames.STATUS, "UNKNOWN");
}
@Override
protected KeyValue outcome(ServerRequestObservationContext context) {
if (context.isConnectionAborted() && !context.getResponse().isCommitted()) {
return KeyValue.of(LowCardinalityKeyNames.OUTCOME, "SUCCESS");
}
return super.outcome(context);
}
}Let us know if:
|
bclozel
added
the
status: waiting-for-feedback
|
Thanks, I tested CustomServerObservationConvention and with 20000 requests (20 threads, 1000 times) in 20 seconds Now status="UNKNOWN"-->"200", and outcome="UNKNOWN" still as only status is overwritten by CustomServerObservationConvention Total count was 13 extra, do not understand where they come from, uri is correct. Something must be counted twice. http_server_requests_seconds_count{app="service-v3",cid="",error="none",exception="none",host="localcast",method="GET",outcome="UNKNOWN",springBoot="3.1.4",status="200",uri="/customers"} 1479.0 http_client_requests_seconds_count{app="dbf-customerinfo-service-v3",cid="",client_name="localhost",clientName="localhost",error="none",exception="none",host="FINPWM18138472",method="GET",outcome="SUCCESS",springBoot="3.1.4",status="200",uri="/customers/{customer-id}/info",ver="3.1.10-SNAPSHOT",} 20000.0 I did not notice any logs from CustomWebFilter , should I see something ? |
spring-projects-issues
added
status: feedback-provided
|
Update, Now CustomWebFilter works Test 1 3022 reactor log events, 2021 parallel, 1001 nio: 1001 request(unbounded), parallel 1000, 1 http-nio Summary:
Http server records one extra metrics. Up to 20 parallel requests one extra seems to be last one, nio (1001) and coming 50s late !!! test 2: Running similar test with 10x more data, 20x 5000 results two extra http_server metrics entry and matching nio events, one in the middle and one coming after tests. When test time is increased these extra nio events increase. test 3 - testing external client cancel with override This override which checks isConnectionAborted and !isCommitted successfully turn external client cancels to outcome="CANCELED". I will comment new issues created tomorrow |
|
I've created #31417 which should address the main problem here. |
|
Thanks, again. As said in my tests there is no client cancel. There is 20 connection and no cancels. Jmeter should use http client with 4min connection timeout. I will turn on more logging to get confirmation. Unfortunately no metrics show if new sockets opened like netty client metrics does client like Jmeter cancel was separate issue I reported. I made more tests and here are my findings Summary of analysis
So I suspect that root cause for cancels is ServerWebExchangeReactorContextWebFilter context propagation error. Below metrics showing this quite clearly something wrong in ServerWebExchangeReactorContextWebFilter |
|
Thanks for the update. With #31417, we are going to fix the root cause of those "extra" observations being recorded. The frequency of those in my tests (and in yours it seems) is approx 1/5000, so quite far from the 10% you were mentioning initially. With #31388, the "status" tag will not be "UNKNOWN" as much as it was before. As for the With that being said, I don't se anything remaining in this issue here. The |
|
Thanks, We need investigate the ServerWebExchangeReactorContextWebFilter which in our case is probably reason for 5-10% ratio. We have also some custom MDC but after removing we still have issue. I can confirm that Jmeter in my test use only 20 connection, and success fully reuse them, sockets only closed after test completed. I made short test with 20 thread, 5 requests each ; then each socket reused 5 times, here socket 45205 shown |
|
Thanks, I'm closing this issue for now, we can reopen if it turns out the issues we've opened are not enough. |
bclozel
added
status: superseded
|
Thanks, I executed longer tests in our DEV 20x5000 (100 000 requests), connection pool used --> no eager socket close
My close to 10% UNKNOWN seems to happen in Windows, which seems to generate cancel 100x more frequently. However more concerning result from DEV test and from longer 24h tests is that This means the some false cancel() (or onComplete+cancel() is not catched by observation longTaskTimers when spring_security_filterchains_active post filter is applied and thus observation is never stop. Maybe cancel() close context --> stop cannot be called ! Note that some security needs to be used to activate the spring_security_filterchain observations. We use JWT token I did not fully understood if #31417 will eliminate the all false cancels() (when socket is not closed) which is root cause in my opinion or just try to minimize the issues in http_server_metrics. Frequency seems to be VM specific and and load specific, require at least 10 thread parallel requests in my tests. I can see that http_server_requests_active_seconds_active_count count goes down to zero (1 as prometheus query increase to 1 at least), I do not understand why it is stopped but spring_security_filterchains is not. I would expect it is run after spring_security_filterchain. What comes to issues you created And I did notice how exception label will be fixed, missing and clientCanceled (in SpringBoot 2.5 exception was set) |
The only difference here must be the networking stack and how the connection pools are dealing with socket events.
I've already replied to that, you should create an issue in the Spring Security project.
I fixes the fact that both "COMPLETE" and "CANCEL" signals can be received and only records observations once. If I'm not mistaken this was the main problem reported here. This is now fixed in SNAPSHOTs.
I've also replied to that already:
As for the last request:
I don't think we should bring that back as this exception was artificial and was only confusing users in the past. You can bring that back if you wish to with a custom convention. |
|
Understood, you fixes remove extra metrics, and related UNKNOWN. However root cause for cancel() is still open. It happen also in Linux as spring_security_filterchain "after" increase and resulting OOM or registry issue in micrometer unless it limit max longRunningTasks. I Override MeterObservationHandler onStart and onStop, Normal success case indicate that: When Failure/cancel() --> status UNKNOWN case then Sounds that filter are stopped in wrong order, and applying http.server.requests onStop trigger cancel() resulting status="UNKNOWN" and spring.security.filterchain after not to be stopped, or .. maybe something else leaks cancel() resulting filters to be stopped in random order. spring_security_filter are implemented in ObservationWebFilterChainDecorator --> I will raise spring security issue as it fails to catch the cancel() or ... |
Current situation:
There are 3 main issues in http_server_requests_seconds_count/sum/max/bucket metrics in SpringBoot 3.x/Springframework 6.x
success response are randomly often counted as status="UNKNOWN", outcome="UNKNOWN", error="none". Up to 10% of the calls might be incorrectly reported. The calls itself works correctly, so some doOnCancel due race before metrics are recorded
random extra status="UNKNOWN", outcome="UNKNOWN", error="none" metrics added not matching the request count. Probability << 1%. Those are not real meatrics but some kind of duplicate false doOnCancel events, maybe race double doOnCancels
calling client cancel (TCP close/reset) are not recorded with exception/error label but reported as status="UNKNOWN", outcome="UNKNOWN",error="none. doNotCancel source not recording to exception/error like in SringBoot2.5
Mixing success and UNKNOWN, and reporting incorrect counts results that http_server_requests_seconds_count/sum/max/bucket cannot be used to alerting or monitoring purpose. Data is false and cause false alerts.
metrics spring_security_filterchains_seconds_count and reactor_netty_http_server_data_sent_time_seconds_count report correct counts and status="200" for 1 and 2. Also all metrics generate by service like http_client_* and related netty metrics are correct.
canceled case 3 requests reported correctly in spring_security_filterchains_seconds_count filter spring_security_reached_filter_name="AuthorizationWebFilter"
Not reported in filter spring_security_reached_filter_name="ServerWebExchangeReactorContextWebFilter", also reactor_netty_http_server_data_sent_time_seconds_count seems not to report other than 200
Expected behavior:
metrics success count status="200, outcome="SUCCESS", error="none" to match requests count when no errors, success not reported as status="UNKNOWN", outcome="UNKNOWN", error="none"
no extra/duplicate status="UNKNOWN", outcome="UNKNOWN", error="none" metrics without matching requests
client calling the spring application and requests canceled should be counted as status="UNKNOWN", outcome="UNKNOWN", exception/error="CancelledServerWebExchangeException" instead of status="UNKNOWN", outcome="UNKNOWN", exception/error="none"
Tested Versions:
SpringBoot 3.1.4 (also 3.1.2)
Spring Framework 6.x matching springBoot
Wndows and Linux
Java 17
We use reactive programming and new observation framework.
How to reproduce:
1 and 2. Simplest way just generate requests usign Jmeter with paraller threads for long enough duration, for example 20 threads and 100000 request for each thread, then check that metrics report 2M success and no UNKNOWN.
3 can be tested by generating traffic similar way, but stopping the jmeter forcefully. Metrics should report canceled call with exception/error label different than "none", or as success if specific thread was not canceled. No status="UNKNOWN, outcome=UNKNOWN", error="none" should be reported.
Detailed description:
In our testing we noticed that metrics "http_server_requests_seconds_count" reporting is incorrectly and result are misleading.
For example if we make 1 requests (warmup after restart) plus 2000 requests (20 threads, 100 times) from Jmeter, we expect to see 2001 success responses reported by metrics. Jmeter reports 2001 success response as expected.
However http_server_requests_seconds_count reports less that 2001 success
http_server_requests_seconds_count{app="service-v3",cid="",error="none",exception="none",host="hostx",method="GET",outcome="SUCCESS",springBoot="3.1.4",status="200",uri="/customers/",ver="3.1.10-SNAPSHOT",} 1868.0
And we see one or more status="UNKNOWN", outcome="UNKNOWN"
http_server_requests_seconds_count{app="service-v3",cid="",error="none",exception="none",host="hostx",method="GET",outcome="UNKNOWN",springBoot="3.1.4",status="UNKNOWN",uri="/customers/",ver="3.1.10-SNAPSHOT",} 134.0
Total count might be larger than requests count, in our case we got one alltogether 2002 response when we expect to get 2001 success.
Jmeter is using connection pool and closing 20 connection only after the test.
If we use single thread issue is not seen. Looks that something in spring FW is generating false doOnCancel.
There is identical error created for springBoot Spring Boot (version 3.1.2) has UNKNOWN status in prometheus metrics but apparently issue not progressing as FW issue, not springboot issue.
Other metrics in system reports correctly 2001 requests.
Spring security, and reactor netty metrics showns correctly 2001 requests, also http client:
spring_security_filterchains_seconds_count{app="service-v3",cid="",error="none",host="hostx",spring_security_filterchain_position="9",spring_security_filterchain_size="9",spring_security_reached_filter_name="AuthorizationWebFilter",spring_security_reached_filter_section="before",springBoot="3.1.4",ver="3.1.10-SNAPSHOT",} 2001.0
http_client_requests_seconds_count{app="service-v3",cid="",client_name="localhost",clientName="localhost",error="none",exception="none",host="hostx",method="GET",outcome="SUCCESS",springBoot="3.1.4",status="200",uri="/customers/{customer-id}",ver="3.1.10-SNAPSHOT",} 2001.0
reactor_netty_http_server_data_received_time_seconds_count{app="service-v3",cid="",host="hostx",method="GET",springBoot="3.1.4",uri="/",ver="3.1.10-SNAPSHOT",} 2001.0
reactor_netty_http_server_data_sent_time_seconds_count{app="service-v3",cid="",host="hostx",method="GET",springBoot="3.1.4",status="200",uri="/",ver="3.1.10-SNAPSHOT",} 2001.0
Seems that issue happens in ServerHttpObservationFilter class filter and doOnCancel get triggered randomly resulting reporting SUCCESS as UNKNOWN.
In addition we think there is regression for exception/error label handling. doOnCancel does not set exception/error label values.
If we generate client error by canceling JMETER forcefully during the test pressing stop (jmeter close socket or sends reset while waiting response), in springboot 2.5 onwards it reported consistently
"status="200", outcome="UNKNOWN", exception="CancelledServerWebExchangeException."
In SpringBoot 2 initially http_server metrics did not implement doOnCancel at all for metrics at all, so no metrics were seen. We raised the issue to and it was added to 2.5 SpringBoot, fix was apparently done to spring FW.
Unfortunately status was still incorrectly "200" as there is no standard error codes for client canceling connection (de facto 599 could be used) and spring developer made unfortunate decision to leave status to 200
Now in 3.1 it looks that client cancel is not detected at all or very seldom. And cancel errors are reported just like these incorrectly reported "UNKNOWN".
I can see that "cancels ends to be handled in ServerHttpObservationFilter filter as "doOnCancel", but now in 3.1 there are no exception/error set.
Actually ServerHttpObservationFilter filter has code which should catch DISCONNECTED_CLIENT_EXCEPTIONS but apparently lower level stack throw doOnCancel which get triggered instead.
http_server_requests_seconds_count{app="service-v3",cid="",error="none",exception="none",host="hostx",method="GET",outcome="UNKNOWN",springBoot="3.1.4",status="UNKNOWN",uri="/customers/",ver="3.1.10-SNAPSHOT",}
If service can response fast when requests is canceled sometimes we might get these metrics, but very seldom. AbortedException probably means that cancel is propagated, but not happening consistently. Sometimes also uri is changed to "UNKNOWN.
http_server_requests_seconds_count{app="service-v3",cid="",error="none",exception="none",host="hostx",method="GET",outcome="UNKNOWN",springBoot="3.1.4",status="UNKNOWN",uri="UNKNOWN",ver="3.1.10-SNAPSHOT",} 5.0
http_server_requests_seconds_count{app="service-v3",cid="",error="AbortedException",exception="AbortedException",host="hostx",method="GET",outcome="UNKNOWN",springBoot="3.1.4",status="UNKNOWN",uri="/customers/",ver="3.1.10-SNAPSHOT",} 2.0
if service use http client and client calls timeout then WebClientRequestException is added correctly to server and client metrics.
http_server_requests_seconds_count{app="service-v3",cid="",error="WebClientRequestException",exception="WebClientRequestException",host="hostx",method="GET",outcome="SERVER_ERROR",springBoot="3.1.4",status="500",uri="/customers"} 1.0
http_client_requests_seconds_count{app="dbf-customerinfo-service-v3",cid="",client_name="localhost",clientName="localhost",error="WebClientRequestException",exception="WebClientRequestException",host="hostx",method="GET",outcome="UNKNOWN",springBoot="3.1.4",status="CLIENT_ERROR",uri="/customers/{customer-id}} 1.0
Sounds that DISCONNECTED_CLIENT_EXCEPTIONS is catching only http client calls the service initiates but fails due timeouts etc, but not cancel which http server receiver from calling client.
I think that "CancelledServerWebExchangeException" exception/error should somehow also propagated to "doOnCancel"
All this means that http_server metrics are now very unreliable, inaccurate, random , thus very hard or impossible to use for tracking and correlating to errors.
doOnCancel should always set exception/error to other than "none", to differentiate form success.
The text was updated successfully, but these errors were encountered: