GStreamer pipeline is hanging randomly

2

I have a few pipelines I've developed with GStreamer. One of these pipelines is a pipeline for writing a Vec<Sample> onto disk as a MP4 file.

appsrc ! h264parse ! mp4mux faststart=true ! filesink location=/home/valmirpretto/video.mp4

Having said that, I've been encountering a weird bug. This pipeline runs normally most of the time. Once in a blue moon, the bus will simply not receive the EOS message even though I am making sure that my appsrc is sending it. I've read the GST_DEBUG=6 logs over and over again and I haven't been able to pinpoint why this is happening.

Below I've attached a log of a successful cycle of instantiating the pipeline, instantiating the elements, writing the samples and then cleaning everything up. The Iteration [] lines are markers that I use to tell when one cycle is done. The new message [] lines are for inspecting messages that are being received. The insert_samples() returned line is the point at which my async function is done inserting samples onto the pipeline through the appsrc.

Iteration 3088 began.
0:07:05.564710676 20687 0x7fa2e0009600 DEBUG                    bin gstbin.c:2879:gst_bin_change_state_func:</home/valmirpretto/video.mp4> clearing EOS elements
0:07:05.566044050 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<appsrc3089:src> Removing pending EOS and StreamGroupDone events
0:07:05.566074632 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5706:gst_pad_send_event_unchecked:<h264parse3089:sink> Removing pending EOS events
0:07:05.566086620 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<h264parse3089:src> Removing pending EOS and StreamGroupDone events
0:07:05.566124648 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5706:gst_pad_send_event_unchecked:<mp4mux3089:video_0> Removing pending EOS events
0:07:05.566170877 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<mp4mux3089:video_0> Removing pending EOS and StreamGroupDone events
0:07:05.566217680 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<h264parse3089:sink> Removing pending EOS and StreamGroupDone events
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StreamStatus]
new message [StreamStatus]
new message [StateChanged]
new message [StateChanged]
new message [NewClock]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
insert_samples() returned
0:07:05.570884804 20687 0x7fa2e0009600 DEBUG                 appsrc gstappsrc.c:2054:gst_app_src_end_of_stream:<appsrc3089> sending EOS
0:07:05.571517355 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<mp4mux3089:src> Removing pending EOS and StreamGroupDone events
0:07:05.571541677 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5706:gst_pad_send_event_unchecked:<filesink3088:sink> Removing pending EOS events
0:07:05.571751883 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<filesink3088:sink> Removing pending EOS and StreamGroupDone events
new message [StreamStart]
new message [StateChanged]
new message [AsyncDone]
0:07:05.573383907 20687 0x7fa28400af70 DEBUG               basesink gstbasesink.c:3443:gst_base_sink_needs_preroll:<filesink3088> have_preroll: 1, EOS: 0 => needs preroll: 0
new message [StateChanged]
new message [StateChanged]
0:07:05.574030455 20687 0x7fa28400af70 DEBUG                    bin gstbin.c:889:find_message:</home/valmirpretto/video.mp4>   eos
0:07:05.574038897 20687 0x7fa28400af70 DEBUG                    bin gstbin.c:994:is_eos: sink 'filesink3088' did not post EOS yet
0:07:05.574044509 20687 0x7fa28400af70 LOG                      bin gstbin.c:3554:bin_do_eos:</home/valmirpretto/video.mp4> Not forwarding EOS due to in progress state change,  or already posted, or waiting for more EOS
0:07:05.649355431 20687 0x7fa2dc008800 DEBUG                 appsrc gstappsrc.c:1294:gst_app_src_create:<appsrc3089> we are EOS
0:07:05.649360292 20687 0x7fa2dc008800 DEBUG                basesrc gstbasesrc.c:2659:gst_base_src_get_range:<appsrc3089> create returned -3 (eos)
0:07:05.649363474 20687 0x7fa2dc008800 INFO                 basesrc gstbasesrc.c:2853:gst_base_src_loop:<appsrc3089> pausing after gst_base_src_get_range() = eos
0:07:05.649366703 20687 0x7fa2dc008800 DEBUG                basesrc gstbasesrc.c:3025:gst_base_src_loop:<appsrc3089> pausing task, reason eos
0:07:05.649379602 20687 0x7fa2dc008800 DEBUG              GST_EVENT gstevent.c:308:gst_event_new_custom: creating new event 0x7fa2a0006710 eos 28174
0:07:05.649384389 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<appsrc3089:src> stored sticky event eos
0:07:05.649421874 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5408:gst_pad_push_event_unchecked:<appsrc3089:src> sending event 0x7fa2a0006710 (eos) to peerpad <h264parse3089:sink>
0:07:05.649426960 20687 0x7fa2dc008800 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<h264parse3089:sink> have event type eos event: 0x7fa2a0006710, time 99:99:99.999999999, seq-num 263093, (NULL)
0:07:05.649431524 20687 0x7fa2dc008800 DEBUG              baseparse gstbaseparse.c:1179:gst_base_parse_sink_event_default:<h264parse3089> handling event 28174, eos
0:07:05.649452395 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<h264parse3089:src> stored sticky event eos
0:07:05.649489640 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5408:gst_pad_push_event_unchecked:<h264parse3089:src> sending event 0x7fa2a0006710 (eos) to peerpad <mp4mux3089:video_0>
0:07:05.649497385 20687 0x7fa2dc008800 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<mp4mux3089:video_0> have event type eos event: 0x7fa2a0006710, time 99:99:99.999999999, seq-num 263093, (NULL)
0:07:05.649503217 20687 0x7fa2dc008800 DEBUG            collectpads gstcollectpads.c:1997:gst_collect_pads_event:<mp4mux3089:video_0> Got eos event on sink pad
0:07:05.649521493 20687 0x7fa2dc008800 DEBUG            collectpads gstcollectpads.c:1678:gst_collect_pads_event_default:<mp4mux3089:video_0> Got 'eos' event
0:07:05.649527054 20687 0x7fa2dc008800 DEBUG            collectpads gstcollectpads.c:1333:gst_collect_pads_check_collected:<collectpads3089> All active pads (1) areEOS, calling gst_qt_mux_collected
0:07:05.649645352 20687 0x7fa2dc008800 DEBUG                  qtmux gstqtmux.c:5025:find_best_pad:<mp4mux3089> No best pad: EOS
0:07:05.683670309 20687 0x7fa2dc008800 DEBUG                  qtmux gstqtmux.c:5072:gst_qt_mux_collected:<mp4mux3089> Pushing eos
0:07:05.683676666 20687 0x7fa2dc008800 DEBUG              GST_EVENT gstevent.c:308:gst_event_new_custom: creating new event 0x7fa2bc035870 eos 28174
0:07:05.683682348 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<mp4mux3089:src> stored sticky event eos
0:07:05.683700640 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5408:gst_pad_push_event_unchecked:<mp4mux3089:src> sending event 0x7fa2bc035870 (eos) to peerpad <filesink3088:sink>
0:07:05.683705851 20687 0x7fa2dc008800 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<filesink3088:sink> have event type eos event: 0x7fa2bc035870, time 99:99:99.999999999, seq-num 263135, (NULL)
0:07:05.683710823 20687 0x7fa2dc008800 DEBUG               basesink gstbasesink.c:3354:gst_base_sink_event:<filesink3088> received event 0x7fa2bc035870 eos event: 0x7fa2bc035870, time 99:99:99.999999999, seq-num 263135, (NULL)
0:07:05.683831158 20687 0x7fa2dc008800 DEBUG               basesink gstbasesink.c:2063:gst_base_sink_get_sync_times:<filesink3088> sync times for EOS 99:99:99.999999999
0:07:05.683834162 20687 0x7fa2dc008800 DEBUG               basesink gstbasesink.c:3223:gst_base_sink_default_event:<filesink3088> Now posting EOS
0:07:05.683841421 20687 0x7fa2dc008800 LOG              GST_MESSAGE gstmessage.c:303:gst_message_new_custom: source filesink3088: creating new message 0x7fa2dc06ea10 eos
0:07:05.683874798 20687 0x7fa2dc008800 DEBUG                GST_BUS gstbus.c:315:gst_bus_post:<bus6186> [msg 0x7fa2dc06ea10] posting on bus eos message: 0x7fa2dc06ea10, time 99:99:99.999999999, seq-num 263135, element 'filesink3088', (NULL)
0:07:05.683882145 20687 0x7fa2dc008800 DEBUG                    bin gstbin.c:3718:gst_bin_handle_message_func:</home/valmirpretto/video.mp4> [msg 0x7fa2dc06ea10] handling child filesink3088 message of type eos
0:07:05.683905854 20687 0x7fa2dc008800 DEBUG                    bin gstbin.c:889:find_message:</home/valmirpretto/video.mp4>   eos
0:07:05.683909542 20687 0x7fa2dc008800 DEBUG                    bin gstbin.c:928:bin_replace_message:</home/valmirpretto/video.mp4> got new message 0x7fa2dc06ea10, eos from filesink3088
0:07:05.683942427 20687 0x7fa2dc008800 DEBUG                    bin gstbin.c:990:is_eos: sink 'filesink3088' posted EOS
0:07:05.683995623 20687 0x7fa2dc008800 DEBUG                    bin gstbin.c:956:bin_remove_messages:<filesink3088> deleting message 0x7fa2dc06ea10 of type eos (types 0x00000001)
0:07:05.684000904 20687 0x7fa2dc008800 LOG              GST_MESSAGE gstmessage.c:208:_gst_message_free: finalize message 0x7fa2dc06ea10, eos from filesink3088
0:07:05.684007420 20687 0x7fa2dc008800 LOG              GST_MESSAGE gstmessage.c:303:gst_message_new_custom: source /home/valmirpretto/video.mp4: creating new message 0x7fa2dc06ea90 eos
0:07:05.684011216 20687 0x7fa2dc008800 DEBUG                    bin gstbin.c:3550:bin_do_eos:</home/valmirpretto/video.mp4> all sinks posted EOS, posting seqnum #263135
0:07:05.684032833 20687 0x7fa2dc008800 DEBUG                GST_BUS gstbus.c:315:gst_bus_post:<bus6187> [msg 0x7fa2dc06ea90] posting on bus eos message: 0x7fa2dc06ea90, time 99:99:99.999999999, seq-num 263135, element '/home/valmirpretto/video.mp4', (NULL)
0:07:05.684148589 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<filesink3088:sink> stored sticky event eos
0:07:05.684155253 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5415:gst_pad_push_event_unchecked:<mp4mux3089:src> sent event 0x7fa2bc035870 (eos) to peerpad <filesink3088:sink>, ret ok
new message [Eos]
0:07:05.684160326 20687 0x7fa2dc008800 DEBUG               GST_PADS gstpad.c:3936:push_sticky:<mp4mux3089:src> event eos marked received
0:07:05.684169006 20687 0x7fa2dc008800 DEBUG            collectpads gstcollectpads.c:1862:gst_collect_pads_event_default:<collectpads3089> dropping event: eos event: 0x7fa2a0006710, time 99:99:99.999999999, seq-num 263093, (NULL)
0:07:05.684182538 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<mp4mux3089:video_0> stored sticky event eos
0:07:05.684183686 20687 0x7fa2e0009600 DEBUG                GST_BUS gstbus.c:542:gst_bus_timed_pop_filtered:<bus6187> got message 0x7fa2dc06ea90, eos from /home/valmirpretto/video.mp4, type mask is 4294967295
0:07:05.684203394 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5415:gst_pad_push_event_unchecked:<h264parse3089:src> sent event 0x7fa2a0006710 (eos) to peerpad <mp4mux3089:video_0>, ret ok
0:07:05.684208227 20687 0x7fa2dc008800 DEBUG               GST_PADS gstpad.c:3936:push_sticky:<h264parse3089:src> event eos marked received
0:07:05.684229175 20687 0x7fa2e0009600 LOG              GST_MESSAGE gstmessage.c:208:_gst_message_free: finalize message 0x7fa2dc06ea90, eos from /home/valmirpretto/video.mp4
0:07:05.684238553 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<h264parse3089:sink> stored sticky event eos
0:07:05.684258099 20687 0x7fa2dc008800 LOG                 GST_PADS gstpad.c:5415:gst_pad_push_event_unchecked:<appsrc3089:src> sent event 0x7fa2a0006710 (eos) to peerpad <h264parse3089:sink>, ret ok
0:07:05.684262734 20687 0x7fa2dc008800 DEBUG               GST_PADS gstpad.c:3936:push_sticky:<appsrc3089:src> event eos marked received
0:07:05.684320127 20687 0x7fa2e0009600 DEBUG                    bin gstbin.c:2879:gst_bin_change_state_func:</home/valmirpretto/video.mp4> clearing EOS elements
0:07:05.684484352 20687 0x7fa2e0009600 DEBUG               basesink gstbasesink.c:3443:gst_base_sink_needs_preroll:<filesink3088> have_preroll: 0, EOS: 1 => needs preroll: 0
0:07:05.685613709 20687 0x7fa2e0009600 LOG                GST_EVENT gstevent.c:222:_gst_event_free: freeing event 0x7fa2bc035870 type eos
0:07:05.686403984 20687 0x7fa2e0009600 LOG                GST_EVENT gstevent.c:222:_gst_event_free: freeing event 0x7fa2a0006710 type eos
Iteration 3088 ended.

