Spring-cloud-gateway: Only one connection receive subscriber allowed with Content-Type application/x-www-form-urlencoded

[dave-fl]

Running on SR1.Finchley.

When the Gateway is under load I am seeing this occasionally. We are not doing anything where we are trying to intercept the response body.

2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT 2018-09-11 17:01:39.717 ERROR 14 --- [client-epoll-19] .a.w.r.e.DefaultErrorWebExceptionHandler : Failed to handle request [POST ]
2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT java.lang.IllegalStateException: Only one connection receive subscriber allowed.
2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT     at reactor.ipc.netty.channel.FluxReceive.startReceiver(FluxReceive.java:276) ~[reactor-netty-0.7.8.RELEASE.jar!/:0.7.8.RELEASE]
2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT     at reactor.ipc.netty.channel.FluxReceive.lambda$subscribe$2(FluxReceive.java:127) ~[reactor-netty-0.7.8.RELEASE.jar!/:0.7.8.RELEASE]
2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT     at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]
2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT     at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]
2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT     at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:322) ~[netty-transport-native-epoll-4.1.27.Final-linux-x86_64.jar!/:4.1.27.Final]
2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT     at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]
2018-09-11T13:01:39.71-0400 [APP/PROC/WEB/0] OUT     at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_172]

Only using retry and rewrite path filter + custom filter which populates headers and sets path.

[spencergibb]

Not much to go on. Doesn't look like it has anything specific to do with the gateway.

[canglang1973]

I also meet this question, if I use GET method ,I can request success.but I use POST method ,we will see this
exception like the first man's comment. My request params like KEY-VALUES. Who can fix this problem?

[dave-fl]

@canglang1973 Are you able to create a simple test scenario or does it only happen after a while or under load?

[spencergibb]

cc @violetagg

[violetagg]

Works by design
https://github.com/reactor/reactor-netty/issues/247

[dave-fl]

@violetagg @spencergibb
Spencer says not a gateway issue, Violetagg says not a Reactor Issue.

For whatever reason there appears at least in my testing that somehow POST bodies are being read by the gateway twice (or they are being put back into the pool with an invalid state).

[dave-fl]

@canglang1973 Using a simple test of having a query parameter + POST is not enough for me to reproduce the error.

[canglang1973]

` @Bean
public RouteLocator customRouteLocator(RouteLocatorBuilder builder) {
return builder.routes()
.route(r -> r.path("/router/rest")
.uri("http://127.0.0.1:8084")
).build();
}
This is my simple test ,not have other filters ,@dave-fl``` Have you solved this problem?Can you tell me your solution?

[canglang1973]

@spencergibb you can give me a simple test can support POST ,I think spring cloud gateway impossible not support POST method.

[spencergibb]

@violetagg in all these cases, the body isn't being read twice.

[spencergibb]

@canglang1973 we can't reproduce it

[canglang1973]

@spencergibb I used spring cloud gateway version is 2.0.1.RELEASE ,spring boot version is 2.0.5.RELEASE ,jdk is 1.8 .The point is I don't have user-defined filters .

[canglang1973]

I see all the issues ,man people meet this same question but nobody fix

[spencergibb]

@canglang1973 provide a project that recreates the problem and steps to reproduce it. It should be something we can clone or download.

[canglang1973]

@spencergibb This is my simple test url https://github.com/canglang1973/open-gateway , you can reproduce it . I hope you can help me to solve this problem.

[sabirove]

Hi. Seems like spring-boot issue. Happens with version 2.0.5. Lower versions are fine.
I have reported it here: https://github.com/spring-projects/spring-boot/issues/14509

[canglang1973]

@toffytofik Thank you very much ! I also use Spring boot 2.0.4 ,this problem has solved. So this is a bug for Spring boot 2.0.5 ? @spencergibb You can reproduce this problem use my simple.

[wilkinsona]

Please don't open multiple issues for the same problem until the root cause has been identified. It just wastes time and duplicates effort. If the problem occurs in Spring Boot 2.0.5 but does not occur in Spring Boot 2.0.4, then I think the most likely reason is a change in Reactor Netty. Another possibility is a change in Spring WebFlux although I think that's less likely. Spring Boot itself isn't really involved at the level where this problem is apparently occurring.

[dave-fl]

@canglang1973 For the 2.x branch of Spring Cloud gateway all my tests were on 2.0.4 which is why I only saw the issue intermittently rather than easily reproducible. I definitely do think there is an issue with 0.8.x and POSTS as I've already reported weird behavior with it.

[violetagg]

Thanks all for the details about the issue.
I'm using the reproducible scenario provided with https://github.com/spring-cloud/spring-cloud-gateway/issues/541#issuecomment-422634564

Here is what I see when debugging the issue:
The first subscriber is:

