suspiciously large buffer stack traces

[rasos]

Description

We observe on several jitsi videobridges buffer warnings. This is also reported in the community forum e.g. here.

Current behavior

The warnings seem to be related with users being in a state when they are loosing connectivity and finally fall out of the conference. We first investigated if it was related to VPN users only, but also have seen this with other users connected without VPN.

JVB 2021-12-01 14:33:17.486 WARNING: [36] [confId=6914397c4f2e16bb epId=bf6fef05 gid=52154 stats_id=Katelyn-P6m conf_name=meetme@conference.myjitsiserver.net] Transceiver$rtpReceiver$1.invoke#116: Sending large locally-generated RTCP packet of size 15436, first packet of type 205.
JVB 2021-12-01 14:33:17.487 WARNING: [102] ByteBufferPool.returnBuffer#226: Received a suspiciously large buffer (size = 15436)
 +java.base/java.lang.Thread.getStackTrace(Thread.java:1602)
org.jitsi.nlj.util.UtilKt.getStackTrace(Util.kt:67)
org.jitsi.videobridge.util.ByteBufferPool.returnBuffer(ByteBufferPool.java:228)
org.jitsi.videobridge.Videobridge.lambda$static$0(Videobridge.java:136)
org.jitsi.rtp.ByteArrayBufferImpl.grow(ByteArrayBufferImpl.java:137)
org.jitsi.srtp.SrtcpCryptoContext.transformPacket(SrtcpCryptoContext.java:460)
org.jitsi.nlj.srtp.SrtcpEncryptTransformer.transform(SrtpTransformer.kt:159)
org.jitsi.nlj.srtp.SrtcpEncryptTransformer.transform(SrtpTransformer.kt:153)
org.jitsi.nlj.srtp.AbstractSrtpTransformer.transform(SrtpTransformer.kt:90)
org.jitsi.nlj.transform.node.SrtpTransformerNode.transform(SrtpTransformerNode.kt:82)
org.jitsi.nlj.transform.node.MultipleOutputTransformerNode.doProcessPacket(Node.kt:466)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.NeverDiscardNode.doProcessPacket(Node.kt:363)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.NeverDiscardNode.doProcessPacket(Node.kt:363)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.RtpSenderImpl.handlePacket(RtpSenderImpl.kt:269)
org.jitsi.nlj.RtpSenderImpl.access$handlePacket(RtpSenderImpl.kt:67)
org.jitsi.nlj.RtpSenderImpl$incomingPacketQueue$1.invoke(RtpSenderImpl.kt:93)
org.jitsi.nlj.RtpSenderImpl$incomingPacketQueue$1.invoke(RtpSenderImpl.kt:93)
org.jitsi.nlj.util.PacketInfoQueue._init_$lambda-0(PacketInfoQueue.kt:31)
org.jitsi.utils.queue.PacketQueue$HandlerAdapter.handleItem(PacketQueue.java:381)
org.jitsi.utils.queue.AsyncQueueHandler$1.run(AsyncQueueHandler.java:133)
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
java.base/java.lang.Thread.run(Thread.java:829)

Expected Behavior

Maybe drop large packets, keep user in conference, or do not spill stackTraces in the log if this is a minor warning issue.

Environment details

    jitsi-videobridge2 2.1-570-gb802be83-1

[bgrozev]

We keep the stack trace is in the logs because we still don't understand the issue(s). We do drop these packets in the sense that we don't return them back to the memory pool, and we don't remove the user from the conference.

This instance is due to a large TCC feedback packet that we generate. Your observation that it correlates with users losing connectivity is interesting -- perhaps the encoding is inefficient when packet loss is high.

[ArnoSoontjens]

We are experiencing the same issue. This warning is shown multiple times (20+ times over 2 seconds.). Users lose connection or video freezes.

JVB 2022-01-20 13:38:57.782 WARNING: [27] [confId=ac3bcb539e4dfbb6 epId=a3aa9e26 gid=40561 stats_id=Nyasia-NoZ conf_name=essentialcharacteristicspledgelately@conference.consult.bloomup.org] Transceiver$rtpReceiver$1.invoke#116: Sending large locally-generated RTCP packet of size 15436, first packet of type 205.
JVB 2022-01-20 13:38:57.782 WARNING: [86] ByteBufferPool.returnBuffer#226: Received a suspiciously large buffer (size = 15436)
 +java.base/java.lang.Thread.getStackTrace(Thread.java:1596)
org.jitsi.nlj.util.UtilKt.getStackTrace(Util.kt:67)
org.jitsi.videobridge.util.ByteBufferPool.returnBuffer(ByteBufferPool.java:228)
org.jitsi.videobridge.Videobridge.lambda$static$0(Videobridge.java:145)
org.jitsi.rtp.ByteArrayBufferImpl.grow(ByteArrayBufferImpl.java:137)
org.jitsi.srtp.SrtcpCryptoContext.transformPacket(SrtcpCryptoContext.java:460)
org.jitsi.nlj.srtp.SrtcpEncryptTransformer.transform(SrtpTransformer.kt:159)
org.jitsi.nlj.srtp.SrtcpEncryptTransformer.transform(SrtpTransformer.kt:153)
org.jitsi.nlj.srtp.AbstractSrtpTransformer.transform(SrtpTransformer.kt:90)
org.jitsi.nlj.transform.node.SrtpTransformerNode.transform(SrtpTransformerNode.kt:82)
org.jitsi.nlj.transform.node.MultipleOutputTransformerNode.doProcessPacket(Node.kt:466)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.NeverDiscardNode.doProcessPacket(Node.kt:363)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.NeverDiscardNode.doProcessPacket(Node.kt:363)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.RtpSenderImpl.handlePacket(RtpSenderImpl.kt:269)
org.jitsi.nlj.RtpSenderImpl.access$handlePacket(RtpSenderImpl.kt:67)
org.jitsi.nlj.RtpSenderImpl$incomingPacketQueue$1.invoke(RtpSenderImpl.kt:93)
org.jitsi.nlj.RtpSenderImpl$incomingPacketQueue$1.invoke(RtpSenderImpl.kt:93)
org.jitsi.nlj.util.PacketInfoQueue._init_$lambda-0(PacketInfoQueue.kt:31)
org.jitsi.utils.queue.PacketQueue$HandlerAdapter.handleItem(PacketQueue.java:381)
org.jitsi.utils.queue.AsyncQueueHandler$1.run(AsyncQueueHandler.java:133)
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
java.base/java.lang.Thread.run(Thread.java:831)