To complement the previous log, below I'm attaching the log of one instance where it hangs. It's completely random. Some times it hangs on iteration 0, sometimes it hangs on iteration 140k.

Iteration 3089 began.
0:07:05.693057276 20687 0x7fa2e0009600 DEBUG                    bin gstbin.c:2879:gst_bin_change_state_func:</home/valmirpretto/video.mp4> clearing EOS elements
0:07:05.694438521 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<appsrc3090:src> Removing pending EOS and StreamGroupDone events
0:07:05.694472194 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5706:gst_pad_send_event_unchecked:<h264parse3090:sink> Removing pending EOS events
0:07:05.694500122 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<h264parse3090:src> Removing pending EOS and StreamGroupDone events
0:07:05.694525084 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5706:gst_pad_send_event_unchecked:<mp4mux3090:video_0> Removing pending EOS events
0:07:05.694548935 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<mp4mux3090:video_0> Removing pending EOS and StreamGroupDone events
0:07:05.694576843 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<h264parse3090:sink> Removing pending EOS and StreamGroupDone events
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
new message [StreamStatus]
new message [StateChanged]
new message [StreamStatus]
new message [StateChanged]
new message [NewClock]
new message [StateChanged]
new message [StateChanged]
new message [StateChanged]
insert_samples() returned
0:07:05.699642747 20687 0x7fa2e0009600 DEBUG                 appsrc gstappsrc.c:2054:gst_app_src_end_of_stream:<appsrc3090> sending EOS
0:07:05.700604914 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<mp4mux3090:src> Removing pending EOS and StreamGroupDone events
0:07:05.700630095 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5706:gst_pad_send_event_unchecked:<filesink3089:sink> Removing pending EOS events
0:07:05.700982208 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5164:store_sticky_event:<filesink3089:sink> Removing pending EOS and StreamGroupDone events
new message [StreamStart]
new message [StateChanged]
new message [AsyncDone]
0:07:05.703190520 20687 0x7fa28400af70 DEBUG               basesink gstbasesink.c:3443:gst_base_sink_needs_preroll:<filesink3089> have_preroll: 1, EOS: 0 => needs preroll: 0
new message [StateChanged]
0:07:05.704053266 20687 0x7fa28400af70 DEBUG                    bin gstbin.c:889:find_message:</home/valmirpretto/video.mp4>   eos
new message [StateChanged]
0:07:05.704066690 20687 0x7fa28400af70 DEBUG                    bin gstbin.c:994:is_eos: sink 'filesink3089' did not post EOS yet
0:07:05.704075483 20687 0x7fa28400af70 LOG                      bin gstbin.c:3554:bin_do_eos:</home/valmirpretto/video.mp4> Not forwarding EOS due to in progress state change,  or already posted, or waiting for more EOS
0:07:05.795483298 20687 0x7fa2cc005940 DEBUG                 appsrc gstappsrc.c:1294:gst_app_src_create:<appsrc3090> we are EOS
0:07:05.795488124 20687 0x7fa2cc005940 DEBUG                basesrc gstbasesrc.c:2659:gst_base_src_get_range:<appsrc3090> create returned -3 (eos)
0:07:05.795491398 20687 0x7fa2cc005940 INFO                 basesrc gstbasesrc.c:2853:gst_base_src_loop:<appsrc3090> pausing after gst_base_src_get_range() = eos
0:07:05.795494682 20687 0x7fa2cc005940 DEBUG                basesrc gstbasesrc.c:3025:gst_base_src_loop:<appsrc3090> pausing task, reason eos
0:07:05.795507625 20687 0x7fa2cc005940 DEBUG              GST_EVENT gstevent.c:308:gst_event_new_custom: creating new event 0x7fa2d80060a0 eos 28174
0:07:05.795512423 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<appsrc3090:src> stored sticky event eos
0:07:05.795549706 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5408:gst_pad_push_event_unchecked:<appsrc3090:src> sending event 0x7fa2d80060a0 (eos) to peerpad <h264parse3090:sink>
0:07:05.795555079 20687 0x7fa2cc005940 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<h264parse3090:sink> have event type eos event: 0x7fa2d80060a0, time 99:99:99.999999999, seq-num 263178, (NULL)
0:07:05.795559666 20687 0x7fa2cc005940 DEBUG              baseparse gstbaseparse.c:1179:gst_base_parse_sink_event_default:<h264parse3090> handling event 28174, eos
0:07:05.795566960 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<h264parse3090:src> stored sticky event eos
0:07:05.795602528 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5408:gst_pad_push_event_unchecked:<h264parse3090:src> sending event 0x7fa2d80060a0 (eos) to peerpad <mp4mux3090:video_0>
0:07:05.795607079 20687 0x7fa2cc005940 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<mp4mux3090:video_0> have event type eos event: 0x7fa2d80060a0, time 99:99:99.999999999, seq-num 263178, (NULL)
0:07:05.795623657 20687 0x7fa2cc005940 DEBUG            collectpads gstcollectpads.c:1997:gst_collect_pads_event:<mp4mux3090:video_0> Got eos event on sink pad
0:07:05.795627575 20687 0x7fa2cc005940 DEBUG            collectpads gstcollectpads.c:1678:gst_collect_pads_event_default:<mp4mux3090:video_0> Got 'eos' event
0:07:05.795631548 20687 0x7fa2cc005940 DEBUG            collectpads gstcollectpads.c:1333:gst_collect_pads_check_collected:<collectpads3090> All active pads (1) areEOS, calling gst_qt_mux_collected
0:07:05.795698943 20687 0x7fa2cc005940 DEBUG                  qtmux gstqtmux.c:5025:find_best_pad:<mp4mux3090> No best pad: EOS
0:07:05.821031290 20687 0x7fa2cc005940 DEBUG                  qtmux gstqtmux.c:5072:gst_qt_mux_collected:<mp4mux3090> Pushing eos
0:07:05.821039525 20687 0x7fa2cc005940 DEBUG              GST_EVENT gstevent.c:308:gst_event_new_custom: creating new event 0x7fa2dc0614b0 eos 28174
0:07:05.821069632 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<mp4mux3090:src> stored sticky event eos
0:07:05.821088321 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5408:gst_pad_push_event_unchecked:<mp4mux3090:src> sending event 0x7fa2dc0614b0 (eos) to peerpad <filesink3089:sink>
0:07:05.821093318 20687 0x7fa2cc005940 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<filesink3089:sink> have event type eos event: 0x7fa2dc0614b0, time 99:99:99.999999999, seq-num 263220, (NULL)
0:07:05.821098520 20687 0x7fa2cc005940 DEBUG               basesink gstbasesink.c:3354:gst_base_sink_event:<filesink3089> received event 0x7fa2dc0614b0 eos event: 0x7fa2dc0614b0, time 99:99:99.999999999, seq-num 263220, (NULL)
0:07:05.821214590 20687 0x7fa2cc005940 DEBUG               basesink gstbasesink.c:2063:gst_base_sink_get_sync_times:<filesink3089> sync times for EOS 99:99:99.999999999
0:07:05.821217923 20687 0x7fa2cc005940 DEBUG               basesink gstbasesink.c:3223:gst_base_sink_default_event:<filesink3089> Now posting EOS
0:07:05.821239557 20687 0x7fa2cc005940 LOG              GST_MESSAGE gstmessage.c:303:gst_message_new_custom: source filesink3089: creating new message 0x7fa2bc03a600 eos
0:07:05.821246899 20687 0x7fa2cc005940 DEBUG                GST_BUS gstbus.c:315:gst_bus_post:<bus6188> [msg 0x7fa2bc03a600] posting on bus eos message: 0x7fa2bc03a600, time 99:99:99.999999999, seq-num 263220, element 'filesink3089', (NULL)
0:07:05.821252429 20687 0x7fa2cc005940 DEBUG                    bin gstbin.c:3718:gst_bin_handle_message_func:</home/valmirpretto/video.mp4> [msg 0x7fa2bc03a600] handling child filesink3089 message of type eos
0:07:05.821260095 20687 0x7fa2cc005940 DEBUG                    bin gstbin.c:889:find_message:</home/valmirpretto/video.mp4>   eos
0:07:05.821264196 20687 0x7fa2cc005940 DEBUG                    bin gstbin.c:928:bin_replace_message:</home/valmirpretto/video.mp4> got new message 0x7fa2bc03a600, eos from filesink3089
0:07:05.821314194 20687 0x7fa2cc005940 DEBUG                    bin gstbin.c:990:is_eos: sink 'filesink3089' posted EOS
0:07:05.821358464 20687 0x7fa2cc005940 DEBUG                    bin gstbin.c:956:bin_remove_messages:<filesink3089> deleting message 0x7fa2bc03a600 of type eos (types 0x00000001)
0:07:05.821364134 20687 0x7fa2cc005940 LOG              GST_MESSAGE gstmessage.c:208:_gst_message_free: finalize message 0x7fa2bc03a600, eos from filesink3089
0:07:05.821370377 20687 0x7fa2cc005940 LOG              GST_MESSAGE gstmessage.c:303:gst_message_new_custom: source /home/valmirpretto/video.mp4: creating new message 0x7fa2b443cb40 eos
0:07:05.821375384 20687 0x7fa2cc005940 DEBUG                    bin gstbin.c:3550:bin_do_eos:</home/valmirpretto/video.mp4> all sinks posted EOS, posting seqnum #263220
0:07:05.821383248 20687 0x7fa2cc005940 DEBUG                GST_BUS gstbus.c:315:gst_bus_post:<bus6189> [msg 0x7fa2b443cb40] posting on bus eos message: 0x7fa2b443cb40, time 99:99:99.999999999, seq-num 263220, element '/home/valmirpretto/video.mp4', (NULL)
0:07:05.822761273 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<filesink3089:sink> stored sticky event eos
0:07:05.822771354 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5415:gst_pad_push_event_unchecked:<mp4mux3090:src> sent event 0x7fa2dc0614b0 (eos) to peerpad <filesink3089:sink>, ret ok
0:07:05.822777665 20687 0x7fa2cc005940 DEBUG               GST_PADS gstpad.c:3936:push_sticky:<mp4mux3090:src> event eos marked received
0:07:05.822800216 20687 0x7fa2cc005940 DEBUG            collectpads gstcollectpads.c:1862:gst_collect_pads_event_default:<collectpads3090> dropping event: eos event: 0x7fa2d80060a0, time 99:99:99.999999999, seq-num 263178, (NULL)
0:07:05.822831906 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<mp4mux3090:video_0> stored sticky event eos
0:07:05.822853368 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5415:gst_pad_push_event_unchecked:<h264parse3090:src> sent event 0x7fa2d80060a0 (eos) to peerpad <mp4mux3090:video_0>, ret ok
0:07:05.822859342 20687 0x7fa2cc005940 DEBUG               GST_PADS gstpad.c:3936:push_sticky:<h264parse3090:src> event eos marked received
0:07:05.822876953 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5224:store_sticky_event:<h264parse3090:sink> stored sticky event eos
0:07:05.822884517 20687 0x7fa2cc005940 LOG                 GST_PADS gstpad.c:5415:gst_pad_push_event_unchecked:<appsrc3090:src> sent event 0x7fa2d80060a0 (eos) to peerpad <h264parse3090:sink>, ret ok
0:07:05.822890167 20687 0x7fa2cc005940 DEBUG               GST_PADS gstpad.c:3936:push_sticky:<appsrc3090:src> event eos marked received

