search

tieto / sipe

A third-party Pidgin plugin for Microsoft Lync/OCS - clone of upstream http://repo.or.cz/w/siplcs.git
GNU General Public License v2.0
129 stars 24 forks source link

Inaudible speech during first minutes of Pidgin calls #107

Open xnandersson opened 8 years ago

xnandersson commented 8 years ago

Still an issue. Several reports. Can it be something else but the codec?

"Audio (both sent and received) is distorted and full of static -- basically unusable -- at the beginning of a call or meeting, but after anywhere between 1 and 10 minutes, it suddenly clears up. This happens regardless of whether I'm using the office Ethernet, the office WiFi, or connected via the VPN."

tmuehlhoff commented 8 years ago

I am affected still as well (peers are keep on telling me that my voice is distorted), though I haven't yet had taken any measures. Compared to before it doesn't seem to bother my peers as much as before, so it has definitely improved. Let me know if I can assist. /To

xhaakon commented 8 years ago

Please make some logs with GST_DEBUG=4 and post your dpkg --list. What's your settings in Pidgin's Voice/Video preferences?

rbordelo commented 8 years ago

Attached are the requested logs and dpkg --list. The logs was taken during calls to both the test call service and to a cell phone.

dpkg_list.txt pidgin_gst_debug.log.gz pidgin_gst_debug2.log.gz pidgin_gst_debug3.log.gz pidgin_gst_debug4.log.gz

xnandersson commented 8 years ago

Perhaps there are some pointers in the packets. RTCP-packets might carry useful information https://en.wikipedia.org/wiki/RTP_Control_Protocol

Either it is the packets, or it is an issue with the codec.

xhaakon commented 8 years ago

Is here anyone who has these audio issues and uses something else than Ubuntu 14.04?

@rbordelo is on 14.04 according to his logs, and if I remember correctly the same is true for @tmuehlhoff. Might be an issue with old GStreamer...

xnandersson commented 8 years ago

I'm on 16.04 and have issues.

rbeldin commented 8 years ago

I am on 16.04 and have experienced complete silence for 1-2 minutes during the beginning of a call that usually ends up with the other party hanging up. Once this happens, I can't connect back to them and they just hear a couple of fast beeps before it hangs up. Most of the people I engage with are running 'real' Skype for Business on Windows PCs.

xnandersson commented 8 years ago

@rbeldin Sounds like a different issue to me. I also wouldn't claim that this issue is "inaudible" as the headline suggest, but definitely a "cracking" noise whenever your counterpart speaks. During moments of silence there is no background noise. It seems like a decoder issue, because the other party (who is on MS Lync) can hear everything just perfectly. The cracking noise is only on the Pidgin client. Also if both TX and RX uses similar routes, that perhaps also cancel out the possibility of a bandwidth issue (latency) or packet loss.

xnandersson commented 8 years ago

Finding from one of our users:

"If it helps, see below something experienced in last few days:

The above happened on 2 occasions already, coincidence?"

xhaakon commented 8 years ago

@xnandersson That doesn't have to be so far-fetched a coincidence as it may look since Evolution might connect to pulseaudio server in order to e.g. play notification sounds.

I've seen something similar under unrelated circumstances - if I recall correctly, when I would launch a QEMU virtual machine (with a configured sound card) using libvirt, the volume of my media player would suddenly decrease, and after turning the VM off, it would return to the original level. Sound quality wasn't affected though, just the volume.

The user could try to collect some potentially useful piece of data should the situation you described happen again:

xnandersson commented 7 years ago

Looks like one can "fix" the problem by opening some other applications. If I start and close Thunderbird for example a few times it seems like it can fix the sound. No idea how this correlates though.... So perhaps it is just a matter of kicking pulse-audio a few times?

joakim-tjernlund commented 7 years ago

I got bad received Audio, either I got no audio at all or there is audio with static noise in it. Using Gentoo with gst 1.8.2 and lastest sipe, libnice and farstream from https://github.com/tieto/

xhaakon commented 7 years ago

@joakim-tjernlund Does the noise go away after a while or is it persistent? The former would be consistent with this bug report.

joakim-tjernlund commented 7 years ago

@xhaakon In this one off test I had noisy received audio to begin with and after a minute or two received audio died and we ended the test shortly after that. He could hear me all the time though.

xnandersson commented 7 years ago

@joakim-tjernlund Try next time to let the call go on for longer. Preferably 10-20 minutes. Also try and open/close some other programs at the same time.

joakim-tjernlund commented 7 years ago

