[Home]

Summary:ASTERISK-26666: chan_pjsip: Opus offered and used, but uLaw is sent, Result No Audio
Reporter:Luke Escude (lukeescude)Labels:
Date Opened:2016-12-19 18:06:12.000-0600Date Closed:2017-03-02 17:10:28.000-0600
Priority:MajorRegression?
Status:Closed/CompleteComponents:Channels/chan_pjsip
Versions:13.13.1 Frequency of
Occurrence
Related
Issues:
is duplicated byASTERISK-26478 codec_opus: Opus transcoding one-way audio issue
is duplicated byASTERISK-26593 chan_sip: One way audio due to RTP bridging when it shouldn't
Environment:x64 CentOSAttachments:( 0) asterisk.pcap
( 1) asterisk.txt
( 2) call2.pcap
( 3) flowroute-280984.pcap
( 4) gs.pcap
( 5) opus-debug
( 6) opus-debug.txt
( 7) opus-debug2.txt
( 8) yl.pcap
Description:The following codecs are configured for an endpoint, in order of priority:

Opus
uLaw
iLBC
g729

Asterisk and the handset settle on Opus being the codec for the call, but no audio can be heard from the echo test (or extension-to-extension, or anything).

Running "pjsip show channelstats" shows uLaw as the codec, even though it should say Opus. opus-debug file shows a lot of the following error:

Oooh, got a frame with format of opus on channel 'PJSIP/100-0000001d' when we're sending 'ulaw', switching to match
Comments:By: Asterisk Team (asteriskteam) 2016-12-19 18:06:13.655-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Luke Escude (lukeescude) 2016-12-19 18:07:09.073-0600

PCAP of the phone call (echo test on server, *43)

And debug output of the call setup, with RTP debugging enabled.
By: Luke Escude (lukeescude) 2016-12-19 18:09:23.542-0600

Note this is not a problem when allow=opus is the only allowed codec in the endpoint's settings.
By: Rusty Newton (rnewton) 2016-12-21 14:22:34.124-0600

Reattaching opus-debug as opus-debug.txt for accessibility. (prevents others from having to download to view)
By: Rusty Newton (rnewton) 2016-12-21 14:24:02.607-0600

Can you attach a similar debug log but including the SIP trace?

Having the pcap is really nice, but it helps if the pcap correlates with a SIP trace in the debug log to pinpoint specific events in the call.
By: Luke Escude (lukeescude) 2016-12-21 20:30:56.209-0600

Here you are!

Same test, dialing *43 (echo test) but no audio.

Please ignore the extra SIP messages and INVITEs, since this is a hosted server, it gets a lot of requests from the open internet.
By: Luke Escude (lukeescude) 2016-12-21 20:36:05.368-0600

This looks interesting:
[Dec 22 02:27:18] DEBUG[96958] rtp_engine.c: Don't have a default tx payload type 125 format for m type on 0x7fe7f2e08d90
By: Joshua C. Colp (jcolp) 2017-01-03 06:22:31.492-0600

The "Don't have" message is normal. It's a dynamic payload from the remote side, so there is no default on our side.

As for the underlying problem I'd suggest using 13 from git or waiting until the next release as I believe this was already fixed by ASTERISK-26603. The format would not switch in all circumstances.
By: Luke Escude (lukeescude) 2017-01-12 19:19:13.689-0600

No problem - I will wait for the next release and see if that fixes it.
By: Joshua C. Colp (jcolp) 2017-01-13 10:03:02.200-0600

Waiting on next release and testing of it.
By: Asterisk Team (asteriskteam) 2017-01-27 12:00:02.309-0600

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines
By: Luke Escude (lukeescude) 2017-02-09 12:36:18.981-0600

Still getting one-way audio when one endpoint uses Opus. Apparently Asterisk is still trying to send uLaw to the phone when the phone is expecting Opus.

My engineer is getting pcaps and logs for us, so I'll post those soon.

Using 13.14.0 RC 2
By: Asterisk Team (asteriskteam) 2017-02-09 12:36:19.258-0600

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Luke Escude (lukeescude) 2017-02-09 18:33:47.584-0600

Attached: PCAPs of Asterisk, Grandstream Opus endpoint, and Yealink PCMU endpoint.
By: Luke Escude (lukeescude) 2017-02-10 09:30:01.465-0600

Additionally, running pjsip show channelstats shows the opus endpoint as using uLaw instead of opus.

By: Kevin Harwell (kharwell) 2017-02-13 17:49:05.208-0600

