Unpublished track appears in browser

[SijmenHuizenga]

We are using the server-sdk-go using this version of the sdk: https://github.com/livekit/server-sdk-go/commit/15f576aa52c50ee6eff4b63ceb1c9d9b7956f4c1

These are the logs from our application related to the TR_VCBfCwP22ZVpFv track. Timestamps in UTC. Most lines originate from our application, some from the sdk.

1730936364403   {"log":"2024/11/06 23:39:24 INF [livekit] [room robot-bixi-03 0] [RM_c8KiFQNyqqj7] [right#gJHNSI] [TR_VCBfCwP22ZVpFv] track finished"}
1730936364403   {"log":"2024/11/06 23:39:24 INF [livekit] [room robot-bixi-03 0] [RM_c8KiFQNyqqj7] [right#gJHNSI] [TR_VCBfCwP22ZVpFv] unpublished track"}
1730936364403   {"log":"2024/11/06 23:39:24 INF [livekit] \"ts\"=\"2024-11-06 23:39:24.403267\" \"caller\"={\"file\"=\"logger.go\" \"line\"=440} \"level\"=0 \"msg\"=\"unpublished track\" \"name\"=\"right#gJHNSI\" \"sid\"=\"TR_VCBfCwP22ZVpFv\""}
1730936364403   {"log":"2024/11/06 23:39:24 INF [livekit] [room robot-bixi-03 0] [RM_c8KiFQNyqqj7] local track unpublished right#gJHNSI TR_VCBfCwP22ZVpFv"}
1730936364403   {"log":"2024/11/06 23:39:24 WAR [livekit] [room robot-bixi-03 0] [RM_c8KiFQNyqqj7] [right#gJHNSI] [TR_VCBfCwP22ZVpFv] buffer stale, unpublishing track"}
1730933409023   {"log":"2024/11/06 22:50:09 INF [livekit] [room robot-bixi-03 0] [RM_c8KiFQNyqqj7] [left#pzretr] [TR_VCBfCwP22ZVpFv] SID changed from TR_VCBfCwP22ZVpFv to TR_VC8EASj3bZAcHM"}
1730933409022   {"log":"2024/11/06 22:50:09 INF [livekit] [room robot-bixi-03 0] [RM_c8KiFQNyqqj7] [left#pzretr] [TR_VCBfCwP22ZVpFv] published track TR_VCBfCwP22ZVpFv"}
1730933409022   {"log":"2024/11/06 22:50:09 INF [livekit] \"ts\"=\"2024-11-06 22:50:09.022876\" \"caller\"={\"file\"=\"logger.go\" \"line\"=440} \"level\"=0 \"msg\"=\"published track\" \"name\"=\"left#pzretr\" \"source\"=\"CAMERA\" \"trackID\"=\"TR_VCBfCwP22ZVpFv\""}
1730933409022   {"log":"2024/11/06 22:50:09 INF [livekit] [room robot-bixi-03 0] [RM_c8KiFQNyqqj7] [right#gJHNSI] [TR_VC5qbe3WyGtKKq] SID changed from TR_VC5qbe3WyGtKKq to TR_VCBfCwP22ZVpFv"}
1730933409022   {"log":"2024/11/06 22:50:09 INF [livekit] [room robot-bixi-03 0] [RM_c8KiFQNyqqj7] local track published right#gJHNSI TR_VCBfCwP22ZVpFv"}

Note the unpublished track originates from the SDK here: https://github.com/livekit/server-sdk-go/blob/15f576aa52c50ee6eff4b63ceb1c9d9b7956f4c1/localparticipant.go#L428

Nothing weird so far.

Now today I got a report of a stream not working. I go into the browser, open the room, look at the logs and see the track that was supposedly closed, according to above logs.

This is what i saw in the browser. This screenshot was taken at 2024/11/07 14:12:11 UTC:

How can a track that was unpublished, show up at a different client 14 hours after it was unpublished by the server sdk?

[SijmenHuizenga]

Two occurrences of this problem in the same room (RM_AipbuMjjhbph) at the same time. I was connected to the room from my browser at 2024/11/11 09:09:53 UTC (after a page refresh) and see these tracks show up:

---

Track TR_VCepcFSfrQbHYc was unpublished at 2024/11/11 05:01:36 UTC

Logs from the sdk:

{"log":"2024/11/11 05:01:36 INF [livekit] \"ts\"=\"2024-11-11 05:01:36.403392\" \"caller\"={\"file\"=\"logger.go\" \"line\"=440} \"level\"=0 \"msg\"=\"unpublished track\" \"name\"=\"back#TVsGqD\" \"sid\"=\"TR_VCepcFSfrQbHYc\""}
{"log":"2024/11/11 04:48:05 INF [livekit] \"ts\"=\"2024-11-11 04:48:05.570487\" \"caller\"={\"file\"=\"logger.go\" \"line\"=440} \"level\"=0 \"msg\"=\"published track\" \"name\"=\"right#cVWSER\" \"source\"=\"CAMERA\" \"trackID\"=\"TR_VCepcFSfrQbHYc\""}

---

Track TR_VCN6UjPd6i8N3n was unpublished at 2024/11/09 18:02:12 UTC

{"log":"2024/11/09 18:02:12 INF [livekit] \"ts\"=\"2024-11-09 18:02:12.167878\" \"caller\"={\"file\"=\"logger.go\" \"line\"=440} \"level\"=0 \"msg\"=\"unpublished track\" \"name\"=\"left#Wcluwj\" \"sid\"=\"TR_VCN6UjPd6i8N3n\""}
{"log":"2024/11/09 18:01:57 INF [livekit] \"ts\"=\"2024-11-09 18:01:57.174899\" \"caller\"={\"file\"=\"logger.go\" \"line\"=440} \"level\"=0 \"msg\"=\"published track\" \"name\"=\"back#seKwSH\" \"source\"=\"CAMERA\" \"trackID\"=\"TR_VCN6UjPd6i8N3n\""}

[SijmenHuizenga]

We have found that restarting the go application that publishes the tracks consistently removes any and all lingering tracks. Makes me suspect that there's an issue inside the sdk, not inside the livekit servers.

[SijmenHuizenga]

I think the behavior seen here is caused by #555 and solved with #556

This problem seems to always trigger after a full room-reconnect while multiple tracks are streaming. During the re-publish all tracks are published at the same time, triggering the race condition. Our application would get callbacks with wrong 'trackid' <-> 'trackname', which is the information that is later on used to unpublish the track. This unpublish would fail, because the wrong trackId would be unpublished, causing leftover tracks.