0:00:00.013422827 32228       0x9c5010 DEBUG                  check pipelines/oggmux.c:384:test_vorbis_theora: test start
0:00:00.021842715 32228       0x9c5010 WARN               theoraenc gsttheoraenc.c:315:gst_theora_enc_class_init: Failed to determine settings for the speed-level property.
0:00:00.022816652 32228       0x9c5010 LOG                theoraenc gsttheoraenc.c:603:theora_enc_get_supported_formats: format I420 is supported
0:00:00.023633988 32228       0x9c5010 LOG                theoraenc gsttheoraenc.c:603:theora_enc_get_supported_formats: format Y42B is supported
0:00:00.024447469 32228       0x9c5010 LOG                theoraenc gsttheoraenc.c:603:theora_enc_get_supported_formats: format Y444 is supported
0:00:00.026357215 32228       0x9c5010 DEBUG               oggdemux gstoggdemux.c:3644:gst_ogg_demux_plugin_init: binding text domain gst-plugins-base-0.10 to locale dir /usr/share/locale
0:00:00.036971321 32228       0x9c5010 DEBUG                 oggmux gstoggmux.c:457:gst_ogg_mux_request_new_pad:<mux> Creating new pad for serial 773151224
0:00:00.037050894 32228       0x9c5010 DEBUG                 oggmux gstoggmux.c:321:gst_ogg_mux_sinkconnect:<mux> sinkconnect triggered on sink_773151224
0:00:00.078186969 32228       0x9c5010 DEBUG                 oggmux gstoggmux.c:457:gst_ogg_mux_request_new_pad:<mux> Creating new pad for serial 310169398
0:00:00.078234506 32228       0x9c5010 DEBUG                 oggmux gstoggmux.c:321:gst_ogg_mux_sinkconnect:<mux> sinkconnect triggered on sink_310169398
0:00:00.081662095 32228       0x9c5010 DEBUG              theoraenc gsttheoraenc.c:1415:theora_enc_change_state:<theoraenc0> READY->PAUSED Initing theora state
0:00:00.086514849 32228       0xc39ce0 DEBUG                 oggmux gstoggmux.c:335:gst_ogg_mux_sink_event:<mux:sink_310169398> Got newsegment event
0:00:00.087032273 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:992:gst_vorbis_enc_sink_event:<vorbisenc0> Initial segment time segment start=0:00:00.000000000, stop=99:99:99.999999999, last_stop=0:00:00.000000000, duration=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, accum=0:00:00.000000000
0:00:00.087195312 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:335:gst_ogg_mux_sink_event:<mux:sink_773151224> Got newsegment event
0:00:00.087242083 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:335:gst_ogg_mux_sink_event:<mux:sink_773151224> Got tag event
0:00:00.087266843 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:373:gst_ogg_mux_sink_event:<mux> Got tags taglist, description=(string)"audiotest\ wave";
0:00:00.087987216 32228       0xc33dc0 DEBUG              theoraenc gsttheoraenc.c:728:theora_enc_sink_setcaps:<theoraenc0> keyframe_frequency_force is 64, granule shift is 6
0:00:00.089942170 32228       0xc33dc0 DEBUG              theoraenc gsttheoraenc.c:1316:theora_enc_chain:<theoraenc0> output headers
0:00:00.090653617 32228       0xc33dc0 DEBUG              theoraenc gsttheoraenc.c:1353:theora_enc_chain: here are the caps: video/x-theora, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, streamheader=(buffer)< 807468656f72610302010014000f0001400000f000000000001e0000000100000000000000000000c0c0, 817468656f72612b000000586970682e4f7267206c69627468656f726120312e312032303039303832322028546875736e656c64612900000000,   >
0:00:00.102952846 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.102969070 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1084:gst_vorbis_enc_chain:<vorbisenc0> creating and sending header packets
0:00:00.102975506 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:644:gst_vorbis_enc_set_metadata:<vorbisenc0> upstream tags = taglist, description=(string)"audiotest\ wave";
0:00:00.102987256 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:645:gst_vorbis_enc_set_metadata:<vorbisenc0> user-set tags = (NULL)
0:00:00.102996578 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:652:gst_vorbis_enc_set_metadata:<vorbisenc0> merged   tags = taglist, description=(string)"audiotest\ wave";
0:00:00.103019421 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:622:gst_vorbis_enc_metadata_set1:<vorbisenc0> vorbis comment: DESCRIPTION=audiotest wave
0:00:00.103124364 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:876:gst_vorbis_enc_buffer_from_header_packet: created header packet buffer, 30 bytes
0:00:00.103135264 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:876:gst_vorbis_enc_buffer_from_header_packet: created header packet buffer, 75 bytes
0:00:00.103141746 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:876:gst_vorbis_enc_buffer_from_header_packet: created header packet buffer, 3189 bytes
0:00:00.103159659 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1101:gst_vorbis_enc_chain: here are the caps: audio/x-vorbis, streamheader=(buffer)< 01766f72626973000000000144ac0000000000008038010000000000b801, 03766f726269731d000000586970682e4f7267206c6962566f726269732049203230303930373039010000001a0000004445534352495054494f4e3d617564696f74657374207761766501,   >
0:00:00.103612844 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 0, ts 99:99:99.999999999
0:00:00.103635119 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 0, ts 99:99:99.999999999
0:00:00.103643890 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 0, ts 99:99:99.999999999
0:00:00.103655769 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.103716889 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.103735050 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.103755201 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_310169398> popped buffer 0xc24550
0:00:00.103929061 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.103943781 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.104002083 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.103768423 32228       0xc39db0 INFO                oggdemux gstoggstream.c:2090:gst_ogg_stream_setup_map_from_caps_headers: Checking streamheader on caps video/x-theora, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, streamheader=(buffer)< 807468656f72610302010014000f0001400000f000000000001e0000000100000000000000000000c0c0, 817468656f72612b000000586970682e4f7267206c69627468656f726120312e312032303039303832322028546875736e656c64612900000000,   >
0:00:00.104122497 32228       0xc39db0 INFO                oggdemux gstoggstream.c:2131:gst_ogg_stream_setup_map_from_caps_headers: Found headers on caps, using those to determine type
0:00:00.104130067 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:2059:gst_ogg_stream_setup_map: found mapper for '€theora'
0:00:00.104139049 32228       0xc39db0 LOG                 oggdemux gstoggstream.c:384:setup_theora_mapper: fps = 30/1, PAR = 0/0, width = 320, height = 240
0:00:00.104151470 32228       0xc39db0 LOG                 oggdemux gstoggstream.c:395:setup_theora_mapper: bit rate: 0
0:00:00.104133099 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.104167052 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:2067:gst_ogg_stream_setup_map: got stream type video/x-theora, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1
0:00:00.104222902 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:990:gst_ogg_mux_queue_pads:0xc30540 caps detected: video/x-theora, width=(int)320, height=(int)240, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1
0:00:00.104246515 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1001:gst_ogg_mux_queue_pads:<mux> got header buffer in control state, ignoring
0:00:00.104257296 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.104263567 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc32c60
0:00:00.104316695 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.104393202 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.104403224 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 43 bytes
0:00:00.104408681 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 0, ts 0:00:00.000000000
0:00:00.104422120 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.104466693 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.104475067 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 20 bytes
0:00:00.104480375 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 128, ts 0:00:00.000000000
0:00:00.104490260 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.104270363 32228       0xc39db0 INFO                oggdemux gstoggstream.c:2090:gst_ogg_stream_setup_map_from_caps_headers: Checking streamheader on caps audio/x-vorbis, streamheader=(buffer)< 01766f72626973000000000144ac0000000000008038010000000000b801, 03766f726269731d000000586970682e4f7267206c6962566f726269732049203230303930373039010000001a0000004445534352495054494f4e3d617564696f74657374207761766501,   >
0:00:00.104689419 32228       0xc39db0 INFO                oggdemux gstoggstream.c:2131:gst_ogg_stream_setup_map_from_caps_headers: Found headers on caps, using those to determine type
0:00:00.104696148 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:2059:gst_ogg_stream_setup_map: found mapper for 'vorbis'
0:00:00.104701333 32228       0xc39db0 LOG                 oggdemux gstoggstream.c:727:setup_vorbis_mapper: sample rate: 44100
0:00:00.104707652 32228       0xc39db0 LOG                 oggdemux gstoggstream.c:745:setup_vorbis_mapper: bit rate: 80000
0:00:00.104716132 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:2067:gst_ogg_stream_setup_map: got stream type audio/x-vorbis, rate=(int)44100, channels=(int)1
0:00:00.104730012 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.104749020 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 56 bytes
0:00:00.104754862 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 704, ts 0:00:00.002902494
0:00:00.104727595 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:990:gst_ogg_mux_queue_pads:0xc24800 caps detected: audio/x-vorbis, rate=(int)44100, channels=(int)1
0:00:00.104786459 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1001:gst_ogg_mux_queue_pads:<mux> got header buffer in control state, ignoring
0:00:00.104835437 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.104848070 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.104878270 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.104923720 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.104943035 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.104955944 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_310169398> popped buffer 0xc245e0
0:00:00.104966617 32228       0xc39ce0 DEBUG                 oggmux gstoggmux.c:1001:gst_ogg_mux_queue_pads:<mux> got header buffer in control state, ignoring
0:00:00.104974145 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.104986498 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc32cf0
0:00:00.104993960 32228       0xc39ce0 DEBUG                 oggmux gstoggmux.c:1001:gst_ogg_mux_queue_pads:<mux> got header buffer in control state, ignoring
0:00:00.105017677 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.105035234 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.105050992 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_310169398> popped buffer 0xc24670
0:00:00.105063177 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1001:gst_ogg_mux_queue_pads:<mux> got header buffer in control state, ignoring
0:00:00.105070528 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.105076350 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc32d80
0:00:00.105083343 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1001:gst_ogg_mux_queue_pads:<mux> got header buffer in control state, ignoring
0:00:00.105112361 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.105124509 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.105144476 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.105125399 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 38 bytes
0:00:00.105171804 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_310169398> popped buffer 0xc32990
0:00:00.105193160 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 1728, ts 0:00:00.015963718
0:00:00.105208742 32228       0xc39ce0 DEBUG                 oggmux gstoggmux.c:1008:gst_ogg_mux_queue_pads:<mux> got data buffer in control state, switching to data mode
0:00:00.105262357 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_310169398> buffer ts 0:00:00.000000000, duration 0:00:00.033333333, granule duration 1
0:00:00.105279711 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_310169398> expected granule 0 == time 0:00:00.000000000 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.105298726 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32990
0:00:00.105308579 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.105313011 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.105327485 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.105314102 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4a940
0:00:00.105352530 32228       0xc39ce0 DEBUG                 oggmux gstoggmux.c:1008:gst_ogg_mux_queue_pads:<mux> got data buffer in control state, switching to data mode
0:00:00.105355497 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.105365832 32228       0xc39ce0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 0
0:00:00.105444186 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.000000000, duration 0:00:00.000000000, granule duration 0
0:00:00.105456653 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 0 == time 0:00:00.000000000 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.105592447 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.105604052 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 38 bytes
0:00:00.105609481 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 2752, ts 0:00:00.039183673
0:00:00.105674057 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.105685104 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.105712205 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.105929691 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.105939625 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 37 bytes
0:00:00.105944978 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 3776, ts 0:00:00.062403628
0:00:00.106007676 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.106018135 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.106045250 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.106262773 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.106272738 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 37 bytes
0:00:00.106278417 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 4800, ts 0:00:00.085623582
0:00:00.106339836 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.106350078 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.106377147 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.106593134 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.106603204 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 37 bytes
0:00:00.106608822 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 5824, ts 0:00:00.108843537
0:00:00.106669297 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.106679414 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.106712656 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.106931609 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.106941835 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 38 bytes
0:00:00.106947572 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 6848, ts 0:00:00.132063492
0:00:00.107008582 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:1066:gst_vorbis_enc_chain:<vorbisenc0> Initial ts is 0:00:00.000000000
0:00:00.107018884 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1220:gst_vorbis_enc_chain:<vorbisenc0> wrote 1024 samples to vorbis
0:00:00.107045895 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.107263544 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.107273473 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 37 bytes
0:00:00.107279213 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 7872, ts 0:00:00.155283446
0:00:00.107293469 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:961:gst_vorbis_enc_sink_event:<vorbisenc0> EOS, clearing state and sending event on
0:00:00.108053914 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.108280734 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.108291893 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 57 bytes
0:00:00.108297289 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 8896, ts 0:00:00.178503401
0:00:00.108309503 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.108356029 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.108364282 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 20 bytes
0:00:00.108369489 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 9472, ts 0:00:00.201723356
0:00:00.108380410 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.108438076 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.108450201 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 20 bytes
0:00:00.108455565 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 9600, ts 0:00:00.214784580
0:00:00.108467530 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.108511957 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.108525993 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 22 bytes
0:00:00.108531568 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 9728, ts 0:00:00.217687074
0:00:00.108542832 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.108586004 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.108594060 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 22 bytes
0:00:00.108599221 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 9856, ts 0:00:00.220589569
0:00:00.108609839 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.108652006 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.108660106 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 22 bytes
0:00:00.108665286 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 9984, ts 0:00:00.223492063
0:00:00.108676053 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.108718848 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.108727757 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 22 bytes
0:00:00.108733029 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 10112, ts 0:00:00.226394557
0:00:00.108741006 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1262:gst_vorbis_enc_output_buffers:<vorbisenc0> analysed to a block
0:00:00.108788519 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:1269:gst_vorbis_enc_output_buffers:<vorbisenc0> pushing out a data packet
0:00:00.108796335 32228 0x2ab548001e70 LOG                vorbisenc gstvorbisenc.c:854:gst_vorbis_enc_buffer_from_packet:<vorbisenc0> encoded buffer of 43 bytes
0:00:00.108801526 32228 0x2ab548001e70 DEBUG              vorbisenc gstvorbisenc.c:889:gst_vorbis_enc_push_buffer:<vorbisenc0> Pushing buffer with GP 10240, ts 0:00:00.229297052
0:00:00.111646318 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.111669276 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.111682758 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32990
0:00:00.111699329 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.111707492 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from (NULL)
0:00:00.111720869 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1622:gst_ogg_mux_process_best_pad:<mux:sink_310169398> pulling from best pad
0:00:00.111729320 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1628:gst_ogg_mux_process_best_pad:<mux:sink_310169398> updated times, next ts 0:00:00.000000000
0:00:00.111743318 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1329:gst_ogg_mux_send_headers:<mux> collecting headers
0:00:00.111760892 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1341:gst_ogg_mux_send_headers:<mux> looking at pad mux:sink_310169398
0:00:00.111770128 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1060:gst_ogg_mux_get_headers:<mux:sink_310169398> getting headers
0:00:00.111780650 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1069:gst_ogg_mux_get_headers:<mux:sink_310169398> got header
0:00:00.111789748 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1074:gst_ogg_mux_get_headers:<mux:sink_310169398> got fixed list
0:00:00.111797487 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1079:gst_ogg_mux_get_headers:<mux:sink_310169398> item 0
0:00:00.111805558 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1083:gst_ogg_mux_get_headers:<mux:sink_310169398> adding item 0 to header list
0:00:00.111814488 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1079:gst_ogg_mux_get_headers:<mux:sink_310169398> item 1
0:00:00.111822207 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1083:gst_ogg_mux_get_headers:<mux:sink_310169398> adding item 1 to header list
0:00:00.111830418 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1079:gst_ogg_mux_get_headers:<mux:sink_310169398> item 2
0:00:00.111838002 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1083:gst_ogg_mux_get_headers:<mux:sink_310169398> adding item 2 to header list
0:00:00.111846541 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1341:gst_ogg_mux_send_headers:<mux> looking at pad mux:sink_773151224
0:00:00.111854719 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1060:gst_ogg_mux_get_headers:<mux:sink_773151224> getting headers
0:00:00.111863449 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1069:gst_ogg_mux_get_headers:<mux:sink_773151224> got header
0:00:00.111871431 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1074:gst_ogg_mux_get_headers:<mux:sink_773151224> got fixed list
0:00:00.111879013 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1079:gst_ogg_mux_get_headers:<mux:sink_773151224> item 0
0:00:00.111886667 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1083:gst_ogg_mux_get_headers:<mux:sink_773151224> adding item 0 to header list
0:00:00.111894968 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1079:gst_ogg_mux_get_headers:<mux:sink_773151224> item 1
0:00:00.111902733 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1083:gst_ogg_mux_get_headers:<mux:sink_773151224> adding item 1 to header list
0:00:00.111911001 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1079:gst_ogg_mux_get_headers:<mux:sink_773151224> item 2
0:00:00.111918671 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1083:gst_ogg_mux_get_headers:<mux:sink_773151224> adding item 2 to header list
0:00:00.111927014 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1351:gst_ogg_mux_send_headers:<mux> creating BOS pages
0:00:00.111935288 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1371:gst_ogg_mux_send_headers:<mux:sink_310169398> looping over headers
0:00:00.111951554 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1395:gst_ogg_mux_send_headers:<mux:sink_310169398> flushing out BOS page
0:00:00.111969216 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:570:gst_ogg_mux_buffer_from_page:<mux> [gp        0] created buffer 0xc32cf0 from ogg page
0:00:00.111979965 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1402:gst_ogg_mux_send_headers:<mux> swapped out page with mime type video/x-theora
0:00:00.111988514 32228       0xc39ce0 DEBUG                 oggmux gstoggmux.c:1412:gst_ogg_mux_send_headers:<mux:sink_310169398> putting video/x-theora page at the front
0:00:00.111997492 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1371:gst_ogg_mux_send_headers:<mux:sink_773151224> looping over headers
0:00:00.112013470 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1395:gst_ogg_mux_send_headers:<mux:sink_773151224> flushing out BOS page
0:00:00.112024914 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:570:gst_ogg_mux_buffer_from_page:<mux> [gp        0] created buffer 0xc245e0 from ogg page
0:00:00.112034285 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1402:gst_ogg_mux_send_headers:<mux> swapped out page with mime type audio/x-vorbis
0:00:00.112042726 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1431:gst_ogg_mux_send_headers:<mux> creating next headers
0:00:00.112050418 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1446:gst_ogg_mux_send_headers:<mux> looping over headers for pad mux:sink_310169398
0:00:00.112059095 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1474:gst_ogg_mux_send_headers:<mux> try to swap out page
0:00:00.112069025 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1466:gst_ogg_mux_send_headers:<mux> flushing page as packet 2 is first or last packet
0:00:00.112101705 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:570:gst_ogg_mux_buffer_from_page:<mux> [gp        0] created buffer 0x2ab54c064ed0 from ogg page
0:00:00.112111179 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1470:gst_ogg_mux_send_headers:<mux> swapped out page
0:00:00.112119851 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1446:gst_ogg_mux_send_headers:<mux> looping over headers for pad mux:sink_773151224
0:00:00.112128819 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1474:gst_ogg_mux_send_headers:<mux> try to swap out page
0:00:00.112138290 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1466:gst_ogg_mux_send_headers:<mux> flushing page as packet 2 is first or last packet
0:00:00.112170895 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:570:gst_ogg_mux_buffer_from_page:<mux> [gp        0] created buffer 0xc47840 from ogg page
0:00:00.112179905 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1470:gst_ogg_mux_send_headers:<mux> swapped out page
0:00:00.112195825 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1128:gst_ogg_mux_set_header_on_caps: Setting IN_CAPS on buffer of length 70
0:00:00.112210287 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1128:gst_ogg_mux_set_header_on_caps: Setting IN_CAPS on buffer of length 58
0:00:00.112222931 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1128:gst_ogg_mux_set_header_on_caps: Setting IN_CAPS on buffer of length 2710
0:00:00.112235939 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1128:gst_ogg_mux_set_header_on_caps: Setting IN_CAPS on buffer of length 3305
0:00:00.112314994 32228       0xc39ce0 DEBUG                  check pipelines/oggmux.c:119:validate_ogg_page: new theora chain
0:00:00.112740167 32228       0xc4a4c0 WARN                     bin gstbin.c:2395:gst_bin_do_latency_func:<pipeline0> did not really configure latency of 0:00:00.000000000
0:00:00.112939581 32228       0xc39ce0 DEBUG                  check pipelines/oggmux.c:119:validate_ogg_page: new vorbis chain
0:00:00.113031417 32228       0xc39ce0 DEBUG                  check pipelines/oggmux.c:143:validate_ogg_page: other package on theora chain
0:00:00.113102888 32228       0xc39ce0 DEBUG                  check pipelines/oggmux.c:143:validate_ogg_page: other package on vorbis chain
0:00:00.113134929 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_310169398> pulling from pad
0:00:00.113147260 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_310169398> [gp       64] packet 3 (8443 bytes) created from buffer
0:00:00.113167423 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_310169398> [gp       64] packet 3, gp time 0:00:00.033333333, timestamp 0:00:00.000000000 packetin'd
0:00:00.113217931 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1790:gst_ogg_mux_process_best_pad:<mux:sink_310169398> [gp       64] packet 3, time 0:00:00.000000000) caused new page
0:00:00.113228934 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1793:gst_ogg_mux_process_best_pad:<mux:sink_310169398> [gp       -1] new page 3
0:00:00.113237107 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1809:gst_ogg_mux_process_best_pad:<mux:sink_310169398> [gp       64] packet spans beyond current page, keeping old gp time 0:00:00.000000000
0:00:00.113250551 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:570:gst_ogg_mux_buffer_from_page:<mux> [gp       -1] created buffer 0xc47b10 from ogg page
0:00:00.113261260 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:744:gst_ogg_mux_pad_queue_page:<mux:sink_310169398> [gp       -1] queued buffer page 0xc47b10 (gp time 0:00:00.000000000, timestamp 0:00:00.000000000), 1 page buffers queued
0:00:00.113273245 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:649:gst_ogg_mux_dequeue_page:<mux:sink_310169398> No page timestamps in queue, can't dequeue
0:00:00.113310469 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:570:gst_ogg_mux_buffer_from_page:<mux> [gp       64] created buffer 0xc47ba0 from ogg page
0:00:00.113320282 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:744:gst_ogg_mux_pad_queue_page:<mux:sink_310169398> [gp       64] queued buffer page 0xc47ba0 (gp time 0:00:00.033333333, timestamp 0:00:00.000000000), 2 page buffers queued
0:00:00.113331520 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:630:gst_ogg_mux_dequeue_page:<mux:sink_773151224> no pages in this queue, can't dequeue
0:00:00.113340671 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.113349217 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.113365130 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_310169398> popped buffer 0xc32ab0
0:00:00.113378917 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_310169398> buffer ts 0:00:00.033333333, duration 0:00:00.033333333, granule duration 1
0:00:00.113389366 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_310169398> expected granule 1 == time 0:00:00.033333333 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.113401056 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.113411344 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.113419031 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_773151224> new best pad, with buffer 0xc4a940
0:00:00.113440149 32228       0xc39ce0 DEBUG                 oggmux gstoggmux.c:335:gst_ogg_mux_sink_event:<mux:sink_310169398> Got eos event
0:00:00.113452200 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.113460674 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.113468203 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.113478326 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.113485887 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_773151224> new best pad, with buffer 0xc4a940
0:00:00.113495389 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_773151224>, currently pulling from (NULL)
0:00:00.113514881 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1622:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from best pad
0:00:00.113523535 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1628:gst_ogg_mux_process_best_pad:<mux:sink_773151224> updated times, next ts 0:00:00.000000000
0:00:00.113531964 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.113539508 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp        0] packet 3 (43 bytes) created from buffer
0:00:00.113549152 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp        0] packet 3, gp time 0:00:00.000000000, timestamp 0:00:00.000000000 packetin'd
0:00:00.113560882 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.113569213 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.113576867 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.113586950 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.113602116 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4a8b0
0:00:00.113612890 32228       0xc39ce0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 128
0:00:00.113621367 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.000000000, duration 0:00:00.002902494, granule duration 128
0:00:00.113631512 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 0 == time 0:00:00.000000000 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.113643330 32228       0xc39ce0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_773151224> new best pad, with buffer 0xc4a8b0
0:00:00.113674955 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.113700126 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.113713332 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.113726545 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.113734633 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_773151224> new best pad, with buffer 0xc4a8b0
0:00:00.113744796 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_773151224>, currently pulling from <mux:sink_773151224>
0:00:00.113757400 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.113765511 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp      128] packet 4 (20 bytes) created from buffer
0:00:00.113776120 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp      128] packet 4, gp time 0:00:00.002902494, timestamp 0:00:00.000000000 packetin'd
0:00:00.113788614 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.002902494
0:00:00.113812111 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.113821254 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.113828851 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.113838939 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.113847197 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4a820
0:00:00.113857190 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 576
0:00:00.113865681 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.002902494, duration 0:00:00.013061224, granule duration 576
0:00:00.113876446 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 128 == time 0:00:00.002902494 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.113889719 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_773151224> new best pad, with buffer 0xc4a820
0:00:00.113904702 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.113913740 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.113921464 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.113931314 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.113938836 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_773151224> new best pad, with buffer 0xc4a820
0:00:00.113947984 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_773151224>, currently pulling from <mux:sink_773151224>
0:00:00.113959034 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.113966794 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp      704] packet 5 (56 bytes) created from buffer
0:00:00.113975448 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp      704] packet 5, gp time 0:00:00.015963718, timestamp 0:00:00.002902494 packetin'd
0:00:00.113986679 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.015963718
0:00:00.113999103 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114007133 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114014625 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114024287 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114032124 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc32bd0
0:00:00.114047255 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 1024
0:00:00.114056187 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.015963718, duration 0:00:00.023219955, granule duration 1024
0:00:00.114066413 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 704 == time 0:00:00.015963718 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.114078087 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_773151224> new best pad, with buffer 0xc32bd0
0:00:00.114092491 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114101326 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114108875 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114118657 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114126204 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_773151224> new best pad, with buffer 0xc32bd0
0:00:00.114135490 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_773151224>, currently pulling from <mux:sink_773151224>
0:00:00.114146485 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.114154275 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     1728] packet 6 (38 bytes) created from buffer
0:00:00.114163049 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     1728] packet 6, gp time 0:00:00.039183673, timestamp 0:00:00.015963718 packetin'd
0:00:00.114174085 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.039183673
0:00:00.114186230 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114194130 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114201667 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114211256 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114219028 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc32b40
0:00:00.114228171 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 1024
0:00:00.114236307 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.039183673, duration 0:00:00.023219955, granule duration 1024
0:00:00.114246184 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 1728 == time 0:00:00.039183673 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.114261395 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114270496 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114284193 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114294827 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114302354 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.114313965 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.114321988 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.114329332 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     2752] packet 7 (38 bytes) created from buffer
0:00:00.114337994 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     2752] packet 7, gp time 0:00:00.062403628, timestamp 0:00:00.039183673 packetin'd
0:00:00.114349059 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.062403628
0:00:00.114360598 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.114368844 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.114377629 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114385539 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114392982 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114402842 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114410757 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4aa60
0:00:00.114420008 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 1024
0:00:00.114428196 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.062403628, duration 0:00:00.023219954, granule duration 1024
0:00:00.114437991 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 2752 == time 0:00:00.062403628 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.114453250 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114462275 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114469897 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114479837 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114487416 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.114498764 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.114506642 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.114520088 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     3776] packet 8 (37 bytes) created from buffer
0:00:00.114529607 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     3776] packet 8, gp time 0:00:00.085623582, timestamp 0:00:00.062403628 packetin'd
0:00:00.114540786 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.085623582
0:00:00.114552543 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.114560523 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.114569212 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114577230 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114584759 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114594431 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114602348 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4ab80
0:00:00.114611569 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 1024
0:00:00.114619690 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.085623582, duration 0:00:00.023219955, granule duration 1024
0:00:00.114629532 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 3776 == time 0:00:00.085623582 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.114644761 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114653841 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114661586 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114671578 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114679150 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.114690411 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.114698263 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.114705667 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     4800] packet 9 (37 bytes) created from buffer
0:00:00.114714334 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     4800] packet 9, gp time 0:00:00.108843537, timestamp 0:00:00.085623582 packetin'd
0:00:00.114725219 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.108843537
0:00:00.114736730 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.114750615 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.114759626 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114767588 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114775067 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114784869 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114792737 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4aca0
0:00:00.114801988 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 1024
0:00:00.114810181 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.108843537, duration 0:00:00.023219955, granule duration 1024
0:00:00.114819995 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 4800 == time 0:00:00.108843537 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.114835412 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114844605 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114852372 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114862355 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114869901 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.114881107 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.114888927 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.114896356 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     5824] packet 10 (37 bytes) created from buffer
0:00:00.114905158 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     5824] packet 10, gp time 0:00:00.132063492, timestamp 0:00:00.108843537 packetin'd
0:00:00.114915785 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.132063492
0:00:00.114927266 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.114935106 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.114943768 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.114951753 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.114959177 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.114968791 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.114983335 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4adc0
0:00:00.114993511 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 1024
0:00:00.115001830 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.132063492, duration 0:00:00.023219954, granule duration 1024
0:00:00.115011795 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 5824 == time 0:00:00.132063492 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.115027517 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115036620 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115044146 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115054287 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115061884 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.115073127 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.115081024 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.115088461 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     6848] packet 11 (38 bytes) created from buffer
0:00:00.115097208 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     6848] packet 11, gp time 0:00:00.155283446, timestamp 0:00:00.132063492 packetin'd
0:00:00.115108163 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.155283446
0:00:00.115119632 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.115127750 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.115136181 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115144041 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115151492 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115161082 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115168894 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4aee0
0:00:00.115178049 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 1024
0:00:00.115186220 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.155283446, duration 0:00:00.023219955, granule duration 1024
0:00:00.115195922 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 6848 == time 0:00:00.155283446 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.115217679 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115227113 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115234765 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115244981 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115252605 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.115263921 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.115271834 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.115279283 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     7872] packet 12 (37 bytes) created from buffer
0:00:00.115288380 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     7872] packet 12, gp time 0:00:00.178503401, timestamp 0:00:00.155283446 packetin'd
0:00:00.115299260 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.178503401
0:00:00.115310907 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.115318775 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.115327031 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115334931 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115342387 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115351941 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115359721 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0x2ab54c064810
0:00:00.115369044 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 1024
0:00:00.115377162 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.178503401, duration 0:00:00.023219955, granule duration 1024
0:00:00.115386879 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 7872 == time 0:00:00.178503401 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.115401935 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115411018 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115418644 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115428597 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115436221 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.115453660 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.115462127 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.115469533 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     8896] packet 13 (57 bytes) created from buffer
0:00:00.115478445 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     8896] packet 13, gp time 0:00:00.201723356, timestamp 0:00:00.178503401 packetin'd
0:00:00.115489185 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.201723356
0:00:00.115500792 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.115508717 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.115517386 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115525404 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115532868 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115542540 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115550382 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4ae50
0:00:00.115559563 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 576
0:00:00.115567678 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.201723356, duration 0:00:00.013061224, granule duration 576
0:00:00.115577578 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 8896 == time 0:00:00.201723356 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.115592834 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115601927 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115609521 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115619519 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115627061 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.115638209 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.115646016 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.115653397 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9472] packet 14 (20 bytes) created from buffer
0:00:00.115661969 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9472] packet 14, gp time 0:00:00.214784580, timestamp 0:00:00.201723356 packetin'd
0:00:00.115681280 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.214784580
0:00:00.115694055 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.115702002 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.115710551 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115718557 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115725998 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115735737 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115743595 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4ad30
0:00:00.115752833 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 128
0:00:00.115761011 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.214784580, duration 0:00:00.002902494, granule duration 128
0:00:00.115770971 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 9472 == time 0:00:00.214784580 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.115786403 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115795528 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115803072 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115813038 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115820624 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.115831900 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.115839838 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.115847327 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9600] packet 15 (20 bytes) created from buffer
0:00:00.115856034 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9600] packet 15, gp time 0:00:00.217687074, timestamp 0:00:00.214784580 packetin'd
0:00:00.115866648 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.217687074
0:00:00.115877904 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.115885683 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.115894473 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115902478 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115915955 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.115926594 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.115934532 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4ac10
0:00:00.115943793 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 128
0:00:00.115952084 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.217687074, duration 0:00:00.002902495, granule duration 128
0:00:00.115962066 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 9600 == time 0:00:00.217687074 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.115977495 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.115986573 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.115994122 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116004270 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116011794 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.116022950 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.116030850 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.116038281 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9728] packet 16 (22 bytes) created from buffer
0:00:00.116046931 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9728] packet 16, gp time 0:00:00.220589569, timestamp 0:00:00.217687074 packetin'd
0:00:00.116057698 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.220589569
0:00:00.116069164 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.116077064 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.116085804 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.116093774 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.116101260 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116110950 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116118692 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4aaf0
0:00:00.116127767 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 128
0:00:00.116135910 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.220589569, duration 0:00:00.002902494, granule duration 128
0:00:00.116151815 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 9728 == time 0:00:00.220589569 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.116167746 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.116176693 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.116184280 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116194518 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116202107 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.116213346 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.116221243 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.116228747 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9856] packet 17 (22 bytes) created from buffer
0:00:00.116237557 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9856] packet 17, gp time 0:00:00.223492063, timestamp 0:00:00.220589569 packetin'd
0:00:00.116248332 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.223492063
0:00:00.116259750 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.116267555 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.116276227 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.116284154 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.116291626 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116301255 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116309075 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0xc4a9d0
0:00:00.116318200 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 128
0:00:00.116326409 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.223492063, duration 0:00:00.002902494, granule duration 128
0:00:00.116336208 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 9856 == time 0:00:00.223492063 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.116351149 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.116360166 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.116367700 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116377618 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116391140 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.116403223 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.116411165 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.116418574 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9984] packet 18 (22 bytes) created from buffer
0:00:00.116427266 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp     9984] packet 18, gp time 0:00:00.226394557, timestamp 0:00:00.223492063 packetin'd
0:00:00.116438071 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.226394557
0:00:00.116449467 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.116457377 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.116466104 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.116474162 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.116481668 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116491262 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116499142 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0x2ab54c0648a0
0:00:00.116508508 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 128
0:00:00.116516734 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.226394557, duration 0:00:00.002902495, granule duration 128
0:00:00.116526526 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 9984 == time 0:00:00.226394557 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.116541680 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.116550748 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.116558314 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116568430 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116575894 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.116587019 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.116594819 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.116602285 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp    10112] packet 19 (22 bytes) created from buffer
0:00:00.116617070 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp    10112] packet 19, gp time 0:00:00.229297052, timestamp 0:00:00.226394557 packetin'd
0:00:00.116628572 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1852:gst_ogg_mux_process_best_pad:<mux:sink_773151224> Updated running gp time of pad <mux:sink_773151224> to 0:00:00.229297052
0:00:00.116640121 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.116647983 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 0
0:00:00.116656758 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.116664663 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.116672229 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116681823 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116689633 32228       0xc39db0 LOG                   oggmux gstoggmux.c:952:gst_ogg_mux_queue_pads:<mux:sink_773151224> popped buffer 0x2ab54c064930
0:00:00.116701258 32228       0xc39db0 DEBUG               oggdemux gstoggstream.c:828:packet_duration_vorbis: duration 128
0:00:00.116709584 32228       0xc39db0 LOG                   oggmux gstoggmux.c:855:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> buffer ts 0:00:00.229297052, duration 0:00:00.002902494, granule duration 128
0:00:00.116719458 32228       0xc39db0 LOG                   oggmux gstoggmux.c:873:gst_ogg_mux_decorate_buffer:<mux:sink_773151224> expected granule 10112 == time 0:00:00.229297052 --> ts diff 0:00:00.000000000 < tolerance 0:00:00.040000000 (?)
0:00:00.116735865 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:335:gst_ogg_mux_sink_event:<mux:sink_773151224> Got eos event
0:00:00.116747053 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1903:gst_ogg_mux_collected:<mux> collected
0:00:00.116755515 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_310169398> looking at pad for buffer
0:00:00.116763031 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1040:gst_ogg_mux_queue_pads:<mux:sink_310169398> new best pad, with buffer 0xc32ab0
0:00:00.116773031 32228       0xc39db0 LOG                   oggmux gstoggmux.c:945:gst_ogg_mux_queue_pads:<mux:sink_773151224> looking at pad for buffer
0:00:00.116780558 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1557:gst_ogg_mux_process_best_pad:<mux> best pad <mux:sink_310169398>, currently pulling from <mux:sink_773151224>
0:00:00.116791297 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1566:gst_ogg_mux_process_best_pad:<mux:sink_773151224> setting eos to true
0:00:00.116799285 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1579:gst_ogg_mux_process_best_pad:<mux:sink_310169398> setting eos to true
0:00:00.116806832 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1651:gst_ogg_mux_process_best_pad:<mux:sink_773151224> pulling from pad
0:00:00.116814223 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1684:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp    10240] packet 20 (43 bytes) created from buffer
0:00:00.116822331 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1759:gst_ogg_mux_process_best_pad:<mux:sink_773151224> swapping in EOS packet
0:00:00.116830288 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1774:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp    10240] packet 20, gp time 0:00:00.232199546, timestamp 0:00:00.229297052 packetin'd
0:00:00.116846519 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1790:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp    10240] packet 20, time 0:00:00.229297052) caused new page
0:00:00.116862830 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1793:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp    10240] new page 3
0:00:00.116871492 32228       0xc39db0 LOG                   oggmux gstoggmux.c:1803:gst_ogg_mux_process_best_pad:<mux:sink_773151224> [gp    10240] packet finishes on current page, updating gp time to 0:00:00.232199546
0:00:00.116884154 32228       0xc39db0 LOG                   oggmux gstoggmux.c:570:gst_ogg_mux_buffer_from_page:<mux> [gp    10240] created buffer 0xc4aca0 from ogg page
0:00:00.116894383 32228       0xc39db0 LOG                   oggmux gstoggmux.c:744:gst_ogg_mux_pad_queue_page:<mux:sink_773151224> [gp    10240] queued buffer page 0xc4aca0 (gp time 0:00:00.232199546, timestamp 0:00:00.000000000), 1 page buffers queued
0:00:00.116906716 32228       0xc39db0 LOG                   oggmux gstoggmux.c:665:gst_ogg_mux_dequeue_page:<mux:sink_310169398> [gp        -1] pushing page
0:00:00.116972422 32228       0xc39db0 DEBUG                  check pipelines/oggmux.c:143:validate_ogg_page: other package on theora chain
0:00:00.117021739 32228       0xc39db0 LOG                   oggmux gstoggmux.c:677:gst_ogg_mux_dequeue_page:<mux> no oldest yet, taking buffer 0xc47ba0 from pad <mux:sink_310169398> with gp time 0:00:00.033333333
0:00:00.117040394 32228       0xc39db0 LOG                   oggmux gstoggmux.c:700:gst_ogg_mux_dequeue_page:<mux:sink_310169398> [gp       64] pushing oldest page buffer 0xc47ba0 (granulepos time 0:00:00.033333333)
0:00:00.117093458 32228       0xc39db0 DEBUG                  check pipelines/oggmux.c:143:validate_ogg_page: other package on theora chain
0:00:00.117128466 32228       0xc39db0 LOG                   oggmux gstoggmux.c:627:gst_ogg_mux_dequeue_page:<mux:sink_310169398> pad is EOS, skipping for dequeue decision
0:00:00.117140599 32228       0xc39db0 LOG                   oggmux gstoggmux.c:677:gst_ogg_mux_dequeue_page:<mux> no oldest yet, taking buffer 0xc4aca0 from pad <mux:sink_773151224> with gp time 0:00:00.232199546
0:00:00.117153244 32228       0xc39db0 LOG                   oggmux gstoggmux.c:700:gst_ogg_mux_dequeue_page:<mux:sink_773151224> [gp    10240] pushing oldest page buffer 0xc4aca0 (granulepos time 0:00:00.232199546)
0:00:00.117179746 32228       0xc39db0 DEBUG                  check pipelines/oggmux.c:138:validate_ogg_page: mark vorbis chain as EOS
0:00:00.117215591 32228       0xc39db0 LOG                   oggmux gstoggmux.c:627:gst_ogg_mux_dequeue_page:<mux:sink_310169398> pad is EOS, skipping for dequeue decision
0:00:00.117227313 32228       0xc39db0 LOG                   oggmux gstoggmux.c:627:gst_ogg_mux_dequeue_page:<mux:sink_773151224> pad is EOS, skipping for dequeue decision
0:00:00.117236118 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_310169398> oggpad 0xc30540 eos 1
0:00:00.117244366 32228       0xc39db0 DEBUG                 oggmux gstoggmux.c:1875:all_pads_eos:<mux:sink_773151224> oggpad 0xc24800 eos 1
0:00:00.117368803 32228       0x9c5010 DEBUG                  check pipelines/oggmux.c:261:eos_watch:<pipeline0> got EOS
0:00:00.118062489 32228       0x9c5010 DEBUG              theoraenc gsttheoraenc.c:1460:theora_enc_change_state:<theoraenc0> PAUSED->READY Clearing theora state
0:00:00.023353108 32235      0x1086010 WARN               theoraenc gsttheoraenc.c:315:gst_theora_enc_class_init: Failed to determine settings for the speed-level property.
0:00:00.110593319 32235      0x12f88a0 WARN                     bin gstbin.c:2395:gst_bin_do_latency_func:<pipeline0> did not really configure latency of 0:00:00.000000000
make: *** [pipelines/oggmux.check] Error 1
