0:00:00.011045898 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:720:gst_stream_synchronizer_request_new_pad:<streamsync>[00m Requesting new pad for stream 0
0:00:00.011548319 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:720:gst_stream_synchronizer_request_new_pad:<streamsync>[00m Requesting new pad for stream 1
0:00:00.011937833 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:872:gst_stream_synchronizer_change_state:<streamsync>[00m State change NULL->READY
0:00:00.011964687 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.012022940 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4921:gst_base_sink_change_state:<fakesink1>[00m READY to PAUSED
0:00:00.012039873 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4942:gst_base_sink_change_state:<fakesink1>[00m doing async state change
0:00:00.012057278 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4082:gst_base_sink_pad_activate:<fakesink1>[00m Trying pull mode first
0:00:00.012066356 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4088:gst_base_sink_pad_activate:<fakesink1>[00m pull mode disabled
0:00:00.012073310 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4138:gst_base_sink_pad_activate:<fakesink1>[00m Falling back to push mode
0:00:00.012084707 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4140:gst_base_sink_pad_activate:<fakesink1>[00m Success activating push mode
0:00:00.012099909 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4921:gst_base_sink_change_state:<fakesink0>[00m READY to PAUSED
0:00:00.012108533 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4942:gst_base_sink_change_state:<fakesink0>[00m doing async state change
0:00:00.012120697 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4082:gst_base_sink_pad_activate:<fakesink0>[00m Trying pull mode first
0:00:00.012129666 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4088:gst_base_sink_pad_activate:<fakesink0>[00m pull mode disabled
0:00:00.012136335 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4138:gst_base_sink_pad_activate:<fakesink0>[00m Falling back to push mode
0:00:00.012143807 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4140:gst_base_sink_pad_activate:<fakesink0>[00m Success activating push mode
0:00:00.012158267 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:877:gst_stream_synchronizer_change_state:<streamsync>[00m State change READY->PAUSED
0:00:00.012171427 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.013012790 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event stream-start: stream-start event: 0x7eb5f0, time 99:99:99.999999999, seq-num 31, GstEventStreamStart, stream-id=(string)52a9ed4bb314fb5f23ca703edfdde824, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.013040653 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event stream-start: stream-start event: 0x7fafe0003970, time 99:99:99.999999999, seq-num 32, GstEventStreamStart, stream-id=(string)3634599866ba497200e34bc8fb57fdfe, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.013171521 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:337:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Stream 0 changed
0:00:00.013241720 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:337:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Stream 1 changed
0:00:00.013261502 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:357:gst_stream_synchronizer_sink_event:<streamsync>[00m All streams have changed to group id 0 -- unblocking
0:00:00.013277469 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:386:gst_stream_synchronizer_sink_event:<streamsync>[00m New group start time: 0:00:00.000000000
0:00:00.013257177 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7eb5f0 stream-start event: 0x7eb5f0, time 99:99:99.999999999, seq-num 31, GstEventStreamStart, stream-id=(string)52a9ed4bb314fb5f23ca703edfdde824, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.013317312 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3056:gst_base_sink_default_event:<fakesink0>[00m Now posting STREAM_START (seqnum:31)
0:00:00.013317557 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe0003970 stream-start event: 0x7fafe0003970, time 99:99:99.999999999, seq-num 32, GstEventStreamStart, stream-id=(string)3634599866ba497200e34bc8fb57fdfe, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.013350843 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3056:gst_base_sink_default_event:<fakesink1>[00m Now posting STREAM_START (seqnum:32)
0:00:00.013515510 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink1>[00m Checking if requested caps audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)1 are a subset of pad caps ANY result 1
0:00:00.013520944 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink0>[00m Checking if requested caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive are a subset of pad caps ANY result 1
0:00:00.013569222 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event caps: caps event: 0x7fafe00039e0, time 99:99:99.999999999, seq-num 37, GstEventCaps, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)1";
0:00:00.013582884 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event caps: caps event: 0x7eb660, time 99:99:99.999999999, seq-num 38, GstEventCaps, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive";
0:00:00.013619299 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink1>[00m Checking if requested caps audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)1 are a subset of pad caps ANY result 1
0:00:00.013632829 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink0>[00m Checking if requested caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive are a subset of pad caps ANY result 1
0:00:00.013648974 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe00039e0 caps event: 0x7fafe00039e0, time 99:99:99.999999999, seq-num 37, GstEventCaps, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)1";
0:00:00.013699399 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3073:gst_base_sink_default_event:<fakesink1>[00m caps 0x7fafe00039e0
0:00:00.013686211 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7eb660 caps event: 0x7eb660, time 99:99:99.999999999, seq-num 38, GstEventCaps, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive";
0:00:00.013733668 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3073:gst_base_sink_default_event:<fakesink0>[00m caps 0x7eb660
0:00:00.014016413 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event segment: segment event: 0x7fafe0003ac0, time 99:99:99.999999999, seq-num 26, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.014136656 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:226:gst_stream_synchronizer_wait:<streamsync:sink_1>[00m Stream not waiting anymore
0:00:00.014151440 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:423:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Segment was: UNDEFINED segment
0:00:00.014166708 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:426:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Segment now is: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.014192187 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:430:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Stream start running time: 0:00:00.000000000
0:00:00.014220108 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe0003b30 segment event: 0x7fafe0003b30, time 99:99:99.999999999, seq-num 26, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.014282468 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3105:gst_base_sink_default_event:<fakesink1>[00m configured segment time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.014330331 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event tag: tag event: 0x7fafe0003a50, time 99:99:99.999999999, seq-num 39, GstTagList-stream, taglist=(taglist)"taglist\,\ description\=\(string\)\"audiotest\\\ wave\"\;";
0:00:00.014362306 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe0003a50 tag event: 0x7fafe0003a50, time 99:99:99.999999999, seq-num 39, GstTagList-stream, taglist=(taglist)"taglist\,\ description\=\(string\)\"audiotest\\\ wave\"\;";
0:00:00.014423222 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:610:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Handling buffer 0x7fafd80060b0: size=2048, timestamp=0:00:00.000000000 duration=0:00:00.023219954 offset=0 offset_end=1024
0:00:00.014449354 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:627:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Updating position from 0:00:00.000000000 to 0:00:00.000000000
0:00:00.014468661 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3342:gst_base_sink_chain_unlocked:<fakesink1>[00m got times start: 0:00:00.000000000, end: 0:00:00.023219954
0:00:00.014487014 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink1>[00m got times start: 0:00:00.000000000, stop: 0:00:00.023219954, do_sync 1
0:00:00.014506110 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink1>[00m prerolling object 0x7fafd80060b0
0:00:00.014518731 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink1>[00m setting last buffer to 0x7fafd80060b0
0:00:00.014530479 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink1>[00m preroll buffer 0:00:00.000000000
0:00:00.014544734 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink1>[00m commiting state to PAUSED
0:00:00.014554979 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink1>[00m posting PAUSED state change message
0:00:00.014573877 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink1>[00m posting async-done message
0:00:00.014591974 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink1>[00m waiting in preroll for flush or PLAYING
0:00:00.014916884 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event segment: segment event: 0x7eb6d0, time 99:99:99.999999999, seq-num 22, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.014973507 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:226:gst_stream_synchronizer_wait:<streamsync:sink_0>[00m Stream not waiting anymore
0:00:00.014981405 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:423:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Segment was: UNDEFINED segment
0:00:00.014996734 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:426:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Segment now is: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.015011682 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:430:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Stream start running time: 0:00:00.000000000
0:00:00.015027161 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7eb740 segment event: 0x7eb740, time 99:99:99.999999999, seq-num 22, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.015065613 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3105:gst_base_sink_default_event:<fakesink0>[00m configured segment time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.015085020 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:610:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Handling buffer 0x7fafd8006710: size=115200, timestamp=0:00:00.000000000 duration=0:00:00.033333333 offset=0 offset_end=1
0:00:00.015098515 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:627:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Updating position from 0:00:00.000000000 to 0:00:00.000000000
0:00:00.015110072 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3342:gst_base_sink_chain_unlocked:<fakesink0>[00m got times start: 0:00:00.000000000, end: 0:00:00.033333333
0:00:00.015120563 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink0>[00m got times start: 0:00:00.000000000, stop: 0:00:00.033333333, do_sync 1
0:00:00.015131543 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink0>[00m prerolling object 0x7fafd8006710
0:00:00.015139245 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink0>[00m setting last buffer to 0x7fafd8006710
0:00:00.015146831 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink0>[00m preroll buffer 0:00:00.000000000
0:00:00.015155570 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink0>[00m commiting state to PAUSED
0:00:00.015162096 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink0>[00m posting PAUSED state change message
0:00:00.015177898 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink0>[00m posting async-done message
0:00:00.015546239 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink0>[00m waiting in preroll for flush or PLAYING
0:00:00.015743415 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink1>[00m we are ready for LATENCY query
0:00:00.015782795 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink1>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.015801237 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink1>[00m query latency returns 1
0:00:00.015813719 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink0>[00m we are ready for LATENCY query
0:00:00.015830356 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink0>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.015843912 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink0>[00m query latency returns 1
0:00:00.015864016 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink1>[00m handling event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;
0:00:00.015883588 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink1>[00m latency set to 0:00:00.000000000
0:00:00.015896623 [336m20693[00m 0x7fafe0003000 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_1>[00m Handling event latency: latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;
0:00:00.015917526 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink1>[00m handled event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;: 1
0:00:00.015933947 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink0>[00m handling event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;
0:00:00.015946723 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink0>[00m latency set to 0:00:00.000000000
0:00:00.015956998 [336m20693[00m 0x7fafe0003000 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_0>[00m Handling event latency: latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;
0:00:00.015972785 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink0>[00m handled event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;: 1
0:00:00.016013058 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.016024524 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink1>[00m PAUSED to PLAYING, don't need preroll
0:00:00.016031938 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink1>[00m signal preroll
0:00:00.016052708 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink1>[00m continue after preroll
0:00:00.016054621 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.016076080 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink0>[00m PAUSED to PLAYING, don't need preroll
0:00:00.016083858 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink0>[00m signal preroll
0:00:00.016079665 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2474:gst_base_sink_do_sync:<fakesink1>[00m reset rc_time to time 0:00:00.000000000
0:00:00.016104034 [336m20693[00m 0x7fafe0003000 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.016101666 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink0>[00m continue after preroll
0:00:00.016112477 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2486:gst_base_sink_do_sync:<fakesink1>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.016133553 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2474:gst_base_sink_do_sync:<fakesink0>[00m reset rc_time to time 0:00:00.000000000
0:00:00.016147892 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m            basesink gstbasesink.c:2072:gst_base_sink_wait_clock:<fakesink1>[00m time 0:00:00.000000000, base_time 0:15:23.092741105
0:00:00.016158195 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2486:gst_base_sink_do_sync:<fakesink0>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.016174494 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2493:gst_base_sink_do_sync:<fakesink1>[00m clock returned 1, jitter  0:00:00.000482253
0:00:00.016178290 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m            basesink gstbasesink.c:2072:gst_base_sink_wait_clock:<fakesink0>[00m time 0:00:00.000000000, base_time 0:15:23.092741105
0:00:00.016196124 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2817:gst_base_sink_is_too_late:<fakesink1>[00m frame dropping disabled
0:00:00.016216896 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2493:gst_base_sink_do_sync:<fakesink0>[00m clock returned 1, jitter  0:00:00.000524830
0:00:00.016224500 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3424:gst_base_sink_chain_unlocked:<fakesink1>[00m rendering object 0x7fafd80060b0
0:00:00.016245616 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2817:gst_base_sink_is_too_late:<fakesink0>[00m frame dropping disabled
0:00:00.016244334 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3463:gst_base_sink_chain_unlocked:<fakesink1>[00m object unref after render 0x7fafd80060b0
0:00:00.016263751 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3424:gst_base_sink_chain_unlocked:<fakesink0>[00m rendering object 0x7fafd8006710
0:00:00.016265752 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED
0:00:00.016284936 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3463:gst_base_sink_chain_unlocked:<fakesink0>[00m object unref after render 0x7fafd8006710
0:00:00.016289296 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink1>[00m got preroll lock
0:00:00.016303389 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:642:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Push returned: ok
0:00:00.016290536 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:642:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Push returned: ok
0:00:00.016351355 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:659:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Updating position from 0:00:00.000000000 to 0:00:00.033333333
0:00:00.016337549 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 0, EOS: 0 => needs preroll: 1
0:00:00.016382636 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:659:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Updating position from 0:00:00.000000000 to 0:00:00.023219954
0:00:00.016419046 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5044:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED, we are not prerolled
0:00:00.016444232 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5049:gst_base_sink_change_state:<fakesink1>[00m doing async state change
0:00:00.016458672 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink1>[00m rendered: 1, dropped: 0
0:00:00.016478786 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED
0:00:00.016486704 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink0>[00m got preroll lock
0:00:00.016493300 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 0, EOS: 0 => needs preroll: 1
0:00:00.016502543 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5044:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED, we are not prerolled
0:00:00.016509342 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5049:gst_base_sink_change_state:<fakesink0>[00m doing async state change
0:00:00.016517345 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink0>[00m rendered: 1, dropped: 0
0:00:00.016531180 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.016523352 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:610:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Handling buffer 0x7fafd80061c0: size=2048, timestamp=0:00:00.023219954 duration=0:00:00.023219955 offset=1024 offset_end=2048
0:00:00.016542336 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:912:gst_stream_synchronizer_change_state:<streamsync>[00m State change PLAYING->PAUSED
0:00:00.016560029 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:627:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Updating position from 0:00:00.023219954 to 0:00:00.023219954
0:00:00.016585116 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3342:gst_base_sink_chain_unlocked:<fakesink1>[00m got times start: 0:00:00.023219954, end: 0:00:00.046439909
0:00:00.016612972 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink1>[00m got times start: 0:00:00.023219954, stop: 0:00:00.046439909, do_sync 1
0:00:00.016633650 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink1>[00m prerolling object 0x7fafd80061c0
0:00:00.016646487 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink1>[00m setting last buffer to 0x7fafd80061c0
0:00:00.016660983 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink1>[00m preroll buffer 0:00:00.023219954
0:00:00.016675210 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink1>[00m commiting state to PAUSED
0:00:00.016685046 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink1>[00m posting PAUSED state change message
0:00:00.016706859 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink1>[00m posting async-done message
0:00:00.016723896 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink1>[00m waiting in preroll for flush or PLAYING
0:00:00.017145558 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:610:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Handling buffer 0x7fafd8006820: size=115200, timestamp=0:00:00.033333333 duration=0:00:00.033333333 offset=1 offset_end=2
0:00:00.017169787 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:627:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Updating position from 0:00:00.033333333 to 0:00:00.033333333
0:00:00.017182185 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3342:gst_base_sink_chain_unlocked:<fakesink0>[00m got times start: 0:00:00.033333333, end: 0:00:00.066666666
0:00:00.017193358 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink0>[00m got times start: 0:00:00.033333333, stop: 0:00:00.066666666, do_sync 1
0:00:00.017204861 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink0>[00m prerolling object 0x7fafd8006820
0:00:00.017212831 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink0>[00m setting last buffer to 0x7fafd8006820
0:00:00.017222395 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink0>[00m preroll buffer 0:00:00.033333333
0:00:00.017231656 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink0>[00m commiting state to PAUSED
0:00:00.017238248 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink0>[00m posting PAUSED state change message
0:00:00.017254578 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink0>[00m posting async-done message
0:00:00.017274349 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink0>[00m waiting in preroll for flush or PLAYING
0:00:00.017297808 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink1>[00m we are ready for LATENCY query
0:00:00.017327079 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink1>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.017343529 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink1>[00m query latency returns 1
0:00:00.017355008 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink0>[00m we are ready for LATENCY query
0:00:00.017369706 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink0>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.017382878 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink0>[00m query latency returns 1
0:00:00.017399008 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink1>[00m handling event 0x7eb510 latency event: 0x7eb510, time 99:99:99.999999999, seq-num 72, GstEventLatency, latency=(guint64)0;
0:00:00.017414674 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink1>[00m latency set to 0:00:00.000000000
0:00:00.017425441 [336m20693[00m       0x7eb900 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_1>[00m Handling event latency: latency event: 0x7eb510, time 99:99:99.999999999, seq-num 72, GstEventLatency, latency=(guint64)0;
0:00:00.017442560 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink1>[00m handled event 0x7eb510 latency event: 0x7eb510, time 99:99:99.999999999, seq-num 72, GstEventLatency, latency=(guint64)0;: 1
0:00:00.017457933 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink0>[00m handling event 0x7eb510 latency event: 0x7eb510, time 99:99:99.999999999, seq-num 72, GstEventLatency, latency=(guint64)0;
0:00:00.017469518 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink0>[00m latency set to 0:00:00.000000000
0:00:00.017479291 [336m20693[00m       0x7eb900 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_0>[00m Handling event latency: latency event: 0x7eb510, time 99:99:99.999999999, seq-num 72, GstEventLatency, latency=(guint64)0;
0:00:00.017494186 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink0>[00m handled event 0x7eb510 latency event: 0x7eb510, time 99:99:99.999999999, seq-num 72, GstEventLatency, latency=(guint64)0;: 1
0:00:00.017521060 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.017530938 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink1>[00m PAUSED to PLAYING, don't need preroll
0:00:00.017538111 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink1>[00m signal preroll
0:00:00.017552518 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink1>[00m continue after preroll
0:00:00.017558921 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.017563139 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2474:gst_base_sink_do_sync:<fakesink1>[00m reset rc_time to time 0:00:00.023219954
0:00:00.017579594 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink0>[00m PAUSED to PLAYING, don't need preroll
0:00:00.017592728 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2486:gst_base_sink_do_sync:<fakesink1>[00m possibly waiting for clock to reach 0:00:00.023219954, adjusted 0:00:00.023219954
0:00:00.017603847 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink0>[00m signal preroll
0:00:00.017614395 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m            basesink gstbasesink.c:2072:gst_base_sink_wait_clock:<fakesink1>[00m time 0:00:00.023219954, base_time 0:15:23.093421292
0:00:00.017631714 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink0>[00m continue after preroll
0:00:00.017635177 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.017648062 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2474:gst_base_sink_do_sync:<fakesink0>[00m reset rc_time to time 0:00:00.033333333
0:00:00.017667598 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2486:gst_base_sink_do_sync:<fakesink0>[00m possibly waiting for clock to reach 0:00:00.033333333, adjusted 0:00:00.033333333
0:00:00.017679439 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m            basesink gstbasesink.c:2072:gst_base_sink_wait_clock:<fakesink0>[00m time 0:00:00.033333333, base_time 0:15:23.093421292
0:00:00.017702494 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED
0:00:00.017711348 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink1>[00m got preroll lock
0:00:00.017718151 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5029:gst_base_sink_change_state:<fakesink1>[00m unschedule clock
0:00:00.017731107 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 0, EOS: 0 => needs preroll: 1
0:00:00.017740561 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5044:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED, we are not prerolled
0:00:00.017747641 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5049:gst_base_sink_change_state:<fakesink1>[00m doing async state change
0:00:00.017755967 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink1>[00m rendered: 0, dropped: 0
0:00:00.017770599 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED
0:00:00.017769901 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2493:gst_base_sink_do_sync:<fakesink1>[00m clock returned 2, jitter -0:00:00.021954326
0:00:00.017780263 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink0>[00m got preroll lock
0:00:00.017793023 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2506:gst_base_sink_do_sync:<fakesink1>[00m unscheduled, waiting some more
0:00:00.017804550 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5029:gst_base_sink_change_state:<fakesink0>[00m unschedule clock
0:00:00.017815732 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink1>[00m prerolling object 0x7fafd80061c0
0:00:00.017838435 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 0, EOS: 0 => needs preroll: 1
0:00:00.017848234 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink1>[00m preroll buffer 0:00:00.023219954
0:00:00.017855337 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5044:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED, we are not prerolled
0:00:00.017863686 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink1>[00m commiting state to PAUSED
0:00:00.017874826 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5049:gst_base_sink_change_state:<fakesink0>[00m doing async state change
0:00:00.017886242 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink1>[00m posting PAUSED state change message
0:00:00.017899100 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink0>[00m rendered: 0, dropped: 0
0:00:00.017911024 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink1>[00m posting async-done message
0:00:00.017924544 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.017933261 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink1>[00m waiting in preroll for flush or PLAYING
0:00:00.017923627 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2493:gst_base_sink_do_sync:<fakesink0>[00m clock returned 2, jitter -0:00:00.032011140
0:00:00.017937397 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:912:gst_stream_synchronizer_change_state:<streamsync>[00m State change PLAYING->PAUSED
0:00:00.017965557 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2506:gst_base_sink_do_sync:<fakesink0>[00m unscheduled, waiting some more
0:00:00.017985843 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink0>[00m prerolling object 0x7fafd8006820
0:00:00.017994196 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink0>[00m preroll buffer 0:00:00.033333333
0:00:00.018003648 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink0>[00m commiting state to PAUSED
0:00:00.018012553 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink0>[00m posting PAUSED state change message
0:00:00.018006620 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4034:gst_base_sink_set_flushing:<fakesink1>[00m flushing out data thread, need preroll to TRUE
0:00:00.018026637 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink0>[00m posting async-done message
0:00:00.018040634 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2168:gst_base_sink_wait_preroll:<fakesink1>[00m preroll interrupted because of flush
0:00:00.018054968 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink0>[00m waiting in preroll for flush or PLAYING
0:00:00.018073752 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2272:gst_base_sink_do_preroll:<fakesink1>[00m preroll failed: flushing
0:00:00.018099447 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2546:gst_base_sink_do_sync:<fakesink1>[00m preroll failed
0:00:00.018107091 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3496:gst_base_sink_chain_unlocked:<fakesink1>[00m do_sync returned flushing
0:00:00.018114925 [336m20693[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3463:gst_base_sink_chain_unlocked:<fakesink1>[00m object unref after render 0x7fafd80061c0
0:00:00.018126227 [336m20693[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:642:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Push returned: flushing
0:00:00.018136546 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink1>[00m setting last buffer to (nil)
0:00:00.018149625 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5096:gst_base_sink_change_state:<fakesink1>[00m PAUSED to READY, don't need_preroll
0:00:00.018167028 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4034:gst_base_sink_set_flushing:<fakesink0>[00m flushing out data thread, need preroll to TRUE
0:00:00.018180964 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2168:gst_base_sink_wait_preroll:<fakesink0>[00m preroll interrupted because of flush
0:00:00.018191473 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2272:gst_base_sink_do_preroll:<fakesink0>[00m preroll failed: flushing
0:00:00.018199555 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2546:gst_base_sink_do_sync:<fakesink0>[00m preroll failed
0:00:00.018206280 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3496:gst_base_sink_chain_unlocked:<fakesink0>[00m do_sync returned flushing
0:00:00.018213721 [336m20693[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3463:gst_base_sink_chain_unlocked:<fakesink0>[00m object unref after render 0x7fafd8006820
0:00:00.018224711 [336m20693[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:642:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Push returned: flushing
0:00:00.018232269 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink0>[00m setting last buffer to (nil)
0:00:00.018243401 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5096:gst_base_sink_change_state:<fakesink0>[00m PAUSED to READY, don't need_preroll
0:00:00.018258643 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:888:gst_stream_synchronizer_change_state:<streamsync>[00m State change PAUSED->READY
0:00:00.018282708 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.018291468 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:932:gst_stream_synchronizer_change_state:<streamsync>[00m State change PAUSED->READY
0:00:00.018430590 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.018448739 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:952:gst_stream_synchronizer_change_state:<streamsync>[00m State change READY->NULL
0:00:00.018543170 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:783:gst_stream_synchronizer_release_stream:<streamsync>[00m Releasing stream 0
0:00:00.018562090 [336m20693[00m       0x7eb900 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:783:gst_stream_synchronizer_release_stream:<streamsync>[00m Releasing stream 1
0:00:00.022624501 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:720:gst_stream_synchronizer_request_new_pad:<streamsync>[00m Requesting new pad for stream 0
0:00:00.022756471 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:720:gst_stream_synchronizer_request_new_pad:<streamsync>[00m Requesting new pad for stream 1
0:00:00.022924980 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:872:gst_stream_synchronizer_change_state:<streamsync>[00m State change NULL->READY
0:00:00.022935770 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.023004302 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4921:gst_base_sink_change_state:<fakesink1>[00m READY to PAUSED
0:00:00.023017080 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4942:gst_base_sink_change_state:<fakesink1>[00m doing async state change
0:00:00.023028740 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4082:gst_base_sink_pad_activate:<fakesink1>[00m Trying pull mode first
0:00:00.023036096 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4088:gst_base_sink_pad_activate:<fakesink1>[00m pull mode disabled
0:00:00.023042477 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4138:gst_base_sink_pad_activate:<fakesink1>[00m Falling back to push mode
0:00:00.023050116 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4140:gst_base_sink_pad_activate:<fakesink1>[00m Success activating push mode
0:00:00.023061481 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4921:gst_base_sink_change_state:<fakesink0>[00m READY to PAUSED
0:00:00.023068705 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4942:gst_base_sink_change_state:<fakesink0>[00m doing async state change
0:00:00.023078104 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4082:gst_base_sink_pad_activate:<fakesink0>[00m Trying pull mode first
0:00:00.023084874 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4088:gst_base_sink_pad_activate:<fakesink0>[00m pull mode disabled
0:00:00.023091226 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4138:gst_base_sink_pad_activate:<fakesink0>[00m Falling back to push mode
0:00:00.023098240 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4140:gst_base_sink_pad_activate:<fakesink0>[00m Success activating push mode
0:00:00.023109553 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:877:gst_stream_synchronizer_change_state:<streamsync>[00m State change READY->PAUSED
0:00:00.023120320 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.023469535 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event stream-start: stream-start event: 0x7eb9f0, time 99:99:99.999999999, seq-num 31, GstEventStreamStart, stream-id=(string)fe0955e3f11d9ee4789d008e15617264, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.023488368 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event stream-start: stream-start event: 0x7fafe0004570, time 99:99:99.999999999, seq-num 32, GstEventStreamStart, stream-id=(string)755e0f280c85e0c35b91c4239c196801, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.023540158 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:337:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Stream 0 changed
0:00:00.023572962 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:337:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Stream 1 changed
0:00:00.023589669 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:357:gst_stream_synchronizer_sink_event:<streamsync>[00m All streams have changed to group id 0 -- unblocking
0:00:00.023582262 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7eb9f0 stream-start event: 0x7eb9f0, time 99:99:99.999999999, seq-num 31, GstEventStreamStart, stream-id=(string)fe0955e3f11d9ee4789d008e15617264, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.023607457 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:386:gst_stream_synchronizer_sink_event:<streamsync>[00m New group start time: 0:00:00.000000000
0:00:00.023624551 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3056:gst_base_sink_default_event:<fakesink0>[00m Now posting STREAM_START (seqnum:31)
0:00:00.023651037 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe0004570 stream-start event: 0x7fafe0004570, time 99:99:99.999999999, seq-num 32, GstEventStreamStart, stream-id=(string)755e0f280c85e0c35b91c4239c196801, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.023683010 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3056:gst_base_sink_default_event:<fakesink1>[00m Now posting STREAM_START (seqnum:32)
0:00:00.023773129 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink1>[00m Checking if requested caps audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)1 are a subset of pad caps ANY result 1
0:00:00.023767824 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink0>[00m Checking if requested caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive are a subset of pad caps ANY result 1
0:00:00.023811585 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event caps: caps event: 0x7fafe00045e0, time 99:99:99.999999999, seq-num 38, GstEventCaps, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)1";
0:00:00.023823187 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event caps: caps event: 0x7eba60, time 99:99:99.999999999, seq-num 37, GstEventCaps, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive";
0:00:00.023860663 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink1>[00m Checking if requested caps audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)1 are a subset of pad caps ANY result 1
0:00:00.023878751 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink0>[00m Checking if requested caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive are a subset of pad caps ANY result 1
0:00:00.023888725 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe00045e0 caps event: 0x7fafe00045e0, time 99:99:99.999999999, seq-num 38, GstEventCaps, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)1";
0:00:00.023918620 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3073:gst_base_sink_default_event:<fakesink1>[00m caps 0x7fafe00045e0
0:00:00.023907594 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7eba60 caps event: 0x7eba60, time 99:99:99.999999999, seq-num 37, GstEventCaps, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive";
0:00:00.023946816 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3073:gst_base_sink_default_event:<fakesink0>[00m caps 0x7eba60
0:00:00.024117364 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event segment: segment event: 0x7fafe00046c0, time 99:99:99.999999999, seq-num 26, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.024190430 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:226:gst_stream_synchronizer_wait:<streamsync:sink_1>[00m Stream not waiting anymore
0:00:00.024202277 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:423:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Segment was: UNDEFINED segment
0:00:00.024215492 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:426:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Segment now is: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.024237381 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:430:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Stream start running time: 0:00:00.000000000
0:00:00.024260267 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe0004730 segment event: 0x7fafe0004730, time 99:99:99.999999999, seq-num 26, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.024320794 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3105:gst_base_sink_default_event:<fakesink1>[00m configured segment time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.024352155 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event tag: tag event: 0x7fafe0004650, time 99:99:99.999999999, seq-num 39, GstTagList-stream, taglist=(taglist)"taglist\,\ description\=\(string\)\"audiotest\\\ wave\"\;";
0:00:00.024380193 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe0004650 tag event: 0x7fafe0004650, time 99:99:99.999999999, seq-num 39, GstTagList-stream, taglist=(taglist)"taglist\,\ description\=\(string\)\"audiotest\\\ wave\"\;";
0:00:00.024422105 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:610:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Handling buffer 0x7fafd80050b0: size=2048, timestamp=0:00:00.000000000 duration=0:00:00.023219954 offset=0 offset_end=1024
0:00:00.024446308 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:627:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Updating position from 0:00:00.000000000 to 0:00:00.000000000
0:00:00.024467116 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3342:gst_base_sink_chain_unlocked:<fakesink1>[00m got times start: 0:00:00.000000000, end: 0:00:00.023219954
0:00:00.024485737 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink1>[00m got times start: 0:00:00.000000000, stop: 0:00:00.023219954, do_sync 1
0:00:00.024505762 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink1>[00m prerolling object 0x7fafd80050b0
0:00:00.024518746 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink1>[00m setting last buffer to 0x7fafd80050b0
0:00:00.024531053 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink1>[00m preroll buffer 0:00:00.000000000
0:00:00.024545043 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink1>[00m commiting state to PAUSED
0:00:00.024554959 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink1>[00m posting PAUSED state change message
0:00:00.024575799 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink1>[00m posting async-done message
0:00:00.024593241 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink1>[00m waiting in preroll for flush or PLAYING
0:00:00.024938449 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event segment: segment event: 0x7ebad0, time 99:99:99.999999999, seq-num 22, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.024992318 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:226:gst_stream_synchronizer_wait:<streamsync:sink_0>[00m Stream not waiting anymore
0:00:00.025000626 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:423:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Segment was: UNDEFINED segment
0:00:00.025009251 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:426:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Segment now is: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.025023088 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:430:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Stream start running time: 0:00:00.000000000
0:00:00.025037906 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7ebb40 segment event: 0x7ebb40, time 99:99:99.999999999, seq-num 22, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.025068056 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3105:gst_base_sink_default_event:<fakesink0>[00m configured segment time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.025086923 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:610:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Handling buffer 0x7fafd8005710: size=115200, timestamp=0:00:00.000000000 duration=0:00:00.033333333 offset=0 offset_end=1
0:00:00.025100441 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:627:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Updating position from 0:00:00.000000000 to 0:00:00.000000000
0:00:00.025112164 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3342:gst_base_sink_chain_unlocked:<fakesink0>[00m got times start: 0:00:00.000000000, end: 0:00:00.033333333
0:00:00.025122690 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink0>[00m got times start: 0:00:00.000000000, stop: 0:00:00.033333333, do_sync 1
0:00:00.025133893 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink0>[00m prerolling object 0x7fafd8005710
0:00:00.025141724 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink0>[00m setting last buffer to 0x7fafd8005710
0:00:00.025149132 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink0>[00m preroll buffer 0:00:00.000000000
0:00:00.025163305 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink0>[00m commiting state to PAUSED
0:00:00.025170607 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink0>[00m posting PAUSED state change message
0:00:00.025186738 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink0>[00m posting async-done message
0:00:00.025577688 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink0>[00m waiting in preroll for flush or PLAYING
0:00:00.025763948 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink1>[00m we are ready for LATENCY query
0:00:00.025801107 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink1>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.025819082 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink1>[00m query latency returns 1
0:00:00.025831539 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink0>[00m we are ready for LATENCY query
0:00:00.025847996 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink0>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.025861529 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink0>[00m query latency returns 1
0:00:00.025881151 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink1>[00m handling event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;
0:00:00.025900538 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink1>[00m latency set to 0:00:00.000000000
0:00:00.025913478 [334m20697[00m 0x7fafe0003000 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_1>[00m Handling event latency: latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;
0:00:00.025933286 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink1>[00m handled event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;: 1
0:00:00.025949665 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink0>[00m handling event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;
0:00:00.025962255 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink0>[00m latency set to 0:00:00.000000000
0:00:00.025972258 [334m20697[00m 0x7fafe0003000 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_0>[00m Handling event latency: latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;
0:00:00.025988194 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink0>[00m handled event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 54, GstEventLatency, latency=(guint64)0;: 1
0:00:00.026039493 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.026051013 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink1>[00m PAUSED to PLAYING, don't need preroll
0:00:00.026058319 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink1>[00m signal preroll
0:00:00.026076849 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink1>[00m continue after preroll
0:00:00.026080109 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.026092757 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2474:gst_base_sink_do_sync:<fakesink1>[00m reset rc_time to time 0:00:00.000000000
0:00:00.026108164 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink0>[00m PAUSED to PLAYING, don't need preroll
0:00:00.026105608 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2486:gst_base_sink_do_sync:<fakesink1>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.026121176 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink0>[00m signal preroll
0:00:00.026132729 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m            basesink gstbasesink.c:2072:gst_base_sink_wait_clock:<fakesink1>[00m time 0:00:00.000000000, base_time 0:15:23.102765296
0:00:00.026147320 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink0>[00m continue after preroll
0:00:00.026151786 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2493:gst_base_sink_do_sync:<fakesink1>[00m clock returned 1, jitter  0:00:00.000435326
0:00:00.026164254 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2474:gst_base_sink_do_sync:<fakesink0>[00m reset rc_time to time 0:00:00.000000000
0:00:00.026170224 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2817:gst_base_sink_is_too_late:<fakesink1>[00m frame dropping disabled
0:00:00.026184698 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2486:gst_base_sink_do_sync:<fakesink0>[00m possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.026201651 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3424:gst_base_sink_chain_unlocked:<fakesink1>[00m rendering object 0x7fafd80050b0
0:00:00.026151555 [334m20697[00m 0x7fafe0003000 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.026215355 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m            basesink gstbasesink.c:2072:gst_base_sink_wait_clock:<fakesink0>[00m time 0:00:00.000000000, base_time 0:15:23.102765296
0:00:00.026231696 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3463:gst_base_sink_chain_unlocked:<fakesink1>[00m object unref after render 0x7fafd80050b0
0:00:00.026276292 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2493:gst_base_sink_do_sync:<fakesink0>[00m clock returned 1, jitter  0:00:00.000560063
0:00:00.026288456 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:642:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Push returned: ok
0:00:00.026293993 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2817:gst_base_sink_is_too_late:<fakesink0>[00m frame dropping disabled
0:00:00.026317437 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:659:gst_stream_synchronizer_sink_chain:<streamsync:sink_1>[00m Updating position from 0:00:00.000000000 to 0:00:00.023219954
0:00:00.026328525 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3424:gst_base_sink_chain_unlocked:<fakesink0>[00m rendering object 0x7fafd8005710
0:00:00.026328965 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED
0:00:00.026354941 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event eos: eos event: 0x7fafd80034a0, time 99:99:99.999999999, seq-num 26, (NULL)
0:00:00.026353677 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3463:gst_base_sink_chain_unlocked:<fakesink0>[00m object unref after render 0x7fafd8005710
0:00:00.026376800 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:498:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Have EOS for stream 1
0:00:00.026397635 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:642:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Push returned: ok
0:00:00.026369088 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink1>[00m got preroll lock
0:00:00.026397697 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:244:gst_stream_synchronizer_wait:<streamsync:src_1>[00m Send GAP event, position: 0:00:00.023219954 duration: 99:99:99.999999999
0:00:00.026443318 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 0, EOS: 0 => needs preroll: 1
0:00:00.026454643 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:659:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Updating position from 0:00:00.000000000 to 0:00:00.033333333
0:00:00.026454597 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafd8003510 gap event: 0x7fafd8003510, time 99:99:99.999999999, seq-num 62, GstEventGap, timestamp=(guint64)23219954, duration=(guint64)18446744073709551615;
0:00:00.026461457 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5044:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED, we are not prerolled
0:00:00.026543015 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5049:gst_base_sink_change_state:<fakesink1>[00m doing async state change
0:00:00.026559936 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink1>[00m rendered: 1, dropped: 0
0:00:00.026587751 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED
0:00:00.026586175 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1866:gst_base_sink_get_sync_times:<fakesink1>[00m Got Gap time 0:00:00.023219954 duration 99:99:99.999999999
0:00:00.026597335 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink0>[00m got preroll lock
0:00:00.026614852 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink1>[00m got times start: 0:00:00.023219954, stop: 99:99:99.999999999, do_sync 1
0:00:00.026647667 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink1>[00m prerolling object 0x7fafd8003510
0:00:00.026649096 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 0, EOS: 0 => needs preroll: 1
0:00:00.026667159 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink1>[00m commiting state to PAUSED
0:00:00.026683127 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5044:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED, we are not prerolled
0:00:00.026699509 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink1>[00m posting PAUSED state change message
0:00:00.026717466 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5049:gst_base_sink_change_state:<fakesink0>[00m doing async state change
0:00:00.026720492 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink1>[00m posting async-done message
0:00:00.026731135 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink0>[00m rendered: 1, dropped: 0
0:00:00.026752935 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink1>[00m waiting in preroll for flush or PLAYING
0:00:00.026755475 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.026769285 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:912:gst_stream_synchronizer_change_state:<streamsync>[00m State change PLAYING->PAUSED
0:00:00.027222699 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:610:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Handling buffer 0x7fafd8005820: size=115200, timestamp=0:00:00.033333333 duration=0:00:00.033333333 offset=1 offset_end=2
0:00:00.027244080 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:627:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Updating position from 0:00:00.033333333 to 0:00:00.033333333
0:00:00.027258168 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3342:gst_base_sink_chain_unlocked:<fakesink0>[00m got times start: 0:00:00.033333333, end: 0:00:00.066666666
0:00:00.027269650 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink0>[00m got times start: 0:00:00.033333333, stop: 0:00:00.066666666, do_sync 1
0:00:00.027282126 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink0>[00m prerolling object 0x7fafd8005820
0:00:00.027289969 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink0>[00m setting last buffer to 0x7fafd8005820
0:00:00.027299554 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink0>[00m preroll buffer 0:00:00.033333333
0:00:00.027308856 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink0>[00m commiting state to PAUSED
0:00:00.027322016 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink0>[00m posting PAUSED state change message
0:00:00.027339725 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink0>[00m posting async-done message
0:00:00.027360117 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink0>[00m waiting in preroll for flush or PLAYING
0:00:00.027384516 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink1>[00m we are ready for LATENCY query
0:00:00.027405559 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink1>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.027421495 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink1>[00m query latency returns 1
0:00:00.027432979 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink0>[00m we are ready for LATENCY query
0:00:00.027447780 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink0>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.027462134 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink0>[00m query latency returns 1
0:00:00.027478606 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink1>[00m handling event 0x7eb910 latency event: 0x7eb910, time 99:99:99.999999999, seq-num 74, GstEventLatency, latency=(guint64)0;
0:00:00.027494176 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink1>[00m latency set to 0:00:00.000000000
0:00:00.027504851 [334m20697[00m       0x7ebd00 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_1>[00m Handling event latency: latency event: 0x7eb910, time 99:99:99.999999999, seq-num 74, GstEventLatency, latency=(guint64)0;
0:00:00.027521960 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink1>[00m handled event 0x7eb910 latency event: 0x7eb910, time 99:99:99.999999999, seq-num 74, GstEventLatency, latency=(guint64)0;: 1
0:00:00.027537150 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink0>[00m handling event 0x7eb910 latency event: 0x7eb910, time 99:99:99.999999999, seq-num 74, GstEventLatency, latency=(guint64)0;
0:00:00.027548711 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink0>[00m latency set to 0:00:00.000000000
0:00:00.027558416 [334m20697[00m       0x7ebd00 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_0>[00m Handling event latency: latency event: 0x7eb910, time 99:99:99.999999999, seq-num 74, GstEventLatency, latency=(guint64)0;
0:00:00.027573119 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink0>[00m handled event 0x7eb910 latency event: 0x7eb910, time 99:99:99.999999999, seq-num 74, GstEventLatency, latency=(guint64)0;: 1
0:00:00.027600297 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.027618575 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink1>[00m PAUSED to PLAYING, don't need preroll
0:00:00.027626191 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink1>[00m signal preroll
0:00:00.027640560 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink1>[00m continue after preroll
0:00:00.027647530 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.027651823 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2474:gst_base_sink_do_sync:<fakesink1>[00m reset rc_time to time 0:00:00.023219954
0:00:00.027660523 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink0>[00m PAUSED to PLAYING, don't need preroll
0:00:00.027672389 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2486:gst_base_sink_do_sync:<fakesink1>[00m possibly waiting for clock to reach 0:00:00.023219954, adjusted 0:00:00.023219954
0:00:00.027682871 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink0>[00m signal preroll
0:00:00.027693524 [334m20697[00m       0x7c2280 [33;01mLOG    [00m [00m            basesink gstbasesink.c:2072:gst_base_sink_wait_clock:<fakesink1>[00m time 0:00:00.023219954, base_time 0:15:23.103341305
0:00:00.027710608 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink0>[00m continue after preroll
0:00:00.027714240 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.027726837 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2474:gst_base_sink_do_sync:<fakesink0>[00m reset rc_time to time 0:00:00.033333333
0:00:00.027744666 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2486:gst_base_sink_do_sync:<fakesink0>[00m possibly waiting for clock to reach 0:00:00.033333333, adjusted 0:00:00.033333333
0:00:00.027755794 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m            basesink gstbasesink.c:2072:gst_base_sink_wait_clock:<fakesink0>[00m time 0:00:00.033333333, base_time 0:15:23.103341305
0:00:00.027777624 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED
0:00:00.027786380 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink1>[00m got preroll lock
0:00:00.027792953 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5029:gst_base_sink_change_state:<fakesink1>[00m unschedule clock
0:00:00.027805311 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 0, EOS: 0 => needs preroll: 1
0:00:00.027814564 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5044:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED, we are not prerolled
0:00:00.027821465 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5049:gst_base_sink_change_state:<fakesink1>[00m doing async state change
0:00:00.027829665 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink1>[00m rendered: 0, dropped: 0
0:00:00.027850217 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED
0:00:00.027849486 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2493:gst_base_sink_do_sync:<fakesink1>[00m clock returned 2, jitter -0:00:00.021795397
0:00:00.027860053 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink0>[00m got preroll lock
0:00:00.027872576 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2506:gst_base_sink_do_sync:<fakesink1>[00m unscheduled, waiting some more
0:00:00.027883555 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5029:gst_base_sink_change_state:<fakesink0>[00m unschedule clock
0:00:00.027894694 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink1>[00m prerolling object 0x7fafd8003510
0:00:00.027906243 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink1>[00m commiting state to PAUSED
0:00:00.027912168 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 0, EOS: 0 => needs preroll: 1
0:00:00.027915309 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink1>[00m posting PAUSED state change message
0:00:00.027924157 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5044:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED, we are not prerolled
0:00:00.027941200 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink1>[00m posting async-done message
0:00:00.027947085 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5049:gst_base_sink_change_state:<fakesink0>[00m doing async state change
0:00:00.027961060 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink1>[00m waiting in preroll for flush or PLAYING
0:00:00.027969470 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink0>[00m rendered: 0, dropped: 0
0:00:00.027992714 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.027990725 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2493:gst_base_sink_do_sync:<fakesink0>[00m clock returned 2, jitter -0:00:00.031854969
0:00:00.028005406 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:912:gst_stream_synchronizer_change_state:<streamsync>[00m State change PLAYING->PAUSED
0:00:00.028018870 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2506:gst_base_sink_do_sync:<fakesink0>[00m unscheduled, waiting some more
0:00:00.028038050 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink0>[00m prerolling object 0x7fafd8005820
0:00:00.028046282 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink0>[00m preroll buffer 0:00:00.033333333
0:00:00.028055504 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink0>[00m commiting state to PAUSED
0:00:00.028059247 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4034:gst_base_sink_set_flushing:<fakesink1>[00m flushing out data thread, need preroll to TRUE
0:00:00.028062359 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink0>[00m posting PAUSED state change message
0:00:00.028086717 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink0>[00m posting async-done message
0:00:00.028090732 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2168:gst_base_sink_wait_preroll:<fakesink1>[00m preroll interrupted because of flush
0:00:00.028107953 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink0>[00m waiting in preroll for flush or PLAYING
0:00:00.028117983 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2272:gst_base_sink_do_preroll:<fakesink1>[00m preroll failed: flushing
0:00:00.028141998 [334m20697[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2546:gst_base_sink_do_sync:<fakesink1>[00m preroll failed
0:00:00.028158965 [334m20697[00m       0x7c2280 [31;01mERROR  [00m [00m  streamsynchronizer gststreamsynchronizer.c:251:gst_stream_synchronizer_wait:<streamsync:src_1>[00m Failed to send GAP event
0:00:00.028168565 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink1>[00m setting last buffer to (nil)
0:00:00.028189159 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5096:gst_base_sink_change_state:<fakesink1>[00m PAUSED to READY, don't need_preroll
0:00:00.028207732 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4034:gst_base_sink_set_flushing:<fakesink0>[00m flushing out data thread, need preroll to TRUE
0:00:00.028223560 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2168:gst_base_sink_wait_preroll:<fakesink0>[00m preroll interrupted because of flush
0:00:00.028238395 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2272:gst_base_sink_do_preroll:<fakesink0>[00m preroll failed: flushing
0:00:00.028251313 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2546:gst_base_sink_do_sync:<fakesink0>[00m preroll failed
0:00:00.028262771 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3496:gst_base_sink_chain_unlocked:<fakesink0>[00m do_sync returned flushing
0:00:00.028272781 [334m20697[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3463:gst_base_sink_chain_unlocked:<fakesink0>[00m object unref after render 0x7fafd8005820
0:00:00.028285130 [334m20697[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:642:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Push returned: flushing
0:00:00.028300805 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink0>[00m setting last buffer to (nil)
0:00:00.028316893 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5096:gst_base_sink_change_state:<fakesink0>[00m PAUSED to READY, don't need_preroll
0:00:00.028334966 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:888:gst_stream_synchronizer_change_state:<streamsync>[00m State change PAUSED->READY
0:00:00.028359231 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.028368055 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:932:gst_stream_synchronizer_change_state:<streamsync>[00m State change PAUSED->READY
0:00:00.028517543 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.028530253 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:952:gst_stream_synchronizer_change_state:<streamsync>[00m State change READY->NULL
0:00:00.028624826 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:783:gst_stream_synchronizer_release_stream:<streamsync>[00m Releasing stream 0
0:00:00.028643750 [334m20697[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:783:gst_stream_synchronizer_release_stream:<streamsync>[00m Releasing stream 1
0:00:00.032603405 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:720:gst_stream_synchronizer_request_new_pad:<streamsync>[00m Requesting new pad for stream 0
0:00:00.032727126 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:720:gst_stream_synchronizer_request_new_pad:<streamsync>[00m Requesting new pad for stream 1
0:00:00.032897561 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:872:gst_stream_synchronizer_change_state:<streamsync>[00m State change NULL->READY
0:00:00.032912698 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.032946414 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4921:gst_base_sink_change_state:<fakesink1>[00m READY to PAUSED
0:00:00.032955413 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4942:gst_base_sink_change_state:<fakesink1>[00m doing async state change
0:00:00.032966937 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4082:gst_base_sink_pad_activate:<fakesink1>[00m Trying pull mode first
0:00:00.032974389 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4088:gst_base_sink_pad_activate:<fakesink1>[00m pull mode disabled
0:00:00.032980724 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4138:gst_base_sink_pad_activate:<fakesink1>[00m Falling back to push mode
0:00:00.032988499 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4140:gst_base_sink_pad_activate:<fakesink1>[00m Success activating push mode
0:00:00.032999505 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4921:gst_base_sink_change_state:<fakesink0>[00m READY to PAUSED
0:00:00.033006566 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4942:gst_base_sink_change_state:<fakesink0>[00m doing async state change
0:00:00.033015842 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4082:gst_base_sink_pad_activate:<fakesink0>[00m Trying pull mode first
0:00:00.033022560 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4088:gst_base_sink_pad_activate:<fakesink0>[00m pull mode disabled
0:00:00.033028904 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4138:gst_base_sink_pad_activate:<fakesink0>[00m Falling back to push mode
0:00:00.033035760 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4140:gst_base_sink_pad_activate:<fakesink0>[00m Success activating push mode
0:00:00.033046806 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:877:gst_stream_synchronizer_change_state:<streamsync>[00m State change READY->PAUSED
0:00:00.033066903 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.033405834 [332m20701[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event stream-start: stream-start event: 0x7fafe0004570, time 99:99:99.999999999, seq-num 32, GstEventStreamStart, stream-id=(string)9760dd91039f96efa3d81cc1ddad9553, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.033388399 [332m20701[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event stream-start: stream-start event: 0x7eb9f0, time 99:99:99.999999999, seq-num 31, GstEventStreamStart, stream-id=(string)1238141ba8bb3495eb9651277a6c9930, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.033455578 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:337:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Stream 1 changed
0:00:00.033486317 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:337:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Stream 0 changed
0:00:00.033504184 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:357:gst_stream_synchronizer_sink_event:<streamsync>[00m All streams have changed to group id 0 -- unblocking
0:00:00.033495888 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe0004570 stream-start event: 0x7fafe0004570, time 99:99:99.999999999, seq-num 32, GstEventStreamStart, stream-id=(string)9760dd91039f96efa3d81cc1ddad9553, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.033521004 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:386:gst_stream_synchronizer_sink_event:<streamsync>[00m New group start time: 0:00:00.000000000
0:00:00.033538400 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3056:gst_base_sink_default_event:<fakesink1>[00m Now posting STREAM_START (seqnum:32)
0:00:00.033565419 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7eb9f0 stream-start event: 0x7eb9f0, time 99:99:99.999999999, seq-num 31, GstEventStreamStart, stream-id=(string)1238141ba8bb3495eb9651277a6c9930, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)0;
0:00:00.033598115 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3056:gst_base_sink_default_event:<fakesink0>[00m Now posting STREAM_START (seqnum:31)
0:00:00.033638538 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink1>[00m Checking if requested caps audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)1 are a subset of pad caps ANY result 1
0:00:00.033675600 [332m20701[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event caps: caps event: 0x7fafe00045e0, time 99:99:99.999999999, seq-num 37, GstEventCaps, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)1";
0:00:00.033723635 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink1>[00m Checking if requested caps audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)1 are a subset of pad caps ANY result 1
0:00:00.033726107 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink0>[00m Checking if requested caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive are a subset of pad caps ANY result 1
0:00:00.033762672 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe00045e0 caps event: 0x7fafe00045e0, time 99:99:99.999999999, seq-num 37, GstEventCaps, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)1";
0:00:00.033796616 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3073:gst_base_sink_default_event:<fakesink1>[00m caps 0x7fafe00045e0
0:00:00.033780031 [332m20701[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event caps: caps event: 0x7eba60, time 99:99:99.999999999, seq-num 38, GstEventCaps, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive";
0:00:00.033832359 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4848:gst_base_sink_default_query:<fakesink0>[00m Checking if requested caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive are a subset of pad caps ANY result 1
0:00:00.033864981 [332m20701[00m       0x7c2280 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Handling event eos: eos event: 0x7fafe0004650, time 99:99:99.999999999, seq-num 26, (NULL)
0:00:00.033884900 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:498:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m Have EOS for stream 1
0:00:00.033864540 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7eba60 caps event: 0x7eba60, time 99:99:99.999999999, seq-num 38, GstEventCaps, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive";
0:00:00.033903897 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:565:gst_stream_synchronizer_sink_event:<streamsync:sink_1>[00m send EOS event
0:00:00.033923133 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3073:gst_base_sink_default_event:<fakesink0>[00m caps 0x7eba60
0:00:00.033938106 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink1>[00m received event 0x7fafe00046c0 eos event: 0x7fafe00046c0, time 99:99:99.999999999, seq-num 40, (NULL)
0:00:00.033958580 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1853:gst_base_sink_get_sync_times:<fakesink1>[00m sync times for EOS 99:99:99.999999999
0:00:00.033975926 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink1>[00m prerolling object 0x7fafe00046c0
0:00:00.033989047 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink1>[00m commiting state to PAUSED
0:00:00.034000339 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink1>[00m posting PAUSED state change message
0:00:00.034032581 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink1>[00m posting async-done message
0:00:00.034054717 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink1>[00m waiting in preroll for flush or PLAYING
0:00:00.034752046 [332m20701[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:272:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Handling event segment: segment event: 0x7ebad0, time 99:99:99.999999999, seq-num 22, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.034802370 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:226:gst_stream_synchronizer_wait:<streamsync:sink_0>[00m Stream not waiting anymore
0:00:00.034810136 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:423:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Segment was: UNDEFINED segment
0:00:00.034819028 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:426:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Segment now is: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.034833799 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:430:gst_stream_synchronizer_sink_event:<streamsync:sink_0>[00m Stream start running time: 0:00:00.000000000
0:00:00.034848396 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3170:gst_base_sink_event:<fakesink0>[00m received event 0x7ebb40 segment event: 0x7ebb40, time 99:99:99.999999999, seq-num 22, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.034878591 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3105:gst_base_sink_default_event:<fakesink0>[00m configured segment time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.034898688 [332m20701[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:610:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Handling buffer 0x7fafe002f0d0: size=115200, timestamp=0:00:00.000000000 duration=0:00:00.033333333 offset=0 offset_end=1
0:00:00.034912472 [332m20701[00m       0x7c21e0 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:627:gst_stream_synchronizer_sink_chain:<streamsync:sink_0>[00m Updating position from 0:00:00.000000000 to 0:00:00.000000000
0:00:00.034924902 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3342:gst_base_sink_chain_unlocked:<fakesink0>[00m got times start: 0:00:00.000000000, end: 0:00:00.033333333
0:00:00.034936188 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1901:gst_base_sink_get_sync_times:<fakesink0>[00m got times start: 0:00:00.000000000, stop: 0:00:00.033333333, do_sync 1
0:00:00.034972225 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink0>[00m prerolling object 0x7fafe002f0d0
0:00:00.034986249 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:936:gst_base_sink_set_last_buffer_unlocked:<fakesink0>[00m setting last buffer to 0x7fafe002f0d0
0:00:00.034994557 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2219:gst_base_sink_do_preroll:<fakesink0>[00m preroll buffer 0:00:00.000000000
0:00:00.035003557 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1454:gst_base_sink_commit_state:<fakesink0>[00m commiting state to PAUSED
0:00:00.035010062 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1479:gst_base_sink_commit_state:<fakesink0>[00m posting PAUSED state change message
0:00:00.035025998 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1485:gst_base_sink_commit_state:<fakesink0>[00m posting async-done message
0:00:00.035421007 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink0>[00m waiting in preroll for flush or PLAYING
0:00:00.035582274 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink1>[00m we are ready for LATENCY query
0:00:00.035613308 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink1>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.035631471 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink1>[00m query latency returns 1
0:00:00.035643604 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1071:gst_base_sink_query_latency:<fakesink0>[00m we are ready for LATENCY query
0:00:00.035660162 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:1113:gst_base_sink_query_latency:<fakesink0>[00m latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999
0:00:00.035674189 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4804:default_element_query:<fakesink0>[00m query latency returns 1
0:00:00.035695109 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink1>[00m handling event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 51, GstEventLatency, latency=(guint64)0;
0:00:00.035714943 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink1>[00m latency set to 0:00:00.000000000
0:00:00.035728297 [332m20701[00m 0x7fafe0003000 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_1>[00m Handling event latency: latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 51, GstEventLatency, latency=(guint64)0;
0:00:00.035749341 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink1>[00m handled event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 51, GstEventLatency, latency=(guint64)0;: 1
0:00:00.035766306 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4345:gst_base_sink_send_event:<fakesink0>[00m handling event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 51, GstEventLatency, latency=(guint64)0;
0:00:00.035779520 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4362:gst_base_sink_send_event:<fakesink0>[00m latency set to 0:00:00.000000000
0:00:00.035801653 [332m20701[00m 0x7fafe0003000 [33;01mLOG    [00m [00m  streamsynchronizer gststreamsynchronizer.c:150:gst_stream_synchronizer_src_event:<streamsync:src_0>[00m Handling event latency: latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 51, GstEventLatency, latency=(guint64)0;
0:00:00.035819593 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4392:gst_base_sink_send_event:<fakesink0>[00m handled event 0x7fafd4005820 latency event: 0x7fafd4005820, time 99:99:99.999999999, seq-num 51, GstEventLatency, latency=(guint64)0;: 1
0:00:00.035859079 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 1, EOS: 1 => needs preroll: 0
0:00:00.035870535 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink1>[00m PAUSED to PLAYING, don't need preroll
0:00:00.035877713 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink1>[00m signal preroll
0:00:00.035897742 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink1>[00m continue after preroll
0:00:00.035923843 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3038:gst_base_sink_default_event:<fakesink1>[00m Now posting EOS
0:00:00.035899323 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.035941475 [332m20701[00m       0x7c2280 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3041:gst_base_sink_default_event:<fakesink1>[00m Got seqnum #40
0:00:00.035962715 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4957:gst_base_sink_change_state:<fakesink0>[00m PAUSED to PLAYING, don't need preroll
0:00:00.035977514 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m            basesink gstbasesink.c:4970:gst_base_sink_change_state:<fakesink0>[00m signal preroll
0:00:00.036003531 [332m20701[00m 0x7fafe0003000 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.036070617 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED
0:00:00.036081792 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink1>[00m got preroll lock
0:00:00.036088899 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink1>[00m have_preroll: 0, EOS: 1 => needs preroll: 0
0:00:00.036098911 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5036:gst_base_sink_change_state:<fakesink1>[00m PLAYING to PAUSED, we are prerolled
0:00:00.036105932 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink1>[00m rendered: 0, dropped: 0
0:00:00.036122656 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5009:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED
0:00:00.036130274 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5018:gst_base_sink_change_state:<fakesink0>[00m got preroll lock
0:00:00.036136830 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:3259:gst_base_sink_needs_preroll:<fakesink0>[00m have_preroll: 1, EOS: 0 => needs preroll: 0
0:00:00.036145225 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5036:gst_base_sink_change_state:<fakesink0>[00m PLAYING to PAUSED, we are prerolled
0:00:00.036159813 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m            basesink gstbasesink.c:5057:gst_base_sink_change_state:<fakesink0>[00m rendered: 0, dropped: 0
0:00:00.036176086 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:904:gst_stream_synchronizer_change_state:<streamsync>[00m Base class state changed returned: 1
0:00:00.036184915 [332m20701[00m       0x7ebd00 [37mDEBUG  [00m [00m  streamsynchronizer gststreamsynchronizer.c:912:gst_stream_synchronizer_change_state:<streamsync>[00m State change PLAYING->PAUSED
0:00:00.037493847 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2161:gst_base_sink_wait_preroll:<fakesink0>[00m continue after preroll
0:00:00.037544447 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2200:gst_base_sink_do_preroll:<fakesink0>[00m prerolling object 0x7fafe002f0d0
0:00:00.037581699 [332m20701[00m       0x7c21e0 [37mDEBUG  [00m [00m            basesink gstbasesink.c:2153:gst_base_sink_wait_preroll:<fakesink0>[00m waiting in preroll for flush or PLAYING