Both of these logs were filtered by grep eos.

The pipelines are not being reused. For each iteration (or better yet, each time a file needs to be saved), a new pipeline is instantiated.

Has anyone else encountered this before? I've been trying to solve this for a few days now and I haven't been making any progress.


Edit 01:

How to reproduce (replace the file_path variable to your liking):

use {futures::prelude::*, gstreamer::prelude::*};

use {
    futures::executor,
    gstreamer::{BusStream, ElementFactory, MessageView, Pipeline, Sample, State},
    gstreamer_app::{AppSink, AppSrc},
};

fn generate_samples() -> Vec<Sample> {
    let videotestsrc = ElementFactory::make("videotestsrc", None).unwrap();
    let x264enc = ElementFactory::make("x264enc", None).unwrap();
    let appsink = ElementFactory::make("appsink", None).unwrap();

    videotestsrc.set_property("num-buffers", &200).unwrap();

    let pipeline = Pipeline::new(None);
    pipeline.add(&videotestsrc).unwrap();
    pipeline.add(&x264enc).unwrap();
    pipeline.add(&appsink).unwrap();

    videotestsrc.link(&x264enc).unwrap();
    x264enc.link(&appsink).unwrap();

    let app_sink = appsink.dynamic_cast::<AppSink>().unwrap();

    pipeline.set_state(State::Playing).unwrap();

    let mut samples = Vec::new();

    while let Ok(sample) = app_sink.pull_sample() {
        samples.push(sample);
    }

    pipeline.set_state(State::Null).unwrap();

    samples
}