I just hit another odd thing, I tested an Audio call with a coworker and while he could hear me fine, I just heard myself! BTW, it would be great if one could call oneself for testing purposes.

xhaakon commented 7 years ago

BTW, it would be great if one could call oneself for testing purposes.

You can use Lync's integrated test call bot for checking your audio configuration. In Pidgin, go to Accounts -> [your sipe account] -> Test call.

joakim-tjernlund commented 7 years ago

Ahh, news to me. Test Call works fine for me.

joakim-tjernlund commented 7 years ago

Anyone compared ALSA vs. Pulseaudio?

xnandersson commented 7 years ago

No. But reportedly Debian is not tainted with this problem...

joakim-tjernlund commented 7 years ago

And debian uses ALSA? I just tried to use ALSA instead and did a Test Call but heard no sound at all :(

joakim-tjernlund commented 7 years ago

Tried again a few times and now I got choppy sound using ALSA. Wonder if this can anything to do with kernel conf CONFIG_SND_HDA_PREALLOC_SIZE=64 ?

joakim-tjernlund commented 7 years ago

On another machine I get choppy audio and GST_DEBUG=4 pidgin gives me

alsa conf.c:4817:snd_config_expand: alsalib error: Unknown parameters {AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
alsa pcm.c:2450:snd_pcm_open_noupdate: alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
alsa gstalsasink.c:330:gst_alsasink_getcaps:<autoaudiosink0-actual-sink-alsa> returning caps 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

Any chance this is related?

joakim-tjernlund commented 7 years ago

Which H264 impl. fits SIPE best, openh264 or x264 ? Minimum version of there?

joakim-tjernlund commented 7 years ago

Are people using srtp 1.5.4/2.0.0 yet?

xhaakon commented 7 years ago

Which H264 impl. fits SIPE best, openh264 or x264 ? Minimum version of there?

Sipe uses x264 through GStreamer encoder and decoder plugins from the "ugly" set. We don't prescribe any minimal required version, but best choose something less ancient than what Ubuntu 14.04 has (our oldest supported system). The exact version number is a bit complex 2:0.142.2389+git956c8d8-2 - that upstream commit ID it includes is probably your best guide.

We'd also like to take advantage of hardware accelerated H264 encoding & decoding through VAAPI, but its support in Farstream isn't quite there yet and causes crashes.

Are people using srtp 1.5.4/2.0.0 yet?

They use libsrtp that ships with their distro. I see Ubuntu 16.04 still has 1.4.5, so the versions you mentioned aren't in widespread use yet.

joakim-tjernlund commented 7 years ago

On another machine I get choppy audio when doing a test call and GST_DEBUG=3 pidgin gives me

0:00:25.990256495   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio OPUS clock:48000 channels:2 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.993439095   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio SPEEX clock:0 channels:1 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.995910786   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for 14: audio MPA-ROBUST clock:90000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 14
0:00:25.996000636   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for 14: audio X-MP3-DRAFT-00 clock:90000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 14
0:00:25.996087353   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for 14: audio MPA clock:90000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 14
0:00:25.996198072   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio MPEG4-GENERIC clock:0 channels:0 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.996304298   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio MP4A-LATM clock:0 channels:0 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.996410063   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio ILBC clock:8000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.996511580   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for 3: audio GSM clock:8000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 3
0:00:25.996614194   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for 18: audio G729 clock:8000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 18
0:00:25.996724167   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio G726-16 clock:8000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.996824658   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for 4: audio G723 clock:8000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 4
0:00:25.996929156   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for 9: audio G722 clock:8000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 9
0:00:25.997034073   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio DV clock:90000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.997137798   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio CELT clock:0 channels:0 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.997247018   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio BV16 clock:8000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.997335582   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio BV32 clock:16000 channels:0 params:(nil): Could not link element inside the send codec bin for pt 96
0:00:25.997447482   541       0xb4de70 WARN    fsrtpconference_disco fs-rtp-discover-codecs.c:1847:codec_blueprints_add_caps: Could not create send codec bin from blueprint for -1: audio AMR clock:8000 channels:1 params:0xd91000: Could not link element inside the send codec bin for pt 96
0:00:26.011592389   541       0xd81e80 FIXME                default gstutils.c:3766:gst_pad_create_stream_id_internal:<pidgindefaultaudiosrc-actual-src-als:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:26.014365086   541       0xd81800 FIXME                default gstutils.c:3766:gst_pad_create_stream_id_internal:<nicesrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:26.014538466   541       0xd60190 FIXME                default gstutils.c:3766:gst_pad_create_stream_id_internal:<nicesrc1:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:26.845820302   541       0xdf3000 FIXME                default gstutils.c:3766:gst_pad_create_stream_id_internal:<dtmfsrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:26.885192426   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:26.885203711   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.035488878   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.035501904   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.042801082   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.042809590   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.140500743   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.140511739   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.140523866   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.140528500   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.140732835   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.140741396   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.246121626   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.246133472   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.246144716   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.246150185   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.252821379   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.252830789   541       0xd81800 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.349692428   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.349704217   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.450357693   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.450370150   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:27.450386644   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:00:27.450392225   541       0xd60190 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:00:28.668527950   541       0xd6bd90 WARN                    alsa conf.c:4674:parse_args: alsalib error: Unknown parameter AES0
0:00:28.668549478   541       0xd6bd90 WARN                    alsa conf.c:4834:snd_config_expand: alsalib error: Parse arguments error: No such file or directory
0:00:28.668556339   541       0xd6bd90 WARN                    alsa pcm.c:2450:snd_pcm_open_noupdate: alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:00:28.670857076   541 0x7f19fc001d90 FIXME               basesink gstbasesink.c:3126:gst_base_sink_default_event:<autoaudiosink0-actual-sink-alsa> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:00:29.105186044   541       0xd81e80 FIXME               basesink gstbasesink.c:3126:gst_base_sink_default_event:<fakesink1> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:00:29.105206767   541       0xd81e80 FIXME               basesink gstbasesink.c:3126:gst_base_sink_default_event:<nicesink0> stream-start event without group-id. Consider implementing group-id handling in the upstream elements

Is this normal?

joakim-tjernlund commented 7 years ago

Using Pulseaudio I get lots of distortions and this is logged:

0:01:29.844006215  6545       0xec7000 FIXME                default gstutils.c:3766:gst_pad_create_stream_id_internal:<dtmfsrc1:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:01:29.880480370  6545       0xa76d40 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:01:29.880495216  6545       0xa76d40 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:01:30.031578036  6545       0xa76d40 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:01:30.031590115  6545       0xa76d40 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:01:30.136099400  6545       0xcfeca0 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:01:30.136110203  6545       0xcfeca0 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:01:30.240363985  6545       0xcfeca0 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:01:30.240380940  6545       0xcfeca0 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:01:30.445889525  6545       0xcfeca0 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:01:30.445901340  6545       0xcfeca0 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:01:30.445914226  6545       0xcfeca0 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:01:30.445919778  6545       0xcfeca0 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:01:30.451417850  6545       0xa76d40 WARN                 srtpdec gstsrtpdec.c:644:validate_buffer:<srtpdec_1> No SSRC found in buffer
0:01:30.451427231  6545       0xa76d40 WARN                 srtpdec gstsrtpdec.c:1212:gst_srtp_dec_chain:<srtpdec_1> Invalid buffer, dropping
0:01:31.925619276  6545 0x7f2f38000de0 FIXME               basesink gstbasesink.c:3126:gst_base_sink_default_event:<pulsesink0> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:01:32.544682365  6545 0x7f2f40004940 FIXME               basesink gstbasesink.c:3126:gst_base_sink_default_event:<fakesink4> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:01:32.544705968  6545 0x7f2f40004940 FIXME               basesink gstbasesink.c:3126:gst_base_sink_default_event:<nicesink2> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:01:33.562772804  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:34.701854643  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:35.222741723  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:36.602065978  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:37.422366630  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:37.661758349  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:38.122282867  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:38.761967358  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:38.882477889  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:39.042694845  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:39.201751559  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:39.942103724  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow
0:01:40.262564357  6545 0x7f2f00007120 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<pulsesink0> Got underflow

I have the feeling that these audio issues are latency based. This test machine has 175 ms ping time to the Lync server. Could it be that GST or SIPE fails to compensate for latency?

joakim-tjernlund commented 7 years ago

Here is a somewhat better data point, using http://repo.or.cz/siplcs.git/shortlog/refs/heads/mob I get lots of distortion on first Test call and lots of this(GST_DEBUG=3)

0:00:44.420026545  8681 0x7f36cc002cf0 WARN           audiobasesink gstaudiobasesink.c:1807:gst_audio_base_sink_get_alignment:<pulsesink0> Unexpected discontinuity in audio timestamps of +0:00:00.030000000, resyncing

while using pidgin-sipe 1.21.1 I get almost no distortion(if any) Tested several times

joakim-tjernlund commented 7 years ago

I there a way to play the Test Call with gst-play(or similar)? That would present a great way to narrow down the problem.

tmuehlhoff commented 7 years ago

Hi, I'm still suffering from bad outgoing voice. But only in conferences, not in direct calls. I'm attaching a sample file recorded by my colleagues Lync client (female voice, not distorted). ?Tomas

TMCM-ThursdayNovember17201632642PM.mp4.zip

xhaakon commented 7 years ago

@tmuehlhoff The sample sounds to me as if some very low-quality encoding was used. Could you please provide a Pidgin log from a conference call? I'd be interested in the codec being selected.

Does your sound improve after a while as @xnandersson describes in the original post, or keeps being distorted for the whole duration of the call?

Also what's the Ubuntu version you're currently using?

But only in conferences, not in direct calls.

Lync conference servers usually support somewhat limited range of codecs compared to the desktop clients themselves, so this observation would support the theory that Sipe selects some low-bandwidth encoder although better options should be available on your system. There still remains the question why only some users experience this sound quality problem...

tmuehlhoff commented 7 years ago

Hi, thanks for answering. What kind of logs are you referring to ? the Pidgin "System log" remains empty even though I checked all 3 log boxes in preferences/logging. I captured some seconds in Wireshark, but it's all TLS encrypted, so that won't help I assume. Ubuntu Version is 14.04.05, Kernel 3.13.0-100-generic, Pidgin 1:3.0.0 collab-1+201611050947 ubuntu14.04.1, sipe 1.21.1+sipe-0+201611140632 ubuntu14.04.1, remmina 1.2.0 rcgit+sipe-0+201608170747~ubuntu14.04.1 /Tomas

xhaakon commented 7 years ago

What kind of logs are you referring to ?

@tmuehlhoff I mean the terminal output when running Pidgin from shell with debug parameter:

pidgin --debug
tmuehlhoff commented 7 years ago

I did a capture, I'm a bit hesitating to attach the whole log here since it contains company data. I'll snip out what I think is relevant. I can send you the full file via E-Mail. PCMU seems to me not the most efficient codec. /Tomas

grep -i codec pidgin-debug.txt -A 10 -B 10 (13:39:55) sipe: process_input_message: msg->response(200),msg->method(INVITE) (13:39:55) sipe: process_input_message: we have a transaction callback (13:39:55) sipe: sipe_dialog_parse_routes: route <sip:SESSFEPOOL202.ericsson.com:5061;transport=tls;ms-fe=sessmwfe2204.ericsson.se;opaque=state:T:Tc.JNSu814HJlq-CXalIJ_2FccTAAAAAAAA:F:Fc.JNSu814HJlq-CXvlIJ_2FccTAAAAAAAA:Eu:Ci.R5a038200;lr;ms-route-sig=fl0dytzDOYoa44E4w6YJFUQ8OUNplheX7GgWBTbJRWbotAF5ziVFo5xwAA> (13:39:55) sipe: NTLM MAC(): Extented Session Security (13:39:55) sipe: NTLM MAC(): Key Exchange (13:39:55) sipe: NTLM calculated MAC: 01000000452B9B7858EC494E64000000 (13:39:55) sipe: process_input_message: removing CSeq 3 (13:39:55) sipe: SIP transactions count:0 after removal (13:39:55) backend-fs2: farstream-component-state-changed: component: 1 state: CONNECTING (13:39:55) backend-fs2: farstream-component-state-changed: component: 2 state: CONNECTING (13:39:55) backend-fs2: farstream-send-codec-changed: codec: 0: audio PCMU clock:8000 channels:1 (13:39:55) sipe: sip_sec_verify_signature: message is:<3F4EEEE5><57>sessmwfe2204.ericsson.se><9D93gCEC6a94BCi7447mD0AAtF1E6bBB0FxECCAx><4><BENOTIFY><sip:tomas.muehlhoff@ericsson.com;gruu;opaque=app:conf:focus:id:2FKR6YGW6A250080><sip:tomas.muehlhoff@ericsson.com<6173451478><><><> signature to verify is:01000000232d0aabd67d1d6a64000000 (13:39:55) sipe: NTLM MAC(): Extented Session Security (13:39:55) sipe: NTLM MAC(): Key Exchange (13:39:55) sipe: NTLM calculated MAC: 01000000232D0AABD67D1D6A64000000 (13:39:55) sipe: sip_transport_input: signature of incoming message validated (13:39:55) sipe: process_input_message: msg->response(0),msg->method(BENOTIFY) (13:39:55) sipe: send->process_incoming_benotify (13:39:55) sipe: process_incoming_notify: subscription_state: active;expires=3600 (13:39:55) sipe: sipe_dialog_find who='sip:tomas.muehlhoff@ericsson.com;gruu;opaque=app:conf:chat:id:2FKR6YGW' (13:39:55) media: candidate pair established (13:39:55) sipe: sipe_status_and_note: switch to 'in-a-conference' for the account (13:39:55) g_log: purple_xmlnode_insert_data: assertion 'data != NULL' failed (13:39:55) util: Writing file blist.xml to directory /home/eddtomu/.purple (13:39:55) util: Writing file /home/eddtomu/.purple/blist.xml (13:39:56) g_log: gst_rtcp_packet_get_rb_count: assertion 'packet->type == GST_RTCP_TYPE_RR || packet->type == GST_RTCP_TYPE_SR' failed (13:39:56) accels: saving accels to /home/eddtomu/.purple/accels (13:39:56) util: Writing file prefs.xml to directory /home/eddtomu/.purple (13:39:56) util: Writing file /home/eddtomu/.purple/prefs.xml (13:39:57) gtkmedia: state: 1 sid: audio name: sip:tomas.muehlhoff@ericsson.com;gruu;opaque=app:conf:audio-video:id:2FKR6YGW (13:39:57) sipe: sipe_media_state_changed_cb: 1 audio sip:tomas.muehlhoff@ericsson.com;gruu;opaque=app:conf:audio-video:id:2FKR6YGW (13:39:57) backend-fs2: farstream-recv-codecs-changed: PCMU (13:40:00) util: Writing file status.xml to directory /home/eddtomu/.purple (13:40:00) util: Writing file /home/eddtomu/.purple/status.xml (13:40:00) util: Writing file accounts.xml to directory /home/eddtomu/.purple (13:40:00) util: Writing file /home/eddtomu/.purple/accounts.xml (13:40:00) g_log: gst_rtcp_packet_get_rb_count: assertion 'packet->type == GST_RTCP_TYPE_RR || packet->type == GST_RTCP_TYPE_SR' failed (13:40:00) g_log: gst_rtcp_packet_add_rb: assertion 'packet->type == GST_RTCP_TYPE_RR || packet->type == GST_RTCP_TYPE_SR' failed (13:40:00) g_log: gst_rtcp_packet_get_rb_count: assertion 'packet->type == GST_RTCP_TYPE_RR || packet->type == GST_RTCP_TYPE_SR' failed (13:40:00) g_log: gst_rtcp_packet_get_rb_count: assertion 'packet->type == GST_RTCP_TYPE_RR || packet->type == GST_RTCP_TYPE_SR' failed (13:40:00) g_log: gst_rtcp_packet_get_rb_count: assertion 'packet->type == GST_RTCP_TYPE_RR || packet->type == GST_RTCP_TYPE_SR' failed (13:40:00) g_log: gst_rtcp_packet_get_rb_count: assertion 'packet->type == GST_RTCP_TYPE_RR || packet->type == GST_RTCP_TYPE_SR' failed

joakim-tjernlund commented 7 years ago

I would appreciate a list of codecs supported by SIPE, it is a jungle out there and for an amateur like me it is hard to keep up. I just saw http://blog.schertz.name/2014/03/media-codecs-in-lync-2013/ where SILK is mentioned but if I understand correctly it is now renamed to Opus, should I have Opus(via gstreamer) installed too?

tmuehlhoff commented 7 years ago

I would assume G.729 would do fine...

joakim-tjernlund commented 7 years ago

Just FYI, my audio became much better when I upgraded to ALSA 1.1.3

tmuehlhoff commented 7 years ago

seems the PPA doesn't support trusty anymore in which I am still...

tmuehlhoff commented 7 years ago

Is there anything I can do about my bad uplink audio in multiparty calls ? One2one is usually ok!

joakim-tjernlund commented 6 years ago

Got a similar issue now, doing a test call or one2one my microphon stops working for 10th's of seconds and then it start working again. Usin GST_DEBUG=3 pidgin -d I can see when microphone stops:


(17:30:02) sipe: send->process_incoming_benotify
(17:30:02) sipe: process_incoming_notify: subscription_state: active;expires=24718
(17:30:02) sipe: sipe_process_presence: Content-Type: application/msrtc-event-categories+xml
(17:30:02) sipe: process_incoming_notify_rlmi: startTime=2017-08-24T00:00:00Z granularity=15 cal_free_busy_base64=
AAAAAAAAACqqAACqUAAAAAAAAAAAAAAAAAAAAAAAACqqAACqqqoAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
0:01:19.783409509  9590 0x7fadd4002e30 WARN           audiobasesink gstaudiobasesink.c:1512:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew -0:00:00.020036104 < -+0:00:00.020000000
0:01:20.781816887  9590 0x7fadd4002e30 WARN           audiobasesink gstaudiobasesink.c:1807:gst_audio_base_sink_get_alignment:<alsasink0> Unexpected discontinuity in audio timestamps of -0:00:00.040000000, resyncing

0:01:21.976524414  9590 0x7fadd4002e30 WARN           audiobasesink gstaudiobasesink.c:1484:gst_audio_base_sink_skew_slaving:<alsasink0> correct clock skew +0:00:00.020017986 > +0:00:00.020000000
(17:30:06) util: Writing file status.xml to directory /home/jocke/.purple
(17:30:06) util: Writing file /home/jocke/.purple/status.xml
(17:30:06) util: Writing file prefs.xml to directory /home/jocke/.purple
(17:30:06) util: Writing file /home/jocke/.purple/prefs.xml
(17:30:06) util: Writing file accounts.xml to directory /home/jocke/.purple
(17:30:06) util: Writing file /home/jocke/.purple/accounts.xml
0:01:22.749810151  9590 0x7fadb00028f0 FIXME                default gstutils.c:3826:gst_pad_create_stream_id_internal:<dtmfsrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
(17:30:06) backend-fs2: farstream-send-codec-changed: codec: 97: audio SIREN clock:16000 channels:1 bitrate=16000
0:01:22.750796555  9590      0x33dda80 FIXME                default gstutils.c:3826:gst_pad_create_stream_id_internal:<rtpdtmfsrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:01:22.751515608  9590      0x33dda80 FIXME               basesink gstbasesink.c:3077:gst_base_sink_default_event:<fakesink1> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:01:22.751549322  9590      0x33dda80 FIXME               basesink gstbasesink.c:3077:gst_base_sink_default_event:<nicesink0> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:01:22.752589680  9590      0x33cfe30 WARN         audio-resampler audio-resampler.c:273:convert_taps_gint16_c: can't find exact taps
0:01:22.752955241  9590      0x33cfe30 WARN         audio-resampler audio-resampler.c:273:convert_taps_gint16_c: can't find exact taps
0:01:22.753786892  9590 0x7fadb00028f0 WARN         audio-resampler audio-resampler.c:273:convert_taps_gint16_c: can't find exact taps
0:01:22.788078887  9590      0x33cfe30 WARN         audio-resampler audio-resampler.c:273:convert_taps_gint16_c: can't find exact taps
0:01:22.980198515  9590 0x7fadd4002e30 WARN           audiobasesink gstaudiobasesink.c:1807:gst_audio_base_sink_get_alignment:<alsasink0> Unexpected discontinuity in audio timestamps of +0:00:00.040000000, resyncing
(17:30:08) backend-fs2: farstream-component-state-changed: component: 1 state: READY

Then a lon PAUSE and when microphone returns again this:

(17:30:53) sipe: sipe_core_schedule_execute: executing <+http-timeout>
(17:30:53) sipe: sipe_core_schedule_execute timeouts count 9 after removal
(17:30:53) sipe: sipe_http_transport_drop: dropping connection 'autodiscover.infinera.com:443': timeout
(17:30:53) sipe: sipe_http_transport_free: destroying connection 'autodiscover.infinera.com:443'
(17:30:53) sipe: sipe_schedule_allocate timeouts count 10 after addition
(17:30:53) sipe: scheduling action <+http-timeout> timeout 2 seconds
(17:30:53) sipe: sipe_schedule_remove: action name=<+http-timeout>
(17:30:53) sipe: sipe_schedule_allocate timeouts count 10 after addition
(17:30:53) sipe: scheduling action <+http-timeout> timeout 2 seconds
(17:30:53) sipe: transport_deferred_destroy: 0x331a730
(17:30:55) sipe: sipe_core_schedule_execute: executing <+http-timeout>
(17:30:55) sipe: sipe_core_schedule_execute timeouts count 9 after removal
(17:30:55) sipe: sipe_http_transport_drop: dropping connection 'owa.infinera.com:443': timeout
(17:30:55) sipe: sipe_http_transport_free: destroying connection 'owa.infinera.com:443'
(17:30:55) sipe: transport_deferred_destroy: 0x33191c0
(17:31:07) sipe: sip_sec_verify_signature: message is:<TLS-DSK><65209277><44><SIP Communications Service><sv-sfbfe-prd1.infinera.com><8900g69B8a49A0i35F6mAF1Ft797Eb54FCx36F0x><14><BENOTIFY><sip:Joakim.Tjernlund@infinera.com><AA6C0080><sip:Joakim.Tjernlund@infinera.com><1922124904><><><> signature to verify is:0da17af99c71817fbe2744bedb42bdf330358536
(17:31:07) sipe: sip_transport_input: signature of incoming message validated
(17:31:07) sipe: process_input_message: msg->response(0),msg->method(BENOTIFY)
(17:31:07) sipe: send->process_incoming_benotify
(17:31:07) sipe: process_incoming_notify: subscription_state: active;expires=24653
(17:31:07) sipe: sipe_process_presence: Content-Type: application/msrtc-event-categories+xml
(17:31:07) sipe: process_incoming_notify_rlmi: busyidle
(17:31:07) blist: Updating buddy status for sip:martin.wahlsten@infinera.com (Office Communicator)
joakim-tjernlund commented 6 years ago

with GST_DEBUG=4 I see when microphone is silent lost of:


0:02:19.208063748 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 16
0:02:19.218124733 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 17
0:02:19.228361825 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 18
0:02:19.238568681 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 19
0:02:19.247724360 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 0
0:02:19.257898382 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 1
0:02:19.268007819 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 2
0:02:19.278210043 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 3
0:02:19.288457947 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 4
0:02:19.298537960 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.696551616 @ 5
0:02:19.308790236 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 6
0:02:19.319001174 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 7
0:02:19.329202550 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 8
0:02:19.339414289 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 9
0:02:19.349572822 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 10
0:02:19.358714833 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 11
0:02:19.368878436 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 12
0:02:19.378992202 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 13
0:02:19.389280092 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 14
0:02:19.399440791 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 15
0:02:19.408946623 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 16
0:02:19.419081363 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 17
0:02:19.429278141 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 18
0:02:19.439553692 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.695551616 @ 19
0:02:19.449730573 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.694551616 @ 0
0:02:19.459939642 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.694551616 @ 1
0:02:19.470124673 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.694551616 @ 2
0:02:19.480331012 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.694551616 @ 3
0:02:19.490581502 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.694551616 @ 4
0:02:19.500735300 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.693551616 @ 5
0:02:19.510946002 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.693551616 @ 6
0:02:19.521182920 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.693551616 @ 7
0:02:19.531254798 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.693551616 @ 8
0:02:19.541450605 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.693551616 @ 9
0:02:19.551663885 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.692551616 @ 10
0:02:19.561928239 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.692551616 @ 11
0:02:19.572086806 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.692551616 @ 12
0:02:19.582270092 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.692551616 @ 13
0:02:19.592483895 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.692551616 @ 14
0:02:19.602760433 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 15
0:02:19.612868173 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 16
0:02:19.622980890 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 17
0:02:19.633213451 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 18
0:02:19.643428776 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 19
0:02:19.653545829 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 0
0:02:19.662801377 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 1
0:02:19.672983981 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 2
0:02:19.683275950 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 3
0:02:19.693402658 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 4
0:02:19.703613134 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.691551616 @ 5
0:02:19.713846650 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.690551616 @ 6
0:02:19.724008708 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.690551616 @ 7
0:02:19.734208063 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.690551616 @ 8
0:02:19.744402690 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.690551616 @ 9

Then, when  microphone returns again I see:

0:02:19.744505336 10466      0x22fee80 INFO              ringbuffer gstaudioringbuffer.c:1793:gst_audio_ring_buffer_read:<audiosrcringbuffer1> Retrieved timestamp 5124095:34:33.690551616 @ 9
0:02:19.744720933 10466      0x1527b50 INFO               GST_EVENT gstevent.c:1511:gst_event_new_reconfigure: creating reconfigure event
0:02:19.754630157 10466 0x7fdadc002230 INFO              ringbuffer gstaudioringbuffer.c:2033:gst_audio_ring_buffer_set_timestamp:<audiosrcringbuffer1> Storing timestamp 5124095:34:33.690551616 @ 10
0:02:19.754704748 10466      0x22fee80 INFO              ringbuffer gstaudioringbuffer.c:1793:gst_audio_ring_buffer_read:<audiosrcringbuffer1> Retrieved timestamp 5124095:34:33.690551616 @ 10
0:02:19.754825691 10466      0x22fee80 INFO           basetransform gstbasetransform.c:1370:gst_base_transform_setcaps:<volume_audio> reuse caps
0:02:19.754870821 10466      0x22fee80 INFO                GST_PADS gstpad.c:4112:gst_pad_peer_query:<valve_discovery_1:src> pad has no peer
0:02:19.754910228 10466      0x22fee80 INFO               structure gststructure.c:3051:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, layout=(string)interleaved, rate=(int)16000, channels=(int)1;
0:02:19.754968060 10466      0x22fee80 INFO           basetransform gstbasetransform.c:1370:gst_base_transform_setcaps:<sendlevel_audio> reuse caps
0:02:19.755215701 10466      0x22fee80 INFO                GST_PADS gstpad.c:4112:gst_pad_peer_query:<valve_discovery_1:src> pad has no peer
0:02:19.755604870 10466      0x22fee80 INFO               structure gststructure.c:3051:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, layout=(string)interleaved, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:02:19.755695199 10466      0x22fee80 INFO               structure gststructure.c:3051:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)16000, channels=(int)1, layout=(string)interleaved;
0:02:19.756814386 10466      0x22fee80 INFO               structure gststructure.c:3051:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)16000, channels=(int)1, layout=(string)interleaved;
0:02:19.756839433 10466      0x22fee80 INFO               structure gststructure.c:3051:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, layout=(string)interleaved, rate=
joakim-tjernlund commented 6 years ago