There appears something odd to be going on. When you look at the debug logs it seems that it keeps trying to switch to opus after receiving opus from the endpoint, but doesn't seem to actually do it. For instance in one debug log you see the following:
{noformat}
[Dec 22 02:27:18] DEBUG[21455][C-00000013] acl.c: For destination '72.190.32.250', our source address is '206.126.62.165'.
[Dec 22 02:27:18] DEBUG[21455][C-00000013] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fe71c00c720'
[Dec 22 02:27:18] DEBUG[21455][C-00000013] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address 72.190.32.250:5006
[Dec 22 02:27:18] VERBOSE[21455][C-00000013] res_rtp_asterisk.c: Got  RTP packet from    72.190.32.250:5006 (type 125, seq 011941, ts 126720, len 000042)
[Dec 22 02:27:18] DEBUG[21455][C-00000013] channel.c: Channel PJSIP/100-0000001f setting write format path: gsm -> ulaw
[Dec 22 02:27:18] DEBUG[21455][C-00000013] res_rtp_asterisk.c: Ooh, format changed from none to ulaw
[Dec 22 02:27:18] VERBOSE[21455][C-00000013] res_rtp_asterisk.c: Sent RTP packet to      72.190.32.250:5006 (type 00, seq 032522, ts 000160, len 000160)
[Dec 22 02:27:18] DEBUG[21455][C-00000013] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Dec 22 02:27:18] VERBOSE[21455][C-00000013] file.c: <PJSIP/100-0000001f> Playing 'demo-echotest.gsm' (language 'en')
[Dec 22 02:27:18] DEBUG[21455][C-00000013] res_rtp_asterisk.c: 0x7fe71c0059a0 -- Probation learning mode pass with source address 72.190.32.250:5006
[Dec 22 02:27:18] VERBOSE[21455][C-00000013] res_rtp_asterisk.c: Got  RTP packet from    72.190.32.250:5006 (type 125, seq 011942, ts 127680, len 000042)
[Dec 22 02:27:18] DEBUG[21455][C-00000013] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/100-0000001f' when we're sending 'ulaw', switching to match
[Dec 22 02:27:18] DEBUG[21455][C-00000013] channel.c: Channel PJSIP/100-0000001f setting write format path: gsm -> ulaw
[Dec 22 02:27:18] VERBOSE[21455][C-00000013] res_rtp_asterisk.c: Sent RTP packet to      72.190.32.250:5006 (type 00, seq 032523, ts 000320, len 000160)
{noformat}
And in another you see something similar:
{noformat}
Dec 19 23:56:34] VERBOSE[95833][C-00000011] file.c: <PJSIP/100-0000001d> Playing 'demo-echotest.gsm' (language 'en')
[Dec 19 23:56:34] DEBUG[95833][C-00000011] res_rtp_asterisk.c: 0x7fe778021d70 -- Probation learning mode pass with source address 72.190.32.250:5006
[Dec 19 23:56:34] DEBUG[95833][C-00000011] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/100-0000001d' when we're sending 'ulaw', switching to match
[Dec 19 23:56:34] DEBUG[95833][C-00000011] channel.c: Channel PJSIP/100-0000001d setting write format path: gsm -> ulaw
[Dec 19 23:56:34] DEBUG[95833][C-00000011] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/100-0000001d' when we're sending 'ulaw', switching to match
[Dec 19 23:56:34] DEBUG[95833][C-00000011] channel.c: Channel PJSIP/100-0000001d setting write format path: gsm -> ulaw
[Dec 19 23:56:34] DEBUG[95833][C-00000011] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/100-0000001d' when we're sending 'ulaw', switching to match
[Dec 19 23:56:34] DEBUG[95833][C-00000011] channel.c: Channel PJSIP/100-0000001d setting write format path: gsm -> ulaw
[Dec 19 23:56:34] DEBUG[95833][C-00000011] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/100-0000001d' when we're sending 'ulaw', switching to match
{noformat}
It seems to keep trying to switch without success. Another oddity is why is Asterisk choosing ulaw in the first place when opus was negotiated?
By: Luke Escude (lukeescude) 2017-02-13 17:52:14.943-0600

In those tests, I believe Opus was the only codec even allowed. Not sure if that's correct though.

Are you able to recreate it? Or is it unique to my server? I'd be happy to provision you a testbed server to SSH into and play around with.
By: Luke Escude (lukeescude) 2017-02-13 22:02:32.326-0600

Asterisk release 13.14 with new codec_opus does not make a difference.
By: Kevin Harwell (kharwell) 2017-02-14 09:38:59.372-0600

{quote}
Are you able to recreate it? Or is it unique to my server? I'd be happy to provision you a testbed server to SSH into and play around with.
{quote}
I have not been able to recreate the problem myself. The issue has now been moved from triage to opened. That being said I'm not sure when a developer will get around to formally looking into this issue, but they can ping you at that time about a testbed if needed.

A couple more questions/things to try to help narrow the scope:

Does this only occur with opus? What if you put something like g729 as the first codec and opus last or even removed it from the list?

Is it possible to setup a test with no NAT involved to see if the problem still occurs?
By: Luke Escude (lukeescude) 2017-02-14 19:43:00.935-0600

Order of codecs in Asterisk does not matter.