async fn write_samples(location: &str, samples: Vec<Sample>) {
    let appsrc = ElementFactory::make("appsrc", None).unwrap();
    let h264parse = ElementFactory::make("h264parse", None).unwrap();
    let mp4mux = ElementFactory::make("mp4mux", None).unwrap();
    let filesink = ElementFactory::make("filesink", None).unwrap();

    mp4mux.set_property("faststart", &true).unwrap();
    filesink.set_property("location", &location).unwrap();

    let pipeline = Pipeline::new(None);
    pipeline.add(&appsrc).unwrap();
    pipeline.add(&h264parse).unwrap();
    pipeline.add(&mp4mux).unwrap();
    pipeline.add(&filesink).unwrap();

    appsrc.link(&h264parse).unwrap();
    h264parse.link(&mp4mux).unwrap();
    mp4mux.link(&filesink).unwrap();

    let app_src = appsrc.dynamic_cast::<AppSrc>().unwrap();

    for sample in samples {
        app_src.push_sample(&sample).unwrap();
    }

    app_src.end_of_stream().unwrap();

    let bus = pipeline.get_bus().unwrap();
    let mut bus_stream = BusStream::new(&bus);

    pipeline.set_state(State::Playing).unwrap();

    while let Some(message) = bus_stream.next().await {
        println!("new message [{:?}]", message.get_type());

        match message.view() {
            MessageView::Eos(..) => {
                pipeline.set_state(State::Null).unwrap();
                return;
            }
            MessageView::Error(..) => {
                pipeline.set_state(State::Null).unwrap();
                panic!("error");
            }
            _ => (),
        }
    }

    unreachable!()
}

#[test]
fn stress() {
    gstreamer::init().unwrap();

    let samples = generate_samples();

    for index in 0.. {
        println!("Iteration {} began.", index);

        let file_path = "/home/valmirpretto/video.mp4";
        let samples = samples.iter().cloned().collect();
        executor::block_on(write_samples(file_path, samples));

        println!("Iteration {} ended.", index);
    }
}

Edit 02:

These are the dependencies I've used:

futures = "0.3.1"
gstreamer = "0.15.1"
gstreamer-app = "0.15.0"

Edit 03:

I've pinpointed the bug to be on BusStream. If I iterate the messages on the bus through for message in bus.iter_timed(ClockTime::none()) {} it doesn't hang.


Edit 04:

Thread on Reddit

Issue on the gstreamer-rs repository

rust
gstreamer
asked on Stack Overflow Jan 28, 2020 by Valmir Junior • edited Jan 28, 2020 by Valmir Junior

0 Answers

Nobody has answered this question yet.


User contributions licensed under CC BY-SA 3.0