[Home]

Summary:ASTERISK-20806: Strange values reported by CHANNEL(rtpqos,audio,all) - outbound call
Reporter:Leonard Andre (anle)Labels:
Date Opened:2012-12-17 03:20:10.000-0600Date Closed:2013-02-07 08:45:30.000-0600
Priority:MinorRegression?
Status:Closed/CompleteComponents:Core/RTP Functions/func_channel
Versions:1.8.18.0 Frequency of
Occurrence
Related
Issues:
Environment:CentOS 6.2Attachments:( 0) PBX.zip
( 1) PBX.zip
Description:the reported rtt value is "strange" for outbound calls.
(measures logged from [macro-hangupcall])

Example:

ssrc=1888837987;themssrc=2540558895;lp=0;rxjitter=0.001343;rxcount=6207;txjitter=0.000000;txcount=6220;rlp=0;rtt=65535.005000

ssrc=1533549072;themssrc=399931211;lp=0;rxjitter=0.001413;rxcount=20608;txjitter=0.000000;txcount=20627;rlp=0;rtt=65535.389000
Comments:By: Rusty Newton (rnewton) 2012-12-28 14:22:48.300-0600

please read through: https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines

1] Does this occur on all outbound calls?

2] Is SIP RTT populated appropriately on all inbound calls?

3] Can you provide a SIP PCAP for a call where this occurs, and an Asterisk full log with VERBOSE and DEBUG (set to level 5 at least) for the same call?

4] Can you explain how to reproduce this, and do you know if it happens on any other version?

5] What SIP endpoint is in use and what model/firmware version are you using?
By: Leonard Andre (anle) 2013-01-08 08:30:57.166-0600

1) Does this occur on all outbound calls? --> YES

2] Is SIP RTT populated appropriately on all inbound calls? --> YES

4] Can you explain how to reproduce this, and do you know if it happens on any other version?
--> I'm using asterisk via freepbx distro
--> issue also after an upgrade to version 1.18.19
--> code use in extensions_override_freepbx.conf:
[macro-hangupcall]
exten => s,1,System(echo "Call Ended at ${STRFTIME(,,%c)} to {CALLERID(num)} ${CHANNEL(rtpqos,audio,all)}" >> /var/spool/asterisk/tmp/callended.log)
...

5] What SIP endpoint is in use and what model/firmware version are you using? --> Internal phones are SNOM 300 & Snom 320

By: Rusty Newton (rnewton) 2013-01-11 16:23:03.981-0600

Thank you for the information. Can you please provide a packet capture (SIP and RTP) for both an  example outbound and inbound call?
By: Leonard Andre (anle) 2013-01-17 16:46:04.869-0600

The issue seems related to the NATing.

Is that making sense?


By: Rusty Newton (rnewton) 2013-01-18 14:23:34.782-0600

Not yet. Without the debug that was requested, it is hard to see what is going on. I'll put this in waiting for feedback until you can provide the packet captures.
By: Leonard Andre (anle) 2013-01-19 08:08:43.134-0600

Communication traces:
SIP Pcap 1 Inbound & 1 Oubound call
Asterisk debug trace of both
By: Leonard Andre (anle) 2013-01-19 08:12:45.895-0600

Hi,
I uploaded the trace files:
- 1 inbound call from 3222301675 to 3228949918
- 1 oubound call from 3228949918 to 32477980856

NB: since this call opening, I add to redefine a new trunk to my provider and the behavior is not identicall as before.
Thanks,
Andre.

By: Rusty Newton (rnewton) 2013-01-26 17:03:08.135-0600

I don't see any RTP/RTCP packets in your captures. You'll need to post a capture with RTP/RTCP included before anyone can look into it.

Also, you forgot to enable DEBUG for the full log (or else forget to run it up past 0 before logging) https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information    You'll need a full log of the calls included in the pcap, along with VERBOSE/DEBUG at level 5 at least.

Thanks.
By: Leonard Andre (anle) 2013-01-27 04:10:03.133-0600

A new set of captures: 1 inbound and 1 outbound call (322477980856 - 3228949918)
By: Leonard Andre (anle) 2013-01-31 09:12:45.787-0600

HI,

An other way to display the strange values is the command "sip show channelstats":

Example:
{noformat}
Peer             Call ID      Duration Recv: Pack  Lost       (     %) Jitter Send: Pack  Lost       (     %) Jitter
192.168.5.155    510a887288b  00:01:42 0000005017  0000000000 ( 0.00%) 0.0000 0000005039  0000000000 ( 0.00%) 0.0001
217.111.202.70   055fddf9492  00:00:29 0000001487  0000131070 (98.88%) 0.0000 0000001482  0000000000 ( 0.00%) 0.0002
217.111.202.70   21737eb35c4  00:02:32 0000007648  0000851955 (99.11%) 0.0000 0000007614  0000000000 ( 0.00%) 0.0001
192.168.5.161    682e4584115  00:00:20 0000000000  0000000000 ( 0.00%) 0.0000 0000000000  0000000000 ( 0.00%) 0.0000
192.168.5.155    23d197ce283  00:00:20 0000000000  0000000000 ( 0.00%) 0.0000 0000000000  0000000000 ( 0.00%) 0.0000
85.119.188.3     2cb72b9904a  00:01:42 0000005039  0000000002 ( 0.04%) 0.0000 0000005017  0000000001 ( 0.02%) 0.0002
192.168.5.159    60f35a033f9  00:02:02 0000005695  0000000000 ( 0.00%) 0.0000 0000005715  0000000000 ( 0.00%) 0.0002
7 active SIP channels
{noformat}

By: Matt Jordan (mjordan) 2013-02-07 08:45:03.676-0600

This is a bug in whatever device is sending the RTCP packets to Asterisk.

RTT times are computed using three values: the timestamp a source received this Reception Report (RR), the timestamp of the last Source Report (SR), and the delay since the last Source Report (del). RTT is calculated as follows:

{{RTT = RR - SR - del}}

Asterisk calculates the RTT appropriately, as seen in {{res_rtp_asterisk}}, where {{comp}} is {{RR}}, {{lsr}} is {{SR}}, and {{dlsr}} is {{del}}:

{noformat}
comp = ((msw & 0xffff) << 16) | ((lsw & 0xffff0000) >> 16);
lsr = ntohl(rtcpheader[i + 4]);
dlsr = ntohl(rtcpheader[i + 5]);
rtt = comp - lsr - dlsr;
{noformat}

In your pcap, the RTCP packets received from the external device have a correctly populated Reception Report time and Source Delay time. However, the last Source Report timestamp is always 0. This means the device is not informing us correctly of the time it last saw a source report, and the calculated RTT time is skewed.
By: Leonard Andre (anle) 2013-02-07 15:50:09.647-0600

HI,

Thanks Matt.

Could you also check why the packet loss counter is not valid ?

Thanks,
André.