[Freeswitch-users] Opus problem

Mon Sep 25 19:35:08 UTC 2017

This is due to an incomplete implementation of the asymmetric sample rate
feature.  It should work fine without that setting.

On Mon, Sep 25, 2017 at 2:22 PM Volkan Oransoy <voransoy at gmail.com> wrote:

> Hi All,
>
> I am trying to transcode between OPUS and G711. I encountered a strange
> problem which I couldn’t find any clue about the cause. After the channel
> has been answered with opus, I hear a strange sound (highly distorted
> version of my voice)  for 10 seconds and it starts to operate properly with
> the message "[DEBUG] switch_core_media_bug.c:1198 Removing BUG from…” . I
> can reproduce same problem with echo application. Here is my logs and
> opus.conf.xml files. Did anybody experienced this issue?
>
> Thanks.
>
> /Volkan
>
>
> My FreeSWITH Version:
> FreeSWITCH Version 1.6.16+git~20170407T164913Z~3da6bd0108~64bit (git
> 3da6bd0 2017-04-07 16:49:13Z 64bit)
>
> Opus.xml config:
> <configuration name="opus.conf">
> <settings>
> <param name="use-vbr" value="1"/>
> <param name="use-dtx" value="1"/>
> <param name="complexity" value="10"/>
> <param name="maxaveragebitrate" value="14400"/>
> <param name="maxplaybackrate" value="8000"/>
> <param name="packet-loss-percent" value="15"/>
> <param name="keep-fec-enabled" value="1"/>
> <param name="use-jb-lookahead" value="0"/>
> <param name="advertise-useinbandfec" value="1"/>
> <param name="asymmetric-sample-rates" value="1"/>
> </settings>
> </configuration>
>
> Freeswitch Log:
> 2017-09-25 22:01:06.277462 [NOTICE] switch_channel.c:1104 New Channel
> sofia/internalopus/2223 at sip.example.com
> [1048c869-8d71-41fd-b0b7-f8fbd01a0d93]
> 2017-09-25 22:01:06.277462 [DEBUG] switch_core_state_machine.c:584 (
> sofia/internalopus/2223 at sip.example.com) Running State Change CS_NEW (Cur
> 2 Tot 3196652)
> 2017-09-25 22:01:06.277462 [DEBUG] sofia.c:9828
> sofia/internalopus/2223 at sip.example.com receiving invite from
> 192.168.100.2:5060 version: 1.6.16 git 3da6bd0 2017-04-07 16:49:13Z 64bit
> 2017-09-25 22:01:06.277462 [DEBUG] sofia.c:7048 Channel
> sofia/internalopus/2223 at sip.example.com entering state [received][100]
> 2017-09-25 22:01:06.277462 [DEBUG] sofia.c:7058 Remote SDP:
> v=0
> o=- 8070049943 45777 IN IP4 192.168.100.2
> s=dvjtiwu
> c=IN IP4 192.168.100.2
> t=0 0
> m=audio 10036 RTP/AVP 103 8 0 9 101
> a=rtpmap:103 opus/48000/2
> a=fmtp:103
> maxplaybackrate=8000;maxaveragebitrate=15500;useinbandfec=1;usedtx=1
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-15
> a=ptime:20
> a=nortpproxy:yes
> .
> .
> .
> .
> .
> 2017-09-25 22:01:06.337394 [INFO] mod_dialplan_xml.c:637 Processing 2223
> <2223>->*71 in context default
> Dialplan: sofia/internalopus/2223 at sip.example.com parsing [default->echo]
> continue=false
> Dialplan: sofia/internalopus/2223 at sip.example.com Regex (PASS) [echo]
> destination_number(*71) =~ /^\*71$/ break=on-false
> Dialplan: sofia/internalopus/2223 at sip.example.com Action answer()
> Dialplan: sofia/internalopus/2223 at sip.example.com Action echo()
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_state_machine.c:286 (
> sofia/internalopus/2223 at sip.example.com) State Change CS_ROUTING ->
> CS_EXECUTE
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_state_machine.c:643 (
> sofia/internalopus/2223 at sip.example.com) State ROUTING going to sleep
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_state_machine.c:584 (
> sofia/internalopus/2223 at sip.example.com) Running State Change CS_EXECUTE
> (Cur 2 Tot 3196652)
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_state_machine.c:650 (
> sofia/internalopus/2223 at sip.example.com) State EXECUTE
> 2017-09-25 22:01:06.357410 [DEBUG] mod_sofia.c:198
> sofia/internalopus/2223 at sip.example.com SOFIA EXECUTE
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_state_machine.c:328
> sofia/internalopus/2223 at sip.example.com Standard EXECUTE
> EXECUTE sofia/internalopus/2223 at sip.example.com answer()
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [opus:103:48000:20:0:1]/[opus:116:48000:20:0:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4484 Audio Codec
> Compare [opus:116:48000:20:0:1] ++++ is saved as a match
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [opus:103:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [opus:103:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4484 Audio Codec
> Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4484 Audio Codec
> Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4429 Audio Codec
> Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4345 Set
> telephone-event payload to 101 at 8000
> 2017-09-25 22:01:06.357410 [DEBUG] mod_opus.c:596 Opus encoder: set
> bitrate based on maxaveragebitrate value found in SDP or local config
> [14400bps]
> 2017-09-25 22:01:06.357410 [DEBUG] mod_opus.c:613 Opus encoder: set audio
> bandwidth to [NARROWBAND] based on maxplaybackrate value found in SDP or
> local config [8000Hz]
> 2017-09-25 22:01:06.357410 [DEBUG] mod_opus.c:596 Opus encoder: set
> bitrate based on maxaveragebitrate value found in SDP or local config
> [14400bps]
> 2017-09-25 22:01:06.357410 [DEBUG] mod_opus.c:613 Opus encoder: set audio
> bandwidth to [NARROWBAND] based on maxplaybackrate value found in SDP or
> local config [8000Hz]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:3049 Set Codec
> sofia/internalopus/2223 at sip.example.com opus/8000 20 ms 960 samples 0
> bits 1 channels
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_codec.c:111
> sofia/internalopus/2223 at sip.example.com Original read codec set to
> opus:116
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:4747
> sofia/internalopus/2223 at sip.example.com Set 2833 dtmf send payload to 101
> recv payload to 101
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:6803 AUDIO RTP [
> sofia/internalopus/2223 at sip.example.com] 192.168.100.12 port 23594 ->
> 192.168.100.2 port 10036 codec: 103 ms: 20
> 2017-09-25 22:01:06.357410 [DEBUG] switch_rtp.c:4096 Starting timer [soft]
> 960 bytes per 20ms
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:7109
> sofia/internalopus/2223 at sip.example.com Set 2833 dtmf send payload to 101
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:7116
> sofia/internalopus/2223 at sip.example.com Set 2833 dtmf receive payload to
> 101
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:7139
> sofia/internalopus/2223 at sip.example.com Set rtp dtmf delay to 40
> 2017-09-25 22:01:06.357410 [NOTICE] sofia_media.c:92 Pre-Answer
> sofia/internalopus/2223 at sip.example.com!
> 2017-09-25 22:01:06.357410 [DEBUG] switch_channel.c:3473 (
> sofia/internalopus/2223 at sip.example.com) Callstate Change RINGING -> EARLY
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media.c:6786 Audio params
> are unchanged for sofia/internalopus/2223 at sip.example.com.
>
> 2017-09-25 22:01:06.357410 [DEBUG] mod_sofia.c:850 Local SDP
> sofia/internalopus/2223 at sip.example.com:
> v=0
> o=FreeSWITCH 1506342472 1506342473 IN IP4 192.168.100.12
> s=FreeSWITCH
> c=IN IP4 192.168.100.12
> t=0 0
> m=audio 23594 RTP/AVP 103 101
> a=rtpmap:103 opus/48000/2
> a=fmtp:103 useinbandfec=1; usedtx=1; maxaveragebitrate=14400;
> maxplaybackrate=8000
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=ptime:20
> a=sendrecv
>
> 2017-09-25 22:01:06.357410 [NOTICE] mod_dptools.c:1312 Channel [
> sofia/internalopus/2223 at sip.example.com] has been answered
> 2017-09-25 22:01:06.357410 [DEBUG] sofia.c:7048 Channel
> sofia/internalopus/2223 at sip.example.com entering state [completed][200]
> 2017-09-25 22:01:06.357410 [DEBUG] switch_core_media_bug.c:828 Attaching
> BUG to sofia/internalopus/2223 at sip.example.com
> 2017-09-25 22:01:06.357410 [DEBUG] switch_channel.c:3772 (
> sofia/internalopus/2223 at sip.example.com) Callstate Change EARLY -> ACTIVE
> EXECUTE sofia/internalopus/2223 at sip.example.com echo()
> 2017-09-25 22:01:06.737463 [DEBUG] sofia.c:7048 Channel
> sofia/internalopus/2223 at sip.example.com entering state [ready][200]
> 2017-09-25 22:01:06.837459 [DEBUG] switch_rtp.c:7229 Correct audio ip/port
> confirmed.
> 2017-09-25 22:01:06.837459 [DEBUG] switch_core_io.c:448 Setting BUG Codec
> opus:116
> 2017-09-25 22:01:06.837459 [DEBUG] mod_opus.c:596 Opus encoder: set
> bitrate based on maxaveragebitrate value found in SDP or local config
> [14400bps]
> 2017-09-25 22:01:06.837459 [DEBUG] mod_opus.c:613 Opus encoder: set audio
> bandwidth to [NARROWBAND] based on maxplaybackrate value found in SDP or
> local config [8000Hz]
> 2017-09-25 22:01:06.837459 [DEBUG] switch_core_io.c:780 Engaging Read
> Buffer at 320 bytes vs 15
> [...CREEPY VOICE STARTS HERE AND ENDS WITH THE BELOW MESSAGE...]
> 2017-09-25 22:01:16.017463 [DEBUG] switch_core_media_bug.c:1198 Removing
> BUG from sofia/internalopus/2223 at sip.example.com
>
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://confluence.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20170925/1b8f735f/attachment-0001.html>