0.14: IllegalReferenceCountException: refCnt: 0 #573

hylkevds · 2021-02-04T10:28:12Z

This one is probably hard to track down. I've only seen it happen once in the last few days.
It did cause the connection to the client to be dropped.
I'm currently using the in-memory persistence store.

Expected behavior

No Exceptions

Actual behavior

10:02:45.602 [nioEventLoopGroup-3-1] ERROR i.m.broker.NewNettyMQTTHandler - Unexpected exception while processing MQTT message. Closing Netty channel. CId=Aggregator
io.netty.util.IllegalReferenceCountException: refCnt: 0
	at io.netty.buffer.AbstractByteBuf.ensureAccessible(AbstractByteBuf.java:1490)
	at io.netty.buffer.AbstractByteBuf.duplicate(AbstractByteBuf.java:1201)
	at io.netty.buffer.AbstractByteBuf.retainedDuplicate(AbstractByteBuf.java:1207)
	at io.moquette.broker.Session.resendInflightNotAcked(Session.java:308)
	at io.moquette.broker.MQTTConnection.resendNotAckedPublishes(MQTTConnection.java:502)
	at io.moquette.broker.NewNettyMQTTHandler.userEventTriggered(NewNettyMQTTHandler.java:112)
	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:346)
	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:332)
	at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:324)
	at io.netty.channel.ChannelInboundHandlerAdapter.userEventTriggered(ChannelInboundHandlerAdapter.java:117)
	at io.netty.handler.codec.ByteToMessageDecoder.userEventTriggered(ByteToMessageDecoder.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:346)
	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:332)
	at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:324)
	at io.netty.channel.ChannelInboundHandlerAdapter.userEventTriggered(ChannelInboundHandlerAdapter.java:117)
	at io.moquette.broker.MoquetteIdleTimeoutHandler.userEventTriggered(MoquetteIdleTimeoutHandler.java:48)
	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:346)
	at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:332)
	at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:324)
	at io.moquette.broker.InflightResender.resendNotAcked(InflightResender.java:160)
	at io.moquette.broker.InflightResender.access$100(InflightResender.java:32)
	at io.moquette.broker.InflightResender$WriterIdleTimeoutTask.run(InflightResender.java:58)
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
	at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
	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)

Steps to reproduce

See below

Minimal yet complete reproducer code (or URL to code) or complete log file

None yet

Moquette MQTT version

0.14 (with the patches from #568, #570, #572)

JVM version (e.g. `java -version`)

OpenJDK 11

OS version (e.g. `uname -a`)

Linux / Docker openjdk:11

The text was updated successfully, but these errors were encountered:

hylkevds · 2021-02-04T14:02:30Z

Ok, I can reproduce it:

Have a client that never sends a QOS1 Ack (Set a breakpoint in Paho:ComsCallback.java:422 )
Send a message
Wait for the resend to happen

I noticed it doesn't happen when using broker.internalPublish(mqttPublishMessage, clientId);, but there the opposite happens, unless I do a payload.release(); right after the internalPublish:

ERROR  i.n.util.ResourceLeakDetector - LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records: 
Created at:
	io.netty.buffer.UnpooledByteBufAllocator.newDirectBuffer(UnpooledByteBufAllocator.java:96)
	io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:187)
	io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:178)
	io.netty.buffer.AbstractByteBufAllocator.buffer(AbstractByteBufAllocator.java:115)
	io.netty.buffer.ByteBufUtil.writeUtf8(ByteBufUtil.java:514)
	tests.moquettetests.Publisher.publishDirect(Publisher.java:92)
	tests.moquettetests.Publisher.run(Publisher.java:76)
	java.base/java.lang.Thread.run(Thread.java:834)

hylkevds · 2021-02-17T10:36:36Z

Do I understand the idea behind the ByteBuf correct in that a method that receives or creates a ByteBuf should either

Pass it on further
Release it

And if the method passes it on more than once, it should retain it for each case?

If that is how it should work, I can see if I can find the missing call to retain() or release()

The main place where ByteBufs were not released was the inflightWindow. Also improves two postoffice methods that passed the payload and retain information twice, once direct and once in the message.

hylkevds · 2021-02-17T22:01:02Z

I think PR #576 fixes the ByteBuf retain/release problems. One of the most important ones was the inflightWindow messages that were not released and retained properly. Of course, these fixes affected lots of tests that played loose with the buffers too.

hylkevds · 2021-02-18T12:11:34Z

PR #464 partially fixed the problem and also adds a test, but that test never runs, because the name of the class the test is in does not end with Test (it ends with Tests) and thus the test class never runs.

andsel · 2021-05-08T09:26:49Z

The reasoning on buffer retain and release is that:

once a piece of code consumes the buffer, for example sending to a channel it should release.
if there is a piece of code that forward a buffer to n channels then it should create n duplicate buffers, one for each channel and call retain to have the duplicated buffer's refCount to 1.

andsel · 2021-05-08T09:49:03Z

As you suggested I think the problem rise when a PublishedMessage is inserted into inflightWindow and then sent to the client with mqttConnection.sendPublish

moquette/broker/src/main/java/io/moquette/broker/Session.java

Lines 241 to 245 in f6f3f6e

    
           inflightWindow.put(packetId, new SessionRegistry.PublishedMessage(topic, qos, payload)); 
        
           inflightTimeouts.add(new InFlightPacket(packetId, FLIGHT_BEFORE_RESEND_MS)); 
        
           MqttPublishMessage publishMsg = MQTTConnection.notRetainedPublishWithMessageId(topic.toString(), qos, 
        
                                                                                          payload, packetId); 
        
           mqttConnection.sendPublish(publishMsg);