JVB 2022-01-20 13:38:57.782 WARNING: [885] ByteBufferPool.returnBuffer#226: Received a suspiciously large buffer (size = 15456)
 +java.base/java.lang.Thread.getStackTrace(Thread.java:1596)
org.jitsi.nlj.util.UtilKt.getStackTrace(Util.kt:67)
org.jitsi.videobridge.util.ByteBufferPool.returnBuffer(ByteBufferPool.java:228)
org.jitsi.videobridge.Endpoint.doSendSrtp(Endpoint.kt:460)
org.jitsi.videobridge.Endpoint.access$doSendSrtp(Endpoint.kt:101)
org.jitsi.videobridge.Endpoint$outgoingSrtpPacketQueue$1.invoke(Endpoint.kt:178)
org.jitsi.videobridge.Endpoint$outgoingSrtpPacketQueue$1.invoke(Endpoint.kt:178)
org.jitsi.nlj.util.PacketInfoQueue._init_$lambda-0(PacketInfoQueue.kt:31)
org.jitsi.utils.queue.PacketQueue$HandlerAdapter.handleItem(PacketQueue.java:381)
org.jitsi.utils.queue.AsyncQueueHandler$1.run(AsyncQueueHandler.java:133)
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
java.base/java.lang.Thread.run(Thread.java:831)

[eddiechen]

I am experience the same issue with jitsi-videobridge2/stable,now 2.1-570-gb802be83-1

[aCandidMind]

Might be related with #1703 (comment), happening on 2.1-617-ga8b39c3f-1 for me too.

[damige]

I seem to have the same problem, leading to video no longer working

JVB 2022-04-01 21:23:28.538 WARNING: [22] [confId=1ce08a4cf2036306 epId=2d3f3862 gid=57031 stats_id=Tiffany-v0u conf_name=www@conference.xx.yy.zz] Transceiver$rtpReceiver$1.invoke#124: Sending large locally-generated RTCP packet of size 15436, first packet of type 205 rc 1.
JVB 2022-04-01 21:23:28.538 WARNING: [67] ByteBufferPool.returnBuffer#226: Received a suspiciously large buffer (size = 15436)
 +java.base/java.lang.Thread.getStackTrace(Thread.java:1610)
org.jitsi.nlj.util.UtilKt.getStackTrace(Util.kt:67)
org.jitsi.videobridge.util.ByteBufferPool.returnBuffer(ByteBufferPool.java:228)
org.jitsi.videobridge.Videobridge.lambda$static$0(Videobridge.java:157)
org.jitsi.rtp.ByteArrayBufferImpl.grow(ByteArrayBufferImpl.java:137)
org.jitsi.srtp.SrtcpCryptoContext.transformPacket(SrtcpCryptoContext.java:468)
org.jitsi.nlj.srtp.SrtcpEncryptTransformer.transform(SrtpTransformer.kt:159)
org.jitsi.nlj.srtp.SrtcpEncryptTransformer.transform(SrtpTransformer.kt:153)
org.jitsi.nlj.srtp.AbstractSrtpTransformer.transform(SrtpTransformer.kt:90)
org.jitsi.nlj.transform.node.SrtpTransformerNode.transform(SrtpTransformerNode.kt:82)
org.jitsi.nlj.transform.node.MultipleOutputTransformerNode.doProcessPacket(Node.kt:466)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.NeverDiscardNode.doProcessPacket(Node.kt:363)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.NeverDiscardNode.doProcessPacket(Node.kt:363)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.transform.node.Node.next(Node.kt:107)
org.jitsi.nlj.transform.node.TransformerNode.doProcessPacket(Node.kt:380)
org.jitsi.nlj.transform.node.StatsKeepingNode.processPacket(Node.kt:206)
org.jitsi.nlj.RtpSenderImpl.handlePacket(RtpSenderImpl.kt:268)
org.jitsi.nlj.RtpSenderImpl.access$handlePacket(RtpSenderImpl.kt:67)
org.jitsi.nlj.RtpSenderImpl$incomingPacketQueue$1.invoke(RtpSenderImpl.kt:92)
org.jitsi.nlj.RtpSenderImpl$incomingPacketQueue$1.invoke(RtpSenderImpl.kt:92)
org.jitsi.nlj.util.PacketInfoQueue._init_$lambda-0(PacketInfoQueue.kt:31)
org.jitsi.utils.queue.PacketQueue$HandlerAdapter.handleItem(PacketQueue.java:416)
org.jitsi.utils.queue.AsyncQueueHandler$1.run(AsyncQueueHandler.java:136)
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
java.base/java.lang.Thread.run(Thread.java:833)