spring-projects / spring-framework

Spring Framework
https://spring.io/projects/spring-framework
Apache License 2.0
56.63k stars 38.13k forks source link

Webservice returns invalid response containing Empty Headers (":") #33164

Closed david0 closed 4 months ago

david0 commented 4 months ago

Our Webservice that uses WebFlux returns sometimes responses like:

...(more requests on same connection)...

POST /foo HTTP/1.1
accept-encoding: gzip
user-agent: ReactorNetty/1.1.16
host: localhost:8080
transfer-encoding: chunked
Accept: application/x-ndjson

HTTP/1.1 200 
Vary: Origin
Vary: Access-Control-Request-Method
Vary: Access-Control-Request-Headers
X-Content-Type-Options: nosniff
: 
X-XSS-Protection: 0
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Pragma: no-cache
Expires: 0
X-Frame-Options: DENY
Content-Type: application/x-ndjson
Transfer-Encoding: chunked
Date: Mon, 08 Jul 2024 13:28:24 GMT

{"i":0}

As you can see, there is an invalid header :.

The WebClient call (Netty) fails with:

IllegalArgumentException: empty headers are not allowed [] ``` 15:54:26.079 [reactor-http-nio-1] WARN reactor.netty.http.client.HttpClientConnect -- [dd6be3b4-31, L:/127.0.0.1:49185 - R:localhost/127.0.0.1:8080] The connection observed an error java.lang.IllegalArgumentException: empty headers are not allowed [] at io.netty.handler.codec.http.DefaultHttpHeadersFactory$1.validateName(DefaultHttpHeadersFactory.java:34) at io.netty.handler.codec.http.DefaultHttpHeadersFactory$1.validateName(DefaultHttpHeadersFactory.java:30) at io.netty.handler.codec.DefaultHeaders.validateName(DefaultHeaders.java:1012) at io.netty.handler.codec.DefaultHeaders.add(DefaultHeaders.java:329) at io.netty.handler.codec.DefaultHeaders.addObject(DefaultHeaders.java:364) at io.netty.handler.codec.http.DefaultHttpHeaders.add(DefaultHttpHeaders.java:182) at io.netty.handler.codec.http.HttpObjectDecoder.readHeaders(HttpObjectDecoder.java:743) at io.netty.handler.codec.http.HttpObjectDecoder.decode(HttpObjectDecoder.java:362) at io.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:320) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1407) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:918) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:840) empty headers are not allowed [] org.springframework.web.reactive.function.client.WebClientRequestException: empty headers are not allowed [] at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:136) Suppressed: The stacktrace has been enhanced by Reactor, refer to additional information below: Error has been observed at the following site(s): *__checkpoint ⇢ Request to POST http://localhost:8080/foo [DefaultWebClient] Original Stack Trace: at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:136) at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:55) at reactor.core.publisher.Mono.subscribe(Mono.java:4568) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93) at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:205) at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124) at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:229) at reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:279) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121) at reactor.core.publisher.FluxConcatMapNoPrefetch$FluxConcatMapNoPrefetchSubscriber.maybeOnError(FluxConcatMapNoPrefetch.java:327) at reactor.core.publisher.FluxConcatMapNoPrefetch$FluxConcatMapNoPrefetchSubscriber.onNext(FluxConcatMapNoPrefetch.java:212) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107) at reactor.core.publisher.SinkManyEmitterProcessor.drain(SinkManyEmitterProcessor.java:476) at reactor.core.publisher.SinkManyEmitterProcessor$EmitterInner.drainParent(SinkManyEmitterProcessor.java:620) at reactor.core.publisher.FluxPublish$PubSubInner.request(FluxPublish.java:874) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136) at reactor.core.publisher.FluxConcatMapNoPrefetch$FluxConcatMapNoPrefetchSubscriber.request(FluxConcatMapNoPrefetch.java:337) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136) at reactor.core.publisher.Operators$DeferredSubscription.request(Operators.java:1743) at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:196) at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:205) at reactor.netty.http.client.HttpClientConnect$HttpObserver.onUncaughtException(HttpClientConnect.java:403) at reactor.netty.ReactorNetty$CompositeConnectionObserver.onUncaughtException(ReactorNetty.java:708) at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onUncaughtException(DefaultPooledConnectionProvider.java:223) at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnection.onUncaughtException(DefaultPooledConnectionProvider.java:476) at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:247) at reactor.netty.channel.FluxReceive.onInboundError(FluxReceive.java:468) at reactor.netty.channel.ChannelOperations.onInboundError(ChannelOperations.java:515) at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:688) at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:114) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1407) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:918) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:840) Suppressed: java.lang.Exception: #block terminated with an error at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:104) at reactor.core.publisher.Mono.block(Mono.java:1779) at com.github.david0.streamedheaderproblem.FooControllerTest.test(FooControllerTest.java:24) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) Caused by: java.lang.IllegalArgumentException: empty headers are not allowed [] at io.netty.handler.codec.http.DefaultHttpHeadersFactory$1.validateName(DefaultHttpHeadersFactory.java:34) at io.netty.handler.codec.http.DefaultHttpHeadersFactory$1.validateName(DefaultHttpHeadersFactory.java:30) at io.netty.handler.codec.DefaultHeaders.validateName(DefaultHeaders.java:1012) at io.netty.handler.codec.DefaultHeaders.add(DefaultHeaders.java:329) at io.netty.handler.codec.DefaultHeaders.addObject(DefaultHeaders.java:364) at io.netty.handler.codec.http.DefaultHttpHeaders.add(DefaultHttpHeaders.java:182) at io.netty.handler.codec.http.HttpObjectDecoder.readHeaders(HttpObjectDecoder.java:743) at io.netty.handler.codec.http.HttpObjectDecoder.decode(HttpObjectDecoder.java:362) at io.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:320) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1407) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:918) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:840 ```

