[Home]

Summary:ASTERISK-09267: RTCP Statistics Broken for Asterisk-to-Asterisk calls
Reporter:davetroy (davetroy)Labels:
Date Opened:2007-04-18 09:17:47Date Closed:2007-07-09 21:20:49
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/RTP
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) rtp-rtcpfixes.patch
( 1) rtp-rtcpfixes2.patch
Description:Calls between two Asterisk endpoints result in bogus values being reported via RTCP for lost packets, remote jitter, and round trip time.  The incorrect lost packets figure is a result of failure to detect RTP SEQNO cycling; this typically results in a negative number, which is then displayed as an large unsigned integer (4bn+).

The incorrect remote jitter figure is a result of Asterisk placing its calculated jitter figure onto the wire as a float, when it should be expressed as an integer.  Multiplying the calculated float value by 65536.0 (the inverse of which has previously been done on receipt) solves this problem and appears to be compatible with other RTCP endpoints we have tested.

Negative round-trip time figures are sometimes reported, presumably due to initialization or lost-packet issues.  Negative values should at least be ignored as invalid.

This patch addresses all three of these problems and greatly improves Asterisk's RTCP reporting functionality.

****** ADDITIONAL INFORMATION ******

Applies to both SVN trunk & 1.4.2; should be applied to 1.4 tree as a bugfix.
Comments:By: Olle Johansson (oej) 2007-04-18 15:24:42

Another issue we need to look at sometime is how to get a report from the bridged channel. The current functionality just reports the channel that is incoming, not the other channel - which might be more important.
By: Olle Johansson (oej) 2007-04-18 15:29:08

Committed to 1.4, rev 61674 and trunk. Thanks!
By: Leif Madsen (lmadsen) 2007-04-18 17:50:18

Reopened per bblack's request on IRC
By: Marcel Barbulescu (marcelbarbulescu) 2007-04-18 17:55:24

After revision 61674 I started getting tons of "SEQNO cycled:..." messages, probably at every RTP frame. I see that the verbose line was there before the patch but this patch changed the test. If the test is right, maybe printing the verbose message can be done in a different way since it fills up the screen and the logs. Here is a snippet from the logs:

[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3071934464     47612
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3062628352     7525
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3072000000     47613
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3062693888     7526
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3072065536     47614
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3062759424     7527
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3072131072     47615
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3062824960     7528
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3072196608     47616
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3062890496     7529
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3072262144     47617
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3062956032     7530
[Apr 18 18:49:29] VERBOSE[13703] logger.c: SEQNO cycled: 3072327680     47618
[Apr 18 18:49:30] VERBOSE[13703] logger.c: SEQNO cycled: 3063021568     7531
By: davetroy (davetroy) 2007-04-18 19:24:59

Marcel, if you're getting those log messages it is an indication of RTP sequencing problems.  What is the endpoint (user agent type & version) you're seeing this result with, so we can try to reproduce this?

You should try this with another UA and see what you see also.
By: Marcel Barbulescu (marcelbarbulescu) 2007-04-18 19:30:37

Dave, I'm getting this using vitelity.com. I know that they used to use Asterisk, not sure what they are using right now.

I'll test some more (with other providers too) and I'll let you know if I can figure out anything.


By: Marcel Barbulescu (marcelbarbulescu) 2007-04-18 19:37:56

I'm seeing the same effect with MERA MSIP v.3.0.
By: davetroy (davetroy) 2007-04-18 19:43:17

Marcel, need to know more about what type of calls you have up.  The issue isn't logging related, it's a question of detecting rtp sequence number cycling.  Previously the code looked to see if "seqno + 1 > 65536" is true.  This never worked right unless you definitely received packet # 65535, and in my test calls, this never happened.

Instead I am looking to see if there is a massive difference in seqnos, indicating a cycling back to the start, and allowing for packet misordering.

From your log I am seeing two different RTP streams being received, which is why the sequence numbers are mismatched.  What sort of call do you have up where we are receiving two separate rtp sequences in the same RT�P session?
By: Marcel Barbulescu (marcelbarbulescu) 2007-04-18 19:48:01

Linksys PAP2 -> Asterisk -> MERA MSIP v.3.0

Here is an snapshot from the log:
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 131072 1558
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 196608 1559
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 262144 1560
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 327680 1561
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 393216 1562
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 458752 1563
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 524288 1564
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 589824 1565
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 655360 1566
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 720896 1567
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 786432 1568
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 851968 1569
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 917504 1570
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 983040 1571
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 1048576        1572
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 1114112        1573
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 1179648        1574
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 1245184        1575
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 1310720        1576
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 1376256        1577
[Apr 18 20:43:14] VERBOSE[29419] logger.c: SEQNO cycled: 1441792        1578
By: davetroy (davetroy) 2007-04-18 20:02:02

Please apply the attached rtp-rtcpfixes2.patch.  This adds back in some simple typecasting I had in an earlier version which I realize now may be breaking things.  Please report back on what your test cases do with this.  Thanks.
By: Marcel Barbulescu (marcelbarbulescu) 2007-04-18 20:21:41

This was it. Problem solved. Thank you.
By: davetroy (davetroy) 2007-04-18 20:28:47

Olle, can you please apply the rtp-rtcpfixes2.patch to 1.4 and trunk also?  Sorry for the trouble, this should have been in the first patch.
By: Leif Madsen (lmadsen) 2007-04-18 21:23:42

Wow, good work on the debugging and fixing guys!
By: Jason Parker (jparker) 2007-04-20 16:37:31

Fixed in svn 1.4 and trunk in revisions 61707 and 60708.