Video received by jitsi-meet UI app from jvb but fails to decode and render

[Dennis_Dowhy]

We have a case where there are 4 people in a conference, for sake of this issue lets call them users Alice, Bob, Claire, and Dave, and everyone has their camera’s on. Everyone can see everyone else except for one user who cannot see one specific person, aka → Alice cannot see Claire, but Bob and Dave can see Claire fine.

OS/Browser versions used:

• Alice Chrome 108.0.0.0 Windows
• Bob Chrome 107.0.0.0 Mac OS X
• Claire Chrome 107.0.0.0 Windows
• Dave Chrome 108.0.0.0 Mac OS X

Looking at jitsi-meet browser logs we only see 1 error or failure in Alice’s browser, but it’s related to Audio and not video:

2022-12-08T16:04:01.022Z 2022-12-08T16:04:01.022Z [modules/detection/VADAudioAnalyser.js] Failed to start VADAudioAnalyser RuntimeError: Aborted(LinkError: WebAssembly.instantiate(): Import #2 module="a" function="memory" error: memory import must be a WebAssembly.Memory object). Build with -sASSERTIONS for more info.

We don’t see any errors in the jvb for Alice either. Alice can see other users fine. This tells me that at least Alice can receive+decrypt+decode+render other users fine (so in other words, it shouldn’t be any issue regarding DTLS-SRTP key negotiation, as all the streams are muxed over the same connection.) And since other users can see Claire fine, this tells me that there is not an issue on Claire’s end sending video to the jvb. Why then can Alice see other users video but not Claire’s?

Where it gets interesting is the callstats data → Digging through the logs and metrics, I can see Claire’s video ssrc as ‘421061617’, so I did a comparison between Bob’s video received metrics for Claire vs Alice’s video received metrics for Claire. It is easy to spot the differences, and very clear about the following:

• Alice is receiving packets of seemingly expected rate/size for a video track for Claire’s video over that ssrc 421061617
• We can even see that the stats is detecting video frame boundaries (assuming this is the webrtc stack looking at whether or not the marker bits are set in the RTP headers, given that the stats for video frames received is incrementing at an expected rate)
• Alice has a high NACK/PLI count for Claire’s video
• On Alice’s side, ZERO packets are being decoded and rendered for Claire’s video.

But there are no errors/warnings/failures in the browser logs or jvb that would indicate any issue. Do we know why this might happen? If it’s not a key negotiation failure, could the JVB be encoding the RTP packets incorrectly, or possible encrypting the payload wrong, or maybe the JVB is sending the wrong encrypted payload over this SSRC id to Alice?

In the images attached, Alice, who cannot see Claire’s video, received metrics for this SSRC is on the right, while Bob, who can see Claire fine, is on the left.

[emrah]

You may test to reproduce the same issue on meet.jit.si using the same clients.
Which version is this?

[Boris_Grozev]

I don’t have an answer, just some additional observations and questions.

Did it eventually recover from this state? Did Alice try to change anything in the interface (e.g. move from time to stage view)?

This was happening for ~20 minutes, so most likely Claire generated a keyframe in that period and it is surprising that it didn’t reset and fix the state of the decoder. Can you check in Claire’s send-side stats that she sent a keyframe?

While the SRTP keying material is shared for the whole session, each SSRC has its own Roll-Over Counter and if it gets out of sync between the sender and receiver you’ll see the receiver discarding packets with SRTP auth failure. That’s probably not the case here, though, as the frame counters wouldn’t be updating.

It is strange that framesDecoded keeps incrementing!

It is strange that there are so many NACKs at a pretty constant rate. That’s probably Alice requesting packets that the bridge no longer has in its cache. The PLIs should have triggered a keyframe, and the keyframe should have fixed the decoder state if that was the problem.

Was there an ICE restart, or a move to a different bridge involving Alice? Anything that would have re-created the endpoint in the backend, but reused the PeerConnection in Alice’s client? There’s a bug with TCC which has similar symptoms. If the bridge endpoint is recreated it starts sending media with TCC seq starting from 0, while chrome expects to receive seqs from the previusly reached value. The result is chrome sending “not received” TCC feedback over and over again and not decoding. But I’m not sure the rest of the details match. Because of this bug we don’t do ICE restarts without starting a new jingle session (which makes a new PeerConnection), but it’s just a matter of config changes to enable this kind of ICE restart.

I assume this is a one-off case and you don’t have a way to reproduce traffic dumps on the bridge enabled?

[Dennis_Dowhy]

Lots of keyframes were generated by ‘Claire’ during this session.

the codecs used during this session:

wrt to that above,

• 2b862d65 = Alice
• e3318a57 = Claire
• cd409949 = Bob
• 6dbe213c = Dave

It also looks like the pli’s were passed up back to the source looking at Claire’s pli count:

No IceRestarts or moving to other bridges (no shard failures or anything). Afaik or that I can see, there’s nothing that would have caused recreation of the endpoint on the bridge. For all intents and purposes it was a standard 4 person conference call.

I’m reaching back out to the user to see if this has happened before or if they can repeat it in any way.

[Dennis_Dowhy]

we had a repeat of this again today, with the same 2 users same situation. Note that at the end of the 11 minute conference, ‘Alice’ left and rejoined and the video worked on the rejoin (aka she could see Claire after rejoining). But troubleshooting the initial join where Alice did not see Claire again, I do see one thing in the logs that looks odd to me →

tracing the logs…

### “Alice” getting the source-add for “Claire’s” stream:
2022-12-12T20:34:41.759Z 2022-12-12T20:34:41.759Z [modules/xmpp/strophe.jingle.js] <Qo.onJingle>: Received source-add from with sources=4eeee752:[3402133222,3469740174]

### seems video track starts muted (by default I guess?)
…
2022-12-12T20:34:42.063Z 2022-12-12T20:34:42.063Z [modules/RTC/JitsiRemoteTrack.js] : New remote track added: RemoteTrack[userID: 4eeee752, type: video, ssrc: 3469740174, p2p: false, sourceName: 4eeee752-v0, status: readyState: live, muted: true, enabled: true]
.
2022-12-12T20:34:42.065Z 2022-12-12T20:34:42.065Z [modules/qualitycontrol/ReceiveVideoController.js] <Ll.updateReceiverVideoConstraints>: Updating ReceiverVideoConstraints {“constraints”:{“4eeee752-v0”:{“maxHeight”:720}},“defaultConstraints”:{“maxHeight”:0},“lastN”:-1,“onStageSources”:[“4eeee752-v0”],“selectedSources”:}
2022-12-12T20:34:42.065Z 2022-12-12T20:34:42.065Z [modules/RTC/BridgeChannel.js] <Sa.sendNewReceiverVideoConstraintsMessage>: Sending ReceiverVideoConstraints with {“constraints”:{“4eeee752-v0”:{“maxHeight”:720}},“defaultConstraints”:{“maxHeight”:0},“lastN”:-1,“onStageSources”:[“4eeee752-v0”],“selectedSources”:}

### video track is immediately unmuted
.
2022-12-12T20:34:42.071Z 2022-12-12T20:34:42.071Z [modules/RTC/JitsiRemoteTrack.js] <xd._addEventListener>: Initializing track streaming status: 4eeee752-v0
2022-12-12T20:34:42.076Z 2022-12-12T20:34:42.076Z [modules/UI/videolayout/LargeVideoManager.js] Scheduled large video update for 4eeee752
2022-12-12T20:34:42.082Z 2022-12-12T20:34:42.082Z [modules/RTC/JitsiRemoteTrack.js] <xd._onTrackUnmute>: “onunmute” event(1670877282082): RemoteTrack[userID: 4eeee752, type: video, ssrc: 3469740174, p2p: false, sourceName: 4eeee752-v0, status: readyState: live, muted: false, enabled: true]
2022-12-12T20:34:42.083Z 2022-12-12T20:34:42.083Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.onTrackRtcUnmuted>: Detector track RTC unmuted: 4eeee752-v0 1670877282082
2022-12-12T20:34:42.083Z 2022-12-12T20:34:42.083Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for 4eeee752-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: true currentStatus => newStatus: active => active

### 3 seconds later track goes back to muted state
…
2022-12-12T20:34:45.401Z 2022-12-12T20:34:45.401Z [modules/RTC/JitsiRemoteTrack.js] <xd._onTrackMute>: “onmute” event(1670877285400): RemoteTrack[userID: 4eeee752, type: video, ssrc: 3469740174, p2p: false, sourceName: 4eeee752-v0, status: readyState: live, muted: true, enabled: true]
2022-12-12T20:34:45.401Z 2022-12-12T20:34:45.401Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.onTrackRtcMuted>: Detector track RTC muted: 4eeee752-v0 1670877285401

This doesn’t seem right, because participant 4eeee752 never muted their video track.

looking at jvb logs, the only errors I see at this time frame when the track when muted for 1 user is this:
VideoQualityLayerLookup.transform#44: Unable to find encoding matching packet! packet=RtpPacket: PT=101, Ssrc=3469740174, SeqNum=23985, M=true, X=true, Ts=937295570, SID=2, TID=1; sources=MediaSourceDesc 1789574891 has encodings:

but those encoding “errors” seem common across jvb logs, we see them all the time but not necessary tied to any user visual errors afaik. Are those errors normal to see in jvb logs or is that some indication of a problem? Also is my analysis above correct? Does that indicate the remote track got muted for some reason, and if so what reasons could that be if Claire never muted her source video camera track?

[Boris_Grozev]

@Dennis_Dowhy

but those encoding “errors” seem common across jvb logs, we see them all the time but not necessary tied to any user visual errors afaik. Are those errors normal to see in jvb logs or is that some indication of a problem?

There is a race condition between signaling and media arriving at the bridge. If the bridge receives video packets before the signaling that describes the encodings has been received this message is printed. In this case the logs are “normal”, i.e. they result in some packets getting dropped and keyframe being requests, but it should recover automatically and very quickly. You can recognize this case if you see the “unable to find encoding” message stop being printed after signaling is received (you may need to enable debug logs for XmppConnection to see signaling, we always keep it on).

Someone else will have to help interpret the client logs (@jallamsetty ?). I think they mean the underlying track stopped playing, not that the sender advertised in presence that the track is muted. That would be consistent with failure to decode/render while receiving packets.

It’s curious that this would happen again with the same user. Perhaps something about their environment is a trigger. This is your own environment, right? Are you running recent versions of jvb/jicofo?

[jallamsetty]

@Dennis_Dowhy

2022-12-12T20:34:45.401Z 2022-12-12T20:34:45.401Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.onTrackRtcMuted>: Detector track RTC muted: 4eeee752-v0 1670877285401

Yes, it does mean that the underlying track stopped playing. Browser fires a “mute” event on the MediaStreamTrack when the JVB stops sending video or when the MediaStreamTrack object’s source is temporarily unable to provide data.

[Dennis_Dowhy]

@Boris_Grozev

There is a race condition between signaling and media arriving at the bridge.

yea I figured this based on searches on this topic, but nice to have that confirmed, ty

@Boris_Grozev

It’s curious that this would happen again with the same user. Perhaps something about their environment is a trigger.

Yea but when Alice left and rejoined at the end of the meeting, the video worked (she could finally see Claire’s video). If it was something environmental in the setup, I was hoping that this would be consistent. Unfortunately it is not.

@Boris_Grozev

Are you running recent versions of jvb/jicofo?

We are using a fairly recent 7882 versions in our deployment.

[Dennis_Dowhy]

@jallamsetty

it does mean that the underlying track stopped playing. Browser fires a “mute” event on the MediaStreamTrack when the JVB stops sending video or when the MediaStreamTrack object’s source is temporarily unable to provide data.

The fact that other users could see Claire fine tells me it’s not an issue on Claire’s end. There must be something between the jvb and Alice that is causing this. No other errors on the jvb end, and no errors /warnings/failures in Alice’s browser logs either. It’s all chrome browser on windows too, no firefox or safari or mac os involved here. So that eliminates any compatibility issues.

If it was backend jvb bandwidth estimation problems, I would expect to see messages like ‘video turned off to save bandwidth’ or some other type of related error or warning, as we’ve seen that in the past too. But I don’t see any of that in these instances. As of right now I can’t tell if the problem is something in Alice’s browser jitsi-meet UI app (meaning some error either in the remote track creation or handling, some bug in the webrtc stack), or if there are some sort of race conditions or hidden errors on the jvb end not sending the right encrypted data. I’m not sure what else this could be.

[jallamsetty]

Do you see Claire’s video source listed as one of the sources that is being forwarded by the bridge? You should see bridge messages in the console log:

2022-12-14T16:01:59.225Z [modules/RTC/BridgeChannel.js] <e.onmessage>: New forwarded sources: 7e943507-v0,a7f4bc6a-v0,5b6210ec-v0,433c5e67-v0,606f735d-v0,da32cba5-v0

Also, there should be a log about the streaming status for that particular source which would give us an indication if the application decided to not render the video received. It looks something like this:

2022-12-14T15:33:08.999Z [modules/connectivity/TrackStreamingStatus.ts] <xd.figureOutStreamingStatus>: Figure out conn status for 5b6210ec-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: true currentStatus => newStatus: active => active

[Dennis_Dowhy]

@jallamsetty

Do you see Claire’s video source listed as one of the sources that is being forwarded by the bridge?

In both cases, yes, on Alice’s browser logs I see the log records ‘New forwarded sources:’ representing Claire’s stream from the bridge.

@jallamsetty

there should be a log about the streaming status for that particular source which would give us an indication if the application decided to not render the video received.

From the logs for the conference from the original post, where ‘e3318a57-v0’ is Claire’s stream and this log is from Alice’s browser:

54sec after start of call

2022-12-08T16:29:56.783Z 2022-12-08T16:29:56.783Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for e3318a57-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: true currentStatus => newStatus: restoring => active

1 min 24 sec after start of call

2022-12-08T16:04:50.283Z 2022-12-08T16:04:50.283Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for e3318a57-v0, is video muted: false video track frozen: true p2p mode: false is in forwarded sources: true currentStatus => newStatus: active => restoring

also 1 min 24 sec after start of call

2022-12-08T16:05:00.292Z 2022-12-08T16:05:00.292Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for e3318a57-v0, is video muted: false video track frozen: true p2p mode: false is in forwarded sources: true currentStatus => newStatus: restoring => restoring

26 min 1 s (last second of call before ending)

2022-12-08T16:29:56.783Z 2022-12-08T16:29:56.783Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for e3318a57-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: true currentStatus => newStatus: restoring => active

From the logs for the other conference a few days ago, where ‘4eeee752-v0’ is Claire’s stream and this log is from Alice’s browser:

6 sec

2022-12-12T20:34:42.083Z 2022-12-12T20:34:42.083Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for 4eeee752-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: true currentStatus => newStatus: active => active

45 sec

2022-12-12T20:34:55.403Z 2022-12-12T20:34:55.403Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for 4eeee752-v0, is video muted: false video track frozen: true p2p mode: false is in forwarded sources: true currentStatus => newStatus: active => restoring
2022-12-12T20:35:05.407Z 2022-12-12T20:35:05.407Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for 4eeee752-v0, is video muted: false video track frozen: true p2p mode: false is in forwarded sources: true currentStatus => newStatus: restoring => restoring

3 min 31 sec

2022-12-12T20:38:06.401Z 2022-12-12T20:38:06.401Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for 4eeee752-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: true currentStatus => newStatus: restoring => active

4 min 1 sec

2022-12-12T20:38:11.530Z 2022-12-12T20:38:11.530Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for 4eeee752-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: false currentStatus => newStatus: active => active
2022-12-12T20:38:11.544Z 2022-12-12T20:38:11.544Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for 4eeee752-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: true currentStatus => newStatus: active => active

5 min 1 sec

2022-12-12T20:39:40.134Z 2022-12-12T20:39:40.134Z [modules/connectivity/TrackStreamingStatus.ts] <Nd.figureOutStreamingStatus>: Figure out conn status for 4eeee752-v0, is video muted: false video track frozen: false p2p mode: false is in forwarded sources: true currentStatus => newStatus: active => active

So what I see in both of those cases above is that ‘video track frozen: true’, does this confirm that from Alice’s pov that Claire’s stream was indeed not able to get decoded and rendered?

[jallamsetty]

@Dennis_Dowhy

So what I see in both of those cases above is that ‘video track frozen: true’, does this confirm that from Alice’s pov that Claire’s stream was indeed not able to get decoded and rendered?

Yes, it does confirm that Alice was not able to decode or render Claire’s stream. The issue doesn’t seem to be in the jitsi-meet UI app as remote track creation was successful. It does sound like its deeper, at the webrtc stack level and browser’s webrtc debug logs can help.