[Home]

Summary:ASTERISK-26593: chan_sip: One way audio due to RTP bridging when it shouldn't
Reporter:Luke Escude (lukeescude)Labels:
Date Opened:2016-11-14 11:25:45.000-0600Date Closed:2017-01-12 19:20:41.000-0600
Priority:MinorRegression?
Status:Closed/CompleteComponents:Channels/chan_sip/CodecHandling
Versions:13.12.2 Frequency of
Occurrence
Related
Issues:
duplicatesASTERISK-26666 chan_pjsip: Opus offered and used, but uLaw is sent, Result No Audio
Environment:CentOS x64Attachments:( 0) cli_case1.txt
( 1) console_log.txt
( 2) flowroute-280984.pcap02
( 3) ilbc_case1.pcap
( 4) messages
( 5) rtcp_log.txt
( 6) sip_debug.rtf
Description:As soon as the call switches from simple_bridge to native_rtp, the server stops receiving RTCP information, and the call will drop because it thinks there's inactivity. We've had to set the rtp timeout to 24 hours to compensate for this.

Log readout during a phone call:
[Edit by Rusty - moved debug to console_log.txt]
Comments:By: Asterisk Team (asteriskteam) 2016-11-14 11:25:46.529-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: Joshua C. Colp (jcolp) 2016-11-14 15:20:54.021-0600

Thank you for taking the time to report this bug and helping to make Asterisk better. Unfortunately, we cannot work on this bug because your description did not include enough information. Please read over the Asterisk Issue Guidelines [1] which discusses the information necessary for your issue to be resolved and the format that information needs to be in. We would be grateful if you would then provide a more complete description of the problem. At a minimum, we need:

1. The specific steps or actions you took that caused you to encounter the problem.
2. The behavior you expected and the location of documentation that led you to that expectation.
3. The behavior you actually encountered.

To demonstrate the issue in detail, please include Asterisk log files generated per the instructions on the wiki [2]. If applicable, please ensure that protocol-level trace debugging is enabled, e.g., 'sip set debug on' if the issue involves chan_sip, and configuration information such as dialplan and channel configuration.

Thanks!

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines

[2] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

As well please confirm the version of Asterisk you are using.
By: Luke Escude (lukeescude) 2016-11-14 15:29:58.705-0600

1. We simply placed phone calls, and sent the CLI a "sip show channelstats" command 1 time per second (hence my log of multiple commands being issued).

2. We expect that RTCP be sent and received like normal, despite the voice core handing off the RTP to the audio stack. Documentation is located in the Bridges section.

3. You will notice from my log in the first post that issuing "sip show channelstats" over and over works for the beginning of the phone call - you can see jitter fluctate from the endpoint at IP address 98.6.78.250. (ignore the other jitter rating, as that is our PSTN trunk... It is always 0.)

However, the moment the call enters native_rtp (happens in the middle of my log), issuing sip show channelstats now shows a constant jitter rating. It is no longer reporting/receiving RTCP.
By: Joshua C. Colp (jcolp) 2016-11-14 15:34:39.163-0600

The logs we need include SIP and debug level. Native RTP bridge can actually mean 2 different things. Either a local optimized one, or a remote bridge in which case media and RTCP would not be going through Asterisk. It's unclear which exactly is being done. As well the configuration would allow us to reproduce it, and different configuration influences the results of the bridge and the choice. Finally we reverted a change in Asterisk 13.12.2 which caused rtptimeout to occur when it shouldn't. Thus my question about confirmation of version.
By: Luke Escude (lukeescude) 2016-11-14 15:45:51.995-0600

CLI output with SIP debugging attached. I'll post up dial plan configuration next.

Using asterisk 13.12.2, compiled from source.
By: Luke Escude (lukeescude) 2016-11-14 15:47:19.489-0600

Trunk Configuration:
{noformat}
[flowroute]
username=REDACTED
fromuser=REDACTED
secret=REDACTED
host=sip.flowroute.com
type=friend
context=from-trunk
insecure=port,invite
trustrpid=yes
sendrpid=yes
directmedia=no
qualify=yes
keepalive=45
nat=force_rport,comedia
dtmfmode=rfc2833
disallow=all
allow=ulaw
t38pt_udptl=yes,redundancy,maxdatagram=400
defaultexpiry=120
registertimeout=1
registerattempts=0
{noformat}

Endpoint Config:
{noformat}
[1033]
secret=REDACTED
dial=SIP/1033
mailbox=1033@voicemail
callerid=Luke Office <1033>
deny=0.0.0.0/0.0.0.0
permit=0.0.0.0/0.0.0.0
disallow=all
allow=ulaw
allow=ilbc:30
allow=g729
dtmfmode=rfc2833
canreinvite=no
context=from-internal
host=dynamic
trustrpid=yes
sendrpid=pai
type=friend
nat=force_rport,comedia
port=5060
qualify=10000
qualifyfreq=15
transport=udp,tcp,tls
avpf=no
force_avp=no
icesupport=no
encryption=no
namedcallgroup=
namedpickupgroup=
callcounter=yes
faxdetect=no
cc_monitor_policy=generic
{noformat}
By: Rusty Newton (rnewton) 2016-11-14 16:22:44.294-0600

