Remote Video frames not received when SDPSemantic is set to "PlanB" in peer connection

[KarthikRichie]

Describe the bug I'm creating a separate peer connection for audio and video with sdp semantic set to "PlanB". Audio is being properly sent to remote and received from remote. But with respect to video, local video is being sent but the remote video frames are not triggering. But I could see the remote track added event being triggered, but somehow the I420FrameReady event for the remote track is not getting called even though it is subscribed.

Expected behavior Ideally, on setting the remote description from remote peer, the remote video frames should be received after remote video track creation.

What I tried a) Since "msid-semantic WMS" was missing in the remote sdp, I tried explicitly adding it ahead of "m=video" line before setting remote description. But it was of no help b) Debugged Mixed reality's source code and tried updating sink_settings.rotation_applied=false in remote_video_track.cpp to see if frames are being received. But it was of no help c) Removed the check for magic prefix 'mrsw#' for automatic Plan B track pairing (as the stream id in my remote sdp doesn't start with mrsw#. The stream id in my case is an alpha numeric value) to allow the creation of remote video track. But, when doing this, the mline index was updated to a weird value. I assume mline index has less role to play in "Plan B". Pls correct me if I'm wrong. d) Explicitly added video stream id "mrsw#0" in the remote sdp to allow the creation of remote video tracks. But that didn't help.

SDP messages v=0 o=XYZ 1624490253 1624490254 IN IP4 169.38.120.86 s=XYZ c=IN IP4 169.38.120.86 t=0 0 m=video 17720 UDP/TLS/RTP/SAVPF 96 b=AS:1024 a=rtpmap:96 VP8/90000 a=sendrecv a=fingerprint:sha-256 85:C5:68:22:8E:FE:93:D5:E8:A3:77:F2:6F:49:2D:03:56:DC:0A:60:F2:2C:4A:52:92:15:E8:EB:47:87:24:41 a=setup:active a=rtcp-mux a=rtcp:17720 IN IP4 169.38.120.86 a=rtcp-fb:96 ccm fir a=rtcp-fb:96 nack a=rtcp-fb:96 nack pli a=ssrc:2173402053 cname:F3rfMyWVq1 a=ssrc:2173402053 msid:1104381000000027163_v v2 a=ssrc:2173402053 mslabel:1104381000000027163_v a=ssrc:2173402053 label:1104381000000027163_vv2 a=ice-ufrag:Dy8Oxuwo6XyWmzCk a=ice-pwd:oFrjUsKTgQi2euiHSgmgBIuy a=candidate:0448559912 1 udp 659136 169.38.120.86 17720 typ host generation 0 a=end-of-candidates

Environment Local Machine 1:-

• MR-WebRTC 2.0.2-> releases/2.0
• Platform: [Windows 10 UWP]
• Architecture: [x64]
• Target device: [e.g. Windows Desktop, HoloLens 1, HoloLens 2, Android Phone]

Remote Machine 2:-

• Browser-> Chrome
• Platform-> Windows 10

Additional context Webrtc logs after setting remote description

