This message was deleted.
# helpdesk
s
This message was deleted.
f
That should be fine. They do not affect quality directly. But, some stats and connection quality measurement may be affected a bit. This backtrace is showing down stream. There is a fixed size list which maintains metadata about packets sent to subscriber. That list size is not enough. That list is quite big. So, the log should be rare. But, if it is happening a lot, probably an indication of something else. Are you doing very high bit rate? That list is 8K packets deep. Should be good to contain more than 25 seconds for video packets metadata at 2.4 mbps. That is a deep buffer. What rate are you using? The other time where it could getting filled up is when there is down stream congestion and padding is used to probe for available bandwidth. That packet rate could be high, but that still should not overflow often. What is your down stream client? If it is a browser, it should be sending RTCP feedback frequently. That should prevent that overflow also. But, if the RTCP feedback happens spaced apart a lot, it could overflow.
d
Thank you very much for the detailed explanation! I've seen it for the up-stream as well, they usually show up in pairs but not always. I've pasted a sample below with a pair. This is from a video call with only two participants, a web browser and a react native app. Both are using pretty resent SDK versions but perhaps not the latest. So perhaps the react native client isn't sending RTCP feedback frequently enough? I'm only doing h264 at 640x480, 15fps, we have had seen problems for users with old phones so we set the mark pretty low in an effort to make video calls more stable for them. We do have issues with calls ending prematurely, especially longer calls > 30 minutes, so perhaps we might have an issue that could relate to these logs... I haven't done much testing on 1.4.5 yet but on 1.4.1 i could see a lot of entries like this, especially for the calls that ended prematurely, usually around the time the "could not find some packets" log entries are written.
Copy code
2023-09-12T12:59:49.931Z	INFO	livekit	streamallocator/streamallocator.go:793	stream allocator: channel congestion detected, updating channel capacity	{"room": "skicka-vidare", "roomID": "RM_fj7wA5CKSeQ4", "participant": "Christian Paulin", "pID": "PA_AiCfffVMfrQL", "remote": false, "transport": "SUBSCRIBER", "reason": "ESTIMATE", "old(bps)": 89182, "new(bps)": 95112, "lastReceived(bps)": 95112, "expectedUsage(bps)": 117223, "channel": "name: non-probe, estimate: {n: non-probe-estimate, t: Tue Sep 12 12:58:39 UTC 2023|Tue Sep 12 12:59:49 UTC 2023|70.73s, v: 328|47695|194834|[194834 194834 194834 194834 194834 194834 194834 95112]|-1.00}, nack {n: non-probe-nack, , p: 0, rn: 0, rn/p: 0.00}"}
I'm hoping that some of the fixes to congestion control logic between 1.4.1 and 1.4.5 might help out here. Here is a sample from the log with bot pub and sub:
Copy code
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | 2023-09-12T20:28:32.476Z#011ERROR#011livekit.pub.sfu#011buffer/rtpstats.go:1608#011could not find some packets#011{"room": "80e1bdb9-ded2-4bb7-ae94-67fd3f1ca1f3", "roomID": "RM_9Xk96MBWLesm", "participant": "16921", "pID": "PA_7qAaCw6JYHb5", "remote": false, "trackID": "TR_VCKz3vsZzQFoF7", "relayed": false, "mime": "video/h264", "layer": 0, "start": 9617, "end": 18753, "count": 944, "highestSN": 18752}
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/buffer.(*RTPStats).getIntervalStats|github.com/livekit/livekit-server/pkg/sfu/buffer.(*RTPStats).getIntervalStats>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/buffer/rtpstats.go:1608
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/buffer.(*RTPStats).DeltaInfo|github.com/livekit/livekit-server/pkg/sfu/buffer.(*RTPStats).DeltaInfo>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/buffer/rtpstats.go:1187
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/buffer.(*Buffer).GetDeltaStats|github.com/livekit/livekit-server/pkg/sfu/buffer.(*Buffer).GetDeltaStats>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/buffer/buffer.go:769
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu.(*WebRTCReceiver).getDeltaStats|github.com/livekit/livekit-server/pkg/sfu.(*WebRTCReceiver).getDeltaStats>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/receiver.go:609
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).updateScoreAt|github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).updateScoreAt>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/connectionquality/connectionstats.go:267
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).getStat|github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).getStat>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/connectionquality/connectionstats.go:308
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).updateStatsWorker|github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).updateStatsWorker>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/connectionquality/connectionstats.go:359

Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | 2023-09-12T20:28:32.653Z#011ERROR#011livekit.sub#011buffer/rtpstats.go:1608#011could not find some packets#011{"room": "80e1bdb9-ded2-4bb7-ae94-67fd3f1ca1f3", "roomID": "RM_9Xk96MBWLesm", "participant": "60054", "pID": "PA_2tHvGfzWtF2L", "remote": false, "trackID": "TR_VCKz3vsZzQFoF7", "relayed": false, "start": 9900, "end": 19020, "count": 928, "highestSN": 19019}
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/buffer.(*RTPStats).getIntervalStats|github.com/livekit/livekit-server/pkg/sfu/buffer.(*RTPStats).getIntervalStats>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/buffer/rtpstats.go:1608
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/buffer.(*RTPStats).DeltaInfo|github.com/livekit/livekit-server/pkg/sfu/buffer.(*RTPStats).DeltaInfo>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/buffer/rtpstats.go:1187
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu.(*DownTrack).getDeltaStats|github.com/livekit/livekit-server/pkg/sfu.(*DownTrack).getDeltaStats>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/downtrack.go:1698
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).updateScoreAt|github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).updateScoreAt>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/connectionquality/connectionstats.go:267
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).getStat|github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).getStat>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/connectionquality/connectionstats.go:308
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | <http://github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).updateStatsWorker|github.com/livekit/livekit-server/pkg/sfu/connectionquality.(*ConnectionStats).updateStatsWorker>
Sep 12 20:28:32 hhwebrtc01 docker-compose[1515407]: livekit-livekit-1  | #011/workspace/pkg/sfu/connectionquality/connectionstats.go:359
Thanks again, i'm happy to provide more information if needed 🙂
f
Sorry, missed a bit of explanation. The connection quality measurement runs every 5 seconds on both up stream and down stream tracks. The stream allocator log indicates congestion. Changes between 1.4.1 and 1.4.5 in that area should make things better (hopefully 🙂 ) , but changes there are mostly to temper declaring congestion too soon. There will still be congestion. That is unavoidable unfortunately. Up stream congestion (usually detected by browser client) means client will send padding only packets to probe the channel for available bandwidth. As padding packets can be a maximum of 255 bytes, packet rate could be high during those probing periods and occupy space in the list. Down stream congestion means server sends padding only packet to probe. That list is one of the things on our plate to improve. To make it more space efficient and avoid those overflows. Don't have a good solution so far. The current size is a compromise between taking too much space and not losing information, but it does overflow once in a while. However, if this has changed recently, looks like you are experiencing a lot more congestion. Maybe, something is changed in your deploy? Maybe, the servers are handling more load and not able to do so causing server induced congestion (bandwidth estimate relies of time stamping packets, so if server is overloaded and sending delayed feedback to the client, client might declare congestion and take remediation action. In this case, network might still be fine, but server being overloaded causes the jitter). In the down stream direction, you can disable congestion control (https://github.com/livekit/livekit/blob/3f9f3adf91a2b296a5934970ca493754c8639314/config-sample.yaml#L68), That will prevent down stream probing, but that also means the down stream congestion will not be handled.
d
Thanks again, this information is very helpful! I'm currently trying to figure out why this has started to show up much more frequently and one theory is that we might have some kind of issue with the phone app, a new version was released around the time i think we saw an increase in this. The react native livekit sdk was not updated in that release, but react native itself was along with some other changes not really related to the video call feature. We also use this liivekit server for other types of video calls where the clients are only connecting using a web browser and during those calls i don't see the "could not find some packets" errors, even though there are occasional "channel congestion detected, updating channel capacity" log entries. Those calls usually have a lot more participants than the calls with the app have, so i don't think the server/deployment is likely to be the issue. The server setup hasn't changed in recent time either. Is it a good theory that if the client (app or browser) have some sort of load issue these errors are more likely to show up? Will experiment with disabling congestion control and see how it affects things, thanks!
f
If this is happening only for clients using react native (and the new app update you mentioned), it is possible that client side issues are resulting in congestion and because of that more padding is used.
d
Thanks, i'll start with trying to figure out if we have a problem in the app 👍
🙇🏽 1