Audio src blocked before session set up
Joakim Tjernlund
Joakim.Tjernlund at infinera.com
Thu Apr 19 04:49:23 EDT 2018
On Thu, 2018-04-19 at 09:27 +0100, David Woodhouse wrote:
>
>
> On Thu, 2018-04-19 at 07:43 +0000, Joakim Tjernlund wrote:
> > On Thu, 2018-04-19 at 08:33 +0100, David Woodhouse wrote:
> > > On Thu, 2018-04-19 at 07:04 +0000, Joakim Tjernlund wrote:
> > > > On Wed, 2018-04-18 at 22:18 +0100, David Woodhouse wrote:
> > > > > I've suddenly started experiencing a problem where my outbound audio in
> > > > > Pidgin is missing — Farstream never seems to send any audio, and I
> > > > > don't even get the farstream-send-codec-changed signal.
> > > > >
> > > > > It's sporadic, and relatively hard to reproduce. And of course the more
> > > > > I turn up the GST_DEBUG debugging, the harder it gets.
> > > > >
> > > > > It looks like the problem occurs when pulsesrc gets blocked:
> > > >
> > > > I have somewhat similar issue in sipe, but input instead. If I change to ALSA and
> > > > do a test call, then the microphone locks up just as the call connects.
> > > > If I recall correctly, USB headsets are needed as well.
> > > > Using Pulse it usually works.
> > > Yeah, that's the same direction — my microphone locks up. I'm also
> > > using a USB headset; perhaps that just affects the latency between
> > > Pidgin setting it to PLAYING, and the first sample arriving?
> >
> > Yes, I think so. My Lync server is in USA and I in Sweden, quite much latency there.
> > Adding USB latency on top kills my microfone.
>
> I don't *think* the network latency is relevant here; this just about
> how long it takes for the microphone to send its first sample, during
> the purple_media_add_stream()...purple_media_add_remote_candidates()...
> purple_media_set_remote_codecs()... code flow.
>
> Although if some of the SDP/ICE negotiation is done over the wire in
> that time for you, perhaps it does make a difference?
>
> And I only really started seeing it this week, which is the first time
> I've been using my code "in anger" for real calls since I implemented
> the DTLS transport. So yeah, maybe the timing of the first incoming
> packet is also relevant somehow; I'm not sure.
>
> > >
> > >
> > > If the first sample arrives *before* the rest of the call setup, it
> > > seems to be OK. It's failing if the sample arrives *during* the call
> > > setup, especially (I think) before _send_src_pad_blocked_callback() is
> > > registered by fs_rtp_session_verify_send_codec_bin_locked().
> > >
> > > Should fs_rtp_session_verify_send_codec_bin_locked() actually be
> > > checking if the pad was *already* blocked, and setting up the codecbin
> > > immediately if so?
> >
> > I cannot say how/where to fix but I will try any patch you throw at me and/or
> > provide logs(just tell me what env. variables to set please :)
>
> Let's start by checking it's the same issue. Does it also occur only
> for some calls?
Choosing ALSA in pidgin, almost every Test call. With Pulse almost never.
>
> Let's look for that 'Task going to paused' message on your microphone
> src element, that I highlighted in my first email. Try something like
> this and compare a working call to a silent one:
>
> GST_DEBUG=3,basesrc:7,task:7 pidgin -d
>
> Annoyingly, I can't reproduce it at all today.
That a big log :) Will this last part do(I hit Ctrl-C when lockup)?:
0:00:44.962957288 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:44.962994192 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:44.963122794 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<alsasrc0>[00m starting negotiation
0:00:44.963142467 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:44.963158904 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3190:gst_base_src_default_negotiate:<alsasrc0>[00m caps of src: audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:44.964819745 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3200:gst_base_src_default_negotiate:<alsasrc0>[00m caps of peer: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:44.964872525 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3211:gst_base_src_default_negotiate:<alsasrc0>[00m have caps: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:44.964923534 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:951:gst_base_src_default_fixate:<alsasrc0>[00m using default caps fixate function
0:00:44.964940314 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3219:gst_base_src_default_negotiate:<alsasrc0>[00m fixated to: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:44.964962911 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:905:gst_base_src_set_caps:<alsasrc0>[00m New caps equal to old ones: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:44.964986677 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3130:gst_base_src_prepare_allocation:<alsasrc0>[00m peer ALLOCATION query failed
0:00:44.965018241 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:44.965033486 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:44.965001168 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<alsasrc0>[00m ALLOCATION (1) params: allocation query: 0x34fd850, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)2\,\ channel-mask\=\(bitmask\)0x0000000000000003", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:44.965060517 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:44.965075912 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:44.973033086 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:44.973070494 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:44.973126003 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:44.973146928 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:44.983102780 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:44.983146420 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:44.983201608 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:44.983221631 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:44.993149909 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:44.993193357 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:44.993247871 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:44.993268328 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.003212725 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.003249741 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.003304927 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.003325225 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.013263736 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.013300748 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.013355941 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.013376215 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.023316895 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.023358678 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.023413866 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.023437161 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.033365041 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.033402153 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.033457887 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.033478238 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.043411888 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.043449128 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.043504170 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.043524619 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.053458993 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.053496120 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.053584351 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.053628215 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.053677074 [336m15587[00m 0x2bfc590 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x2b6c6e0, time 99:99:99.999999999, seq-num 1481, (NULL)
0:00:45.063509394 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.063546914 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.063691214 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<alsasrc0>[00m starting negotiation
0:00:45.063715620 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:45.063732939 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3190:gst_base_src_default_negotiate:<alsasrc0>[00m caps of src: audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.065374715 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3200:gst_base_src_default_negotiate:<alsasrc0>[00m caps of peer: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.065425076 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3211:gst_base_src_default_negotiate:<alsasrc0>[00m have caps: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.065475975 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:951:gst_base_src_default_fixate:<alsasrc0>[00m using default caps fixate function
0:00:45.065492860 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3219:gst_base_src_default_negotiate:<alsasrc0>[00m fixated to: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.065515377 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:905:gst_base_src_set_caps:<alsasrc0>[00m New caps equal to old ones: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.065538675 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3130:gst_base_src_prepare_allocation:<alsasrc0>[00m peer ALLOCATION query failed
0:00:45.065570039 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:45.065585409 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:45.065553005 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<alsasrc0>[00m ALLOCATION (1) params: allocation query: 0x34b3280, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)2\,\ channel-mask\=\(bitmask\)0x0000000000000003", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:45.065616158 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.065631944 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
(10:41:16) backend-fs2: got new local candidate: 26
(10:41:16) backend-fs2: got new local candidate: 25
(10:41:16) backend-fs2: got new local candidate: 24
(10:41:16) backend-fs2: got new local candidate: 23
(10:41:16) backend-fs2: got new local candidate: 22
(10:41:16) backend-fs2: got new local candidate: 21
(10:41:16) backend-fs2: got new local candidate: 26
(10:41:16) backend-fs2: got new local candidate: 25
(10:41:16) backend-fs2: got new local candidate: 24
(10:41:16) backend-fs2: got new local candidate: 23
(10:41:16) backend-fs2: got new local candidate: 22
(10:41:16) backend-fs2: got new local candidate: 21
(10:41:16) backend-fs2: got new local candidate: 19
(10:41:16) backend-fs2: got new local candidate: 17
(10:41:16) backend-fs2: got new local candidate: 16
(10:41:16) backend-fs2: got new local candidate: 19
(10:41:16) backend-fs2: got new local candidate: 17
(10:41:16) backend-fs2: got new local candidate: 16
(10:41:16) backend-fs2: got new local candidate: 15
(10:41:16) backend-fs2: got new local candidate: 14
(10:41:16) backend-fs2: got new local candidate: 13
(10:41:16) backend-fs2: got new local candidate: 12
(10:41:16) backend-fs2: got new local candidate: 11
(10:41:16) backend-fs2: got new local candidate: 10
(10:41:16) backend-fs2: got new local candidate: 9
(10:41:16) backend-fs2: got new local candidate: 8
(10:41:16) backend-fs2: got new local candidate: 7
(10:41:16) backend-fs2: got new local candidate: 15
(10:41:16) backend-fs2: got new local candidate: 14
(10:41:16) backend-fs2: got new local candidate: 13
(10:41:16) backend-fs2: got new local candidate: 12
(10:41:16) backend-fs2: got new local candidate: 11
(10:41:16) backend-fs2: got new local candidate: 10
(10:41:16) backend-fs2: got new local candidate: 9
(10:41:16) backend-fs2: got new local candidate: 8
(10:41:16) backend-fs2: got new local candidate: 7
(10:41:16) backend-fs2: got new local candidate: 1
(10:41:16) backend-fs2: got new local candidate: 2
(10:41:16) backend-fs2: got new local candidate: 3
(10:41:16) backend-fs2: got new local candidate: 4
(10:41:16) backend-fs2: got new local candidate: 5
(10:41:16) backend-fs2: got new local candidate: 6
(10:41:16) backend-fs2: got new local candidate: 1
(10:41:16) backend-fs2: got new local candidate: 2
(10:41:16) backend-fs2: got new local candidate: 3
(10:41:16) backend-fs2: got new local candidate: 4
(10:41:16) backend-fs2: got new local candidate: 5
(10:41:16) backend-fs2: got new local candidate: 6
0:00:45.073548032 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.073598429 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.073658134 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.073681555 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
(10:41:16) sipe: SIP transactions count:1 after addition
(10:41:16) sipe: MESSAGE >>>>>>>>>> SIP(0x33def80)
0:00:45.083621056 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.083668637 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.083720508 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.083739921 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.093689002 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.093733633 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.093785013 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.093804311 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.103735687 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.103777592 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.103828831 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.103847954 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.113782739 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.113819367 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.113875036 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.113895495 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.123820962 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.123862436 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.123917356 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.123937940 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.133888133 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.133925300 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.133980691 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.134001570 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.134021055 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.134032045 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.134067626 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.134083592 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.143963364 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.144011283 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.144104851 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.144127134 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.144190423 [336m15587[00m 0x2bfc590 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x3806990, time 99:99:99.999999999, seq-num 1532, (NULL)
0:00:45.154049010 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.154095305 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.154226759 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<alsasrc0>[00m starting negotiation
0:00:45.154246664 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:45.154263092 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3190:gst_base_src_default_negotiate:<alsasrc0>[00m caps of src: audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.155945081 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3200:gst_base_src_default_negotiate:<alsasrc0>[00m caps of peer: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.155998149 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3211:gst_base_src_default_negotiate:<alsasrc0>[00m have caps: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.156050160 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:951:gst_base_src_default_fixate:<alsasrc0>[00m using default caps fixate function
0:00:45.156066913 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3219:gst_base_src_default_negotiate:<alsasrc0>[00m fixated to: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.156089770 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:905:gst_base_src_set_caps:<alsasrc0>[00m New caps equal to old ones: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.156113353 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3130:gst_base_src_prepare_allocation:<alsasrc0>[00m peer ALLOCATION query failed
0:00:45.156146025 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:45.156161425 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:45.156128104 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<alsasrc0>[00m ALLOCATION (1) params: allocation query: 0x34b5450, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)2\,\ channel-mask\=\(bitmask\)0x0000000000000003", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:45.156188840 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.156204744 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.164088709 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.164133400 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.164188846 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.164209470 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.174194247 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.174237403 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.174292029 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.174312398 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.184234602 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.184271453 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.184326528 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.184346900 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.194281517 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.194318463 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.194373245 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.194393887 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.204331063 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.204368267 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.204423202 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.204443649 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.214378323 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.214415167 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.214471758 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.214492335 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.224427163 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.224469664 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.224524657 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.224545133 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.234486596 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.234523380 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.234578074 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.234623450 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.244538452 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.244575356 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.244677153 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.244703387 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.244764937 [336m15587[00m 0x2bfc590 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x37c8170, time 99:99:99.999999999, seq-num 1534, (NULL)
0:00:45.254673069 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.254709795 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.254838109 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<alsasrc0>[00m starting negotiation
0:00:45.254858060 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:45.254874830 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3190:gst_base_src_default_negotiate:<alsasrc0>[00m caps of src: audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.256536142 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3200:gst_base_src_default_negotiate:<alsasrc0>[00m caps of peer: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.256594525 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3211:gst_base_src_default_negotiate:<alsasrc0>[00m have caps: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.256643600 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:951:gst_base_src_default_fixate:<alsasrc0>[00m using default caps fixate function
0:00:45.256660252 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3219:gst_base_src_default_negotiate:<alsasrc0>[00m fixated to: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.256683034 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:905:gst_base_src_set_caps:<alsasrc0>[00m New caps equal to old ones: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.256706417 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3130:gst_base_src_prepare_allocation:<alsasrc0>[00m peer ALLOCATION query failed
0:00:45.256738017 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:45.256753434 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:45.256720797 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<alsasrc0>[00m ALLOCATION (1) params: allocation query: 0x34b2f20, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)2\,\ channel-mask\=\(bitmask\)0x0000000000000003", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:45.256780421 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.256796149 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.264668565 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.264705198 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.264760140 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.264780732 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.274725019 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.274770615 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.274825227 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.274845678 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.284778576 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.284815455 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.284870215 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.284890611 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.294833838 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.294870664 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.294926055 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.294946579 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.304181425 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.304218687 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.304273665 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.304294247 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.314207736 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.314244850 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.314300221 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.314320650 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.324259093 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.324300628 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.324355703 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.324383341 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.334364737 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.334411185 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.334466917 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.334487283 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.344401915 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.344447158 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.344538355 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.344560740 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.344632379 [336m15587[00m 0x2bfc590 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x3806990, time 99:99:99.999999999, seq-num 1536, (NULL)
0:00:45.354462836 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.354509515 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.354659842 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<alsasrc0>[00m starting negotiation
0:00:45.354685057 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:45.354701963 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3190:gst_base_src_default_negotiate:<alsasrc0>[00m caps of src: audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.356347669 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3200:gst_base_src_default_negotiate:<alsasrc0>[00m caps of peer: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.356404481 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3211:gst_base_src_default_negotiate:<alsasrc0>[00m have caps: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.356449992 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:951:gst_base_src_default_fixate:<alsasrc0>[00m using default caps fixate function
0:00:45.356465946 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3219:gst_base_src_default_negotiate:<alsasrc0>[00m fixated to: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.356488507 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:905:gst_base_src_set_caps:<alsasrc0>[00m New caps equal to old ones: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.356511788 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3130:gst_base_src_prepare_allocation:<alsasrc0>[00m peer ALLOCATION query failed
0:00:45.356543795 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:45.356559360 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:45.356526105 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<alsasrc0>[00m ALLOCATION (1) params: allocation query: 0x34b54a0, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)2\,\ channel-mask\=\(bitmask\)0x0000000000000003", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:45.356586359 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.356609111 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.364512011 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.364557505 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.364628542 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.364653563 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.374556907 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.374622075 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.374681721 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.374703067 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.384628024 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.384673899 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.384729254 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.384749824 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.394684844 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.394730180 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.394785686 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.394806047 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.404712295 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.404757630 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.404813101 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.404833774 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
(10:41:17) sipe: MESSAGE <<<<<<<<<< SIP(0x33def80)
(10:41:17) sipe: sip_sec_verify_signature: message is:<TLS-DSK><71063C8E><24><SIP Communications Service><sv-sfbfe-prd2.infinera.com><18EBg6B52aCE79i6297m9513t582FbB9CDxE951x><1><INVITE><sip:Joakim.Tjernlund at infinera.com><402308230><sip:SFBPool.infinera.com at infinera.com;gruu;opaque=srvr:Microsoft.Rtc.Applications.TestBot:JFxlwS8XWF2-gjeGxzV-3wAA><><><><><100> signature to verify is:e3ec68f8c3fcfcadf33b5eb6bc337c74a5b0e781
(10:41:17) sipe: sip_transport_input: signature of incoming message validated
(10:41:17) sipe: process_input_message: msg->response(100),msg->method(INVITE)
(10:41:17) sipe: process_input_message: got provisional (100) response, ignoring
0:00:45.414780398 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.414825563 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.414881490 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.414901902 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.424830841 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.424881218 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.424937383 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.424958163 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.434866330 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.434911786 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.434967109 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.434987585 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.443933735 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.443979705 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.444066898 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.444089003 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.444125629 [336m15587[00m 0x2bfc590 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x37c8170, time 99:99:99.999999999, seq-num 1538, (NULL)
0:00:45.453986889 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.454031488 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.454159830 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<alsasrc0>[00m starting negotiation
0:00:45.454179873 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:45.454203171 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3190:gst_base_src_default_negotiate:<alsasrc0>[00m caps of src: audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.455867227 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3200:gst_base_src_default_negotiate:<alsasrc0>[00m caps of peer: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.455919639 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3211:gst_base_src_default_negotiate:<alsasrc0>[00m have caps: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.455964508 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:951:gst_base_src_default_fixate:<alsasrc0>[00m using default caps fixate function
0:00:45.455980843 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3219:gst_base_src_default_negotiate:<alsasrc0>[00m fixated to: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.456003386 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:905:gst_base_src_set_caps:<alsasrc0>[00m New caps equal to old ones: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.456031704 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3130:gst_base_src_prepare_allocation:<alsasrc0>[00m peer ALLOCATION query failed
0:00:45.456063977 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:45.456079725 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:45.456046595 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<alsasrc0>[00m ALLOCATION (1) params: allocation query: 0x351a280, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)2\,\ channel-mask\=\(bitmask\)0x0000000000000003", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:45.456107050 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.456122968 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.464039991 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.464085492 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.464141256 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.464162116 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.474097172 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.474146757 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.474202930 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.474226155 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.484141544 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.484186232 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.484241984 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.484262603 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.494186486 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.494237981 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.494293207 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.494313924 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.504237954 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.504283327 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.504338207 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.504358721 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.514279256 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.514324514 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.514380103 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.514400592 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.524329812 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.524380054 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.524435841 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.524456683 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.534390225 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.534435395 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.534491172 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.534511631 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.544430846 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.544475560 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.544564199 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.544586179 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.544649839 [336m15587[00m 0x2bfc590 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x3806990, time 99:99:99.999999999, seq-num 1540, (NULL)
0:00:45.554487232 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.554533362 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.554678161 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<alsasrc0>[00m starting negotiation
0:00:45.554703318 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:45.554720405 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3190:gst_base_src_default_negotiate:<alsasrc0>[00m caps of src: audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.556362090 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3200:gst_base_src_default_negotiate:<alsasrc0>[00m caps of peer: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.556412567 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3211:gst_base_src_default_negotiate:<alsasrc0>[00m have caps: audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.556467447 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:951:gst_base_src_default_fixate:<alsasrc0>[00m using default caps fixate function
0:00:45.556484428 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3219:gst_base_src_default_negotiate:<alsasrc0>[00m fixated to: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.556506596 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:905:gst_base_src_set_caps:<alsasrc0>[00m New caps equal to old ones: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)2, channel-mask=(bitmask)0x0000000000000003
0:00:45.556530325 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3130:gst_base_src_prepare_allocation:<alsasrc0>[00m peer ALLOCATION query failed
0:00:45.556561791 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:45.556577439 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:45.556544414 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<alsasrc0>[00m ALLOCATION (1) params: allocation query: 0x2996f20, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)44100\,\ channels\=\(int\)2\,\ channel-mask\=\(bitmask\)0x0000000000000003", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:45.556607428 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.556623038 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.564538142 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.564583054 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.564656072 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.564677651 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
(10:41:17) sipe: MESSAGE <<<<<<<<<< SIP(0x33def80)
(10:41:17) sipe: sip_sec_verify_signature: message is:<TLS-DSK><A33D4C1A><25><SIP Communications Service><sv-sfbfe-prd2.infinera.com><18EBg6B52aCE79i6297m9513t582FbB9CDxE951x><1><INVITE><sip:Joakim.Tjernlund at infinera.com><402308230><sip:SFBPool.infinera.com at infinera.com;gruu;opaque=srvr:Microsoft.Rtc.Applications.TestBot:JFxlwS8XWF2-gjeGxzV-3wAA><5a4d1a3c4a><sip:RtcApplication-c5536de0-48f7-44e3-b5e8-4f069f771df6 at infinera.com><><><180> signature to verify is:b93a2fe0514c484f6b67a6fa555b60e86ec37dc1
(10:41:17) sipe: sip_transport_input: signature of incoming message validated
(10:41:17) sipe: process_input_message: msg->response(180),msg->method(INVITE)
(10:41:17) sipe: process_input_message: got provisional (180) response, ignoring
0:00:45.574608427 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.574660811 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.574716379 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.574737180 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.584642074 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.584687956 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.584744108 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.584764921 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.594701635 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.594747658 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.594803078 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.594823645 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.604756055 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.604804377 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.604859793 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.604880427 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.614783743 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.614829828 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.614885480 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.614906194 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.624826396 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.624863430 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.624919323 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.624947461 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
(10:41:17) sipe: MESSAGE <<<<<<<<<< SIP(0x33def80)
(10:41:17) sipe: sip_sec_verify_signature: message is:<TLS-DSK><F4A6464A><26><SIP Communications Service><sv-sfbfe-prd2.infinera.com><18EBg6B52aCE79i6297m9513t582FbB9CDxE951x><1><INVITE><sip:Joakim.Tjernlund at infinera.com><402308230><sip:SFBPool.infinera.com at infinera.com;gruu;opaque=srvr:Microsoft.Rtc.Applications.TestBot:JFxlwS8XWF2-gjeGxzV-3wAA><5a4d1a3c4a><sip:RtcApplication-c5536de0-48f7-44e3-b5e8-4f069f771df6 at infinera.com><><><200> signature to verify is:1def2bee25ef8e2668d58dd266fa80d01fecdb40
(10:41:17) sipe: sip_transport_input: signature of incoming message validated
(10:41:17) sipe: process_input_message: msg->response(200),msg->method(INVITE)
(10:41:17) sipe: process_input_message: we have a transaction callback
(10:41:17) sipe: sipe_dialog_parse_routes: route <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd2.infinera.com;opaque=state:F:Ci.R1325d800;lr;ms-route-sig=hnNN6AxCxSRaN8XfYWZInuLvi95jyhtXcMpBTgzo7Mybfb7t4HZTDlQAAA>
(10:41:17) sipe: sipe_schedule_allocate timeouts count 11 after addition
(10:41:17) sipe: scheduling action <media-stream-connect><18EBg6B52aCE79i6297m9513t582FbB9CDxE951x><audio> timeout 30 seconds
(10:41:17) sipe: sipe_schedule_remove: action name=<media-call-request><18EBg6B52aCE79i6297m9513t582FbB9CDxE951x>
(10:41:17) sipe: MESSAGE >>>>>>>>>> SIP(0x33def80)
(10:41:17) sipe: process_input_message: removing CSeq 6
(10:41:17) sipe: SIP transactions count:0 after removal
(10:41:17) backend-fs2: farstream-component-state-changed: component: 1 state: CONNECTING
(10:41:17) backend-fs2: farstream-component-state-changed: component: 2 state: CONNECTING
0:00:45.638912733 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<alsasrc0>[00m no sync needed
0:00:45.638939947 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<alsasrc0>[00m buffer ok
0:00:45.639009520 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x3616f20, time 99:99:99.999999999, seq-num 1544, (NULL)
0:00:45.640550378 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:45.642504306 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x7fb3c40022a0, time 99:99:99.999999999, seq-num 1562, (NULL)
0:00:45.643202826 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1975:gst_base_src_default_event:<alsasrc0>[00m handle event reconfigure event: 0x7fb3c40022a0, time 99:99:99.999999999, seq-num 1586, (NULL)
0:00:45.644318017 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:432:gst_base_src_init:<GstBaseSrc at 0x7fb3c402c300>[00m creating src pad
0:00:45.644354665 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:435:gst_base_src_init:<GstBaseSrc at 0x7fb3c402c300>[00m setting functions on src pad
0:00:45.644368857 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:443:gst_base_src_init:<GstBaseSrc at 0x7fb3c402c300>[00m adding src pad
0:00:45.644381767 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:460:gst_base_src_init:<GstBaseSrc at 0x7fb3c402c300>[00m init done
0:00:45.645526979 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<dtmfsrc0>[00m query caps returns 1
0:00:45.646979296 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3769:gst_base_src_activate_mode:<dtmfsrc0:src>[00m activating in mode 1
0:00:45.647006002 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3695:gst_base_src_activate_push:<dtmfsrc0>[00m Activating in push mode
0:00:45.647016462 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3374:gst_base_src_start_complete:<dtmfsrc0>[00m starting source
0:00:45.647024387 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3398:gst_base_src_start_complete:<dtmfsrc0>[00m format: time, have size: 0, size: 18446744073709551615, duration: -1
0:00:45.647036164 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3401:gst_base_src_start_complete:<dtmfsrc0>[00m is seekable: 0
0:00:45.647044495 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3406:gst_base_src_start_complete:<dtmfsrc0>[00m is random_access: 0
0:00:45.647052499 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3569:gst_base_src_set_flushing:<dtmfsrc0>[00m flushing 0, live_play 0
0:00:45.647062551 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1568:gst_base_src_perform_seek:<dtmfsrc0>[00m doing seek: (NULL)
0:00:45.647071779 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1624:gst_base_src_perform_seek:<dtmfsrc0>[00m seek with seqnum 1633
0:00:45.647079584 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1661:gst_base_src_perform_seek:<dtmfsrc0>[00m segment configured from 0 to -1, position 0
0:00:45.647088441 [336m15587[00m 0x298a000 [36mINFO [00m [00m basesrc gstbasesrc.c:1331:gst_base_src_do_seek:<dtmfsrc0>[00m seeking: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:45.647116253 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m task gsttask.c:431:gst_task_new:[00m Created task 0x37fc5f0
0:00:45.647125523 [336m15587[00m 0x298a000 [36mINFO [00m [00m task gsttask.c:457:gst_task_set_lock:[00m setting stream lock 0x7fb3c40280e0 on task 0x37fc5f0
0:00:45.647148890 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m task gsttask.c:688:gst_task_set_state:<task3>[00m Changing task 0x37fc5f0 to state 0
0:00:45.647209831 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3515:gst_base_src_start_wait:<dtmfsrc0>[00m got ok
0:00:45.647274085 [336m15587[00m 0x34f9850 [37mDEBUG [00m [00m task gsttask.c:290:gst_task_func:[00m Entering task 0x37fc5f0, thread 0x34f9850
0:00:45.647315262 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3804:gst_base_src_change_state:<dtmfsrc0>[00m PAUSED->PLAYING
0:00:45.647353531 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3648:gst_base_src_set_playing:<dtmfsrc0>[00m unschedule clock
0:00:45.647363663 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3655:gst_base_src_set_playing:<dtmfsrc0>[00m live running 1
0:00:45.647374359 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3662:gst_base_src_set_playing:<dtmfsrc0>[00m unlock stop
0:00:45.647375305 [336m15587[00m 0x34f9850 [37mDEBUG [00m [00m task gsttask.c:252:gst_task_configure_name:<dtmfsrc0:src>[00m Setting thread name to 'dtmfsrc0:src'
0:00:45.647384145 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m task gsttask.c:688:gst_task_set_state:<dtmfsrc0:src>[00m Changing task 0x37fc5f0 to state 0
0:00:45.647432369 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3678:gst_base_src_set_playing:<dtmfsrc0>[00m signal
0:00:45.647489426 [336m15587[00m 0x34f9850 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<dtmfsrc0>[00m query uri returns 0
0:00:45.647508316 [336m15587[00m 0x34f9850 [32;01mFIXME [00m [00;04m default gstutils.c:3902:gst_pad_create_stream_id_internal:<dtmfsrc0:src>[00m Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:45.647523866 [336m15587[00m 0x34f9850 [37mDEBUG [00m [00m basesrc gstbasesrc.c:870:gst_base_src_send_stream_start:<dtmfsrc0>[00m Pushing STREAM_START
0:00:45.647572822 [336m15587[00m 0x34f9850 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<dtmfsrc0>[00m starting negotiation
0:00:45.647582392 [336m15587[00m 0x34f9850 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<dtmfsrc0>[00m query caps returns 1
(10:41:17) backend-fs2: farstream-send-codec-changed: codec: 111: audio SIREN clock:16000 channels:1 bitrate=16000
0:00:45.652505447 [336m15587[00m 0x34f9850 [33;01mWARN [00m [00m audio-resampler audio-resampler.c:274:convert_taps_gint16_c:[00m can't find exact taps
0:00:45.652569277 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m audio-resampler audio-resampler.c:274:convert_taps_gint16_c:[00m can't find exact taps
0:00:45.652808345 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m audio-resampler audio-resampler.c:274:convert_taps_gint16_c:[00m can't find exact taps
0:00:45.652903008 [336m15587[00m 0x34f9850 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:45.652926053 [336m15587[00m 0x34f9850 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:45.652882095 [336m15587[00m 0x34f9850 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<dtmfsrc0>[00m ALLOCATION (1) params: allocation query: 0x7fb3a80024a0, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ rate\=\(int\)16000\,\ channels\=\(int\)1\,\ layout\=\(string\)interleaved", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:45.652956119 [336m15587[00m 0x34f9850 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<dtmfsrc0>[00m next_ts 99:99:99.999999999 size 4096
0:00:45.652972368 [336m15587[00m 0x34f9850 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<dtmfsrc0>[00m calling create offset 18446744073709551615 length 4096, time 0
0:00:45.653202424 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3260:gst_base_src_negotiate:<alsasrc0>[00m starting negotiation
0:00:45.653226158 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:1283:gst_base_src_default_query:<alsasrc0>[00m query caps returns 1
0:00:45.653243056 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3190:gst_base_src_default_negotiate:<alsasrc0>[00m caps of src: audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ U8, S16LE, S24_32LE, S32LE, S24LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.661866327 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3200:gst_base_src_default_negotiate:<alsasrc0>[00m caps of peer: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)16000, channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.661970263 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3211:gst_base_src_default_negotiate:<alsasrc0>[00m have caps: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)16000, channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)2, channel-mask=(bitmask)0x0000000000000003; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)1; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)3, channel-mask=(bitmask)0x000000000000000b; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)4, channel-mask=(bitmask)0x0000000000000033; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)16000, channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)6, channel-mask=(bitmask)0x000000000000003f; audio/x-raw, format=(string){ S16LE, S32LE }, layout=(string)interleaved, rate=(int)[ 4000, 384000 ], channels=(int)8, channel-mask=(bitmask)0x0000000000000c3f
0:00:45.662050671 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:951:gst_base_src_default_fixate:<alsasrc0>[00m using default caps fixate function
0:00:45.662073869 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3219:gst_base_src_default_negotiate:<alsasrc0>[00m fixated to: audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)16000, channels=(int)1
0:00:45.705096753 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m audio-resampler audio-resampler.c:274:convert_taps_gint16_c:[00m can't find exact taps
0:00:45.705428642 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3130:gst_base_src_prepare_allocation:<alsasrc0>[00m peer ALLOCATION query failed
0:00:45.705470787 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'allocator' of type 'GArray'
0:00:45.705486381 [336m15587[00m 0x298a000 [33;01mWARN [00m [00m structure gststructure.c:1831:priv_gst_structure_append_to_gstring:[00m No value transform to serialize field 'pool' of type 'GArray'
0:00:45.705449663 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:3137:gst_base_src_prepare_allocation:<alsasrc0>[00m ALLOCATION (1) params: allocation query: 0x34b3280, GstQueryAllocation, caps=(GstCaps)"audio/x-raw\,\ format\=\(string\)S16LE\,\ layout\=\(string\)interleaved\,\ rate\=\(int\)16000\,\ channels\=\(int\)1", need-pool=(boolean)true, allocator=(GArray)NULL, pool=(GArray)NULL;
0:00:45.705512825 [336m15587[00m 0x298a000 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<alsasrc0>[00m next_ts 99:99:99.999999999 size 0
0:00:45.705527340 [336m15587[00m 0x298a000 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<alsasrc0>[00m calling create offset 18446744073709551615 length 0, time 0
0:00:45.773868901 [336m15587[00m 0x351a2d0 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2191:gst_base_src_do_sync:<nicesrc0>[00m no latency needed, live 1, sync 0
0:00:45.773943441 [336m15587[00m 0x351a2d0 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2216:gst_base_src_do_sync:<nicesrc0>[00m startup PTS: 99:99:99.999999999, DTS 99:99:99.999999999, running_time 0:00:16.816680027
0:00:45.773970547 [336m15587[00m 0x351a2d0 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2228:gst_base_src_do_sync:<nicesrc0>[00m no timestamp offset needed
0:00:45.773981219 [336m15587[00m 0x351a2d0 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2244:gst_base_src_do_sync:<nicesrc0>[00m created DTS 0:00:16.816680027
0:00:45.774004812 [336m15587[00m 0x351a2d0 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2266:gst_base_src_do_sync:<nicesrc0>[00m created PTS 0:00:16.816680027
0:00:45.774016609 [336m15587[00m 0x351a2d0 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<nicesrc0>[00m no sync needed
0:00:45.774026466 [336m15587[00m 0x351a2d0 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<nicesrc0>[00m buffer ok
0:00:45.774061640 [336m15587[00m 0x351a2d0 [36mINFO [00m [00m basesrc gstbasesrc.c:2836:gst_base_src_loop:<nicesrc0>[00m marking pending DISCONT
0:00:45.774230879 [336m15587[00m 0x351a2d0 [33;01mWARN [00m [00m srtpdec gstsrtpdec.c:686:validate_buffer:<srtpdec_1>[00m No SSRC found in buffer
0:00:45.774246096 [336m15587[00m 0x351a2d0 [33;01mWARN [00m [00m srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain:<srtpdec_1>[00m Invalid buffer, dropping
0:00:45.774263037 [336m15587[00m 0x351a2d0 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<nicesrc0>[00m next_ts 99:99:99.999999999 size 4096
0:00:45.774278387 [336m15587[00m 0x351a2d0 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<nicesrc0>[00m calling create offset 18446744073709551615 length 4096, time 0
0:00:45.977812956 [336m15587[00m 0x351a2d0 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2256:gst_base_src_do_sync:<nicesrc0>[00m created DTS 0:00:17.020547510
0:00:45.977855370 [336m15587[00m 0x351a2d0 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2266:gst_base_src_do_sync:<nicesrc0>[00m created PTS 0:00:17.020547510
0:00:45.977873128 [336m15587[00m 0x351a2d0 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2304:gst_base_src_do_sync:<nicesrc0>[00m no sync needed
0:00:45.977884591 [336m15587[00m 0x351a2d0 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2513:gst_base_src_get_range:<nicesrc0>[00m buffer ok
0:00:45.977927508 [336m15587[00m 0x351a2d0 [33;01mWARN [00m [00m srtpdec gstsrtpdec.c:686:validate_buffer:<srtpdec_1>[00m No SSRC found in buffer
0:00:45.977945718 [336m15587[00m 0x351a2d0 [33;01mWARN [00m [00m srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain:<srtpdec_1>[00m Invalid buffer, dropping
0:00:45.977961958 [336m15587[00m 0x351a2d0 [33;01mLOG [00m [00m basesrc gstbasesrc.c:2727:gst_base_src_loop:<nicesrc0>[00m next_ts 99:99:99.999999999 size 4096
0:00:45.977986706 [336m15587[00m 0x351a2d0 [37mDEBUG [00m [00m basesrc gstbasesrc.c:2449:gst_base_src_get_range:<nicesrc0>[00m calling create offset 18446744073709551615 length 4096, time 0
(10:41:17) sighandler: Caught signal 2
(10:41:17) account: Disconnecting account Joakim.Tjernlund at infinera.com,jocke at infinera.com (0x281c490)
(10:41:17) connection: Disconnecting connection 0x2ba5c30
(10:41:17) sipe: SIP transactions count:1 after addition
More information about the Devel
mailing list