IllegalReferenceCountException logged with enabled compression

[pschyma]

Hi

Describe the bug
I'm seeing this in 1.11.1.Final after enabling compression via quarkus.http.enable-compression:

2021-01-29 07:19:42,608 WARN  [io.net.cha.ChannelOutboundBuffer] (vert.x-eventloop-thread-4) Failed to mark a promise as success because it has failed already: DefaultChannelPromise@3d236c66(failure: io.netty.handler.codec.EncoderException: io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1), unnotified cause:: io.netty.handler.codec.EncoderException: io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:104)
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717)
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:709)
        at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:792)
        at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:702)
        at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:697)
        at io.netty.handler.codec.MessageToMessageEncoder.writePromiseCombiner(MessageToMessageEncoder.java:137)
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:117)
        at io.netty.handler.codec.MessageToMessageCodec.write(MessageToMessageCodec.java:116)
        at io.vertx.core.http.impl.HttpChunkContentCompressor.write(HttpChunkContentCompressor.java:38)
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717)
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:709)
        at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:792)
        at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:702)
        at io.netty.handler.stream.ChunkedWriteHandler.doFlush(ChunkedWriteHandler.java:300)
        at io.netty.handler.stream.ChunkedWriteHandler.flush(ChunkedWriteHandler.java:132)
        at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
        at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:742)
        at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728)
        at io.netty.channel.ChannelDuplexHandler.flush(ChannelDuplexHandler.java:127)
        at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
        at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765)
        at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:790)
        at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:758)
        at io.vertx.core.net.impl.ConnectionBase.write(ConnectionBase.java:124)
        at io.vertx.core.net.impl.ConnectionBase.lambda$queueForWrite$2(ConnectionBase.java:215)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        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:834)
Caused by: io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
        at io.netty.util.internal.ReferenceCountUpdater.toLiveRealRefCnt(ReferenceCountUpdater.java:74)
        at io.netty.util.internal.ReferenceCountUpdater.release(ReferenceCountUpdater.java:138)
        at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:100)
        at io.vertx.core.http.impl.AssembledHttpResponse.release(AssembledHttpResponse.java:159)
        at io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:88)
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:91)
        ... 32 more

Expected behavior
There should be no exception logged as the content is transfered without any problem.

To Reproduce

Steps to reproduce the behavior:

1. Enable compression
2. Access a (reactive [Mutiny]?) endpoint

I'll try to create a reproducer if needed be.

Configuration

quarkus:
  http:
    auth:
      proactive: true
    cors:
      ~: true
      origins: http://localhost:3000
      methods: DELETE, GET, POST, PUT, OPTIONS
    root-path: /
    limits:
      max-body-size: 20480K
    enable-compression: true
  resteasy:
    gzip:
      enabled: true
      max-input: 20480K

Environment (please complete the following information):

• Output of uname -a or ver: Linux voyager 5.10.11-arch1-1 #1 SMP PREEMPT Wed, 27 Jan 2021 13:53:16 +0000 x86_64 GNU/Linux
• Output of java -version:

openjdk version "11.0.10" 2021-01-19
OpenJDK Runtime Environment (build 11.0.10+8)
OpenJDK 64-Bit Server VM (build 11.0.10+8, mixed mode)

• GraalVM version (if different from Java):
• Quarkus version or git rev: 1.11.1.Final
• Build tool (ie. output of mvnw --version or gradlew --version):

❯ ./gradlew --version

------------------------------------------------------------
Gradle 6.8.1
------------------------------------------------------------

Build time:   2021-01-22 13:20:08 UTC
Revision:     31f14a87d93945024ab7a78de84102a3400fa5b2

Kotlin:       1.4.20
Groovy:       2.5.12
Ant:          Apache Ant(TM) version 1.10.9 compiled on September 27 2020
JVM:          11.0.10 (Oracle Corporation 11.0.10+8)
OS:           Linux 5.10.11-arch1-1 amd64

Additional context

• Adding "quarkus-undertow" dependency like stated in Exception logged by quarkus after SSE client is closed - "Failed to mark a promise as failure because it has failed already: DefaultChannelPromise failure: java.nio.channels.ClosedChannelException" #9194 does not remove the exception.
• Disabling compression removes the exception.

/edit: fixed the statement about the tried workaround – it's not working.

[ghost]

/cc @evanchooly

[fouad-j]

Hello I have the same issue.
Any clue ?

quarkus.resteasy.gzip.enabled=true
quarkus.resteasy.gzip.max-input=10M
quarkus.http.enable-compression=true

I only added this 3 lines based on https://quarkus.io/guides/rest-json#gzip-support

[stuartwdouglas]

Do you have a reproducer? I was not able to reproduce it.

[pschyma]

Thanks for looking at this. I'll try to build one. The error happens in a bigger code base but in a rather simple endpoint that I can't share.

[pschyma]

@stuartwdouglas Sorry for the delay. The reproducer is quite easy as this error seems to be triggered by the size of the response.
Just extending the REST start project by return "Hello RESTEasy\n".repeat(1000); shows the exception as shown in [1].

The reproducer illustrates another problem: depending on the size of the payload the exception is just logged or truncated. See the three tests there.

[1] https://github.com/pschyma/quarkus-compression-error-reproducer.git

[selckin]

Also hit this error.
can confirm the size of the payload matters, worked fine with smallish payload/body
Adding undertow stopped it from corrupting the payload, but the error was still logged
Without compression everything works

Was using resteasy with jackson and returning a View object with a List with 300+ smallish values (worked with 100), maybe this can help with reproducing (jackson maybe writing every one and flushing something?, i have no idea?)

[fouad-j]

a workaround to enable gzip on our APIs is to add @GZIP annotation to our resources.

till the problem is fixed

[stuartwdouglas]

Looks like a Netty issue, I have a potential fix here: netty/netty#11093

[stuartwdouglas]

I have fixed the netty bug, this should be fixed when we upgrade.

[janknobloch]

Seems to be fixed in 1.13.1 ?

was facing the same issue using:
quarkus.http.enable-compression=true

in non-native mode, seems to be gone by now - maybe implicity updating netty under the hood?

Thx @stuartwdouglas

[casell]

I still see this exception on 1.13.1 (resteasy-reactive) in JVM mode.

To me it seems related to the response body size (small responses do not seem to throw the exception)

@stuartwdouglas , is your PR on netty related to bigger responses?

[janknobloch]

Thanks for your input @casell - I’ll try again soon with some bigger responses!

[stuartwdouglas]

The fix is in Netty 4.1.61 which has not been included yet.

[janknobloch]

yep my bad -> still existent but seems to actually be related to larger responses.

[famod]

@stuartwdouglas Netty was upgraded to 4.1.65 via #17436 which is part of 2.0.0.CR1 that was released today.

Still, I'm not sure this is all fixed now:
I don't see a difference when trying @pschyma's reproducer with 2.0.0.CR1. I have to say though that I don't see that exeception trace, but I do see curl "hanging":

$ curl http://localhost:8080/hello-resteasy/1000
Hello RESTEasy
<many more>
Hello RESTEasy
Hello RESTEasy

0

<"hangs" here>

curl ... --compressed returns as expected.

Then again, I do see that exeception being logged when trying the reproducer from #12584 (for the second request, after the first hanging one).

[BigFatDog]

Still an issue in 1.13.6.final, disabling compression works

quarkus.http.enable-compression=false

[stuartwdouglas]

Turns out my fix was incomplete: netty/netty#11358

It fixes it if compression is actually used, but it fails if no accept-encoding header is present.