Track ids get messed up when publishing two tracks at the same time

[SijmenHuizenga]

At about the exact same moment, two tracks were being published in the same room. The track ID's got messed up, it seems inside the sdk. Running sdk version 15f576a. Race condition?

The following log lines happen practically at the same time:

1. The livekit SDK logs that track with name front-xs#kaTUEk is published with track ID TR_VChsPfQLKR5vv8:

2024/11/12 06:03:11 INF [livekit-sdk] ts=2024-11-12 06:03:11.339546 caller={file=logger.go line=440} level=0 msg=published track name=front-xs#kaTUEk source=CAMERA trackID=TR_VChsPfQLKR5vv8

Then OnLocalTrackPublished is called with track name front-xs#kaTUEk and track ID TR_VCAy25euEr8rdM ❌. This is the wrong track id for this track name. As you can see in the full logs below the track Id TR_VCAy25euEr8rdM belongs to a track named left#sZhnyh.

2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] local track published front-xs#kaTUEk TR_VCAy25euEr8rdM

This log line originates from our app:

livekit.GetLocalParticipant().Callback.OnLocalTrackPublished = func(publication *lksdk.LocalTrackPublication, lp *lksdk.LocalParticipant) {
    sid := publication.SID()
    livekit.Log(logger.Info, "local track published %s %s", publication.Name(), sid)

full logs:

2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] local track published left#sZhnyh TR_VChsPfQLKR5vv8
2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] [left#sZhnyh] [] SID changed from  to TR_VChsPfQLKR5vv8
2024/11/12 06:03:11 INF [livekit-sdk] ts=2024-11-12 06:03:11.339546 caller={file=logger.go line=440} level=0 msg=published track name=front-xs#kaTUEk source=CAMERA trackID=TR_VChsPfQLKR5vv8
2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] [front-xs#kaTUEk] [TR_VChsPfQLKR5vv8] published track TR_VChsPfQLKR5vv8
2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] local track published front-xs#kaTUEk TR_VCAy25euEr8rdM
2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] [front-xs#kaTUEk] [TR_VChsPfQLKR5vv8] SID changed from TR_VChsPfQLKR5vv8 to TR_VCAy25euEr8rdM
2024/11/12 06:03:11 INF [livekit-sdk] ts=2024-11-12 06:03:11.340460 caller={file=logger.go line=440} level=0 msg=published track name=left#sZhnyh source=CAMERA trackID=TR_VCAy25euEr8rdM
2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] [left#sZhnyh] [TR_VCAy25euEr8rdM] published track TR_VCAy25euEr8rdM

The noticable effect was that the track did not cleanly unpublish, causing a track without video (blackout) to show up to our users.

[boks1971]

That does look like a race. Just trying to understand the logs better. The first line of full logs show

2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] local track published left#sZhnyh TR_VChsPfQLKR5vv8

Is the wrong trackID for left camera too? That is the trackID of front?

[boks1971]

Can you try this branch https://github.com/livekit/server-sdk-go/tree/raja_publish_chan if you get a chance? Will let you know once it is merged to main.

[SijmenHuizenga]

That does look like a race. Just trying to understand the logs better. The first line of full logs show

2024/11/12 06:03:11 INF [app] [room robot-zora-10 0] [RM_AipbuMjjhbph] local track published left#sZhnyh TR_VChsPfQLKR5vv8

Is the wrong trackID for left camera too? That is the trackID of front?

Thanks for looking into this @boks1971

I suspect that the log lines "published track" by the [livekit-sdk] hold the 'truth' for name-id mapping. But that's just based on my bias trusting the internal livekit-sdk's more than the callbacks 🤷. That would give the correct mappings:

• front-xs#kaTUEk = TR_VChsPfQLKR5vv8
• left#sZhnyh = TR_VCAy25euEr8rdM

[boks1971]

The PR is merged now to main - #556

[SijmenHuizenga]

Amazing! Closing this 🚀