rtpsession obtains incorrect SSRC sources from other pipelines in the same application
Describe your issue
When running multiple pipelines in an application with an rtspsrc element, it looks like there is a race condition happening between the creation of SSRC's in an rtpsession (and eventually rtpssrcdemux). In my setup there is only 1 SSRC per RTSP stream. However in the following log, rtpssrcdemux10
creates 3 SSRC pads:
$ grep -E "creating new pad for SSRC" log_good
0:00:02.566686202 64304 0x7f6ff8001a80 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux0> creating new pad for SSRC e8692e23
0:00:02.638714176 64304 0x7f6ff80024c0 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux1> creating new pad for SSRC 43bcb9c4
0:00:03.582727105 64304 0x7f6ff80036b0 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux2> creating new pad for SSRC 645bfc40
0:00:03.623209089 64304 0x7f6ff8004380 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux3> creating new pad for SSRC ecd969c4
0:00:04.164731381 64304 0x7f6ff8005800 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux4> creating new pad for SSRC 769b57c5
0:00:04.222521126 64304 0x7f6ff8006240 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux5> creating new pad for SSRC 6ac538a2
0:00:06.934675236 64304 0x7f6ff8007430 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux6> creating new pad for SSRC 07da4a93
0:00:06.985989286 64304 0x7f6ff801a480 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux7> creating new pad for SSRC d99353e6
0:00:07.569298489 64304 0x7f6ff801b900 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux8> creating new pad for SSRC fab6fad9
0:00:07.610988520 64304 0x7f6ff801c5d0 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux9> creating new pad for SSRC 3907db63
0:00:08.105779312 64304 0x7f6ff8021520 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux10> creating new pad for SSRC e8692e23
0:00:08.121298484 64304 0x7f6ff8021520 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux10> creating new pad for SSRC 645bfc40
0:00:08.165888405 64304 0x7f6ff8021520 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux10> creating new pad for SSRC 1a2c92e2
0:00:08.167817476 64304 0x7f6ff80216e0 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux11> creating new pad for SSRC d448cbb5
pad e8692e23
is in fact the SSRC from rtpssrcdemux0
and pad 645bfc40
is in fact the SSRC of rtpssrcdemux2
. The 3rd pad 1a2c92e2
is the correct and only pad that should be added to rtpssrcdemux10
.
Due to this I don't get video in the corresponding pipeline.
Expected Behavior
Only the correct pad gets added to the rtpssrcdemux.
Observed Behavior
Multiple incorrect pads sometimes get added to an rtpssrcdemux element.
Setup
- Operating System: Ubuntu 23.10
- Device: Computer
- GStreamer Version: 1.22.5
- Command line: Not applicable. Custom application running multiple RTSP pipelines in parallel.
Steps to reproduce the bug
Create an application which runs multiple RTSP pipelines.
How reproducible is the bug?
The bug is easier to trigger on less powerful systems. However, it is also possible to trigger it on powerful systems. The more pipelines run in parallel, the easier it is to trigger.
Screenshots if relevant
Solutions you have tried
I'm investigating this bug for quite some time already and didn't find anything yet. I could use some pointers of which logging to enable to get a clue where it might go wrong. Just as additional information, here is all the logging filtered on the thread that is adding the first incorrect SSRC to the rtpsession10:
0:00:08.101939019 64304 0x7f6ff8021520 INFO GST_ELEMENT_PADS gstelement.c:1013:gst_element_get_static_pad: no such pad 'sink' in element "udpsrc20"
0:00:08.101966539 64304 0x7f6ff8021520 DEBUG rtpsession gstrtpsession.c:1739:gst_rtp_session_event_recv_rtp_sink:<rtpsession10> received event stream-start
0:00:08.102112031 64304 0x7f6ff8021520 INFO GST_EVENT gstevent.c:918:gst_event_new_caps: creating caps event application/x-rtp, media=(string)video, payload=(int)96, clock-rate=(int)90000, encoding-name=(string)H264, packetization-mode=(string)1, sprop-parameter-sets=(string)"Z0JAH6aAQAYZ\,aM44gA\=\=", a-tool=(string)GStreamer, a-type=(string)broadcast, a-framerate=(string)30, a-ts-refclk=(string)local, a-mediaclk=(string)sender, ssrc-439128802-cname=(string)"user3854258414\@host-588edddc", clock-base=(uint)4241209295, seqnum-base=(uint)27885, npt-start=(guint64)0, play-speed=(double)1, play-scale=(double)1, onvif-mode=(boolean)false
^^^^^^^^^ ssrc-439128802-cname: hex(439128802) = 0x1a2c92e2 << Correct and only SSRC that should be added to rtpssrcdemux10.
0:00:08.102225391 64304 0x7f6ff8021520 DEBUG rtpsession gstrtpsession.c:1739:gst_rtp_session_event_recv_rtp_sink:<rtpsession10> received event caps
0:00:08.102444315 64304 0x7f6ff8021520 DEBUG rtpsession gstrtpsession.c:1638:gst_rtp_session_cache_caps:<rtpsession10> parsing caps
0:00:08.102508237 64304 0x7f6ff8021520 DEBUG rtpbin gstrtpbin.c:4122:caps_changed:<manager> got caps application/x-rtp, media=(string)video, payload=(int)96, clock-rate=(int)90000, encoding-name=(string)H264, packetization-mode=(string)1, sprop-parameter-sets=(string)"Z0JAH6aAQAYZ\,aM44gA\=\=", a-tool=(string)GStreamer, a-type=(string)broadcast, a-framerate=(string)30, a-ts-refclk=(string)local, a-mediaclk=(string)sender, ssrc-439128802-cname=(string)"user3854258414\@host-588edddc", clock-base=(uint)4241209295, seqnum-base=(uint)27885, npt-start=(guint64)0, play-speed=(double)1, play-scale=(double)1, onvif-mode=(boolean)false
0:00:08.102569072 64304 0x7f6ff8021520 DEBUG rtpbin gstrtpbin.c:4133:caps_changed:<manager> insert caps for payload 96
0:00:08.102956409 64304 0x7f6ff8021520 INFO GST_EVENT gstevent.c:998:gst_event_new_segment: creating segment event time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:08.103384563 64304 0x7f6ff8021520 DEBUG rtpsession gstrtpsession.c:1739:gst_rtp_session_event_recv_rtp_sink:<rtpsession10> received event segment
0:00:08.103441649 64304 0x7f6ff8021520 DEBUG rtpsession gstrtpsession.c:1768:gst_rtp_session_event_recv_rtp_sink:<rtpsession10> received segment time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:08.103454289 64304 0x7f6ff8021520 INFO basesrc gstbasesrc.c:3023:gst_base_src_loop:<udpsrc20> marking pending DISCONT
0:00:08.103473005 64304 0x7f6ff8021520 DEBUG GST_SCHEDULING gstpad.c:4459:gst_pad_chain_data_unchecked:<manager:recv_rtp_sink_0> calling chainfunction &gst_proxy_pad_chain_default with buffer buffer: 0x7f6fc80aa7b0, pts 0:00:00.508085745, dts 0:00:00.508085745, dur 99:99:99.999999999, size 37, offset none, offset_end none, flags 0x40
0:00:08.103600585 64304 0x7f6ff8021520 DEBUG GST_SCHEDULING gstpad.c:4459:gst_pad_chain_data_unchecked:<rtpsession10:recv_rtp_sink> calling chainfunction &gst_rtp_session_chain_recv_rtp with buffer buffer: 0x7f6fc80aa7b0, pts 0:00:00.508085745, dts 0:00:00.508085745, dur 99:99:99.999999999, size 37, offset none, offset_end none, flags 0x40
0:00:08.103813185 64304 0x7f6ff8021520 DEBUG rtpsession rtpsession.c:1891:obtain_source: creating new source e8692e23 0x7f6fc80bc150
^^^^^^^^ incorrect SSRC from rtpssrcdemux0 gets added to rtpsession10.
0:00:08.103977769 64304 0x7f6ff8021520 DEBUG rtpsession rtpsession.c:1843:session_update_ptp: doing point-to-point: 1
0:00:08.104140302 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:948:fetch_caps_for_payload: first payload 96
0:00:08.104164607 64304 0x7f6ff8021520 DEBUG rtpsession rtpsession.c:1591:source_caps: got caps application/x-rtp, media=(string)video, payload=(int)96, clock-rate=(int)90000, encoding-name=(string)H264, packetization-mode=(string)1, sprop-parameter-sets=(string)"Z0JAH6aAQAYZ\,aM44gA\=\=", a-tool=(string)GStreamer, a-type=(string)broadcast, a-framerate=(string)30, a-ts-refclk=(string)local, a-mediaclk=(string)sender, ssrc-439128802-cname=(string)"user3854258414\@host-588edddc", clock-base=(uint)4241209295, seqnum-base=(uint)27885, npt-start=(guint64)0, play-speed=(double)1, play-scale=(double)1, onvif-mode=(boolean)false for pt 96
0:00:08.104477065 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:964:fetch_caps_for_payload: got caps application/x-rtp, media=(string)video, payload=(int)96, clock-rate=(int)90000, encoding-name=(string)H264, packetization-mode=(string)1, sprop-parameter-sets=(string)"Z0JAH6aAQAYZ\,aM44gA\=\=", a-tool=(string)GStreamer, a-type=(string)broadcast, a-framerate=(string)30, a-ts-refclk=(string)local, a-mediaclk=(string)sender, ssrc-439128802-cname=(string)"user3854258414\@host-588edddc", clock-base=(uint)4241209295, seqnum-base=(uint)27885, npt-start=(guint64)0, play-speed=(double)1, play-scale=(double)1, onvif-mode=(boolean)false
0:00:08.104562199 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:1164:update_receiver_stats: received first packet
0:00:08.104569954 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:1101:init_seq: base_seq 21631
0:00:08.104778998 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:1180:update_receiver_stats: probation: seqnr 21631 == expected 21631
0:00:08.104842373 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:1194:update_receiver_stats: probation 1: queue packet
0:00:08.104850484 64304 0x7f6ff8021520 DEBUG rtpsession rtptwcc.c:304:rtp_twcc_manager_get_recv_twcc_seqnum: Received TWCC packet, but no extension registered; ignoring
0:00:08.104856563 64304 0x7f6ff8021520 DEBUG GST_SCHEDULING gstpad.c:4465:gst_pad_chain_data_unchecked:<rtpsession10:recv_rtp_sink> called chainfunction &gst_rtp_session_chain_recv_rtp with buffer 0x7f6fc80aa7b0, returned ok
0:00:08.104860544 64304 0x7f6ff8021520 DEBUG GST_SCHEDULING gstpad.c:4465:gst_pad_chain_data_unchecked:<manager:recv_rtp_sink_0> called chainfunction &gst_proxy_pad_chain_default with buffer 0x7f6fc80aa7b0, returned ok
0:00:08.105240823 64304 0x7f6ff8021520 DEBUG GST_SCHEDULING gstpad.c:4459:gst_pad_chain_data_unchecked:<manager:recv_rtp_sink_0> calling chainfunction &gst_proxy_pad_chain_default with buffer buffer: 0x7f6fc80bb370, pts 0:00:00.510371615, dts 0:00:00.510371615, dur 99:99:99.999999999, size 32, offset none, offset_end none, flags 0x0
0:00:08.105315803 64304 0x7f6ff8021520 DEBUG GST_SCHEDULING gstpad.c:4459:gst_pad_chain_data_unchecked:<rtpsession10:recv_rtp_sink> calling chainfunction &gst_rtp_session_chain_recv_rtp with buffer buffer: 0x7f6fc80bb370, pts 0:00:00.510371615, dts 0:00:00.510371615, dur 99:99:99.999999999, size 32, offset none, offset_end none, flags 0x0log_good|857287 col 25-39| 0:00:08.105505984 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:1180:update_receiver_stats: probation: seqnr 21632 == expected 21632
0:00:08.105644591 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:1189:update_receiver_stats: probation done!
0:00:08.105714472 64304 0x7f6ff8021520 DEBUG rtpsource rtpsource.c:1101:init_seq: base_seq 21632
0:00:08.105767825 64304 0x7f6ff8021520 DEBUG GST_SCHEDULING gstpad.c:4459:gst_pad_chain_data_unchecked:<rtpstorage10:sink> calling chainfunction &gst_rtp_storage_chain with buffer buffer: 0x7f6fc80aa7b0, pts 0:00:00.508085745, dts 0:00:00.508085745, dur 99:99:99.999999999, size 37, offset none, offset_end none, flags 0x40
0:00:08.105772339 64304 0x7f6ff8021520 DEBUG GST_SCHEDULING gstpad.c:4459:gst_pad_chain_data_unchecked:<rtpssrcdemux10:sink> calling chainfunction &gst_rtp_ssrc_demux_chain with buffer buffer: 0x7f6fc80aa7b0, pts 0:00:00.508085745, dts 0:00:00.508085745, dur 99:99:99.999999999, size 37, offset none, offset_end none, flags 0x40
0:00:08.105776024 64304 0x7f6ff8021520 DEBUG rtpssrcdemux gstrtpssrcdemux.c:692:gst_rtp_ssrc_demux_chain:<rtpssrcdemux10> received buffer of SSRC e8692e23
0:00:08.105779312 64304 0x7f6ff8021520 DEBUG rtpssrcdemux gstrtpssrcdemux.c:328:find_or_create_demux_pad_for_ssrc:<rtpssrcdemux10> creating new pad for SSRC e8692e23