avfassetsrc deadlock

log.txt

WARNING: no real random source present!
0:00:00.097867000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<GstPlayBin@0x7ffbe9a30240> element <playsink> was added to <GstPlayBin@0x7ffbe9a30240>
0:00:00.097966000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<GstPlayBin@0x7ffbe9a30240> element <streamsynchronizer0> was added to <playsink>
0:00:00.098131000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:976:void gst_play_sink_set_filter(GstPlaySink *, GstPlaySinkType, GstElement *):<playsink> Setting filter <scaletempo0> as filter type 0
0:00:00.098141000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:978:void gst_play_sink_set_filter(GstPlaySink *, GstPlaySinkType, GstElement *):<playsink> locking from thread 0x7ffbea8662f0
0:00:00.098147000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:978:void gst_play_sink_set_filter(GstPlaySink *, GstPlaySinkType, GstElement *):<playsink> locked from thread 0x7ffbea8662f0
0:00:00.098152000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:997:void gst_play_sink_set_filter(GstPlaySink *, GstPlaySinkType, GstElement *):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:01.413675000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:1636:gboolean gst_playbin_uri_is_valid(GstPlayBin *, const gchar *):<playbin> checking uri 'file:///Users/stephan/Library/Developer/CoreSimulator/Devices/92066DDE-68E1-4423-890E-00DC9F3AF6F9/data/Containers/Bundle/Application/989AAF29-F97C-4095-919A-DCE8D57B162B/Demo.app/guitars.m4a'
0:00:01.413710000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:1690:void gst_play_bin_set_uri(GstPlayBin *, const gchar *): set new uri to file:///Users/stephan/Library/Developer/CoreSimulator/Devices/92066DDE-68E1-4423-890E-00DC9F3AF6F9/data/Containers/Bundle/Application/989AAF29-F97C-4095-919A-DCE8D57B162B/Demo.app/guitars.m4a
0:00:01.413734000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:1707:void gst_play_bin_set_suburi(GstPlayBin *, const gchar *): setting new .sub uri to (null)
0:00:02.543656000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:5715:GstStateChangeReturn gst_play_bin_change_state(GstElement *, GstStateChange):<playbin> clearing shutdown flag
0:00:02.544151000 50087 0x7ffbea8662f0 INFO                playsink gstplaysink.c:1423:void do_async_start(GstPlaySink *):<playsink> Sending async_start message
0:00:02.544235000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4253:gboolean gst_play_sink_reconfigure(GstPlaySink *):<playsink> Triggering reconfiguration
0:00:02.544254000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4255:gboolean gst_play_sink_reconfigure(GstPlaySink *):<playsink> locking from thread 0x7ffbea8662f0
0:00:02.544629000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4255:gboolean gst_play_sink_reconfigure(GstPlaySink *):<playsink> locked from thread 0x7ffbea8662f0
0:00:02.544642000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4259:gboolean gst_play_sink_reconfigure(GstPlaySink *):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:02.544730000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:5604:GstStateChangeReturn setup_next_source(GstPlayBin *, GstState):<playbin> setup sources
0:00:02.544744000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:5198:GstStateChangeReturn activate_group(GstPlayBin *, GstSourceGroup *, GstState):<playbin> activating group 0x7ffbe9a306c8
0:00:02.544979000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locking from thread 0x7ffbea8662f0
0:00:02.545005000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locked from thread 0x7ffbea8662f0
0:00:02.545018000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:964:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:02.545028000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locking from thread 0x7ffbea8662f0
0:00:02.545039000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locked from thread 0x7ffbea8662f0
0:00:02.545756000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:964:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:02.545808000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locking from thread 0x7ffbea8662f0
0:00:02.545836000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locked from thread 0x7ffbea8662f0
0:00:02.545860000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:964:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:02.545925000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:5268:GstStateChangeReturn activate_group(GstPlayBin *, GstSourceGroup *, GstState):<playbin> making new uridecodebin
0:00:02.546588000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <uridecodebin0> was added to <playbin>
0:00:02.546917000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:2893:void gst_play_bin_handle_message(GstBin *, GstMessage *):<playbin> Ignoring async state change of uridecodebin: uridecodebin0
0:00:02.607119000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <source> was added to <uridecodebin0>
0:00:02.607416000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:237:gst_avf_asset_src_change_state: NULL => READY
0:00:02.607459000 50087 0x7ffbea8662f0 INFO             avfassetsrc avfassetsrc.m:881:-[GstAVFAssetReader initWithURI::]: Initializing AVFAssetReader with uri: file:///Users/stephan/Library/Developer/CoreSimulator/Devices/92066DDE-68E1-4423-890E-00DC9F3AF6F9/data/Containers/Bundle/Application/989AAF29-F97C-4095-919A-DCE8D57B162B/Demo.app/guitars.m4a
0:00:02.612900000 50087 0x7ffbea8662f0 INFO             avfassetsrc avfassetsrc.m:873:-[GstAVFAssetReader initReader:]: Found 0 video tracks and 1 audio tracks
0:00:02.612955000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:237:gst_avf_asset_src_change_state: READY => PAUSED
0:00:02.612968000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:601:gst_avf_asset_src_start:<source> Creating pads and starting reader
0:00:02.612976000 50087 0x7ffbea8662f0 INFO             avfassetsrc avfassetsrc.m:924:-[GstAVFAssetReader selectTrack::]: Selecting audio track 0
0:00:02.639099000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:444:gst_avf_asset_src_send_start_stream:<source> Pushing STREAM START
0:00:02.639243000 50087 0x7ffbea8662f0 INFO             avfassetsrc avfassetsrc.m:1078:-[GstAVFAssetReader getCaps:]: Using audio caps: audio/x-raw, format=(string)F32LE, rate=(int)44100, channels=(int)2, layout=(string)interleaved
0:00:02.639377000 50087 0x7ffbea8662f0 INFO             avfassetsrc avfassetsrc.m:1078:-[GstAVFAssetReader getCaps:]: Using audio caps: audio/x-raw, format=(string)F32LE, rate=(int)44100, channels=(int)2, layout=(string)interleaved
0:00:02.640940000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3323:void pad_added_cb(GstElement *, GstPad *, GstSourceGroup *):<playbin> pad uridecodebin0:src_0 with caps audio/x-raw, format=(string)F32LE, rate=(int)44100, channels=(int)2, layout=(string)interleaved added in group 0x7ffbe9a306c8
0:00:02.642056000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3364:void pad_added_cb(GstElement *, GstPad *, GstSourceGroup *):<playbin> creating new input selector
0:00:02.642107000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3399:void pad_added_cb(GstElement *, GstPad *, GstSourceGroup *):<playbin> adding new stream combiner 0x7ffbe9a59050
0:00:02.642156000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <inputselector0> was added to <playbin>
0:00:02.642173000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3420:void pad_added_cb(GstElement *, GstPad *, GstSourceGroup *):<playbin> blocking <inputselector0:src>
0:00:02.642214000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3431:void pad_added_cb(GstElement *, GstPad *, GstSourceGroup *):<playbin> got pad inputselector0:sink_0 from combiner
0:00:02.642247000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3465:void pad_added_cb(GstElement *, GstPad *, GstSourceGroup *):<playbin> pad 0x7ffbe94029b0 added to array
0:00:02.642284000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3477:void pad_added_cb(GstElement *, GstPad *, GstSourceGroup *):<playbin> linked pad uridecodebin0:src_0 to combiner 0x7ffbe9a59050
0:00:02.642410000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3692:void no_more_pads_cb(GstElement *, GstSourceGroup *):<playbin> no more pads in group 0x7ffbe9a306c8
0:00:02.642419000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3705:void no_more_pads_cb(GstElement *, GstSourceGroup *):<playbin> requesting new sink pad 0
0:00:02.642424000 50087 0x7ffbea8662f0 DEBUG               playsink gstplaysink.c:4435:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> request pad type 0
0:00:02.642430000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4437:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> locking from thread 0x7ffbea8662f0
0:00:02.642435000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4437:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> locked from thread 0x7ffbea8662f0
0:00:02.642569000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4443:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> creating tee
0:00:02.642682000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <audiotee> was added to <playsink>
0:00:02.642715000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4461:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> ghosting tee sinkpad
0:00:02.642773000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4516:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:02.642784000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4524:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> locking from thread 0x7ffbea8662f0
0:00:02.642790000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4524:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> locked from thread 0x7ffbea8662f0
0:00:02.642810000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4540:GstPad *gst_play_sink_request_pad(GstPlaySink *, GstPlaySinkType):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:02.642880000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3723:void no_more_pads_cb(GstElement *, GstSourceGroup *):<playbin> linked type audio/, result: 0
0:00:02.642904000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3732:void no_more_pads_cb(GstElement *, GstSourceGroup *):<playbin> pending 1 > 0
0:00:02.642914000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:3743:void no_more_pads_cb(GstElement *, GstSourceGroup *):<playbin> last group complete
0:00:02.642929000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:3786:void no_more_pads_cb(GstElement *, GstSourceGroup *):<playbin> unblocking <inputselector0:src>
0:00:02.642949000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4253:gboolean gst_play_sink_reconfigure(GstPlaySink *):<playsink> Triggering reconfiguration
0:00:02.642954000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4255:gboolean gst_play_sink_reconfigure(GstPlaySink *):<playsink> locking from thread 0x7ffbea8662f0
0:00:02.643101000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4255:gboolean gst_play_sink_reconfigure(GstPlaySink *):<playsink> locked from thread 0x7ffbea8662f0
0:00:02.643112000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:4259:gboolean gst_play_sink_reconfigure(GstPlaySink *):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:02.643146000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:1346:void do_async_done(GstPlayBin *):<playbin> posting ASYNC_DONE
0:00:02.643167000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:2893:void gst_play_bin_handle_message(GstBin *, GstMessage *):<playbin> Ignoring async state change of uridecodebin: uridecodebin0
0:00:02.643177000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:691:gst_avf_asset_src_start_reading:<source> Start reading
0:00:03.014016000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:5173:gboolean group_set_locked_state_unlocked(GstPlayBin *, GstSourceGroup *, gboolean):<playbin> locked_state 0 on group 0x7ffbe9a306c8
0:00:03.014103000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.029666000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:00.000000000 dur:0:00:00.185759637
0:00:03.029842000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:4277:GstPadProbeReturn sinkpad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<playsink> locking from thread 0x7ffbea866b10
0:00:03.029866000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:4277:GstPadProbeReturn sinkpad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<playsink> locked from thread 0x7ffbea866b10
0:00:03.029878000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:4285:GstPadProbeReturn sinkpad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<playsink:audio_sink> Audio pad blocked
0:00:03.029888000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:4302:GstPadProbeReturn sinkpad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<playsink> All pads blocked -- reconfiguring
0:00:03.029973000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:4313:GstPadProbeReturn sinkpad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<playsink> Audio pad is raw: 1
0:00:03.030224000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:3199:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> reconfiguring
0:00:03.030267000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:3204:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> locking from thread 0x7ffbea866b10
0:00:03.030307000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:3204:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> locked from thread 0x7ffbea866b10
0:00:03.030318000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:3262:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> audio:1, video:0, vis:0, text:0
0:00:03.030330000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:3408:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> no video needed
0:00:03.030624000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:3477:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> adding audio
0:00:03.030863000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:3545:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> creating new audio chain
0:00:03.030875000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:2680:GstPlayAudioChain *gen_audio_chain(GstPlaySink *, gboolean):<playsink> making audio chain 0x6000006ef680
0:00:03.030921000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:2689:GstPlayAudioChain *gen_audio_chain(GstPlaySink *, gboolean):<playsink> trying autoaudiosink
0:00:03.052437000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:1013:GstElement *gst_play_sink_get_filter(GstPlaySink *, GstPlaySinkType):<playsink> locking from thread 0x7ffbea866b10
0:00:03.052464000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:1013:GstElement *gst_play_sink_get_filter(GstPlaySink *, GstPlaySinkType):<playsink> locked from thread 0x7ffbea866b10
0:00:03.052477000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:1043:GstElement *gst_play_sink_get_filter(GstPlaySink *, GstPlaySinkType):<playsink> unlocking from thread 0x7ffbea866b10
0:00:03.052486000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:2731:GstPlayAudioChain *gen_audio_chain(GstPlaySink *, gboolean):<playsink> adding audio filter
0:00:03.053078000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:2763:GstPlayAudioChain *gen_audio_chain(GstPlaySink *, gboolean):<playsink> adding audio queue
0:00:03.055286000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:1315:gboolean element_has_property(GstElement *, const gchar *, GType):<audiosink> has ts-offset property of type gint64
0:00:03.055373000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:2821:GstPlayAudioChain *gen_audio_chain(GstPlaySink *, gboolean):<playsink> the sink has no volume property
0:00:03.055401000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:2833:GstPlayAudioChain *gen_audio_chain(GstPlaySink *, gboolean):<playsink> creating audioconvert with use-converters 1, use-volume 1
0:00:03.056126000 50087 0x7ffbea866b10 DEBUG   playsinkaudioconvert gstplaysinkaudioconvert.c:55:gboolean gst_play_sink_audio_convert_add_conversion_elements(GstPlaySinkAudioConvert *):<GstPlaySinkAudioConvert@0x7ffbe9725260> Building audio conversion with use-converters 0, use-volume 0
0:00:03.056178000 50087 0x7ffbea866b10 INFO      playsinkconvertbin gstplaysinkconvertbin.c:579:void gst_play_sink_convert_bin_cache_converter_caps(GstPlaySinkConvertBin *):<GstPlaySinkAudioConvert@0x7ffbe9725260> No conversion elements
0:00:03.056264000 50087 0x7ffbea866b10 LOG     playsinkaudioconvert gstplaysinkaudioconvert.c:111:void gst_play_sink_audio_convert_set_property(GObject *, guint, const GValue *, GParamSpec *):<aconv> locking from thread 0x7ffbea866b10
0:00:03.056278000 50087 0x7ffbea866b10 LOG     playsinkaudioconvert gstplaysinkaudioconvert.c:111:void gst_play_sink_audio_convert_set_property(GObject *, guint, const GValue *, GParamSpec *):<aconv> locked from thread 0x7ffbea866b10
0:00:03.056299000 50087 0x7ffbea866b10 DEBUG   playsinkaudioconvert gstplaysinkaudioconvert.c:133:void gst_play_sink_audio_convert_set_property(GObject *, guint, const GValue *, GParamSpec *):<aconv> Rebuilding converter bin
0:00:03.056310000 50087 0x7ffbea866b10 DEBUG   playsinkaudioconvert gstplaysinkaudioconvert.c:55:gboolean gst_play_sink_audio_convert_add_conversion_elements(GstPlaySinkAudioConvert *):<aconv> Building audio conversion with use-converters 1, use-volume 0
0:00:03.058430000 50087 0x7ffbea866b10 INFO      playsinkconvertbin gstplaysinkconvertbin.c:592:void gst_play_sink_convert_bin_cache_converter_caps(GstPlaySinkConvertBin *):<aconv> Converter 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)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ], layout=(string)interleaved
0:00:03.058460000 50087 0x7ffbea866b10 LOG     playsinkaudioconvert gstplaysinkaudioconvert.c:139:void gst_play_sink_audio_convert_set_property(GObject *, guint, const GValue *, GParamSpec *):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.058472000 50087 0x7ffbea866b10 LOG     playsinkaudioconvert gstplaysinkaudioconvert.c:111:void gst_play_sink_audio_convert_set_property(GObject *, guint, const GValue *, GParamSpec *):<aconv> locking from thread 0x7ffbea866b10
0:00:03.058482000 50087 0x7ffbea866b10 LOG     playsinkaudioconvert gstplaysinkaudioconvert.c:111:void gst_play_sink_audio_convert_set_property(GObject *, guint, const GValue *, GParamSpec *):<aconv> locked from thread 0x7ffbea866b10
0:00:03.058490000 50087 0x7ffbea866b10 DEBUG   playsinkaudioconvert gstplaysinkaudioconvert.c:133:void gst_play_sink_audio_convert_set_property(GObject *, guint, const GValue *, GParamSpec *):<aconv> Rebuilding converter bin
0:00:03.058576000 50087 0x7ffbea866b10 DEBUG   playsinkaudioconvert gstplaysinkaudioconvert.c:55:gboolean gst_play_sink_audio_convert_add_conversion_elements(GstPlaySinkAudioConvert *):<aconv> Building audio conversion with use-converters 1, use-volume 1
0:00:03.059085000 50087 0x7ffbea866b10 INFO      playsinkconvertbin gstplaysinkconvertbin.c:592:void gst_play_sink_convert_bin_cache_converter_caps(GstPlaySinkConvertBin *):<aconv> Converter caps: audio/x-raw, format=(string){ F32LE, F64LE, S8, S16LE, S24LE, S32LE }, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ], layout=(string)interleaved; audio/x-raw, rate=(int)[ 1, 2147483647 ], layout=(string)interleaved, 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 }, channels=(int)[ 1, 2147483647 ]
0:00:03.059124000 50087 0x7ffbea866b10 LOG     playsinkaudioconvert gstplaysinkaudioconvert.c:139:void gst_play_sink_audio_convert_set_property(GObject *, guint, const GValue *, GParamSpec *):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.059208000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:2874:GstPlayAudioChain *gen_audio_chain(GstPlaySink *, gboolean):<playsink> linking to sink
0:00:03.059223000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:397:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> locking from thread 0x7ffbea866b10
0:00:03.059232000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:397:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> locked from thread 0x7ffbea866b10
0:00:03.059419000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:486:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.059430000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:490:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv:src> Returning caps audio/x-raw, rate=(int)[ 1, 2147483647 ], layout=(string)interleaved, format=(string)F32LE, channels=(int)[ 1, 2147483647 ]; audio/x-raw, rate=(int)[ 1, 2147483647 ], layout=(string)interleaved, format=(string)F64LE, channels=(int)[ 1, 2147483647 ]; audio/x-raw, rate=(int)[ 1, 2147483647 ], layout=(string)interleaved, format=(string)S16LE, channels=(int)[ 1, 2147483647 ]; audio/x-raw, format=(string){ F32LE, F64LE, S8, S16LE, S24LE, S32LE }, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ], layout=(string)interleaved; audio/x-raw, rate=(int)[ 1, 2147483647 ], layout=(string)interleaved, 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 }, channels=(int)[ 1, 2147483647 ]
0:00:03.059597000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:2887:GstPlayAudioChain *gen_audio_chain(GstPlaySink *, gboolean):<playsink> ghosting sink pad
0:00:03.059751000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:3598:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> adding audio chain
0:00:03.059819000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <abin> was added to <playsink>
0:00:03.059852000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <aconv> was added to <abin>
0:00:03.059869000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <volume> was added to <aconv>
0:00:03.059885000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <resample> was added to <aconv>
0:00:03.059911000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <conv> was added to <aconv>
0:00:03.060066000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <identity> was added to <aconv>
0:00:03.060080000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <aqueue> was added to <abin>
0:00:03.060113000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <scaletempo0> was added to <abin>
0:00:03.060126000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <filter-convert> was added to <abin>
0:00:03.060198000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <audiosink> was added to <abin>
0:00:03.060232000 50087 0x7ffbea866b10 LOG                  playbin gstplaybin2.c:3020:void gst_play_bin_deep_element_added(GstBin *, GstBin *, GstElement *):<playbin> element <audiosink-actual-sink-osxaudio> was added to <audiosink>
0:00:03.060412000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:611:GstStateChangeReturn gst_play_sink_convert_bin_change_state(GstElement *, GstStateChange):<aconv> locking from thread 0x7ffbea866b10
0:00:03.060424000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:611:GstStateChangeReturn gst_play_sink_convert_bin_change_state(GstElement *, GstStateChange):<aconv> locked from thread 0x7ffbea866b10
0:00:03.060432000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:137:void gst_play_sink_convert_bin_set_targets(GstPlaySinkConvertBin *, gboolean):<aconv> Setting pad targets with passthrough 1
0:00:03.060439000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:140:void gst_play_sink_convert_bin_set_targets(GstPlaySinkConvertBin *, gboolean):<aconv> no conversion elements, using identity (0x7ffbe9725ed0) as head/tail
0:00:03.060615000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:157:void gst_play_sink_convert_bin_set_targets(GstPlaySinkConvertBin *, gboolean):<aconv> Ghosting bin sink pad to <identity:sink>
0:00:03.060642000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:162:void gst_play_sink_convert_bin_set_targets(GstPlaySinkConvertBin *, gboolean):<aconv> Ghosting bin src pad to <identity:src>
0:00:03.060670000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:614:GstStateChangeReturn gst_play_sink_convert_bin_change_state(GstElement *, GstStateChange):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.060840000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:632:GstStateChangeReturn gst_play_sink_convert_bin_change_state(GstElement *, GstStateChange):<aconv> locking from thread 0x7ffbea866b10
0:00:03.060864000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:632:GstStateChangeReturn gst_play_sink_convert_bin_change_state(GstElement *, GstStateChange):<aconv> locked from thread 0x7ffbea866b10
0:00:03.060870000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:634:GstStateChangeReturn gst_play_sink_convert_bin_change_state(GstElement *, GstStateChange):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.061105000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:3719:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> no vis needed
0:00:03.061162000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:3799:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> no text needed
0:00:03.061180000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:3996:void update_av_offset(GstPlaySink *):<playsink> no ts_offset elements
0:00:03.061231000 50087 0x7ffbea866b10 INFO                playsink gstplaysink.c:1435:void do_async_done(GstPlaySink *):<playsink> Sending async_done message
0:00:03.061240000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:3851:gboolean gst_play_sink_do_reconfigure(GstPlaySink *):<playsink> unlocking from thread 0x7ffbea866b10
0:00:03.061247000 50087 0x7ffbea866b10 LOG                 playsink gstplaysink.c:4325:GstPadProbeReturn sinkpad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<playsink> unlocking from thread 0x7ffbea866b10
0:00:03.061628000 50087 0x7ffbeb10c200 DEBUG                playbin gstplaybin2.c:2909:void gst_play_bin_handle_message(GstBin *, GstMessage *):<playbin> Stream start from new group 0x7ffbe9a306c8
0:00:03.062037000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:397:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> locking from thread 0x7ffbea866b10
0:00:03.062051000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:397:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> locked from thread 0x7ffbea866b10
0:00:03.062790000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:486:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.062819000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:490:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv:sink> Returning caps audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)1; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)[ 1, 2147483647 ]; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F64LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F64LE, channels=(int)1; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F64LE, channels=(int)[ 1, 2147483647 ]; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)S16LE, channels=(int)1; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)S16LE, channels=(int)[ 1, 2147483647 ]
0:00:03.063843000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:361:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> locking from thread 0x7ffbea866b10
0:00:03.063858000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:361:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> locked from thread 0x7ffbea866b10
0:00:03.064021000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:380:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.064039000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:384:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv:sink> Accept caps: 'audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003' 1
0:00:03.064096000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:361:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> locking from thread 0x7ffbea866b10
0:00:03.064124000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:361:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> locked from thread 0x7ffbea866b10
0:00:03.064237000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:380:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.064246000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:384:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv:sink> Accept caps: 'audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003' 1
0:00:03.064299000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:361:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> locking from thread 0x7ffbeb10c200
0:00:03.064315000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:361:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> locked from thread 0x7ffbeb10c200
0:00:03.064399000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:380:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> unlocking from thread 0x7ffbeb10c200
0:00:03.064407000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:384:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv:sink> Accept caps: 'audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003' 1
0:00:03.064606000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:295:void gst_play_sink_convert_bin_sink_setcaps(GstPlaySinkConvertBin *, GstCaps *):<aconv> Setting sink caps audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:03.064642000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:297:void gst_play_sink_convert_bin_sink_setcaps(GstPlaySinkConvertBin *, GstCaps *):<aconv> locking from thread 0x7ffbeb10c200
0:00:03.064654000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:297:void gst_play_sink_convert_bin_sink_setcaps(GstPlaySinkConvertBin *, GstCaps *):<aconv> locked from thread 0x7ffbeb10c200
0:00:03.064660000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:308:void gst_play_sink_convert_bin_sink_setcaps(GstPlaySinkConvertBin *, GstCaps *):<aconv> raw 1, self->raw 0, blocked 0
0:00:03.064864000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:316:void gst_play_sink_convert_bin_sink_setcaps(GstPlaySinkConvertBin *, GstCaps *):<aconv> Changing caps from non-raw to raw
0:00:03.064891000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:341:void gst_play_sink_convert_bin_sink_setcaps(GstPlaySinkConvertBin *, GstCaps *):<aconv> unlocking from thread 0x7ffbeb10c200
0:00:03.064906000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:197:GstPadProbeReturn pad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<aconv> locking from thread 0x7ffbeb10c200
0:00:03.064912000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:197:GstPadProbeReturn pad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<aconv> locked from thread 0x7ffbeb10c200
0:00:03.065055000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:198:GstPadProbeReturn pad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<aconv> Pad blocked
0:00:03.065066000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:208:GstPadProbeReturn pad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<aconv> Caps audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003 are raw: 1
0:00:03.065107000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:219:GstPadProbeReturn pad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<aconv> Switching to raw conversion pipeline
0:00:03.065121000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:137:void gst_play_sink_convert_bin_set_targets(GstPlaySinkConvertBin *, gboolean):<aconv> Setting pad targets with passthrough 0
0:00:03.065270000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:150:void gst_play_sink_convert_bin_set_targets(GstPlaySinkConvertBin *, gboolean):<aconv> conversion elements in use, picking head:conv and tail:volume
0:00:03.065294000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:157:void gst_play_sink_convert_bin_set_targets(GstPlaySinkConvertBin *, gboolean):<aconv> Ghosting bin sink pad to <conv:sink>
0:00:03.065385000 50087 0x7ffbeb10c200 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:162:void gst_play_sink_convert_bin_set_targets(GstPlaySinkConvertBin *, gboolean):<aconv> Ghosting bin src pad to <volume:src>
0:00:03.065435000 50087 0x7ffbeb10c200 LOG       playsinkconvertbin gstplaysinkconvertbin.c:235:GstPadProbeReturn pad_blocked_cb(GstPad *, GstPadProbeInfo *, gpointer):<aconv> unlocking from thread 0x7ffbeb10c200
0:00:03.070384000 50087 0x7ffbea866b10 DEBUG               playsink gstplaysink.c:4347:void caps_notify_cb(GstPad *, GParamSpec *, GstPlaySink *):<playsink:audio_sink> Audio caps changed: raw 1 reconfigure 0 caps audio/x-raw, format=(string)F32LE, rate=(int)44100, channels=(int)2, layout=(string)interleaved
0:00:03.070588000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:397:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> locking from thread 0x7ffbea866b10
0:00:03.070598000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:397:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> locked from thread 0x7ffbea866b10
0:00:03.071317000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:486:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.071332000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:490:GstCaps *gst_play_sink_convert_bin_getcaps(GstPad *, GstCaps *):<aconv:sink> Returning caps audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)1; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)[ 1, 2147483647 ]; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F64LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F64LE, channels=(int)1; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F64LE, channels=(int)[ 1, 2147483647 ]; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)S16LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)S16LE, channels=(int)1; audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)S16LE, channels=(int)[ 1, 2147483647 ]
0:00:03.072073000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:361:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> locking from thread 0x7ffbea866b10
0:00:03.072088000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:361:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> locked from thread 0x7ffbea866b10
0:00:03.072201000 50087 0x7ffbea866b10 LOG       playsinkconvertbin gstplaysinkconvertbin.c:380:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv> unlocking from thread 0x7ffbea866b10
0:00:03.072210000 50087 0x7ffbea866b10 DEBUG     playsinkconvertbin gstplaysinkconvertbin.c:384:gboolean gst_play_sink_convert_bin_acceptcaps(GstPad *, GstCaps *):<aconv:sink> Accept caps: 'audio/x-raw, rate=(int)44100, layout=(string)interleaved, format=(string)F32LE, channels=(int)2, channel-mask=(bitmask)0x0000000000000003' 1
0:00:03.072245000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.072295000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:00.185759637 dur:0:00:00.185759637
0:00:03.072336000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.072353000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:00.371519274 dur:0:00:00.185759637
0:00:03.072383000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.072398000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:00.557278911 dur:0:00:00.185759637
0:00:03.072488000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.072511000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:00.743038548 dur:0:00:00.185759637
0:00:03.072544000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.072560000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:00.928798185 dur:0:00:00.185759637
0:00:03.072592000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.072614000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:01.114557823 dur:0:00:00.185759637
0:00:03.072735000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.072754000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:01.300317460 dur:0:00:00.185759637
0:00:03.072800000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locking from thread 0x7ffbea8662f0
0:00:03.072810000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locked from thread 0x7ffbea8662f0
0:00:03.072878000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:964:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:03.072911000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:2507:GstElement *gst_play_bin_get_current_sink(GstPlayBin *, GstElement **, const gchar *, GstPlaySinkType):<playbin> play_sink_get_sink() returned video sink (NULL), the originally set video sink is (NULL)
0:00:03.072945000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locking from thread 0x7ffbea8662f0
0:00:03.072980000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:926:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> locked from thread 0x7ffbea8662f0
0:00:03.073167000 50087 0x7ffbea8662f0 LOG                 playsink gstplaysink.c:964:GstElement *gst_play_sink_get_sink(GstPlaySink *, GstPlaySinkType):<playsink> unlocking from thread 0x7ffbea8662f0
0:00:03.073179000 50087 0x7ffbea8662f0 LOG                  playbin gstplaybin2.c:2507:GstElement *gst_play_bin_get_current_sink(GstPlayBin *, GstElement **, const gchar *, GstPlaySinkType):<playbin> play_sink_get_sink() returned video sink (NULL), the originally set video sink is (NULL)
0:00:03.073401000 50087 0x7ffbea8662f0 DEBUG                playbin gstplaybin2.c:2760:void gst_play_bin_update_cached_duration_from_query(GstPlayBin *, gboolean, GstQuery *):<playbin> Updating cached duration from query
0:00:03.074402000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:237:gst_avf_asset_src_change_state: PAUSED => PLAYING
0:00:03.074744000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.074778000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:01.486077097 dur:0:00:00.185759637
0:00:03.272995000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.273099000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:01.671836734 dur:0:00:00.185759637
0:00:03.457657000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.457713000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:01.857596371 dur:0:00:00.185759637
0:00:03.643317000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.643375000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:02.043356009 dur:0:00:00.185759637
0:00:03.817997000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:03.818091000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:02.229115646 dur:0:00:00.185759637
0:00:04.014868000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:04.014979000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:02.414875283 dur:0:00:00.185759637
0:00:04.200893000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:04.201028000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:02.600634920 dur:0:00:00.185759637
0:00:04.386435000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:04.386546000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:02.786394557 dur:0:00:00.185759637
0:00:04.572393000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:04.572520000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:02.972154195 dur:0:00:00.185759637
0:00:04.746471000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:04.746573000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:03.157913832 dur:0:00:00.185759637
0:00:04.944137000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:04.944209000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:03.343673469 dur:0:00:00.185759637
0:00:05.117647000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:05.117735000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:03.529433106 dur:0:00:00.185759637
0:00:05.315124000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:05.315195000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:03.715192743 dur:0:00:00.185759637
0:00:05.501295000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1025:-[GstAVFAssetReader nextBuffer::]: Reading audio next buffer
0:00:05.501679000 50087 0x7ffbea866b10 LOG              avfassetsrc avfassetsrc.m:1064:-[GstAVFAssetReader nextBuffer::]: Copying next audio buffer ts:0:00:03.900952380 dur:0:00:00.185759637
0:00:05.534054000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:237:gst_avf_asset_src_change_state: PLAYING => PAUSED
0:00:05.534400000 50087 0x7ffbea8662f0 DEBUG               playsink gstplaysink.c:4789:gboolean gst_play_sink_send_event(GstElement *, GstEvent *):<playsink> Sending event to a sink
0:00:05.534498000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:368:gst_avf_asset_src_event: Processing SEEK event
0:00:05.534529000 50087 0x7ffbea8662f0 DEBUG            avfassetsrc avfassetsrc.m:726:gst_avf_asset_src_stop_reading:<source> Stop reading

log dump with GST_DEBUG="play*:6,avfassetsrc:9"