Test 1: uLaw endpoint calls Opus endpoint (ulaw endpoint hears audio, Opus does not)
{noformat}
[Feb 15 01:28:49] DEBUG[80906][C-00000173] res_rtp_asterisk.c: Unsupported payload type received
[Feb 15 01:28:49] DEBUG[80906][C-00000173] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/100-0000028c' when we're sending 'ulaw', switching to match
[Feb 15 01:28:49] DEBUG[80906][C-00000173] channel.c: Channel PJSIP/100-0000028c setting write format path: ulaw -> ulaw
{noformat}
It's definitely making the attempt to switch the channel to Opus, but the path it sets is uLaw -> uLaw instead of uLaw -> Opus or whatever the order is.

Test 2 failed as well, it was just the other direction (Opus endpoint calling uLaw endpoint)

Test 3 (This is interesting)... The previous uLaw endpoint is now using iLBC:30... Infinite loop is caused. Look here:
{noformat}
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] chan_pjsip.c: Oooh, got a frame with format of opus on channel 'PJSIP/100-0000029b' when we're sending 'ilbc', switching to match
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] channel.c: Channel PJSIP/100-0000029b setting write format path: ilbc -> ilbc
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] channel.c: Channel PJSIP/100-0000029b setting read format path: opus -> opus
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge_native_rtp.c: Packetization differs between RTP streams (30 != 30 or 20 != 30). Cannot native bridge in RTP
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Chose bridge technology simple_bridge
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: calling simple_bridge technology constructor
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: moving 0x7ffaec236a90(PJSIP/101-0000029a) to dummy bridge temporarily
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: moving 0x7ffaec727240(PJSIP/100-0000029b) to dummy bridge temporarily
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: 0x7ffaec236a90(PJSIP/101-0000029a) is leaving native_rtp technology (dummy)
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/101-0000029a' and 'PJSIP/100-0000029b' - media will flow through Asterisk core
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: 0x7ffaec727240(PJSIP/100-0000029b) is leaving native_rtp technology (dummy)
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: calling native_rtp technology stop
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: 0x7ffaec236a90(PJSIP/101-0000029a) is joining simple_bridge technology
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] channel.c: Channel PJSIP/100-0000029b setting read format path: ilbc -> ilbc
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] channel.c: Channel PJSIP/101-0000029a setting write format path: ilbc -> ilbc
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: 0x7ffaec727240(PJSIP/100-0000029b) is joining simple_bridge technology
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: calling simple_bridge technology start
[Feb 15 01:35:44] DEBUG[81214][C-0000017b] bridge.c: Bridge 582f9bfe-a2fa-4d33-9464-71f52f0fc6a1: calling native_rtp technology destructor
....
{noformat}
The constant switching goes on eternally until I stop the test.

Test 4: Same test, but iLBC:20 and got the same one-way audio, iLBC could hear Opus but Opus could not hear iLBC endpoint.
By: Kevin Harwell (kharwell) 2017-02-23 11:19:55.644-0600

Sounds like you are using the latest version of Asterisk (13.14). What's the version number of codec_opus that you are using/how was it installed?

(note you can find the codec_opus version by looking its manifest file that resides in the modules directory -  lib/asterisk/modules/codec_opus.manifest.xml)

What's the output of the following commands:
{noformat}
*CLI> module show like codec_opus.so
*CLI> module show like format_ogg_opus.so
{noformat}

If you remove opus from the list of codecs does the problem still occur?

What's the output of the following command (replace <endpoint id> with the id of the endpoint in question:
{noformat}
*CLI> pjsip show endpoint <endpoint id>
{noformat}

By: Kevin Harwell (kharwell) 2017-02-23 16:18:24.114-0600

A few more things to check :-)

What's the output of the following CLI commands:
{noformat}
*CLI> core show translation
*CLI> core show translation paths opus
*CLI> core show translation paths gsm
{noformat}
As well as the following, which should be executed on the running call (<channel id> can be retrieved from executing "core show channels"):
{noformat}
*CLI> core show channel <channel id>
{noformat}
By: Kevin Harwell (kharwell) 2017-02-23 16:55:59.043-0600

Also just to double check what is the output of the following (run from system console):
{noformat}
$ asterisk -V
{noformat}
By: Luke Escude (lukeescude) 2017-02-24 17:55:42.775-0600

Kevin,

So while we're able to reproduce this 100% on our testbed server, Opus is working perfectly on our production server. So this might be environment/compiling related.

HOWEVER, on production server (running 13.14 with NEW codec_opus released in Feb), running "pjsip show channelstats" still shows uLaw for an endpoint definitely running Opus. Not sure if that's just a text output bug or something significant.
By: Kevin Harwell (kharwell) 2017-02-27 10:47:38.955-0600

{quote}
So this might be environment/compiling related.
{quote}
Indeed it does. Since the problem seems to lie within your test bed (might just be running an old version of Asterisk) and unless you want to supply some of the info I mentioned we'll probably close this issue out then.

The other problem you mentioned is a bug and I've created a separate issue (ASTERISK-26822) to track it.
By: Kevin Harwell (kharwell) 2017-03-02 17:10:28.516-0600

Since this issue seems resolved and another issue has been created/opened for the separate bug found we are closing this issue.