0:00:00.020241771 [335m30472[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5102:gst_base_sink_change_state:<sink>[00m got preroll lock
0:00:00.020287600 [335m30472[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3592:gst_base_sink_needs_preroll:<sink>[00m have_preroll: 0, EOS: 1 => needs preroll: 0
0:00:00.020320542 [335m30472[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5120:gst_base_sink_change_state:<sink>[00m PLAYING to PAUSED, we are prerolled
0:00:00.020349323 [335m30472[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5142:gst_base_sink_change_state:<sink>[00m rendered: 3, dropped: 0
0:00:00.020443205 [335m30472[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4206:gst_base_sink_set_flushing:<sink>[00m flushing out data thread, need preroll to TRUE
0:00:00.020473091 [335m30472[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1488:gst_base_sink_preroll_queue_flush:<sink>[00m flushing queue 0x641410
0:00:00.020508481 [335m30472[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1016:gst_base_sink_set_last_buffer_unlocked:<sink>[00m setting last buffer to (nil)
0:00:00.020550224 [335m30472[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5179:gst_base_sink_change_state:<sink>[00m PAUSED to READY, don't need_preroll
0:00:00.020689188 [335m30472[00m       0x62e120 [32;01mINFO   [00m [00m               check libs/basesrc.c:579:basesrc_seek_events_rate_update:[00m stopped
0:00:00.020889242 [335m30472[00m       0x62e120 [37mLOG    [00m [00m               check libs/basesrc.c:596:basesrc_seek_events_rate_update:[00m cleaning up tasks
100%: Checks: 1, Failures: 0, Errors: 0
0:00:00.005728610 [332m30475[00m       0x62e120 [37mLOG    [00m [00m               check gstcheck.c:108:print_plugins:[00m         coreelements@../../plugins/elements/.libs/libgstcoreelements.so
0:00:00.005864944 [332m30475[00m       0x62e120 [37mLOG    [00m [00m               check gstcheck.c:108:print_plugins:[00m         coreindexers@../../plugins/indexers/.libs/libgstcoreindexers.so
0:00:00.005895968 [332m30475[00m       0x62e120 [37mLOG    [00m [00m               check gstcheck.c:108:print_plugins:[00m       staticelements@(NULL)
Running suite(s): GstBaseSrc
0:00:00.007098451 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m               check libs/basesrc.c:507:basesrc_seek_events_rate_update:[00m test start
0:00:00.011070471 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:424:gst_base_src_init:<GstBaseSrc@0x646070>[00m creating src pad
0:00:00.011176990 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:427:gst_base_src_init:<GstBaseSrc@0x646070>[00m setting functions on src pad
0:00:00.011217709 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:440:gst_base_src_init:<GstBaseSrc@0x646070>[00m adding src pad
0:00:00.011254022 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:454:gst_base_src_init:<GstBaseSrc@0x646070>[00m init done
0:00:00.011746906 [334m30489[00m       0x62e120 [32;01mINFO   [00m [00m               check libs/basesrc.c:547:basesrc_seek_events_rate_update:[00m going to playing
0:00:00.011878062 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5004:gst_base_sink_change_state:<sink>[00m READY to PAUSED
0:00:00.011888156 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5026:gst_base_sink_change_state:<sink>[00m doing async state change
0:00:00.011903903 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4239:gst_base_sink_pad_activate:<sink>[00m Trying pull mode first
0:00:00.011912576 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4245:gst_base_sink_pad_activate:<sink>[00m pull mode disabled
0:00:00.011919794 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4283:gst_base_sink_pad_activate:<sink>[00m Falling back to push mode
0:00:00.011928386 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4285:gst_base_sink_pad_activate:<sink>[00m Success activating push mode
0:00:00.011940771 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2993:gst_base_src_activate_push:<src>[00m Activating in push mode
0:00:00.011950143 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2746:gst_base_src_start:<src>[00m starting source
0:00:00.011958043 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2779:gst_base_src_start:<src>[00m setting size 18446744073709551615
0:00:00.011968161 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2792:gst_base_src_start:<src>[00m format: bytes, have size: 0, size: 18446744073709551615, duration: -1
0:00:00.011978334 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2795:gst_base_src_start:<src>[00m is seekable: 1
0:00:00.011985787 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2800:gst_base_src_start:<src>[00m is random_access: 1
0:00:00.011994027 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2655:gst_base_src_default_negotiate:<src>[00m caps of src: ANY
0:00:00.012003302 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2704:gst_base_src_default_negotiate:<src>[00m no negotiation needed
0:00:00.012012265 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1343:gst_base_src_perform_seek:<src>[00m doing seek: (NULL)
0:00:00.012021739 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1398:gst_base_src_perform_seek:<src>[00m seek with seqnum 7
0:00:00.012037280 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1434:gst_base_src_perform_seek:<src>[00m segment configured from 0 to -1, position 0
0:00:00.012046038 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1497:gst_base_src_perform_seek:<src>[00m Sending newsegment from 0 to -1
0:00:00.012329818 [334m30489[00m       0x643d40 [37mLOG    [00m [00m             basesrc gstbasesrc.c:2443:gst_base_src_loop:<src>[00m next_ts 0:00:00.000000000 size 4096
0:00:00.012422906 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2088:gst_base_src_update_length:<src>[00m reading offset 0, length 4096, size -1, segment.stop -1, maxsize -1
0:00:00.012463334 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2091:gst_base_src_update_length:<src>[00m dynamic size: 0
0:00:00.012491725 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2186:gst_base_src_get_range:<src>[00m calling create offset 0 length 4096, time 0
0:00:00.012585275 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2045:gst_base_src_do_sync:<src>[00m we have no clock
0:00:00.012650827 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2231:gst_base_src_get_range:<src>[00m buffer ok
0:00:00.012784591 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3439:gst_base_sink_event:<sink>[00m received event 0x643cf0 newsegment event from 'src' at time 99:99:99.999999999: GstEventNewsegment, update=(boolean)false, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_BYTES, start=(gint64)0, stop=(gint64)-1, position=(gint64)0;
0:00:00.012974613 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3474:gst_base_sink_event:<sink>[00m newsegment 0x643cf0
0:00:00.013010479 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1552:gst_base_sink_configure_segment:<sink>[00m configured NEWSEGMENT update 0, rate 1.000000, applied rate 1.000000, format 2, 0 -- -1, time 0, accum 0
0:00:00.013058942 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_queue_object_unlocked:<sink>[00m now 0 prerolled items
0:00:00.013086611 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3312:gst_base_sink_queue_object_unlocked:<sink>[00m need more preroll data 0 <= 0
0:00:00.013127941 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3665:gst_base_sink_chain_unlocked:<sink>[00m got times start: 0:00:00.000000000, end: 99:99:99.999999999
0:00:00.013160746 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_queue_object_unlocked:<sink>[00m now 1 prerolled items
0:00:00.013190927 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3178:gst_base_sink_preroll_object:<sink>[00m prerolling object 0x64b020
0:00:00.013217683 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3196:gst_base_sink_preroll_object:<sink>[00m preroll buffer 0:00:00.000000000
0:00:00.013245882 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1016:gst_base_sink_set_last_buffer_unlocked:<sink>[00m setting last buffer to 0x64b020
0:00:00.013281664 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1605:gst_base_sink_commit_state:<sink>[00m commiting state to PAUSED
0:00:00.013307905 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1630:gst_base_sink_commit_state:<sink>[00m posting PAUSED state change message
0:00:00.013350288 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1636:gst_base_sink_commit_state:<sink>[00m posting async-done message
0:00:00.013521463 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3284:gst_base_sink_queue_object_unlocked:<sink>[00m rendering queued object 0x643cf0
0:00:00.013726824 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2612:gst_base_sink_do_sync:<sink>[00m non syncable object 0x643cf0
0:00:00.013779453 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3044:gst_base_sink_render_object:<sink>[00m rendering event 0x643cf0, type newsegment
0:00:00.013919939 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3058:gst_base_sink_render_object:<sink>[00m Got seqnum #7
0:00:00.013960208 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1552:gst_base_sink_configure_segment:<sink>[00m configured NEWSEGMENT update 0, rate 1.000000, applied rate 1.000000, format 2, 0 -- -1, time 0, accum 0
0:00:00.014013692 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x643cf0
0:00:00.014051773 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2017:gst_base_sink_get_sync_times:<sink>[00m got times start: 0:00:00.000000000, stop: 99:99:99.999999999, do_sync 1
0:00:00.014085575 [334m30489[00m       0x643d40 [37mLOG    [00m [00m            basesink gstbasesink.c:2028:gst_base_sink_get_sync_times:<sink>[00m not time format, don't clip
0:00:00.014114673 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2344:gst_base_sink_do_preroll:<sink>[00m prerolling object 0x64b020
0:00:00.014128416 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1154:gst_base_sink_query_latency:<sink>[00m we are ready for LATENCY query
0:00:00.014228326 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3178:gst_base_sink_preroll_object:<sink>[00m prerolling object 0x64b020
0:00:00.014270794 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2277:gst_base_sink_wait_preroll:<sink>[00m waiting in preroll for flush or PLAYING
0:00:00.014231445 [334m30489[00m       0x644190 [37mLOG    [00m [00m             basesrc gstbasesrc.c:658:gst_base_src_query_latency:<src>[00m latency: live 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.014348865 [334m30489[00m       0x644190 [37mLOG    [00m [00m             basesrc gstbasesrc.c:1078:gst_base_src_default_query:<src>[00m report latency: live 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.014386385 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1134:gst_base_src_default_query:<src>[00m query latency returns 1
0:00:00.014428450 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1197:gst_base_sink_query_latency:<sink>[00m latency query: live: 0, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.014465128 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4947:default_element_query:<sink>[00m query latency returns 1
0:00:00.014514659 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4488:gst_base_sink_send_event:<sink>[00m handling event 0x7fb390001050 latency event from '(NULL)' at time 99:99:99.999999999: GstEventLatency, latency=(guint64)0;
0:00:00.014574338 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4505:gst_base_sink_send_event:<sink>[00m latency set to 0:00:00.000000000
0:00:00.014728669 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1747:gst_base_src_default_event:<src>[00m handle event latency event from 'sink' at time 99:99:99.999999999: GstEventLatency, latency=(guint64)0;
0:00:00.014800848 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1819:gst_base_src_event_handler:<src>[00m subclass refused event
0:00:00.014831051 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4535:gst_base_sink_send_event:<sink>[00m handled event 0x7fb390001050 latency event from 'sink' at time 99:99:99.999999999: GstEventLatency, latency=(guint64)0;: 0
0:00:00.014886308 [334m30489[00m       0x644190 [33;01mWARN   [00m [00;01m                 bin gstbin.c:2395:gst_bin_do_latency_func:<pipeline>[00m did not really configure latency of 0:00:00.000000000
0:00:00.014953173 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3592:gst_base_sink_needs_preroll:<sink>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.014984413 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5041:gst_base_sink_change_state:<sink>[00m PAUSED to PLAYING, don't need preroll
0:00:00.015010995 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5054:gst_base_sink_change_state:<sink>[00m signal preroll
0:00:00.015075304 [334m30489[00m       0x644190 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:3130:gst_base_src_change_state:<src>[00m PAUSED->PLAYING
0:00:00.015095381 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2285:gst_base_sink_wait_preroll:<sink>[00m continue after preroll
0:00:00.015173132 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2568:gst_base_sink_do_sync:<sink>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.015190021 [334m30489[00m       0x62e120 [32;01mINFO   [00m [00m               check libs/basesrc.c:554:basesrc_seek_events_rate_update:[00m seeking
0:00:00.015222423 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2240:gst_base_sink_wait_clock:<sink>[00m sync disabled
0:00:00.015288719 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2575:gst_base_sink_do_sync:<sink>[00m clock returned 4, jitter  0:00:00.000000000
0:00:00.015330450 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2999:gst_base_sink_render_object:<sink>[00m rendering object 0x64b020
0:00:00.015297127 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4488:gst_base_sink_send_event:<sink>[00m handling event 0x643ca0 seek event from '(NULL)' at time 99:99:99.999999999: GstEventSeek, rate=(double)0.5, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_NONE, cur-type=(GstSeekType)GST_SEEK_TYPE_NONE, cur=(gint64)-1, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;
0:00:00.015411177 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x64b020
0:00:00.015415524 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1747:gst_base_src_default_event:<src>[00m handle event seek event from 'sink' at time 99:99:99.999999999: GstEventSeek, rate=(double)0.5, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_NONE, cur-type=(GstSeekType)GST_SEEK_TYPE_NONE, cur=(gint64)-1, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;
0:00:00.015461938 [334m30489[00m       0x643d40 [37mLOG    [00m [00m             basesrc gstbasesrc.c:2443:gst_base_src_loop:<src>[00m next_ts 0:00:00.000000000 size 4096
0:00:00.015468863 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1343:gst_base_src_perform_seek:<src>[00m doing seek: seek event from 'sink' at time 99:99:99.999999999: GstEventSeek, rate=(double)0.5, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_NONE, cur-type=(GstSeekType)GST_SEEK_TYPE_NONE, cur=(gint64)-1, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;
0:00:00.015504042 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2088:gst_base_src_update_length:<src>[00m reading offset 0, length 4096, size -1, segment.stop -1, maxsize -1
0:00:00.015578825 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2091:gst_base_src_update_length:<src>[00m dynamic size: 0
0:00:00.015675885 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2186:gst_base_src_get_range:<src>[00m calling create offset 0 length 4096, time 0
0:00:00.015736045 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2051:gst_base_src_do_sync:<src>[00m no sync needed
0:00:00.015763906 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2231:gst_base_src_get_range:<src>[00m buffer ok
0:00:00.015794444 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3665:gst_base_sink_chain_unlocked:<sink>[00m got times start: 0:00:00.000000000, end: 99:99:99.999999999
0:00:00.015827069 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2017:gst_base_sink_get_sync_times:<sink>[00m got times start: 0:00:00.000000000, stop: 99:99:99.999999999, do_sync 1
0:00:00.015858645 [334m30489[00m       0x643d40 [37mLOG    [00m [00m            basesink gstbasesink.c:2028:gst_base_sink_get_sync_times:<sink>[00m not time format, don't clip
0:00:00.015886787 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2568:gst_base_sink_do_sync:<sink>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.015917910 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2240:gst_base_sink_wait_clock:<sink>[00m sync disabled
0:00:00.015943738 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2575:gst_base_sink_do_sync:<sink>[00m clock returned 4, jitter  0:00:00.000000000
0:00:00.015972960 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2999:gst_base_sink_render_object:<sink>[00m rendering object 0x64b0c0
0:00:00.015999723 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1016:gst_base_sink_set_last_buffer_unlocked:<sink>[00m setting last buffer to 0x64b0c0
0:00:00.016047756 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x64b0c0
0:00:00.016115581 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1398:gst_base_src_perform_seek:<src>[00m seek with seqnum 2
0:00:00.016141399 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1434:gst_base_src_perform_seek:<src>[00m segment configured from 0 to -1, position 0
0:00:00.016150074 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1451:gst_base_src_perform_seek:<src>[00m closing running segment 0 to 0
0:00:00.016166119 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1497:gst_base_src_perform_seek:<src>[00m Sending newsegment from 0 to -1
0:00:00.016185564 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4535:gst_base_sink_send_event:<sink>[00m handled event 0x643ca0 seek event from 'sink' at time 99:99:99.999999999: GstEventSeek, rate=(double)0.5, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_NONE, cur-type=(GstSeekType)GST_SEEK_TYPE_NONE, cur=(gint64)-1, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;: 1
0:00:00.016207415 [334m30489[00m       0x643d40 [37mLOG    [00m [00m             basesrc gstbasesrc.c:2443:gst_base_src_loop:<src>[00m next_ts 0:00:00.000000000 size 4096
0:00:00.016273550 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2088:gst_base_src_update_length:<src>[00m reading offset 0, length 4096, size -1, segment.stop -1, maxsize -1
0:00:00.016305111 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2091:gst_base_src_update_length:<src>[00m dynamic size: 0
0:00:00.016332496 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2186:gst_base_src_get_range:<src>[00m calling create offset 0 length 4096, time 0
0:00:00.016383820 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2051:gst_base_src_do_sync:<src>[00m no sync needed
0:00:00.016410887 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2231:gst_base_src_get_range:<src>[00m buffer ok
0:00:00.016509130 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3439:gst_base_sink_event:<sink>[00m received event 0x643d90 newsegment event from 'src' at time 99:99:99.999999999: GstEventNewsegment, update=(boolean)true, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_BYTES, start=(gint64)0, stop=(gint64)0, position=(gint64)0;
0:00:00.016614335 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3474:gst_base_sink_event:<sink>[00m newsegment 0x643d90
0:00:00.016659636 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1552:gst_base_sink_configure_segment:<sink>[00m configured NEWSEGMENT update 1, rate 1.000000, applied rate 1.000000, format 2, 0 -- 0, time 0, accum 0
0:00:00.016706525 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2612:gst_base_sink_do_sync:<sink>[00m non syncable object 0x643d90
0:00:00.016733529 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3044:gst_base_sink_render_object:<sink>[00m rendering event 0x643d90, type newsegment
0:00:00.016803536 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3058:gst_base_sink_render_object:<sink>[00m Got seqnum #2
0:00:00.016834767 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1552:gst_base_sink_configure_segment:<sink>[00m configured NEWSEGMENT update 1, rate 1.000000, applied rate 1.000000, format 2, 0 -- 0, time 0, accum 0
0:00:00.016870595 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x643d90
0:00:00.016960261 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3439:gst_base_sink_event:<sink>[00m received event 0x643de0 newsegment event from 'src' at time 99:99:99.999999999: GstEventNewsegment, update=(boolean)false, rate=(double)0.5, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_BYTES, start=(gint64)0, stop=(gint64)-1, position=(gint64)0;
0:00:00.017031810 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3474:gst_base_sink_event:<sink>[00m newsegment 0x643de0
0:00:00.017060837 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1552:gst_base_sink_configure_segment:<sink>[00m configured NEWSEGMENT update 0, rate 0.500000, applied rate 1.000000, format 2, 0 -- -1, time 0, accum 0
0:00:00.017097826 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2612:gst_base_sink_do_sync:<sink>[00m non syncable object 0x643de0
0:00:00.017124054 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3044:gst_base_sink_render_object:<sink>[00m rendering event 0x643de0, type newsegment
0:00:00.017190260 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3058:gst_base_sink_render_object:<sink>[00m Got seqnum #2
0:00:00.017236894 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1552:gst_base_sink_configure_segment:<sink>[00m configured NEWSEGMENT update 0, rate 0.500000, applied rate 1.000000, format 2, 0 -- -1, time 0, accum 0
0:00:00.017273997 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x643de0
0:00:00.017310659 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3665:gst_base_sink_chain_unlocked:<sink>[00m got times start: 0:00:00.000000000, end: 99:99:99.999999999
0:00:00.017332781 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:3147:gst_base_src_change_state:<src>[00m PLAYING->PAUSED
0:00:00.017351240 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2017:gst_base_sink_get_sync_times:<sink>[00m got times start: 0:00:00.000000000, stop: 99:99:99.999999999, do_sync 1
0:00:00.017395369 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:3020:gst_base_src_activate_push:<src>[00m Deactivating in push mode
0:00:00.017429399 [334m30489[00m       0x643d40 [37mLOG    [00m [00m            basesink gstbasesink.c:2028:gst_base_sink_get_sync_times:<sink>[00m not time format, don't clip
0:00:00.017484959 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2568:gst_base_sink_do_sync:<sink>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.017516257 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2240:gst_base_sink_wait_clock:<sink>[00m sync disabled
0:00:00.017542053 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2575:gst_base_sink_do_sync:<sink>[00m clock returned 4, jitter  0:00:00.000000000
0:00:00.017571428 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2999:gst_base_sink_render_object:<sink>[00m rendering object 0x64b160
0:00:00.017617557 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1016:gst_base_sink_set_last_buffer_unlocked:<sink>[00m setting last buffer to 0x64b160
0:00:00.017675700 [334m30489[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x64b160
0:00:00.017763199 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2854:gst_base_src_stop:<src>[00m stopping source
0:00:00.017792083 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:3165:gst_base_src_change_state:<src>[00m Sending EOS event
0:00:00.017822753 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3439:gst_base_sink_event:<sink>[00m received event 0x643e30 eos event from 'src' at time 99:99:99.999999999: (NULL)
0:00:00.017836464 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1976:gst_base_sink_get_sync_times:<sink>[00m sync times for EOS 0:00:00.000000000
0:00:00.017845918 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2568:gst_base_sink_do_sync:<sink>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.017855017 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2240:gst_base_sink_wait_clock:<sink>[00m sync disabled
0:00:00.017862670 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2575:gst_base_sink_do_sync:<sink>[00m clock returned 4, jitter  0:00:00.000000000
0:00:00.017871148 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3044:gst_base_sink_render_object:<sink>[00m rendering event 0x643e30, type eos
0:00:00.017896256 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3058:gst_base_sink_render_object:<sink>[00m Got seqnum #2
0:00:00.017904451 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3074:gst_base_sink_render_object:<sink>[00m Now posting EOS
0:00:00.017922773 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x643e30
0:00:00.018069028 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5093:gst_base_sink_change_state:<sink>[00m PLAYING to PAUSED
0:00:00.018081002 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5102:gst_base_sink_change_state:<sink>[00m got preroll lock
0:00:00.018087407 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3592:gst_base_sink_needs_preroll:<sink>[00m have_preroll: 0, EOS: 1 => needs preroll: 0
0:00:00.018094134 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5120:gst_base_sink_change_state:<sink>[00m PLAYING to PAUSED, we are prerolled
0:00:00.018100435 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5142:gst_base_sink_change_state:<sink>[00m rendered: 3, dropped: 0
0:00:00.018124782 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4206:gst_base_sink_set_flushing:<sink>[00m flushing out data thread, need preroll to TRUE
0:00:00.018132456 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1488:gst_base_sink_preroll_queue_flush:<sink>[00m flushing queue 0x641410
0:00:00.018141712 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1016:gst_base_sink_set_last_buffer_unlocked:<sink>[00m setting last buffer to (nil)
0:00:00.018152516 [334m30489[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5179:gst_base_sink_change_state:<sink>[00m PAUSED to READY, don't need_preroll
0:00:00.018189269 [334m30489[00m       0x62e120 [32;01mINFO   [00m [00m               check libs/basesrc.c:579:basesrc_seek_events_rate_update:[00m stopped
0:00:00.018242029 [334m30489[00m       0x62e120 [37mLOG    [00m [00m               check libs/basesrc.c:596:basesrc_seek_events_rate_update:[00m cleaning up tasks
100%: Checks: 1, Failures: 0, Errors: 0
0:00:00.005677529 [331m30492[00m       0x62e120 [37mLOG    [00m [00m               check gstcheck.c:108:print_plugins:[00m         coreelements@../../plugins/elements/.libs/libgstcoreelements.so
0:00:00.005781711 [331m30492[00m       0x62e120 [37mLOG    [00m [00m               check gstcheck.c:108:print_plugins:[00m         coreindexers@../../plugins/indexers/.libs/libgstcoreindexers.so
0:00:00.005813479 [331m30492[00m       0x62e120 [37mLOG    [00m [00m               check gstcheck.c:108:print_plugins:[00m       staticelements@(NULL)
Running suite(s): GstBaseSrc
0:00:00.007002442 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m               check libs/basesrc.c:507:basesrc_seek_events_rate_update:[00m test start
0:00:00.010984116 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:424:gst_base_src_init:<GstBaseSrc@0x646070>[00m creating src pad
0:00:00.011083507 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:427:gst_base_src_init:<GstBaseSrc@0x646070>[00m setting functions on src pad
0:00:00.011147971 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:440:gst_base_src_init:<GstBaseSrc@0x646070>[00m adding src pad
0:00:00.011194699 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:454:gst_base_src_init:<GstBaseSrc@0x646070>[00m init done
0:00:00.011578584 [333m30506[00m       0x62e120 [32;01mINFO   [00m [00m               check libs/basesrc.c:547:basesrc_seek_events_rate_update:[00m going to playing
0:00:00.011818596 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5004:gst_base_sink_change_state:<sink>[00m READY to PAUSED
0:00:00.011852344 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5026:gst_base_sink_change_state:<sink>[00m doing async state change
0:00:00.011905887 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4239:gst_base_sink_pad_activate:<sink>[00m Trying pull mode first
0:00:00.011943978 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4245:gst_base_sink_pad_activate:<sink>[00m pull mode disabled
0:00:00.011969979 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4283:gst_base_sink_pad_activate:<sink>[00m Falling back to push mode
0:00:00.011999394 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4285:gst_base_sink_pad_activate:<sink>[00m Success activating push mode
0:00:00.012040163 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2993:gst_base_src_activate_push:<src>[00m Activating in push mode
0:00:00.012072113 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2746:gst_base_src_start:<src>[00m starting source
0:00:00.012116106 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2779:gst_base_src_start:<src>[00m setting size 18446744073709551615
0:00:00.012170684 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2792:gst_base_src_start:<src>[00m format: bytes, have size: 0, size: 18446744073709551615, duration: -1
0:00:00.012217263 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2795:gst_base_src_start:<src>[00m is seekable: 1
0:00:00.012245295 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2800:gst_base_src_start:<src>[00m is random_access: 1
0:00:00.012274756 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2655:gst_base_src_default_negotiate:<src>[00m caps of src: ANY
0:00:00.012305986 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2704:gst_base_src_default_negotiate:<src>[00m no negotiation needed
0:00:00.012337186 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1343:gst_base_src_perform_seek:<src>[00m doing seek: (NULL)
0:00:00.012369987 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1398:gst_base_src_perform_seek:<src>[00m seek with seqnum 7
0:00:00.012397946 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1434:gst_base_src_perform_seek:<src>[00m segment configured from 0 to -1, position 0
0:00:00.012427570 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1497:gst_base_src_perform_seek:<src>[00m Sending newsegment from 0 to -1
0:00:00.012874360 [333m30506[00m       0x643d40 [37mLOG    [00m [00m             basesrc gstbasesrc.c:2443:gst_base_src_loop:<src>[00m next_ts 0:00:00.000000000 size 4096
0:00:00.012970238 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2088:gst_base_src_update_length:<src>[00m reading offset 0, length 4096, size -1, segment.stop -1, maxsize -1
0:00:00.013010261 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2091:gst_base_src_update_length:<src>[00m dynamic size: 0
0:00:00.013038751 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2186:gst_base_src_get_range:<src>[00m calling create offset 0 length 4096, time 0
0:00:00.013169261 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2045:gst_base_src_do_sync:<src>[00m we have no clock
0:00:00.013243572 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2231:gst_base_src_get_range:<src>[00m buffer ok
0:00:00.013366657 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3439:gst_base_sink_event:<sink>[00m received event 0x643cf0 newsegment event from 'src' at time 99:99:99.999999999: GstEventNewsegment, update=(boolean)false, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_BYTES, start=(gint64)0, stop=(gint64)-1, position=(gint64)0;
0:00:00.013560016 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3474:gst_base_sink_event:<sink>[00m newsegment 0x643cf0
0:00:00.013596314 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1552:gst_base_sink_configure_segment:<sink>[00m configured NEWSEGMENT update 0, rate 1.000000, applied rate 1.000000, format 2, 0 -- -1, time 0, accum 0
0:00:00.013644499 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_queue_object_unlocked:<sink>[00m now 0 prerolled items
0:00:00.013672478 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3312:gst_base_sink_queue_object_unlocked:<sink>[00m need more preroll data 0 <= 0
0:00:00.013714609 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3665:gst_base_sink_chain_unlocked:<sink>[00m got times start: 0:00:00.000000000, end: 99:99:99.999999999
0:00:00.013748083 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_queue_object_unlocked:<sink>[00m now 1 prerolled items
0:00:00.013778217 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3178:gst_base_sink_preroll_object:<sink>[00m prerolling object 0x64b020
0:00:00.013805070 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3196:gst_base_sink_preroll_object:<sink>[00m preroll buffer 0:00:00.000000000
0:00:00.013833256 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1016:gst_base_sink_set_last_buffer_unlocked:<sink>[00m setting last buffer to 0x64b020
0:00:00.013869077 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1605:gst_base_sink_commit_state:<sink>[00m commiting state to PAUSED
0:00:00.013895530 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1630:gst_base_sink_commit_state:<sink>[00m posting PAUSED state change message
0:00:00.013938242 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1636:gst_base_sink_commit_state:<sink>[00m posting async-done message
0:00:00.014083827 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3284:gst_base_sink_queue_object_unlocked:<sink>[00m rendering queued object 0x643cf0
0:00:00.014241196 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2612:gst_base_sink_do_sync:<sink>[00m non syncable object 0x643cf0
0:00:00.014278421 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3044:gst_base_sink_render_object:<sink>[00m rendering event 0x643cf0, type newsegment
0:00:00.014547493 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3058:gst_base_sink_render_object:<sink>[00m Got seqnum #7
0:00:00.014588517 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1552:gst_base_sink_configure_segment:<sink>[00m configured NEWSEGMENT update 0, rate 1.000000, applied rate 1.000000, format 2, 0 -- -1, time 0, accum 0
0:00:00.014635384 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x643cf0
0:00:00.014691425 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1154:gst_base_sink_query_latency:<sink>[00m we are ready for LATENCY query
0:00:00.014695619 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2017:gst_base_sink_get_sync_times:<sink>[00m got times start: 0:00:00.000000000, stop: 99:99:99.999999999, do_sync 1
0:00:00.014793433 [333m30506[00m       0x644190 [37mLOG    [00m [00m             basesrc gstbasesrc.c:658:gst_base_src_query_latency:<src>[00m latency: live 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.014831708 [333m30506[00m       0x643d40 [37mLOG    [00m [00m            basesink gstbasesink.c:2028:gst_base_sink_get_sync_times:<sink>[00m not time format, don't clip
0:00:00.014883119 [333m30506[00m       0x644190 [37mLOG    [00m [00m             basesrc gstbasesrc.c:1078:gst_base_src_default_query:<src>[00m report latency: live 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.014929620 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2344:gst_base_sink_do_preroll:<sink>[00m prerolling object 0x64b020
0:00:00.014979812 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1134:gst_base_src_default_query:<src>[00m query latency returns 1
0:00:00.015020691 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3178:gst_base_sink_preroll_object:<sink>[00m prerolling object 0x64b020
0:00:00.015160890 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2277:gst_base_sink_wait_preroll:<sink>[00m waiting in preroll for flush or PLAYING
0:00:00.015078918 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1197:gst_base_sink_query_latency:<sink>[00m latency query: live: 0, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.015258625 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4947:default_element_query:<sink>[00m query latency returns 1
0:00:00.015310416 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4488:gst_base_sink_send_event:<sink>[00m handling event 0x64f050 latency event from '(NULL)' at time 99:99:99.999999999: GstEventLatency, latency=(guint64)0;
0:00:00.015369384 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4505:gst_base_sink_send_event:<sink>[00m latency set to 0:00:00.000000000
0:00:00.015477221 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1747:gst_base_src_default_event:<src>[00m handle event latency event from 'sink' at time 99:99:99.999999999: GstEventLatency, latency=(guint64)0;
0:00:00.015521577 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1819:gst_base_src_event_handler:<src>[00m subclass refused event
0:00:00.015549777 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4535:gst_base_sink_send_event:<sink>[00m handled event 0x64f050 latency event from 'sink' at time 99:99:99.999999999: GstEventLatency, latency=(guint64)0;: 0
0:00:00.015600342 [333m30506[00m       0x644190 [33;01mWARN   [00m [00;01m                 bin gstbin.c:2395:gst_bin_do_latency_func:<pipeline>[00m did not really configure latency of 0:00:00.000000000
0:00:00.015664207 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3592:gst_base_sink_needs_preroll:<sink>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.015695037 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5041:gst_base_sink_change_state:<sink>[00m PAUSED to PLAYING, don't need preroll
0:00:00.015721410 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5054:gst_base_sink_change_state:<sink>[00m signal preroll
0:00:00.015807763 [333m30506[00m       0x644190 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:3130:gst_base_src_change_state:<src>[00m PAUSED->PLAYING
0:00:00.015821433 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2285:gst_base_sink_wait_preroll:<sink>[00m continue after preroll
0:00:00.015931120 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2568:gst_base_sink_do_sync:<sink>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.015969715 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2240:gst_base_sink_wait_clock:<sink>[00m sync disabled
0:00:00.015991150 [333m30506[00m       0x62e120 [32;01mINFO   [00m [00m               check libs/basesrc.c:554:basesrc_seek_events_rate_update:[00m seeking
0:00:00.016000841 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2575:gst_base_sink_do_sync:<sink>[00m clock returned 4, jitter  0:00:00.000000000
0:00:00.016138923 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2999:gst_base_sink_render_object:<sink>[00m rendering object 0x64b020
0:00:00.016228761 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x64b020
0:00:00.016078022 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4488:gst_base_sink_send_event:<sink>[00m handling event 0x643ca0 seek event from '(NULL)' at time 99:99:99.999999999: GstEventSeek, rate=(double)0.5, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_NONE, cur-type=(GstSeekType)GST_SEEK_TYPE_NONE, cur=(gint64)-1, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;
0:00:00.016282181 [333m30506[00m       0x643d40 [37mLOG    [00m [00m             basesrc gstbasesrc.c:2443:gst_base_src_loop:<src>[00m next_ts 0:00:00.000000000 size 4096
0:00:00.016376768 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2088:gst_base_src_update_length:<src>[00m reading offset 0, length 4096, size -1, segment.stop -1, maxsize -1
0:00:00.016413180 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2091:gst_base_src_update_length:<src>[00m dynamic size: 0
0:00:00.016474822 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2186:gst_base_src_get_range:<src>[00m calling create offset 0 length 4096, time 0
0:00:00.016471068 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1747:gst_base_src_default_event:<src>[00m handle event seek event from 'sink' at time 99:99:99.999999999: GstEventSeek, rate=(double)0.5, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_NONE, cur-type=(GstSeekType)GST_SEEK_TYPE_NONE, cur=(gint64)-1, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;
0:00:00.016539890 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2051:gst_base_src_do_sync:<src>[00m no sync needed
0:00:00.016565571 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1343:gst_base_src_perform_seek:<src>[00m doing seek: seek event from 'sink' at time 99:99:99.999999999: GstEventSeek, rate=(double)0.5, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_NONE, cur-type=(GstSeekType)GST_SEEK_TYPE_NONE, cur=(gint64)-1, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;
0:00:00.016606987 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2231:gst_base_src_get_range:<src>[00m buffer ok
0:00:00.016696042 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3665:gst_base_sink_chain_unlocked:<sink>[00m got times start: 0:00:00.000000000, end: 99:99:99.999999999
0:00:00.016731125 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2017:gst_base_sink_get_sync_times:<sink>[00m got times start: 0:00:00.000000000, stop: 99:99:99.999999999, do_sync 1
0:00:00.016788988 [333m30506[00m       0x643d40 [37mLOG    [00m [00m            basesink gstbasesink.c:2028:gst_base_sink_get_sync_times:<sink>[00m not time format, don't clip
0:00:00.016818165 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2568:gst_base_sink_do_sync:<sink>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.016849392 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2240:gst_base_sink_wait_clock:<sink>[00m sync disabled
0:00:00.016875653 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2575:gst_base_sink_do_sync:<sink>[00m clock returned 4, jitter  0:00:00.000000000
0:00:00.016905188 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2999:gst_base_sink_render_object:<sink>[00m rendering object 0x64b0c0
0:00:00.016931931 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1016:gst_base_sink_set_last_buffer_unlocked:<sink>[00m setting last buffer to 0x64b0c0
0:00:00.016984309 [333m30506[00m       0x643d40 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x64b0c0
0:00:00.017083959 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1398:gst_base_src_perform_seek:<src>[00m seek with seqnum 2
0:00:00.017199318 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1434:gst_base_src_perform_seek:<src>[00m segment configured from 0 to -1, position 0
0:00:00.017234574 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1451:gst_base_src_perform_seek:<src>[00m closing running segment 0 to 0
0:00:00.017287016 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:1497:gst_base_src_perform_seek:<src>[00m Sending newsegment from 0 to -1
0:00:00.017347124 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4535:gst_base_sink_send_event:<sink>[00m handled event 0x643ca0 seek event from 'sink' at time 99:99:99.999999999: GstEventSeek, rate=(double)0.5, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_NONE, cur-type=(GstSeekType)GST_SEEK_TYPE_NONE, cur=(gint64)-1, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;: 1
0:00:00.018600501 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:3147:gst_base_src_change_state:<src>[00m PLAYING->PAUSED
0:00:00.018706139 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:3020:gst_base_src_activate_push:<src>[00m Deactivating in push mode
0:00:00.018870762 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:2854:gst_base_src_stop:<src>[00m stopping source
0:00:00.018973524 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m             basesrc gstbasesrc.c:3165:gst_base_src_change_state:<src>[00m Sending EOS event
0:00:00.019074393 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3439:gst_base_sink_event:<sink>[00m received event 0x643e30 eos event from 'src' at time 99:99:99.999999999: (NULL)
0:00:00.019154315 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1976:gst_base_sink_get_sync_times:<sink>[00m sync times for EOS 0:00:00.000000000
0:00:00.019191861 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2568:gst_base_sink_do_sync:<sink>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.019224306 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2240:gst_base_sink_wait_clock:<sink>[00m sync disabled
0:00:00.019275783 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:2575:gst_base_sink_do_sync:<sink>[00m clock returned 4, jitter  0:00:00.000000000
0:00:00.019307128 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3044:gst_base_sink_render_object:<sink>[00m rendering event 0x643e30, type eos
0:00:00.019353920 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3058:gst_base_sink_render_object:<sink>[00m Got seqnum #2
0:00:00.019382596 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3074:gst_base_sink_render_object:<sink>[00m Now posting EOS
0:00:00.019436205 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3113:gst_base_sink_render_object:<sink>[00m object unref after render 0x643e30
0:00:00.019914534 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5093:gst_base_sink_change_state:<sink>[00m PLAYING to PAUSED
0:00:00.019945463 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5102:gst_base_sink_change_state:<sink>[00m got preroll lock
0:00:00.019972238 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:3592:gst_base_sink_needs_preroll:<sink>[00m have_preroll: 0, EOS: 1 => needs preroll: 0
0:00:00.020000366 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5120:gst_base_sink_change_state:<sink>[00m PLAYING to PAUSED, we are prerolled
0:00:00.020026433 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5142:gst_base_sink_change_state:<sink>[00m rendered: 2, dropped: 0
0:00:00.020137904 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:4206:gst_base_sink_set_flushing:<sink>[00m flushing out data thread, need preroll to TRUE
0:00:00.020182911 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1488:gst_base_sink_preroll_queue_flush:<sink>[00m flushing queue 0x641410
0:00:00.020219964 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:1016:gst_base_sink_set_last_buffer_unlocked:<sink>[00m setting last buffer to (nil)
0:00:00.020261397 [333m30506[00m       0x62e120 [36mDEBUG  [00m [00m            basesink gstbasesink.c:5179:gst_base_sink_change_state:<sink>[00m PAUSED to READY, don't need_preroll
0:00:00.020401108 [333m30506[00m       0x62e120 [32;01mINFO   [00m [00m               check libs/basesrc.c:579:basesrc_seek_events_rate_update:[00m stopped
0%: Checks: 1, Failures: 1, Errors: 0
libs/basesrc.c:586:F:general:basesrc_seek_events_rate_update:0: Assertion 'rate == 0.5' failed