BTW, pidgin-sipe specificall disables SIREN during conference claiming it doesn't work:

/*
     * Do not announce Theora. Its optional parameters are too long,
     * Communicator rejects such SDP message and does not support the codec
     * anyway.
     *
     * For some yet unknown reason, A/V conferencing server does not accept
     * voice stream sent by SIPE when SIREN codec is in use. Nevertheless,
     * we are able to decode incoming SIREN from server and with MSOC
     * client, bidirectional call using the codec works. Until resolved,
     * do not try to negotiate SIREN usage when conferencing. PCMA or PCMU
     * seems to work properly in this scenario.
     */
    while (i) {
        PurpleMediaCodec *codec = i->data;
        gchar *encoding_name = purple_media_codec_get_encoding_name(codec);

        if (sipe_strequal(encoding_name,"THEORA") ||
            (is_conference && sipe_strequal(encoding_name,"SIREN"))) {
            GList *tmp;
            g_object_unref(codec);
            tmp = i->next;
            codecs = g_list_delete_link(codecs, i);
            i = tmp;
        } else if (sipe_strequal(encoding_name, "H264")) {

I took that out and tested conference and that worked fine(using SIREN codec)

jjohnson42 commented 6 years ago

I will confirm that removing the SIREN treatment helped, I also had to greatly reduce volume on the mic in my case.

joakim-tjernlund commented 6 years ago

@xnandersson, any comment on the exclusion of SIREN? Seems to work these days.

Also, this commit, https://bitbucket.org/pidgin/main/commits/08a29966cee99dedfc266e79e8fba31ecc08aa37 ,might help the original audio issue.

xnandersson commented 6 years ago

@joakim-tjernlund @xhaakon Thanks for the heads-up Joakim. Could be time to revisit this issue then.

joakim-tjernlund commented 6 years ago

Sorry for if offtopic but I got this audio prolem where the microphone stops working and the last thing I see using GST_DEBUG=3 is:

0:00:22.044095339  6747 0x562a224f5d60 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb:<autoaudiosink0-actual-sink-pulse> Got underflow
0:00:25.886390874  6747 0x562a231858f0 WARN                audiosrc gstaudiosrc.c:221:audioringbuffer_thread_func:<autoaudiosrc0-actual-src-puls> error reading data -1 (reason: Resource temporarily unavailable), skipping segment

And that comes from:

do {
        read = readfunc (src, readptr, left, &timestamp);
        GST_LOG_OBJECT (src, "transfered %d bytes of %d to segment %d", read,
            left, readseg);
        if (read < 0 || read > left) {
          GST_WARNING_OBJECT (src,
              "error reading data %d (reason: %s), skipping segment", read,
              g_strerror (errno));
          break;
        }
        left -= read;
        readptr += read;
} while (left > 0);

      /* Update timestamp on buffer if required */
      gst_audio_ring_buffer_set_timestamp (buf, readseg, timestamp);

      /* we read one segment */
gst_audio_ring_buffer_advance (buf, 1);

Got no idea if this func should try handle EAGAIN or if readfunc should do that. I cannot even tell where this readfunc is impl.(in pidgin, pidgin-sipe or somewhere else). Any ideas?