Race condition in pads creation during linking in multi-src/sink elements
While issue happened with audiomixer element, it is most likely not specific to this element, but I decided to post bug report here, hopefully this is the right place.
What happens:
- There is a linking code like this (Rust):
Element::link_many(&[&queue, audiomixer])?;
(callsgst_element_link()
under the hood in a loop if there is more than 2 elements) -
queue
comes from one of asynchronously created audio sources (in different threads) - Following unfortunate series of events happens:
0:22:13.903900131 1 0x7fa1880149e0 INFO GST_ELEMENT_PADS gstutils.c:1815:gst_element_link_pads_full: trying to link element queue_1757155_audio_track_in_610370930:(any) to element audiomixer_1757155_main:(any)
0:22:13.903940428 1 0x7fa1d0006760 INFO GST_ELEMENT_FACTORY gstelementfactory.c:358:gst_element_factory_create: creating element "typefind" named "typefind"
0:22:13.903994063 1 0x7fa1880149e0 INFO GST_ELEMENT_PADS gstelement.c:749:gst_element_add_pad:<audiomixer_1757155_main> adding pad 'sink_1'
0:22:13.903996057 1 0x7fa1d0006760 INFO GST_ELEMENT_PADS gstelement.c:749:gst_element_add_pad:<GstTypeFindElement@0x7fa17c012050> adding pad 'sink'
0:22:13.904072398 1 0x7fa1c00574c0 INFO GST_ELEMENT_PADS gstelement.c:749:gst_element_add_pad:<GstQueue@0x7fa17c00acc0> adding pad 'sink'
0:22:13.904083255 1 0x7fa1d0006760 INFO GST_ELEMENT_PADS gstelement.c:749:gst_element_add_pad:<GstTypeFindElement@0x7fa17c012050> adding pad 'src'
0:22:13.904106856 1 0x7fa1c00574c0 INFO GST_ELEMENT_PADS gstelement.c:749:gst_element_add_pad:<GstQueue@0x7fa17c00acc0> adding pad 'src'
0:22:13.904123170 1 0x7fa1d0006760 INFO GST_ELEMENT_PADS gstelement.c:996:gst_element_get_static_pad: found pad typefind:sink
0:22:13.904152705 1 0x7fa1c00574c0 INFO GST_STATES gstelement.c:2728:gst_element_continue_state:<queue_1757155_audio_track_in_2330449165> committing state from NULL to READY, pending PAUSED, next PAUSED
0:22:13.904168126 1 0x7fa1c00574c0 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<queue_1757155_audio_track_in_2330449165> notifying about state-changed NULL to READY (PAUSED pending)
0:22:13.904178506 1 0x7fa1d0006760 INFO GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link sink:proxypad45 and typefind:sink
0:22:13.904189061 1 0x7fa1c00574c0 INFO GST_STATES gstelement.c:2736:gst_element_continue_state:<queue_1757155_audio_track_in_2330449165> continue state change READY to PAUSED, final PAUSED
0:22:13.904196413 1 0x7fa1d0006760 INFO GST_PADS gstpad.c:2585:gst_pad_link_full: linked sink:proxypad45 and typefind:sink, successful
0:22:13.904207381 1 0x7fa1d0006760 INFO GST_EVENT gstevent.c:1587:gst_event_new_reconfigure: creating reconfigure event
0:22:13.904212066 1 0x7fa1c00574c0 INFO task gsttask.c:453:gst_task_set_lock: setting stream lock 0x7fa1f4033b80 on task 0x7fa180016a70
0:22:13.904225941 1 0x7fa1c00574c0 INFO GST_PADS gstpad.c:6237:gst_pad_start_task:<queue_1757155_audio_track_in_2330449165:src> created task 0x7fa180016a70
0:22:13.904231867 1 0x7fa1d0006760 INFO GST_ELEMENT_PADS gstelement.c:749:gst_element_add_pad:<GstDecodeBin@0x7fa17c010040> adding pad 'sink'
0:22:13.904235894 1 0x7fa2000c0060 INFO GST_ELEMENT_FACTORY gstelementfactory.c:358:gst_element_factory_create: creating element "queue" named "queue_1757155_audio_track_in_3598874103"
0:22:13.904285206 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2728:gst_element_continue_state:<queue_1757155_decoding_video_2831187415> committing state from NULL to READY, pending PAUSED, next PAUSED
0:22:13.904302137 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<queue_1757155_decoding_video_2831187415> notifying about state-changed NULL to READY (PAUSED pending)
0:22:13.904322136 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2736:gst_element_continue_state:<queue_1757155_decoding_video_2831187415> continue state change READY to PAUSED, final PAUSED
0:22:13.904323055 1 0x7fa2000c0060 INFO GST_ELEMENT_PADS gstelement.c:749:gst_element_add_pad:<GstQueue@0x7fa17c00b8c0> adding pad 'sink'
0:22:13.904338616 1 0x7fa1c00574c0 INFO GST_STATES gstelement.c:2756:gst_element_continue_state:<queue_1757155_audio_track_in_2330449165> completed state change to PAUSED
0:22:13.904358964 1 0x7fa1c00574c0 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<queue_1757155_audio_track_in_2330449165> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:22:13.904364310 1 0x7fa2000c0060 INFO GST_ELEMENT_PADS gstelement.c:749:gst_element_add_pad:<GstQueue@0x7fa17c00b8c0> adding pad 'src'
0:22:13.904374237 1 0x7fa1d0006760 INFO task gsttask.c:453:gst_task_set_lock: setting stream lock 0x7fa1f4032b50 on task 0x7fa1f4035950
0:22:13.904379227 1 0x7fa1c00574c0 INFO GST_ELEMENT_PADS gstelement.c:996:gst_element_get_static_pad: found pad queue_1757155_audio_track_in_2330449165:sink
0:22:13.904389060 1 0x7fa1d0006760 INFO GST_PADS gstpad.c:6237:gst_pad_start_task:<queue_1757155_decoding_video_2831187415:src> created task 0x7fa1f4035950
0:22:13.904419171 1 0x7fa1c00574c0 INFO GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link decodebin_1757155_decoding_audio_2330449165:src_0 and queue_1757155_audio_track_in_2330449165:sink
0:22:13.904425315 1 0x7fa2000c0060 INFO GST_STATES gstelement.c:2728:gst_element_continue_state:<queue_1757155_audio_track_in_3598874103> committing state from NULL to READY, pending PAUSED, next PAUSED
0:22:13.904438409 1 0x7fa2000c0060 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<queue_1757155_audio_track_in_3598874103> notifying about state-changed NULL to READY (PAUSED pending)
0:22:13.904449356 1 0x7fa1c00574c0 INFO GST_PADS gstpad.c:4309:gst_pad_peer_query:<queue_1757155_audio_track_in_2330449165:src> pad has no peer
0:22:13.904455915 1 0x7fa2000c0060 INFO GST_STATES gstelement.c:2736:gst_element_continue_state:<queue_1757155_audio_track_in_3598874103> continue state change READY to PAUSED, final PAUSED
0:22:13.904467362 1 0x7fa1c00574c0 INFO GST_PADS gstpad.c:2585:gst_pad_link_full: linked decodebin_1757155_decoding_audio_2330449165:src_0 and queue_1757155_audio_track_in_2330449165:sink, successful
0:22:13.904476958 1 0x7fa2000c0060 INFO task gsttask.c:453:gst_task_set_lock: setting stream lock 0x7fa15c078f50 on task 0x7fa180016ef0
0:22:13.904477017 1 0x7fa1c00574c0 INFO GST_EVENT gstevent.c:1587:gst_event_new_reconfigure: creating reconfigure event
0:22:13.904492669 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2756:gst_element_continue_state:<queue_1757155_decoding_video_2831187415> completed state change to PAUSED
0:22:13.904495329 1 0x7fa2000c0060 INFO GST_PADS gstpad.c:6237:gst_pad_start_task:<queue_1757155_audio_track_in_3598874103:src> created task 0x7fa180016ef0
0:22:13.904519121 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<queue_1757155_decoding_video_2831187415> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:22:13.904556841 1 0x7fa1d0006760 INFO GST_STATES gstbin.c:2513:gst_bin_element_set_state:<typefind> current NULL pending VOID_PENDING, desired next READY
0:22:13.904574057 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2756:gst_element_continue_state:<typefind> completed state change to READY
0:22:13.904571714 1 0x7fa1c00574c0 INFO GST_ELEMENT_PADS gstutils.c:1815:gst_element_link_pads_full: trying to link element queue_1757155_audio_track_in_2330449165:(any) to element audiomixer_1757155_main:(any)
0:22:13.904595651 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<typefind> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:22:13.904597587 1 0x7fa2000c0060 INFO GST_STATES gstelement.c:2756:gst_element_continue_state:<queue_1757155_audio_track_in_3598874103> completed state change to PAUSED
0:22:13.904609337 1 0x7fa1c00574c0 INFO GST_PADS gstutils.c:1078:gst_pad_check_link: trying to link queue_1757155_audio_track_in_2330449165:src and audiomixer_1757155_main:sink_1
0:22:13.904614036 1 0x7fa2000c0060 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<queue_1757155_audio_track_in_3598874103> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:22:13.904619486 1 0x7fa1d0006760 INFO GST_STATES gstbin.c:2962:gst_bin_change_state_func:<decodebin_1757155_decoding_video_2831187415> child 'typefind' changed state to 2(READY) successfully
0:22:13.904632772 1 0x7fa2000c0060 INFO GST_ELEMENT_PADS gstelement.c:996:gst_element_get_static_pad: found pad queue_1757155_audio_track_in_3598874103:sink
0:22:13.904638554 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2728:gst_element_continue_state:<decodebin_1757155_decoding_video_2831187415> committing state from NULL to READY, pending PAUSED, next PAUSED
0:22:13.904651382 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<decodebin_1757155_decoding_video_2831187415> notifying about state-changed NULL to READY (PAUSED pending)
0:22:13.904650675 1 0x7fa2000c0060 INFO GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link decodebin_1757155_decoding_audio_3598874103:src_0 and queue_1757155_audio_track_in_3598874103:sink
0:22:13.904675553 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2736:gst_element_continue_state:<decodebin_1757155_decoding_video_2831187415> continue state change READY to PAUSED, final PAUSED
0:22:13.904677592 1 0x7fa1c00574c0 INFO audioaggregator gstaudioaggregator.c:791:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> Getting caps with filter (NULL)
0:22:13.904689879 1 0x7fa2000c0060 INFO GST_PADS gstpad.c:4309:gst_pad_peer_query:<queue_1757155_audio_track_in_3598874103:src> pad has no peer
0:22:13.904709118 1 0x7fa1c00574c0 INFO audioaggregator gstaudioaggregator.c:803:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> first configured pad has sample rate 48000
0:22:13.904721493 1 0x7fa2000c0060 INFO GST_PADS gstpad.c:2585:gst_pad_link_full: linked decodebin_1757155_decoding_audio_3598874103:src_0 and queue_1757155_audio_track_in_3598874103:sink, successful
0:22:13.904750172 1 0x7fa2000c0060 INFO GST_EVENT gstevent.c:1587:gst_event_new_reconfigure: creating reconfigure event
0:22:13.904715126 1 0x7fa1d0006760 INFO GST_STATES gstbin.c:2513:gst_bin_element_set_state:<typefind> current READY pending VOID_PENDING, desired next PAUSED
0:22:13.904786532 1 0x7fa1d0006760 INFO GST_PADS gstpad.c:4309:gst_pad_peer_query:<decodebin_1757155_decoding_video_2831187415:sink> pad has no peer
0:22:13.904825410 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2756:gst_element_continue_state:<typefind> completed state change to PAUSED
0:22:13.904826166 1 0x7fa2000c0060 INFO GST_ELEMENT_PADS gstutils.c:1815:gst_element_link_pads_full: trying to link element queue_1757155_audio_track_in_3598874103:(any) to element audiomixer_1757155_main:(any)
0:22:13.904846918 1 0x7fa1d0006760 INFO GST_STATES gstelement.c:2656:_priv_gst_element_state_changed:<typefind> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:22:13.904872651 1 0x7fa2000c0060 INFO GST_PADS gstutils.c:1078:gst_pad_check_link: trying to link queue_1757155_audio_track_in_3598874103:src and audiomixer_1757155_main:sink_1
0:22:13.904894977 1 0x7fa1d0006760 INFO GST_STATES gstbin.c:2962:gst_bin_change_state_func:<decodebin_1757155_decoding_video_2831187415> child 'typefind' changed state to 3(PAUSED) successfully
0:22:13.904921609 1 0x7fa2000c0060 INFO audioaggregator gstaudioaggregator.c:791:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> Getting caps with filter (NULL)
0:22:13.904921497 1 0x7fa1d0006760 INFO GST_ELEMENT_PADS gstelement.c:996:gst_element_get_static_pad: found pad queue_1757155_decoding_video_2831187415:sink
0:22:13.904952890 1 0x7fa2000c0060 INFO audioaggregator gstaudioaggregator.c:803:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> first configured pad has sample rate 48000
0:22:13.904938150 1 0x7fa1880149e0 INFO GST_PADS gstutils.c:1631:prepare_link_maybe_ghosting: queue_1757155_audio_track_in_610370930 and audiomixer_1757155_main in same bin, no need for ghost pads
0:22:13.904984018 1 0x7fa1880149e0 INFO GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link queue_1757155_audio_track_in_610370930:src and audiomixer_1757155_main:sink_1
0:22:13.905018646 1 0x7fa2000c0060 INFO audioaggregator gstaudioaggregator.c:856:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> returned sink caps : audio/x-raw, format=(string){ S8, U8, S16LE, S16BE, U16LE, U16BE, S24_32LE, S24_32BE, U24_32LE, U24_32BE, S32LE, S32BE, U32LE, U32BE, S24LE, S24BE, U24LE, U24BE, S20LE, S20BE, U20LE, U20BE, S18LE, S18BE, U18LE, U18BE, F32LE, F32BE, F64LE, F64BE }, rate=(int)48000, channels=(int)[ 1, 2147483647 ], layout=(string)interleaved
0:22:13.905042421 1 0x7fa2000c0060 INFO GST_PADS gstutils.c:1631:prepare_link_maybe_ghosting: queue_1757155_audio_track_in_3598874103 and audiomixer_1757155_main in same bin, no need for ghost pads
0:22:13.905060193 1 0x7fa2000c0060 INFO GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link queue_1757155_audio_track_in_3598874103:src and audiomixer_1757155_main:sink_1
0:22:13.905069247 1 0x7fa1880149e0 INFO audioaggregator gstaudioaggregator.c:791:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> Getting caps with filter (NULL)
0:22:13.905085910 1 0x7fa1880149e0 INFO audioaggregator gstaudioaggregator.c:803:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> first configured pad has sample rate 48000
0:22:13.905105967 1 0x7fa2000c0060 INFO audioaggregator gstaudioaggregator.c:791:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> Getting caps with filter (NULL)
0:22:13.905120236 1 0x7fa2000c0060 INFO audioaggregator gstaudioaggregator.c:803:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> first configured pad has sample rate 48000
0:22:13.905157601 1 0x7fa2000c0060 INFO audioaggregator gstaudioaggregator.c:856:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> returned sink caps : audio/x-raw, format=(string){ S8, U8, S16LE, S16BE, U16LE, U16BE, S24_32LE, S24_32BE, U24_32LE, U24_32BE, S32LE, S32BE, U32LE, U32BE, S24LE, S24BE, U24LE, U24BE, S20LE, S20BE, U20LE, U20BE, S18LE, S18BE, U18LE, U18BE, F32LE, F32BE, F64LE, F64BE }, rate=(int)48000, channels=(int)[ 1, 2147483647 ], layout=(string)interleaved
0:22:13.905178592 1 0x7fa2000c0060 INFO GST_PADS gstpad.c:2585:gst_pad_link_full: linked queue_1757155_audio_track_in_3598874103:src and audiomixer_1757155_main:sink_1, successful
0:22:13.905185768 1 0x7fa2000c0060 INFO GST_EVENT gstevent.c:1587:gst_event_new_reconfigure: creating reconfigure event
0:22:13.905286523 1 0x7fa1d0006760 INFO GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link webrtcbin_1757155_main:src_4 and queue_1757155_decoding_video_2831187415:sink
0:22:13.905329049 1 0x7fa1c00574c0 INFO audioaggregator gstaudioaggregator.c:856:gst_audio_aggregator_convert_sink_getcaps:<audiomixer_1757155_main:sink_1> returned sink caps : audio/x-raw, format=(string){ S8, U8, S16LE, S16BE, U16LE, U16BE, S24_32LE, S24_32BE, U24_32LE, U24_32BE, S32LE, S32BE, U32LE, U32BE, S24LE, S24BE, U24LE, U24BE, S20LE, S20BE, U20LE, U20BE, S18LE, S18BE, U18LE, U18BE, F32LE, F32BE, F64LE, F64BE }, rate=(int)48000, channels=(int)[ 1, 2147483647 ], layout=(string)interleaved
0:22:13.905400524 1 0x7fa1c00574c0 INFO GST_PADS gstutils.c:1631:prepare_link_maybe_ghosting: queue_1757155_audio_track_in_2330449165 and audiomixer_1757155_main in same bin, no need for ghost pads
0:22:13.905426303 1 0x7fa1c00574c0 INFO GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link queue_1757155_audio_track_in_2330449165:src and audiomixer_1757155_main:sink_1
0:22:13.905451707 1 0x7fa1c00574c0 INFO GST_PADS gstpad.c:2416:gst_pad_link_prepare: sink audiomixer_1757155_main:sink_1 was already linked to queue_1757155_audio_track_in_3598874103:src
0:22:13.905468145 1 0x7fa1c00574c0 INFO GST_PADS gstpad.c:2527:gst_pad_link_full: link between queue_1757155_audio_track_in_2330449165:src and audiomixer_1757155_main:sink_1 failed: was linked
0:22:13.905494040 1 0x7fa1c00574c0 INFO aggregator gstaggregator.c:1797:gst_aggregator_release_pad:<audiomixer_1757155_main:sink_1> Removing pad
0:22:13.905514300 1 0x7fa1c00574c0 INFO GST_ELEMENT_PADS gstelement.c:865:gst_element_remove_pad:<audiomixer_1757155_main> removing pad 'sink_1'
0:22:13.905532127 1 0x7fa1c00574c0 INFO GST_ELEMENT_PADS gstpad.c:2132:gst_pad_unlink: unlinking queue_1757155_audio_track_in_3598874103:src(0x7fa15c078ee0) and audiomixer_1757155_main:sink_1(0x7fa15001c080)
0:22:13.905555765 1 0x7fa1c00574c0 INFO GST_ELEMENT_PADS gstpad.c:2187:gst_pad_unlink: unlinked queue_1757155_audio_track_in_3598874103:src and audiomixer_1757155_main:sink_1
Looks like sink_1
pad that was created for the first audio source to be linked to, but it was also discovered in another thread by another concurrent linking process and since that pad wasn't actually linked just yet, it was decided to use it for the second linking process too. But in the mean time the first thread finished linking and the second thread when came its turn, obviously, failed.
I'd say this is a confusing behavior and while certainly possible to rather easily work around by requesting pads with deterministic names and linking explicitly, I believe that this particular automagical linking of elements should be free from concurrent operations happening at the same time.
Under the hood Rust bindings call gst_element_link
, so I think this should be different mechanically from gst_element_get_static_pad()
/gst_pad_link()
combo somehow.
I have just checked and docs say:
The function looks for existing pads that aren't linked yet.
Sure, that explains what happened, but at the same time it would be nice if the first thread created/reserved a pad with some kind of a marker that would mean I'll use this pad in a moment myself, if you're not me - don't touch it or bad things will definitely happen.