spring.security counters inaccurate due onComplete and cancel()

[jtorkkel]

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

[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.