In this case the send consumes the payload buffer count, and during a resend due to a missed ACK from client,

moquette/broker/src/main/java/io/moquette/broker/Session.java

Lines 307 to 308 in f6f3f6e

    
           final ByteBuf payload = msg.payload; 
        
           final ByteBuf copiedPayload = payload.retainedDuplicate();

the payload is invalid because reached 0 refCount in the previous send.

The solution could be to handle correctly the insertions/removes into inflightWindow, for each put the payload should be reatainedDuplicate and in remove from the map the payload should be release()-ed

andsel · 2021-05-08T09:49:34Z

This problem could also happen for Qos2 processing, because also that uses the inflightWindow

The main place where ByteBufs were not released was the inflightWindow.

hylkevds · 2021-05-08T18:33:28Z

I've recreated PR #576, and split the postoffice cleanup into #598

Qos2 should now also be properly reference-counted, though the inflightWindow handling has other issues than just reference counting, which have separate PRs (#582, #584 & #588).

hylkevds · 2021-05-08T21:01:10Z

By the way, those other PRs will probably need to be rebased as well, once you get to them. Since all these fixes are on a relatively small section of the code, it's impossible to have the commits not influence each other.

hylkevds · 2021-05-09T16:47:57Z

I've rebased the other PRs. These three are directly related to this issue:

Fix #583 inflight slots incremented too often #584 and Fix #455, #587: qos2 cce and deadlock #588 are directly based on this PR, since they cover the same bit of code.
Fixed ServerLowLevel tests not running #580 adds a test for this reference counting issue. This PR currently fails, as expected :)

- Add unit test to check a second publish is sent if the not PUBACK is received in `FLIGHT_BEFORE_RESEND_MS` interval. - Fixed ServerLowLevel tests not running. * Added a test for #573

Moved buffer release/retain calls to the outside interfaces of moquette.

hylkevds added a commit to FraunhoferIOSB/moquette that referenced this issue Feb 18, 2021

Added a test for moquette-io#573

a3780c2

This was referenced Feb 18, 2021

Fixed ServerLowLevel tests not running #580

Merged

Fix #583 inflight slots incremented too often #584

Merged

hylkevds added a commit to FraunhoferIOSB/moquette that referenced this issue May 8, 2021

Fixed moquette-io#573 ByteBuf reference counting

f0904f7

The main place where ByteBufs were not released was the inflightWindow.

hylkevds added a commit to FraunhoferIOSB/moquette that referenced this issue May 9, 2021

Added a test for moquette-io#573

69e4114

hylkevds added a commit to FraunhoferIOSB/moquette that referenced this issue May 22, 2021

Added a test for moquette-io#573

cbc31c5

hylkevds added a commit to FraunhoferIOSB/moquette that referenced this issue May 22, 2021

Added a test for moquette-io#573

ba0f9eb

hylkevds added a commit to FraunhoferIOSB/moquette that referenced this issue May 24, 2021

Fixed moquette-io#573 ByteBuf reference counting

e5d58a4

Moved buffer release/retain calls to the outside interfaces of moquette.

hylkevds added a commit to FraunhoferIOSB/moquette that referenced this issue May 24, 2021

Fixed moquette-io#573 ByteBuf reference counting

0cdcc27

Moved buffer release/retain calls to the outside interfaces of moquette.

andsel mentioned this issue May 30, 2021

Fixed #573 ByteBuf reference counting #600

Merged

andsel closed this as completed in #600 Jun 6, 2021

andsel pushed a commit that referenced this issue Jun 6, 2021

Fixed #573 ByteBuf reference counting (#600)

7472222

Moved buffer release/retain calls to the outside interfaces of moquette.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

0.14: IllegalReferenceCountException: refCnt: 0 #573

0.14: IllegalReferenceCountException: refCnt: 0 #573

hylkevds commented Feb 4, 2021 •

edited

Loading

hylkevds commented Feb 4, 2021

hylkevds commented Feb 17, 2021

hylkevds commented Feb 17, 2021

hylkevds commented Feb 18, 2021 •

edited

Loading

andsel commented May 8, 2021

andsel commented May 8, 2021

andsel commented May 8, 2021

hylkevds commented May 8, 2021

hylkevds commented May 8, 2021

hylkevds commented May 9, 2021

0.14: IllegalReferenceCountException: refCnt: 0 #573

0.14: IllegalReferenceCountException: refCnt: 0 #573

Comments

hylkevds commented Feb 4, 2021 • edited Loading

Expected behavior

Actual behavior

Steps to reproduce

Minimal yet complete reproducer code (or URL to code) or complete log file

Moquette MQTT version

JVM version (e.g. java -version)

OS version (e.g. uname -a)

hylkevds commented Feb 4, 2021

hylkevds commented Feb 17, 2021

hylkevds commented Feb 17, 2021

hylkevds commented Feb 18, 2021 • edited Loading

andsel commented May 8, 2021

andsel commented May 8, 2021

andsel commented May 8, 2021

hylkevds commented May 8, 2021

hylkevds commented May 8, 2021

hylkevds commented May 9, 2021

hylkevds commented Feb 4, 2021 •

edited

Loading

JVM version (e.g. `java -version`)

OS version (e.g. `uname -a`)

hylkevds commented Feb 18, 2021 •

edited

Loading