HttpWebHandlerAdapter [delegate=ExceptionHandlingWebHandler [delegate=FilteringWebHandler [delegate=org.springframework.web.reactive.DispatcherHandler@781a52cd]]]

2018-09-19 17:32:50.321 DEBUG 64081 --- [ctor-http-nio-2] r.ipc.netty.channel.ChannelOperations    : [HttpServer] [id: 0x21a66a89, L:/0:0:0:0:0:0:0:1:8081 - R:/0:0:0:0:0:0:0:1:62585] handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@2d7bb23a
2018-09-19 17:33:07.929 DEBUG 64081 --- [ctor-http-nio-2] reactor.ipc.netty.channel.FluxReceive    : [id: 0x21a66a89, L:/0:0:0:0:0:0:0:1:8081 - R:/0:0:0:0:0:0:0:1:62585] Subscribing inbound receiver [pending: 1, cancelled:false, inboundDone: true]
2018-09-19 17:33:07.937 TRACE 64081 --- [ctor-http-nio-2] o.s.c.g.f.WeightCalculatorWebFilter      : Weights attr: {}
2018-09-19 17:33:07.943 DEBUG 64081 --- [ctor-http-nio-2] o.s.web.reactive.DispatcherHandler       : Processing POST request for [http://localhost:8081/router/rest]

So Spring Framework is subscribed for the incoming request body.

Then Spring Gateway obtains the the request body here https://github.com/spring-cloud/spring-cloud-gateway/blob/2.0.x/spring-cloud-gateway-core/src/main/java/org/springframework/cloud/gateway/filter/NettyRoutingFilter.java#L123
and tries to send it to the origin. Reactor Netty needs to subscribe to the provided Publisher but it seems that Spring Framework trie to subscribe again, this causes the failure. I might be wrong.

I tried it with Reactor Netty 0.7.9.RELEASE and 0.7.8.RELEASE with both I can see the issue.

@rstoyanchev @spencergibb What do you think?

Regards,
Violeta

[rstoyanchev]

There isn't anything in the Spring Framework that will consume the request body as far as I know. That has to be driven by some code either directly via request.getBody() or indirectly, e.g. exchange.getFormData().

[spencergibb]

@canglang1973 or @violetagg can either of you tell me how to reproduce it, I am unable.

[sabirove]

@rstoyanchev @spencergibb ,
https://github.com/toffytofik/issue541

Steps to reproduce:

1. launch App.main
2. fire a request

curl -d "key=f9a922bd-3007-4393-a76e-925fc009639c.txt&uuid=f9a922bd-3007-4393-a76e-925fc009639c&name=rubycsv.txt&bucket=fineuploadertest&etag=123" -X POST http://localhost:8080/path1/123/path2/path3

fails returning:
{"timestamp":"2018-09-19T16:54:40.866+0000","path":"/path1/123/path2/path3","status":500,"error":"Internal Server Error","message":"Only one connection receive subscriber allowed."}
stacktrace.txt

1. build.gradle -> change springBootVersion: '2.0.5.RELEASE' -> '2.0.4.RELEASE'
2. repeat steps 1. and 2.

works ok returning:
OK. param=123, body={key=[f9a922bd-3007-4393-a76e-925fc009639c.txt], uuid=[f9a922bd-3007-4393-a76e-925fc009639c], name=[rubycsv.txt], bucket=[fineuploadertest], etag=[123]}

ps: unit test with TestWebClient runs fine for all versions.

[violetagg]

I didn't try the latter example but with the previous one I see the stacks below. Th curl command is used curl -d "test" http://localhost:8081/router/rest -v, which output is (note the Content-Type which is set by default):

*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 8081 (#0)
> POST /router/rest HTTP/1.1
> Host: localhost:8081
> User-Agent: curl/7.54.0
> Accept: */*
> Content-Length: 4
> Content-Type: application/x-www-form-urlencoded
> 
* upload completely sent off: 4 out of 4 bytes
< HTTP/1.1 500 Internal Server Error
< Content-Type: application/json;charset=UTF-8
< Content-Length: 171
< 
* Connection #0 to host localhost left intact
{"timestamp":"2018-09-19T18:00:40.508+0000","path":"/router/rest","status":500,"error":"Internal Server Error","message":"Only one connection receive subscriber allowed."}

receiveObject:248, ChannelOperations (reactor.ipc.netty.channel)
receiveObject:270, HttpServerOperations (reactor.ipc.netty.http.server)
receive:90, NettyInbound (reactor.ipc.netty)
getBody:170, ReactorServerHttpRequest (org.springframework.http.server.reactive)
readMono:99, FormHttpMessageReader (org.springframework.http.codec)
initFormData:139, DefaultServerWebExchange (org.springframework.web.server.adapter)
<init>:123, DefaultServerWebExchange (org.springframework.web.server.adapter)
createExchange:191, HttpWebHandlerAdapter (org.springframework.web.server.adapter)
handle:183, HttpWebHandlerAdapter (org.springframework.web.server.adapter)
apply:75, ReactorHttpHandlerAdapter (org.springframework.http.server.reactive)
apply:40, ReactorHttpHandlerAdapter (org.springframework.http.server.reactive)
applyHandler:379, ChannelOperations (reactor.ipc.netty.channel)
onHandlerStart:398, HttpServerOperations (reactor.ipc.netty.http.server)
run:-1, 105998383 (reactor.ipc.netty.channel.ContextHandler$$Lambda$527)
safeExecute$$$capture:163, AbstractEventExecutor (io.netty.util.concurrent)
safeExecute:-1, AbstractEventExecutor (io.netty.util.concurrent)
 - Async stacktrace
addTask:-1, SingleThreadEventExecutor (io.netty.util.concurrent)
execute:765, SingleThreadEventExecutor (io.netty.util.concurrent)
createOperations:245, ContextHandler (reactor.ipc.netty.channel)
channelRead:133, HttpServerHandler (reactor.ipc.netty.http.server)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:340, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:438, CombinedChannelDuplexHandler$DelegatingChannelHandlerContext (io.netty.channel)
fireChannelRead:310, ByteToMessageDecoder (io.netty.handler.codec)
fireChannelRead:297, ByteToMessageDecoder (io.netty.handler.codec)
callDecode:413, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:265, ByteToMessageDecoder (io.netty.handler.codec)
channelRead:253, CombinedChannelDuplexHandler (io.netty.channel)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:340, AbstractChannelHandlerContext (io.netty.channel)
channelRead:241, LoggingHandler (io.netty.handler.logging)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:340, AbstractChannelHandlerContext (io.netty.channel)
channelRead:1434, DefaultChannelPipeline$HeadContext (io.netty.channel)
invokeChannelRead:362, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:348, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:965, DefaultChannelPipeline (io.netty.channel)
read:163, AbstractNioByteChannel$NioByteUnsafe (io.netty.channel.nio)
processSelectedKey:646, NioEventLoop (io.netty.channel.nio)
processSelectedKeysOptimized:581, NioEventLoop (io.netty.channel.nio)
processSelectedKeys:498, NioEventLoop (io.netty.channel.nio)
run:460, NioEventLoop (io.netty.channel.nio)
run:884, SingleThreadEventExecutor$5 (io.netty.util.concurrent)
run:748, Thread (java.lang)

receiveObject:248, ChannelOperations (reactor.ipc.netty.channel)
receiveObject:270, HttpServerOperations (reactor.ipc.netty.http.server)
receive:90, NettyInbound (reactor.ipc.netty)
getBody:170, ReactorServerHttpRequest (org.springframework.http.server.reactive)
lambda$filter$1:115, NettyRoutingFilter (org.springframework.cloud.gateway.filter)
apply:-1, 416080008 (org.springframework.cloud.gateway.filter.NettyRoutingFilter$$Lambda$622)
apply:121, MonoHttpClientResponse$HttpClientHandler (reactor.ipc.netty.http.client)
apply:84, MonoHttpClientResponse$HttpClientHandler (reactor.ipc.netty.http.client)
applyHandler:379, ChannelOperations (reactor.ipc.netty.channel)
onHandlerStart:503, HttpClientOperations (reactor.ipc.netty.http.client)
run:-1, 105998383 (reactor.ipc.netty.channel.ContextHandler$$Lambda$527)
safeExecute$$$capture:163, AbstractEventExecutor (io.netty.util.concurrent)
safeExecute:-1, AbstractEventExecutor (io.netty.util.concurrent)
 - Async stacktrace
addTask:-1, SingleThreadEventExecutor (io.netty.util.concurrent)
execute:765, SingleThreadEventExecutor (io.netty.util.concurrent)
createOperations:245, ContextHandler (reactor.ipc.netty.channel)
connectOrAcquire:199, PooledClientContextHandler (reactor.ipc.netty.channel)
lambda$operationComplete$0:169, PooledClientContextHandler (reactor.ipc.netty.channel)
safeExecute$$$capture:163, AbstractEventExecutor (io.netty.util.concurrent)
safeExecute:-1, AbstractEventExecutor (io.netty.util.concurrent)
 - Async stacktrace
addTask:-1, SingleThreadEventExecutor (io.netty.util.concurrent)
execute:765, SingleThreadEventExecutor (io.netty.util.concurrent)
operationComplete:169, PooledClientContextHandler (reactor.ipc.netty.channel)
notifyListener0:511, DefaultPromise (io.netty.util.concurrent)
notifyListeners0:504, DefaultPromise (io.netty.util.concurrent)
notifyListenersNow:483, DefaultPromise (io.netty.util.concurrent)
access$000:33, DefaultPromise (io.netty.util.concurrent)
run:435, DefaultPromise$1 (io.netty.util.concurrent)
safeExecute$$$capture:163, AbstractEventExecutor (io.netty.util.concurrent)
safeExecute:-1, AbstractEventExecutor (io.netty.util.concurrent)
 - Async stacktrace
addTask:-1, SingleThreadEventExecutor (io.netty.util.concurrent)
execute:765, SingleThreadEventExecutor (io.netty.util.concurrent)
safeExecute:768, DefaultPromise (io.netty.util.concurrent)
notifyListeners:432, DefaultPromise (io.netty.util.concurrent)
trySuccess:103, DefaultPromise (io.netty.util.concurrent)
notifyConnect:212, SimpleChannelPool (io.netty.channel.pool)
access$000:42, SimpleChannelPool (io.netty.channel.pool)
operationComplete:186, SimpleChannelPool$2 (io.netty.channel.pool)
operationComplete:183, SimpleChannelPool$2 (io.netty.channel.pool)
notifyListener0:511, DefaultPromise (io.netty.util.concurrent)
notifyListeners0:504, DefaultPromise (io.netty.util.concurrent)
notifyListenersNow:483, DefaultPromise (io.netty.util.concurrent)
notifyListeners:424, DefaultPromise (io.netty.util.concurrent)
trySuccess:103, DefaultPromise (io.netty.util.concurrent)
trySuccess:84, DefaultChannelPromise (io.netty.channel)
fulfillConnectPromise:306, AbstractNioChannel$AbstractNioUnsafe (io.netty.channel.nio)
finishConnect:341, AbstractNioChannel$AbstractNioUnsafe (io.netty.channel.nio)
processSelectedKey:634, NioEventLoop (io.netty.channel.nio)
processSelectedKeysOptimized:581, NioEventLoop (io.netty.channel.nio)
processSelectedKeys:498, NioEventLoop (io.netty.channel.nio)
run:460, NioEventLoop (io.netty.channel.nio)
run:884, SingleThreadEventExecutor$5 (io.netty.util.concurrent)
run:748, Thread (java.lang)

[spencergibb]

Here is a workaround

    @Bean
    public HiddenHttpMethodFilter hiddenHttpMethodFilter() {
        return new HiddenHttpMethodFilter() {
            @Override
            public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
                return chain.filter(exchange);
            }
        };
    }

[spencergibb]

This is the cause https://github.com/spring-projects/spring-boot/pull/14008

[spencergibb]

See also 58834daf6271c3ae379f5eb0939689ad6a14036e for temporarily auto configuring the work around and https://jira.spring.io/browse/SPR-17291 for the ultimate solution.

[dave-fl]

Nice work 👍

[mfeng-ya]

maybe you used retry filter ,and your request path was wrong or request timeout , the problem is in the retry filter, you could disable retry filter then you will see the real problem

[jayrmotta]

Hey @spencergibb where did you add this workaround?

Tried adding it to the class that has my @Configuration but it didn't fix the problem.

[ryanjbaxter]

@jayrmotta you should no longer need the workaround, the fix is in Boot 2.0.5 and Boot 2.1.0.

[tran302]

Hello, I'm on Spring Boot 2.1.0.RELEASE and it works fine with Webflux when there is no exception. However, I'm still having this issue only when there is internal exception thrown on the server side. Before using WebFlux (ProxyExchange), I used to get empty response back instead of 500 status. Is anyone else still having such issue?

"status": 500, "error": "Internal Server Error", "message": "Only one connection receive subscriber allowed.", "trace": "java.lang.IllegalStateException: Only one connection receive subscriber allowed.\n\tat reactor.netty.channel.FluxReceive.startReceiver(FluxReceive.java:277)\n\tat reactor.netty.channel.FluxReceive.subscribe(FluxReceive.java:127)\n\tat

[ryanjbaxter]

Please open a separate issue and include a sample.

[tran302]

FYI, the issue I mentioned seems to be fixed in Spring Boot 2.1.1.RELEASE.

[zhangxingping]

Not much to go on. Doesn't look like it has anything specific to do with the gateway.

Here is a workaround

    @Bean
    public HiddenHttpMethodFilter hiddenHttpMethodFilter() {
        return new HiddenHttpMethodFilter() {
            @Override
            public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
                return chain.filter(exchange);
            }
        };
    }

thank you ,it did resolved my issues

[spencergibb]

The over-ridden hidden http method filter is part of Finchley and Greenwich automatically disables boots bean here 38ad61cd7e271ff2ff89248475014221de6937e6