On server side nothing is logged.

Here you can find an example that reproduces that problem (It will not always fail and sometimes fail with other errors that sound related): https://github.com/david0/mre-spring-empty-header/blob/main/src/test/java/com/github/david0/streamedheaderproblem/FooControllerTest.java

bclozel commented 4 months ago

I have reproduced this and it seems that this is linked to how Spring Security is writing HTTP response headers.

I cannot reproduce this when using "webflux + reactive security" (so removing the "spring-boot-starter-web-services" which makes the sample an MVC app). I cannot reproduce this without the Spring Security dependency.

I'm unfortunately unable to transfer this issue to the spring-security repository - can you create a new issue there so that they can have a look? You can update the dependencies in your sample to make things clearer with:

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-web'
    implementation 'org.springframework.boot:spring-boot-starter-webflux'
    implementation "org.springframework.boot:spring-boot-starter-security"

    testImplementation 'org.springframework.boot:spring-boot-starter-test'
    testImplementation 'io.projectreactor:reactor-test'
    testRuntimeOnly 'org.junit.platform:junit-platform-launcher'
}

I'm closing this for now but we can reopen depending on the Spring Security team's findings.

Thanks!

david0 commented 3 months ago

The investigations by the spring-security team have shown that this issue can be reproduced without spring security by implementing an simple filter that adds these headers. My example project has been updated to reproduce that problem without spring-security.

@bclozel Since the filter looks straight forward to me I would suggest to reopen this ticket here to investigate further?

yvq137 commented 3 months ago

Having the same issue, please reopen the ticket and continue the investigation

bclozel commented 2 months ago

Thanks for letting us know. I don't think we'll reopen this issue as I don't see how this is related to Spring at all. This custom Servlet Filter is mutating response headers after the call to jakarta.servlet.FilterChain#doFilter, when the response can be committed already. This is most likely a race with the Servlet container between writing response headers and actually commiting the response.

I think you can probably reproduce the same behavior with a HttpServlet writing the response asynchronously instead of using a Spring Controller. This would completely remove Spring from the picture.

Back to the original problem, it seems that Spring Security is itself not writing response headers to the response if it's already committed, which this repro does not reflect. Unfortunately, I cannot reopen the Security issue but I would suggest asking them to reconsider.