SpringBoot IllegalReferenceCountException using webflux in WebEndpoint (with specified produces) using http2 and compression

This was first noticed when testing http2 (with compression already enabled) when the prometheus actuator endpoint was scraped by the system. So mainly this is an issue with enabling http2 (with compression) when using prometheus (we use it for metrics via micrometer-registry-prometheus).

I have tried to make a small test application that can be used to reproduce the issue:

https://github.com/tbfky/webflux-http2-compression-actuator-bug

Note that disabling compression, removing the produces = { .. } declaration, or disabling http2 all remove the problem.

Additionally it seems the compression is actually lost? Using the regular spring web starter and tomcat compressions is applied and visible in the curl output for the repsonse.

√ webflux-http2-compression-actuator-bug % curl --compressed --http2-prior-knowledge -sv -o /dev/null http://localhost:8080/actuator/test
*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 8080 (#0)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fd78780ee00)
> GET /actuator/test HTTP/2
> Host: localhost:8080
> User-Agent: curl/7.64.1
> Accept: */*
> Accept-Encoding: deflate, gzip
> 
* Connection state changed (MAX_CONCURRENT_STREAMS == 4294967295)!
< HTTP/2 200 
< content-type: text/plain;charset=UTF-8
< content-length: 4
< 
{ [4 bytes data]
* Connection #0 to host localhost left intact
* Closing connection 0

2021-07-07 13:43:48.377 DEBUG 33339 --- [ctor-http-nio-2] io.netty.buffer.AbstractByteBuf          : -Dio.netty.buffer.checkAccessible: true
2021-07-07 13:43:48.377 DEBUG 33339 --- [ctor-http-nio-2] io.netty.buffer.AbstractByteBuf          : -Dio.netty.buffer.checkBounds: true
2021-07-07 13:43:48.378 DEBUG 33339 --- [ctor-http-nio-2] i.n.util.ResourceLeakDetectorFactory     : Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@1c911082
2021-07-07 13:43:48.464 DEBUG 33339 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [id:46433f3c, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] New http connection, requesting read
2021-07-07 13:43:48.464 DEBUG 33339 --- [ctor-http-nio-2] reactor.netty.transport.TransportConfig  : [id:46433f3c, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] Initialized pipeline DefaultChannelPipeline{(reactor.left.h2cUpgradeHandler = io.netty.handler.codec.http2.CleartextHttp2ServerUpgradeHandler), (HttpServerCodec#0 = io.netty.handler.codec.http.HttpServerCodec), (HttpServerUpgradeHandler#0 = io.netty.handler.codec.http.HttpServerUpgradeHandler), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-07-07 13:43:48.471 DEBUG 33339 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.maxCapacityPerThread: 4096
2021-07-07 13:43:48.471 DEBUG 33339 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.maxSharedCapacityFactor: 2
2021-07-07 13:43:48.471 DEBUG 33339 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.linkCapacity: 16
2021-07-07 13:43:48.471 DEBUG 33339 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.ratio: 8
2021-07-07 13:43:48.471 DEBUG 33339 --- [ctor-http-nio-2] io.netty.util.Recycler                   : -Dio.netty.recycler.delayedQueue.ratio: 8
2021-07-07 13:43:48.500 DEBUG 33339 --- [ctor-http-nio-2] io.netty.channel.DefaultChannelPipeline  : Discarded inbound message DefaultHttp2SettingsFrame(settings={ENABLE_PUSH=0, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1073741824}) that reached at the tail of the pipeline. Please check your pipeline configuration.
2021-07-07 13:43:48.500 DEBUG 33339 --- [ctor-http-nio-2] io.netty.channel.DefaultChannelPipeline  : Discarded message pipeline : [reactor.left.httpCodec, reactor.left.h2MultiplexHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x46433f3c, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577].
2021-07-07 13:43:48.517 DEBUG 33339 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [id:46433f3c, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577](H2 - 1) New HTTP/2 stream
2021-07-07 13:43:48.517 DEBUG 33339 --- [ctor-http-nio-2] r.netty.http.server.HttpServerConfig     : [id:46433f3c, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577](H2 - 1) Initialized HTTP/2 stream pipeline AbstractHttp2StreamChannel$3{(reactor.left.h2ToHttp11Codec = io.netty.handler.codec.http2.Http2StreamFrameToHttpObjectCodec), (reactor.left.httpTrafficHandler = reactor.netty.http.server.Http2StreamBridgeServerHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-07-07 13:43:48.533 DEBUG 33339 --- [ctor-http-nio-2] reactor.netty.http.server.HttpServer     : [id:46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@498ceb82
2021-07-07 13:43:48.540 TRACE 33339 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] HTTP GET "/actuator/test", headers={masked}
2021-07-07 13:43:48.574 DEBUG 33339 --- [ctor-http-nio-2] .b.a.e.w.r.WebFluxEndpointHandlerMapping : [46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] Mapped to org.springframework.boot.actuate.endpoint.web.reactive.AbstractWebFluxEndpointHandlerMapping$ReadOperationHandler@418e4e6d
2021-07-07 13:43:48.589 DEBUG 33339 --- [oundedElastic-1] .s.w.r.r.m.a.ResponseEntityResultHandler : [46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] Using 'application/octet-stream' given [*/*] and supported [*/*]
2021-07-07 13:43:48.589 DEBUG 33339 --- [oundedElastic-1] .s.w.r.r.m.a.ResponseEntityResultHandler : [46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] 0..1 [java.lang.String]
2021-07-07 13:43:48.595 DEBUG 33339 --- [ctor-http-nio-2] io.netty.channel.DefaultChannelPipeline  : Discarded inbound message DefaultHttp2SettingsAckFrame that reached at the tail of the pipeline. Please check your pipeline configuration.
2021-07-07 13:43:48.595 DEBUG 33339 --- [ctor-http-nio-2] io.netty.channel.DefaultChannelPipeline  : Discarded message pipeline : [reactor.left.httpCodec, reactor.left.h2MultiplexHandler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x46433f3c, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577].
2021-07-07 13:43:48.600 TRACE 33339 --- [oundedElastic-1] o.s.core.codec.CharSequenceEncoder       : [46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] Writing "test"
2021-07-07 13:43:48.619 ERROR 33339 --- [oundedElastic-1] r.n.http.server.HttpServerOperations     : [id:46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] 

io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
    at io.netty.util.internal.ReferenceCountUpdater.toLiveRealRefCnt(ReferenceCountUpdater.java:74) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.internal.ReferenceCountUpdater.release(ReferenceCountUpdater.java:138) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:100) ~[netty-buffer-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.handler.codec.http.DefaultFullHttpRequest.release(DefaultFullHttpRequest.java:103) ~[netty-codec-http-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:88) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at reactor.netty.http.server.HttpServerOperations.compression(HttpServerOperations.java:516) ~[reactor-netty-http-1.0.8.jar:1.0.8]
    at reactor.netty.http.server.HttpServerOperations.afterMarkSentHeaders(HttpServerOperations.java:587) ~[reactor-netty-http-1.0.8.jar:1.0.8]
    at reactor.netty.http.HttpOperations.lambda$send$0(HttpOperations.java:117) ~[reactor-netty-http-1.0.8.jar:1.0.8]
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:125) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:503) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1815) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:61) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Mono.subscribe(Mono.java:4150) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxConcatArray$ConcatArraySubscriber.onComplete(FluxConcatArray.java:208) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxConcatArray.subscribe(FluxConcatArray.java:80) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2397) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe(FluxContextWrite.java:101) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:73) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Operators$MonoInnerProducerBase.complete(Operators.java:2663) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:180) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete(FluxMapFuseable.java:150) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2399) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoSingle$SingleSubscriber.doOnRequest(MonoSingle.java:103) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Operators$MonoInnerProducerBase.request(Operators.java:2730) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2193) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2067) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoSingle$SingleSubscriber.onSubscribe(MonoSingle.java:115) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1815) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:100) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscription.run(FluxSubscribeOnCallable.java:251) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) ~[reactor-core-3.4.7.jar:3.4.7]
    at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) ~[reactor-core-3.4.7.jar:3.4.7]
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[na:na]
    at java.base/java.lang.Thread.run(Thread.java:831) ~[na:na]

2021-07-07 13:43:48.633 TRACE 33339 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] Completed 200 OK, headers={masked}
2021-07-07 13:43:48.634 TRACE 33339 --- [ctor-http-nio-2] o.s.h.s.r.ReactorHttpHandlerAdapter      : [46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577] Handling completed
2021-07-07 13:43:48.634 DEBUG 33339 --- [ctor-http-nio-2] r.n.http.server.HttpServerOperations     : [id:46433f3c/1-1, L:/[0:0:0:0:0:0:0:1]:8080 ! R:/[0:0:0:0:0:0:0:1]:60577] Last HTTP packet was sent, terminating the channel
2021-07-07 13:43:48.635 TRACE 33339 --- [ctor-http-nio-2] reactor.netty.channel.ChannelOperations  : [id:46433f3c, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:60577](H2 - 1) Disposing ChannelOperation from a channel

java.lang.Exception: ChannelOperation terminal stack
    at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:466) ~[reactor-netty-core-1.0.8.jar:1.0.8]
    at reactor.netty.http.server.HttpServerOperations.onInboundClose(HttpServerOperations.java:577) ~[reactor-netty-http-1.0.8.jar:1.0.8]
    at reactor.netty.channel.ChannelOperationsHandler.channelInactive(ChannelOperationsHandler.java:74) ~[reactor-netty-core-1.0.8.jar:1.0.8]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.handler.codec.http2.AbstractHttp2StreamChannel$Http2ChannelUnsafe$2.run(AbstractHttp2StreamChannel.java:737) ~[netty-codec-http2-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at java.base/java.lang.Thread.run(Thread.java:831) ~[na:na]

Comment From: wilkinsona

@violetagg This looks like a (Reactor) Netty problem to me. Could you please take a look and see if you agree?

Comment From: violetagg

@violetagg This looks like a (Reactor) Netty problem to me. Could you please take a look and see if you agree?

I'll take a look

Comment From: violetagg

@wilkinsona @tbfky This should be fixed with this PR in Reactor Netty https://github.com/reactor/reactor-netty/pull/1729

Comment From: wilkinsona

Thanks very much, @violetagg. I'll close this issue in favour of the Reactor Netty PR.

@tbfky Thanks for bringing this to our attention. Boot will pick up the Reactor Netty fix in due course.