(paced_sender.cc:272): Elapsed time (16909 ms) longer than expected, limiting to 2000 ms (messagequeue.cc:513): Message took 11946ms to dispatch. Posted from: cricket::P2PTransportChannel::CheckAndPing@../../p2p/base/p2ptransportchannel.cc:1954 (paced_sender.cc:272): Elapsed time (14615 ms) longer than expected, limiting to 2000 ms (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (openssladapter.cc:819): SSL_accept:TLS server select_certificate (openssladapter.cc:819): SSL_accept:TLS server select_parameters (openssladapter.cc:819): SSL_accept:TLS server send_server_hello (openssladapter.cc:819): SSL_accept:TLS server send_server_certificate (openssladapter.cc:819): SSL_accept:TLS server send_server_key_exchange (openssladapter.cc:819): SSL_accept:TLS server send_server_hello_done (openssladapter.cc:819): SSL_accept:TLS server read_client_certificate (openssladapter.cc:829): SSL_accept:error in TLS server read_client_certificate (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (dtlstransport.cc:591): DtlsTransport[audio|1|]: Received non-DTLS packet before DTLS complete. (webrtcvideoengine.cc:1313): Call stats: 1624555049165, {send_bw_bps: 0, recv_bw_bps: 0, max_pad_bps: 0, pacer_delay_ms: 0, rtt_ms: -1} (dtlssrtptransport.cc:60): Setting RTCP Transport on video transport 0 (dtlssrtptransport.cc:65): Setting RTP Transport on video transport 853c3850 (p2ptransportchannel.cc:403): Received remote ICE parameters: ufrag=d3yaGtsvgsUhD2n5, renomination disabled (dtlstransport.cc:376): DtlsTransport[video|1|]: DTLS setup complete. (channel.cc:530): Channel enabled (channel.cc:909): Changing video state, send=0 (peerconnection.cc:3512): Session: 4184764001769606598 Old state: kHaveLocalOffer New state: kStable (opensslstreamadapter.cc:938): DTLS timeout expired (openssladapter.cc:829): SSL_accept:error in TLS server read_client_certificate (openssladapter.cc:829): SSL_accept:error in TLS server read_client_certificate (openssladapter.cc:819): SSL_accept:TLS server verify_client_certificate (opensslstreamadapter.cc:1087): Accepted peer certificate. (openssladapter.cc:819): SSL_accept:TLS server read_client_key_exchange Video Peer Connection Established (channel.cc:973): Setting remote video description (webrtcvideoengine.cc:686): SetSendParameters: {codecs: [VideoCodec[96:VP8]], conference_mode: no, extensions: [], max_bandwidth_bps: 1024000, mid: video} (webrtcvideoengine.cc:695): Using codec: VideoCodec[96:VP8] (webrtcvideoengine.cc:1678): RTX SSRCs configured but there's no configured RTX payload type. Ignoring. (webrtcvideoengine.cc:1694): RecreateWebRtcStream (send) because of SetCodec. (alr_experiment.cc:65): Using ALR experiment settings: pacing factor: 1, max pacer queue length: 2875, ALR start bandwidth usage percent: 80, ALR end budget level percent: 40, ALR end budget level percent: -60, ALR experiment group ID: 3 (openssladapter.cc:819): SSL_accept:TLS server read_client_certificate_verify (video_send_stream_impl.cc:285): VideoSendStreamInternal: {encoder_settings: { experiment_cpu_load_estimator: off}}, rtp: {ssrcs: [1856303484], rtcp_mode: RtcpMode::kCompound, max_packet_size: 1200, extensions: [], nack: {rtp_history_ms: 1000}, ulpfec: {ulpfec_payload_type: -1, red_payload_type: -1, red_rtx_payload_type: -1}, payload_name: VP8, payload_type: 96, flexfec: {payload_type: -1, ssrc: 0, protected_media_ssrcs: []}, rtx: {ssrcs: [], payload_type: -1}, c_name: nCuyoDrZUgwpk9uE}, rtcp: {video_report_interval_ms: 1000, audio_report_interval_ms: 5000}, pre_encode_callback: nullptr, post_encode_callback: nullptr, render_delay_ms: 0, target_delay_ms: 0, suspend_below_min_bitrate: off} (video_stream_encoder.cc:487): ConfigureEncoder requested. (call.cc:1047): UpdateAggregateNetworkState: aggregate_state=down (send_side_congestion_controller.cc:308): SignalNetworkState Down (video_send_stream.cc:150): VideoSendStream::Stop (video_send_stream_impl.cc:442): VideoSendStream::Stop (webrtcvideoengine.cc:744): SetFeedbackOptions on all the receive streams because the send codec or RTCP mode has changed. (webrtcvideoengine.cc:1137): AddRecvStream: {id:v2;ssrcs:[1856303484];ssrc_groups:;cname:RGXOrM0HFC;stream_ids:1104381000000027197_v;} (openssladapter.cc:819): SSL_accept:TLS server read_change_cipher_spec (openssladapter.cc:819): SSL_accept:TLS server process_change_cipher_spec (openssladapter.cc:819): SSL_accept:TLS server read_next_proto (openssladapter.cc:819): SSL_accept:TLS server read_channel_id (openssladapter.cc:819): SSL_accept:TLS server read_client_finished (openssladapter.cc:819): SSL_accept:TLS server send_server_finished (openssladapter.cc:819): SSL_accept:TLS server finish_server_handshake (video_stream_encoder.cc:792): Video frame parameters changed: dimensions=640x480, texture=0. (video_stream_encoder.cc:156): Set max framerate: 60 (openssladapter.cc:819): SSL_accept:TLS server done (dtlstransport.cc:636): DtlsTransport[audio|1|]: DTLS handshake complete. (jseptransportcontroller.cc:1050): Transport audio writability changed to 1. (quality_scaler.cc:72): Created CheckQpTask. Scheduling on queue... (quality_scaler.cc:125): QP thresholds: low: 29, high: 95 (dtlssrtptransport.cc:218): Extracting keys from transport: audio (video_receive_stream.cc:119): VideoReceiveStream: {decoders: [{decoder: (VideoDecoder), payload_type: 96, name: VP8, codec_params: {}}, {decoder: (VideoDecoder), payload_type: 98, name: VP9, codec_params: {x-google-profile-id: 0}}, {decoder: (VideoDecoder), payload_type: 100, name: H264, codec_params: {packetization-mode: 1}}], rtp: {remote_ssrc: 1856303484, local_ssrc: 1, rtcp_mode: RtcpMode::kCompound, rtcp_xr: {receiver_reference_time_report: off}, remb: off, transport_cc: off, nack: {rtp_history_ms: 1000}, ulpfec_payload_type: 125, red_type: 127, rtx_ssrc: 0, rtx_payload_types: {97 (pt) -> 96 (apt), 99 (pt) -> 98 (apt), 101 (pt) -> 100 (apt), 124 (pt) -> 127 (apt), }, extensions: [{uri: http://tools.ietf.org/html/draft-ietf-avtext-framemarking-07, id: 10}, {uri: http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01, id: 5}, {uri: http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time, id: 3}, {uri: http://www.webrtc.org/experiments/rtp-hdrext/playout-delay, id: 6}, {uri: http://www.webrtc.org/experiments/rtp-hdrext/video-content-type, id: 7}, {uri: http://www.webrtc.org/experiments/rtp-hdrext/video-timing, id: 8}, {uri: urn:3gpp:video-orientation, id: 4}, {uri: urn:ietf:params:rtp-hdrext:toffset, id: 2}]}, renderer: (renderer), render_delay_ms: 10, sync_group: 1104381000000027197_v, target_delay_ms: 0} (call.cc:1047): UpdateAggregateNetworkState: aggregate_state=down (send_side_congestion_controller.cc:308): SignalNetworkState Down (channel.cc:656): Add remote ssrc: 1856303484 (srtptransport.cc:294): SRTP activated with negotiated parameters: send cipher_suite 1 recv cipher_suite 1 (channel.cc:560): Channel writable (audio) for the first time (srtpsession.cc:159): Failed to unprotect SRTCP packet, err=14 (srtptransport.cc:231): Failed to unprotect RTCP packet: size=92, type=201 (video_send_stream.cc:150): VideoSendStream::Stop (video_send_stream_impl.cc:442): VideoSendStream::Stop (channel.cc:909): Changing video state, send=0 (messagequeue.cc:513): Message took 141ms to dispatch. Posted from: cricket::BaseChannel::SetRemoteContent@../../pc/channel.cc:279 (call.cc:1047): UpdateAggregateNetworkState: aggregate_state=up (send_side_congestion_controller.cc:308): SignalNetworkState Up (bitrate_prober.cc:110): Probe cluster (bitrate:min bytes:min packets): (900000:1687:5) (bitrate_prober.cc:110): Probe cluster (bitrate:min bytes:min packets): (1800000:3375:5) (send_side_congestion_controller.cc:555): Bitrate estimate state changed, BWE: 300000 bps. (bitrate_allocator.cc:104): Current BWE 300000 (turnport.cc:1547): Port[82404d30:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: TURN create permission request sent, id=6d623445796b596250337867 (port.cc:1104): Conn[854a3a70:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:WQdl5cve:1:0:relay:udp:52.66.163.63:53392->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--W|-|0|0|2830967580278271|-]: Connection created (p2ptransportchannel.cc:1198): Channel[video|1|]: Created connection with origin: 2, total: 1 (turnport.cc:1547): Port[82404000:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: TURN create permission request sent, id=4153654c3468367472386a54 (port.cc:1104): Conn[854a4770:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:uquX8npx:1:0:relay:udp:52.66.163.63:62768->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--W|-|0|0|2830967613833215|-]: Connection created (p2ptransportchannel.cc:1198): Channel[video|1|]: Created connection with origin: 2, total: 2 (port.cc:1104): Conn[854a2070:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:FySN3J2V:1:0:local:udp:192.168.1.5:60888->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--W|-|0|0|2830971808136703|-]: Connection created (p2ptransportchannel.cc:1198): Channel[video|1|]: Created connection with origin: 2, total: 3 (p2ptransportchannel.cc:1831): Channel[video|1|]: Transport channel state changed from 0 to 1 (jseptransportcontroller.cc:1113): video Transport 1 state changed. Check if state is complete. (p2ptransportchannel.cc:1412): Channel[video|1|]: Have a pingable connection for the first time; starting to ping. (peerconnection.cc:3464): Changing IceConnectionState 0 => 1 (webrtcvoiceengine.cc:316): WebRtcVoiceEngine::ApplyOptions: AudioOptions {aec: 1, ns: 1, hf: 1, audio_jitter_buffer_max_packets: 50, audio_jitter_buffer_fast_accelerate: 0, extended_filter_aec: 1, delay_agnostic_aec: 1, } (peerconnection.cc:4769): Non-rejected SCTP m= section is needed to get the SSL Role of the SCTP transport. (peerconnection.cc:4158): Creating video receiver for track_id=v2 and stream_id=1104381000000027197_v (port.cc:1726): Conn[854a2070:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:FySN3J2V:1:0:local:udp:192.168.1.5:60888->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--W|-|0|0|2830971808136703|-]: Sent STUN ping, id=3473312f67633974494d4273, use_candidate=1, nomination=0 (paced_sender.cc:110): PacedSender resumed. (turnport.cc:1554): Port[82404d30:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: TURN permission requested successfully, id=6d623445796b596250337867, code=0, rtt=34 (turnport.cc:1729): Port[82404d30:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: Create permission for 169.38.120.72:18630 succeeded (turnport.cc:1741): Port[82404d30:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: Scheduled create-permission-request in 240000ms. (turnport.cc:1554): Port[82404000:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: TURN permission requested successfully, id=4153654c3468367472386a54, code=0, rtt=33 (turnport.cc:1729): Port[82404000:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: Create permission for 169.38.120.72:18630 succeeded (turnport.cc:1741): Port[82404000:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: Scheduled create-permission-request in 240000ms. (port.cc:1726): Conn[854a4770:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:uquX8npx:1:0:relay:udp:52.66.163.63:62768->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--W|-|0|0|2830967613833215|-]: Sent STUN ping, id=4b4d6f5661652b3138555472, use_candidate=1, nomination=0 (audio_processing_impl.cc:688): Highpass filter activated: 1 (fixed_gain_controller.cc:60): Gain to apply: 0 db. (audio_processing_impl.cc:702): Gain Controller 2 activated: 0 (audio_processing_impl.cc:704): Pre-amplifier activated: 0 (apm_helpers.cc:114): Echo control set to 1 with mode 0 (apm_helpers.cc:124): EC metrics set to 1 (srtpsession.cc:159): Failed to unprotect SRTCP packet, err=14 (srtptransport.cc:231): Failed to unprotect RTCP packet: size=92, type=201 (port.cc:1726): Conn[854a3a70:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:WQdl5cve:1:0:relay:udp:52.66.163.63:53392->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--W|-|0|0|2830967580278271|-]: Sent STUN ping, id=4b4e3934776661734c6d4841, use_candidate=1, nomination=0 (webrtcvoiceengine.cc:476): Disabling NS since built-in NS will be used instead (apm_helpers.cc:149): NS set to 0 (webrtcvoiceengine.cc:489): NetEq capacity is 50 (webrtcvoiceengine.cc:495): NetEq fast mode? 0 (webrtcvoiceengine.cc:513): Delay agnostic aec is enabled? 1 (webrtcvoiceengine.cc:523): Extended filter aec is enabled? 1 (webrtcvoiceengine.cc:533): Experimental ns is enabled? 0 (audio_processing_impl.cc:688): Highpass filter activated: 1 (fixed_gain_controller.cc:60): Gain to apply: 0 db. (audio_processing_impl.cc:702): Gain Controller 2 activated: 0 (audio_processing_impl.cc:704): Pre-amplifier activated: 0 (impl_webrtc_audiodevicewasapi.cpp:1211): Using communications audio capture device: Microphone Array (2- Realtek Audio) (impl_webrtc_audiodevicewasapi.cpp:1239): Input audio device activated Microphone Array (2- Realtek Audio) (audio_device_buffer.cc:181): SetRecordingSampleRate(48000) (audio_device_buffer.cc:201): SetRecordingChannels(2) (port.cc:1726): Conn[854a2070:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:FySN3J2V:1:0:local:udp:192.168.1.5:60888->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--I|-|0|0|2830971808136703|-]: Sent STUN ping, id=7352562b7278714249307545, use_candidate=1, nomination=0 (audio_device_buffer.cc:181): SetRecordingSampleRate(48000) (audio_device_buffer.cc:201): SetRecordingChannels(2) (audio_device_buffer.cc:118): webrtc::AudioDeviceBuffer::StartRecording (channel.cc:779): Changing voice state, recv=1 send=1 (messagequeue.cc:513): Message took 175ms to dispatch. Posted from: cricket::BaseChannel::UpdateMediaSendRecvState@../../pc/channel.cc:764 (webrtcvideoengine.cc:1267): SetSink: ssrc:1856303484 (ptr) (audio_device_buffer.cc:239): Size of recording buffer: 960 (peer_connection.cpp:912): Added receiver #v2 of type 1 (peer_connection.cpp:915): + Track #v2 with stream #1104381000000027197_v (agc_manager_direct.cc:382): [agc] Initial GetMicVolume()=0 (agc_manager_direct.cc:387): [agc] Initial volume too low, raising to 12 (port.cc:1726): Conn[854a4770:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:uquX8npx:1:0:relay:udp:52.66.163.63:62768->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--I|-|0|0|2830967613833215|-]: Sent STUN ping, id=4a665a395741473964762b77, use_candidate=1, nomination=0 (agc_manager_direct.cc:382): [agc] Initial GetMicVolume()=12 (paced_sender.cc:272): Elapsed time (2217 ms) longer than expected, limiting to 2000 ms (probe_controller.cc:288): kWaitingForProbingResult: timeout (rtp_sender_audio.cc:243): First audio RTP packet sent to pacer (messagequeue.cc:513): Message took 3130ms to dispatch. Posted from: rtc::BasicNetworkManager::UpdateNetworksContinually@../../rtc_base/network.cc:959 (paced_sender.cc:272): Elapsed time (2048 ms) longer than expected, limiting to 2000 ms (port.cc:1726): Conn[854a3a70:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:WQdl5cve:1:0:relay:udp:52.66.163.63:53392->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--I|-|0|0|2830967580278271|-]: Sent STUN ping, id=6956655631564c5166522f65, use_candidate=1, nomination=0 (messagequeue.cc:513): Message took 1498ms to dispatch. Posted from: cricket::P2PTransportChannel::CheckAndPing@../../p2p/base/p2ptransportchannel.cc:1954 (messagequeue.cc:513): Message took 727ms to dispatch. Posted from: cricket::P2PTransportChannel::CheckAndPing@../../p2p/base/p2ptransportchannel.cc:1954 (port.cc:1726): Conn[854a2070:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:FySN3J2V:1:0:local:udp:192.168.1.5:60888->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--I|-|0|0|2830971808136703|-]: Sent STUN ping, id=4676465475732f426a497134, use_candidate=1, nomination=0 (messagequeue.cc:513): Message took 751ms to dispatch. Posted from: cricket::P2PTransportChannel::CheckAndPing@../../p2p/base/p2ptransportchannel.cc:1954 (paced_sender.cc:272): Elapsed time (6002 ms) longer than expected, limiting to 2000 ms (messagequeue.cc:513): Message took 2517ms to dispatch. Posted from: rtc::BasicNetworkManager::UpdateNetworksContinually@../../rtc_base/network.cc:959 (paced_sender.cc:272): Elapsed time (5584 ms) longer than expected, limiting to 2000 ms (paced_sender.cc:272): Elapsed time (2820 ms) longer than expected, limiting to 2000 ms (messagequeue.cc:513): Message took 3883ms to dispatch. Posted from: cricket::P2PTransportChannel::CheckAndPing@../../p2p/base/p2ptransportchannel.cc:1954 (port.cc:1726): Conn[854a4770:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:uquX8npx:1:0:relay:udp:52.66.163.63:62768->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--I|-|0|0|2830967613833215|-]: Sent STUN ping, id=6e357653664f7167504a4f45, use_candidate=1, nomination=0 (bitrate_prober.cc:129): Probe delay too high (next_ms:1624555063795, now_ms: 1624555063800) Remote track added (messagequeue.cc:513): Message took 1221ms to dispatch. Posted from: rtc::BasicNetworkManager::UpdateNetworksContinually@../../rtc_base/network.cc:959 (bitrate_prober.cc:129): Probe delay too high (next_ms:1624555063797, now_ms: 1624555065021) (peer_connection.cpp:783): Added stream #1104381000000027197_v with 0 audio tracks and 1 video tracks. (port.cc:1726): Conn[854a3a70:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:WQdl5cve:1:0:relay:udp:52.66.163.63:53392->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--I|-|0|0|2830967580278271|-]: Sent STUN ping, id=7a556b4862653058316a5136, use_candidate=1, nomination=0 (peer_connection.cpp:202): Remote description successfully set. (bitrate_prober.cc:129): Probe delay too high (next_ms:1624555063797, now_ms: 1624555065028) (dtlstransport.cc:552): DtlsTransport[video|1|]: Packet received before DTLS started. (dtlstransport.cc:561): DtlsTransport[video|1|]: Caching DTLS ClientHello packet until DTLS is started. (messagequeue.cc:513): Message took 15900ms to dispatch. Posted from: webrtc::PeerConnectionProxyWithInternal<class webrtc::PeerConnectionInterface>::SetRemoteDescription@D:\azp2\1\s\external\webrtc-uwp-sdk\webrtc\xplatform\webrtc\api/peerconnectionproxy.h:107 (port.cc:1259): Conn[854a4770:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:uquX8npx:1:0:relay:udp:52.66.163.63:62768->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|CR-I|-|0|0|2830967613833215|-]: Received STUN ping, id=4959695457416d7152346531 (peerconnection.cc:5235): Changing to ICE completed state because all transports are complete. (peerconnection.cc:3464): Changing IceConnectionState 1 => 2 (peerconnection.cc:3464): Changing IceConnectionState 2 => 3 (port.cc:831): Port[82404000:video:1:0:relay:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]]: Sent STUN ping response, to=169.38.120.72:18630, id=4959695457416d7152346531 (dtlstransport.cc:552): DtlsTransport[video|1|]: Packet received before DTLS started. (dtlstransport.cc:574): DtlsTransport[video|1|]: Not a DTLS ClientHello packet; dropping. (bitrate_prober.cc:129): Probe delay too high (next_ms:1624555063797, now_ms: 1624555065035) (port.cc:1460): Conn[854a2070:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:FySN3J2V:1:0:local:udp:192.168.1.5:60888->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--I|-|0|0|2830971808136703|-]: Timed out after 16219 ms without a response, rtt=6000 (messagequeue.cc:513): Message took 1362ms to dispatch. Posted from: webrtc::JsepTransportController::UpdateAggregateStates_n@../../pc/jseptransportcontroller.cc:1157 (peerconnection.cc:5889): Usage signature is 2795 (bitrate_prober.cc:129): Probe delay too high (next_ms:1624555063799, now_ms: 1624555066393) (messagequeue.cc:513): Message took 1354ms to dispatch. Posted from: cricket::BaseChannel::OnPacketReceived@../../pc/channel.cc:506 (port.cc:1460): Conn[854a4770:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:uquX8npx:1:0:relay:udp:52.66.163.63:62768->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|CR-I|-|0|0|2830967613833215|-]: Timed out after 16167 ms without a response, rtt=6000 (port.cc:1460): Conn[854a3a70:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:WQdl5cve:1:0:relay:udp:52.66.163.63:53392->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|C--I|-|0|0|2830967580278271|-]: Timed out after 16117 ms without a response, rtt=6000 (bitrate_prober.cc:129): Probe delay too high (next_ms:1624555063799, now_ms: 1624555066402) (p2ptransportchannel.cc:1831): Channel[video|1|__]: Transport channel state changed from 1 to 3 (jseptransportcontroller.cc:1113): video Transport 1 state changed. Check if state is complete. (peerconnection.cc:3464): Changing IceConnectionState 1 => 4 (p2ptransportchannel.cc:2374): Selecting connection for triggered check: Conn[854a4770:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:uquX8npx:1:0:relay:udp:52.66.163.63:62768->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|CRxI|-|0|0|2830967613833215|-] (bitrate_prober.cc:129): Probe delay too high (next_ms:1624555063799, now_ms: 1624555066465) (port.cc:1726): Conn[854a4770:video:Net[Qualcomm:192.168.1.5/32:Wifi:id=3]:uquX8npx:1:0:relay:udp:52.66.163.63:62768->HS8UfJM/:1:659136:local:udp:169.38.120.72:18630|CRxI|-|0|0|2830967613833215|-]: Sent STUN ping, id=64376d52372b737970577959, use_candidate=1, nomination=0 (port.cc:1773): Connection deleted with number of pings sent: 3 (p2ptransportchannel.cc:2237): Channel[video|1|R_]: Removed connection 854a2070 (2 remaining) (port.cc:1773): Connection deleted with number of pings sent: 3 (p2ptransportchannel.cc:2237): Channel[video|1|R_]: Removed connection 854a3a70 (1 remaining) (bitrate_prober.cc:129): Probe delay too high (next_ms:1624555063799, now_ms: 1624555066472)

[KarthikRichie]

And for the same case, I'm also seeing the following in webrtc logs. Any ideas on what could have gone wrong?

(video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091623, latest=1624637091977 (video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091664, latest=1624637091977 (video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091705, latest=1624637091977 (video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091747, latest=1624637091977 (video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091789, latest=1624637091977 (video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091829, latest=1624637091977 (video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091872, latest=1624637091977 (video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091918, latest=1624637091977 (video_render_frames.cc:61): Frame scheduled out of order, render_time=1624637091961, latest=1624637091977 (webrtcvideoengine.cc:2440): VideoReceiveStream not connected to a VideoSink. (webrtcvideoengine.cc:2440): VideoReceiveStream not connected to a VideoSink. (webrtcvideoengine.cc:2440): VideoReceiveStream not connected to a VideoSink.

[spacecheeserocks]

Is there a particular reason that you are trying to specifically use Plan B over Unified Plan?

To the best of my knowledge, modern browsers all support Unified Plan now.

[KarthikRichie]

Yeah that's right.... looks like the remote web app hasn't adopted Unified plan yet and is sticking to "Plan B". Not sure of the rational behind that. But since the remote sdp's that I'm getting are of "Plan B" specific, I'm creating peer connection with SDPSemantic as "Plan B".

[spacecheeserocks]

In which case, I'm much less familiar with Plan B, so I don't think I can provide more help.

Some quick online searches though seem to point at your SDP offer not quite looking like a Plan B one? Not sure if this is your modifications or what the library is doing for you.

What I tried a) Since "msid-semantic WMS" was missing in the remote sdp, I tried explicitly adding it ahead of "m=video" line before setting remote description. But it was of no help

This might actually be wrong. According to the Transition Guide (there are links at the bottom of the page for details), the msid-semantic line should have more content when using Plan B: Plan B a=msid-semantic: WMS stream-id-2 stream-id-1 Unified Plan a=msid-semantic: WMS

Other than that, I don't think I've ever used this library in Plan B mode, so I'm not sure of any other help I could provide.

[KarthikRichie]

This is the remote sdp to be precise and not the SDP offer. Since I had issues where remote video track events not fired, I posted only the remote SDP when the video is turned on in remote. SDP offer for video has mrsw# in msid-semantic which I believe is created only for Plan B (mixed reality webrtc)