Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use of Hooks.onOperatorDebug causes performance degradation on 404 errors [SPR-17475] #22007

Closed
spring-issuemaster opened this Issue Nov 7, 2018 · 4 comments

Comments

Projects
None yet
2 participants
@spring-issuemaster
Copy link
Collaborator

spring-issuemaster commented Nov 7, 2018

xenv opened SPR-17475 and commented

This problem has existed since Springboot 2.0, but I don't know why nobody mentioned it. It would be exploited by attackers and consume all the resources of the server.

 

When we create a Webfilter in Webflux, if there is a large amount of 404 access, it will cause the Filter chain to be seriously misassembled, resulting in a huge amount of code being executed repeatedly, consuming the resources of the entire server.

 

To reproduce this problem, we just need to create a Webflux project from SPRING INITIALIZR and create a simple Webfilter, and open the log mode.

 

The simple WebFilter like this:

 

@Component
public class TestFilter implements WebFilter {
    @NonNull
    @Override
    public Mono<Void> filter(@NonNull ServerWebExchange ctx, @NonNull WebFilterChain chain) {
        Hooks.onOperatorDebug();
        return chain.filter(ctx).log();
    }
}

 

 

Or you can download the project from my github:  https://github.com/xenv/webflux-bug-example 

 

And then, you just need to access a few urls that don't exist, like /404, you will see that the wrongly assembled Filter chain is getting longer and longer.

 

Error has been observed by the following operator(s):Error has been observed by the following operator(s): |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.log ⇢ com.example.demo.TestFilter.filter(TestFilter.java:19) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119) |_ Mono.error ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.lambda$handle$0(ResourceWebHandler.java:327) |_ Mono.defer ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.switchIfEmpty ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:325) |_ Mono.flatMap ⇢ org.springframework.web.reactive.resource.ResourceWebHandler.handle(ResourceWebHandler.java:329) |_ Mono.then ⇢ org.springframework.web.reactive.result.SimpleHandlerAdapter.handle(SimpleHandlerAdapter.java:46) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:151) |_ Mono.flatMap ⇢ org.springframework.web.reactive.DispatcherHandler.handle(DispatcherHandler.java:152) |_ Mono.defer ⇢ org.springframework.web.server.handler.DefaultWebFilterChain.filter(DefaultWebFilterChain.java:119)

 

If you request a 404 page 10,000 times with a script, the response time of the 404 page may reach 1000-2000ms, and the CPU rises to 100%, which is very terrible. I hope it can be fixed soon. Thank you.

 


Affects: 5.1.2

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Nov 9, 2018

Rossen Stoyanchev commented

Thanks for the report. As mentioned in the Reactor docs, the Hooks.onOperatorDebug() is a debug feature that has performance implications, and should be used as a last resort. It is not expected to be used in production.

That said I do see that the information reported under "Error has been observed by the following operator(s)" multiplies with each request. Simon Baslé is this expected behavior? One thing I considered is to move the call to Hooks.onOperatorDebug() to the main method in DemoApplication, so it's invoked only once on startup. However that didn't seem to make a difference.

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Nov 10, 2018

xenv commented

Thank you for your comment. This is indeed a problem with Hooks.onOperatorDebug(). The bug didn't happen, if it is not turned on anywhere. In the formal environment, I turned it on and ignored the 404 error. I thought it was safe , but it still caused my performance to drop on the 404 page. And the strange thing is that this is only for 404 errors.

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Nov 12, 2018

Simon Baslé commented

This is a limitation coming from the way Hooks.onOperatorDebug() is designed, unfortunately :(

SPR uses a singleton constant Exception for the 404 error, and the way Reactor implements debug "traceback" is that it adds a suppressed exception to the original exception the first time an operator sees it then it enriches said suppressed exception each time it the original exception is seen by further operators.

This allows the "traceback" to display information about the steps through which the error propagated in addition to the steps leading to the error, covering the reactive chain from source to subscription.

The problem with singleton exceptions is that they do not only get enriched by each operator that sees the error, but further enriched by each new occurrence of the error, which can rapidly compound.

@spring-issuemaster

This comment has been minimized.

Copy link
Collaborator Author

spring-issuemaster commented Nov 12, 2018

Rossen Stoyanchev commented

We can change the exception to be created per request.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.