Moving console output from description field to the attached file "console_log.txt".
By: Rusty Newton (rnewton) 2016-11-14 16:50:39.595-0600

bq. CLI output with SIP debugging attached. I'll post up dial plan configuration next.

Actually, you didn't include the "debug" log channel. Can you attach a new log following these instructions:

https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

It should include the logger channels: warning,notice,error,verbose,debug

Important notes:

* Make sure the log has verbose and debug levels both turned up to *5*
* Make sure the log includes the SIP packet trace
* Make sure the log includes the output of "rtcp set debug on"
* Attach the log in *plain* text format. Do not attach it in rtf or anything fancy. Attach it with a .txt extension for accessibility.
* Gather the log as the instructions indicate and do not copy output from the Asterisk console. That is, please use the logger output to a file in /var/log/asterisk/

Thanks!
By: Luke Escude (lukeescude) 2016-11-14 17:05:12.426-0600

Amazing, I had no idea such debugging messages even existed. I've been developing with Asterisk for nearly two years now and never thought about logging that way. Embarrassing, frankly.
By: Joshua C. Colp (jcolp) 2016-11-14 17:22:45.305-0600

The user agent in your log is "Asterisk PBX 13.12.1" which would not be 13.12.2.

What is the output of "core show version"?
By: Luke Escude (lukeescude) 2016-11-14 17:30:23.762-0600

Ah you're right, crap. I was using our testbed which is still on 12.1.

I know for a fact it's happening on 12.2 though, which is why I started this thread.

I'll upgrade the server to 12.2 and repeat the diagnostics.
By: Joshua C. Colp (jcolp) 2016-11-14 17:39:32.418-0600

Will the logs also demonstrate the rtptimeout terminating the call?
By: Luke Escude (lukeescude) 2016-11-14 18:23:51.985-0600

I think they will. I believe it says the call is being hung up due to RTP inactivity or something. I haven't seen that error since I set the rtp timeout to 24 hours.
By: Joshua C. Colp (jcolp) 2016-11-14 18:36:43.903-0600

Bouncing back until we have a new log under 13.12.2
By: Luke Escude (lukeescude) 2016-11-16 15:43:22.876-0600

Joshua, it seems as though the RTCP bug has fixed itself after upgrading to 13.12.2. However, the customer is now complaining about occasional one-way audio calls.

The log is showing a whole lot of this feedback:

[Nov 16 21:20:23] DEBUG[8605][C-00001a35] res_rtp_asterisk.c: Unsupported payload type received
[Nov 16 21:20:23] DEBUG[8604][C-00001a34] translate.c: Sample size different 160 vs 240
[Nov 16 21:20:23] DEBUG[8604][C-00001a34] translate.c: Sample size different 160 vs 240
[Nov 16 21:20:23] DEBUG[8605][C-00001a35] res_rtp_asterisk.c: Unsupported payload type received
[Nov 16 21:20:23] DEBUG[8605][C-00001a35] res_rtp_asterisk.c: Unsupported payload type received
[Nov 16 21:20:23] DEBUG[8604][C-00001a34] translate.c: Sample size different 160 vs 240
[Nov 16 21:20:23] DEBUG[8605][C-00001a35] res_rtp_asterisk.c: Unsupported payload type received

The handsets are forcing ilbc:30, and the trunk is forcing uLaw. Is there a correlation between these errors and the one-way audio?
By: Joshua C. Colp (jcolp) 2016-11-16 15:47:10.225-0600

It's possible but there's not enough information to say for certain. The SIP trace, SDP, full console output, and rtp set debug on would be needed.
By: Joshua C. Colp (jcolp) 2016-11-16 19:13:58.220-0600

If you can provide what I mentioned we can take a look.
By: Luke Escude (lukeescude) 2016-11-17 11:34:05.252-0600

cli_case1 is the CLI output of an iLBC-to-uLaw call.

ilbc_case1.pcap is the packet capture.

messages is the actual debug/verbose message output.

This particular testbed server is still on 13.12.1, but I'll upgrade it right now. I do know this payload error is happening on 12.2 as well.
By: Luke Escude (lukeescude) 2016-11-21 12:27:58.460-0600

Any ideas on that strange error message?
By: Joshua C. Colp (jcolp) 2016-11-21 12:32:19.660-0600

It appears to be sending ulaw to the device when the device is expecting iLBC. It's likely a problem in chan_sip itself in channel codec manipulation.
By: Luke Escude (lukeescude) 2016-11-30 12:22:39.580-0600

What do you make of this capture? iLBC between phone and server, then uLaw from server to Flowroute trunk. One-way audio, callee couldn't hear the caller (ext. 221)
By: Luke Escude (lukeescude) 2017-01-12 19:20:41.581-0600

This is the same bug as ASTERISK-26666.
By: Rene Vogt (rvogt) 2017-03-14 10:55:50.157-0500

I don't think that this bug is related to ASTERISK-26666. This bug is about chan_sip, the other one about pjsip.
I have the same asymmetric codec issue using chan_sip.