Describe the bug
Some spring.security counters contain still wrong value after active counter were fixed#14031
At least the following counters contains too high or too low values.
spring_security_http_secured_requests_seconds_count{error="none",} 10008.0
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="13",spring_security_filterchain_size="13",spring_security_reached_filter_name="ServerWebExchangeReactorContextWebFilter",spring_security_reached_filter_section="after",} 9981.0
To Reproduce Use example apps provided in #14031 and use latest 6.1.6 snapshot for spring security
Use Jmeter or similar with 20 treads, making 500 requests on each thread using connection pool (connection reused)
After test checks the metrics from mx/prometheus endpoint. Most metrics should show count 0, 1 or 10000 (or 10001 as one Prometheus query). In my test the following results were seen. Test was done with TLS but wo TLS similar should be seen on corresponding counters like "spring_security_http_unsecured_requests_seconds_count
This metrics should be 10001 as 10000 requests plus 1 Prometheus requests
spring_security_http_secured_requests_seconds_count{error="none",} 10008.0
And this should be also 10001
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="13",spring_security_filterchain_size="13",spring_security_reached_filter_name="ServerWebExchangeReactorContextWebFilter",spring_security_reached_filter_section="after",} 9981.0
Full results (max and sum removed)
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="13",spring_security_filterchain_size="13",spring_security_reached_filter_name="AuthorizationWebFilter",spring_security_reached_filter_section="before",} 10001.0
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="3",spring_security_filterchain_size="13",spring_security_reached_filter_name="AuthenticationWebFilter",spring_security_reached_filter_section="after",} 1.0
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="7",spring_security_filterchain_size="13",spring_security_reached_filter_name="LoginPageGeneratingWebFilter",spring_security_reached_filter_section="after",} 1.0
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="0",spring_security_filterchain_size="0",spring_security_reached_filter_name="none",spring_security_reached_filter_section="after",} 4.0
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="13",spring_security_filterchain_size="13",spring_security_reached_filter_name="ServerWebExchangeReactorContextWebFilter",spring_security_reached_filter_section="after",} 9981.0
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="10",spring_security_filterchain_size="13",spring_security_reached_filter_name="ServerWebExchangeReactorContextWebFilter",spring_security_reached_filter_section="after",} 1.0
spring_security_authorizations_active_seconds_active_count{spring_security_authentication_type="n/a",spring_security_authorization_decision="unknown",spring_security_object="exchange",} 0.0
spring_security_authorizations_seconds_count{error="none",spring_security_authentication_type="n/a",spring_security_authorization_decision="true",spring_security_object="exchange",} 10001.0
spring_security_http_secured_requests_seconds_count{error="none",} 10008.0
spring_security_http_secured_requests_active_seconds_active_count 1.0
spring_security_filterchains_active_seconds_active_count{spring_security_filterchain_position="0",spring_security_filterchain_size="0",spring_security_reached_filter_name="none",spring_security_reached_filter_section="after",} 0.0
spring_security_filterchains_active_seconds_active_count{spring_security_filterchain_position="0",spring_security_filterchain_size="0",spring_security_reached_filter_name="none",spring_security_reached_filter_section="before",} 0.0
http_server_requests_seconds_count{error="none",exception="none",method="GET",outcome="SUCCESS",status="200",uri="/monoCancel",} 10000.0
reactor_netty_http_server_response_time_seconds_count{method="GET",status="200",uri="/monoCancel",} 10000.0
reactor_netty_http_server_data_received_bytes_count{uri="/monoCancel",} 10000.0
reactor_netty_http_server_data_received_bytes_count{uri="/mx/prometheus",} 1.0
reactor_netty_http_server_data_sent_bytes_count{uri="/monoCancel",} 10000.0
custom_channel_invocations_total{source="None",uri="/monoCancel",} 10000.0
If you query Prometheus metrics during the test you can see "spring_security_filterchains_active_seconds_active_count" "after" is normally 0 but might go to 1. After test querying Prometheus "spring_security_filterchains_active_seconds_active_count" "after" is now back to zero. Also after external cancel active goes back to zero. This confirm #14031 fixed.
** Versions ** - Windows, Linux - SpringBoot 3.14 and security web snap from 6.1.6
Comment From: jzheaux
Thanks, @jtorkkel, for the additional report.
spring_security_filterchains_seconds_count{error="none",spring_security_filterchain_position="13",spring_security_filterchain_size="13",spring_security_reached_filter_name="ServerWebExchangeReactorContextWebFilter",spring_security_reached_filter_section="after",} 9981.0
I don't see this one as a problem. The after observation is only started if it is reached. In the event of a preceding cancellation, the after observation is not started, making the number less than the total number of requests.
Does that sound reasonable?
As for the overage in the other observation, I will take a look and report back.