ASTERISK-03869: iax2 trunking ping timestamp problem

[Home]

Summary: ASTERISK-03869: iax2 trunking ping timestamp problem

Reporter: zoa (zoa) Labels:

Date Opened: 2005-04-05 10:51:11 Date Closed: 2011-06-07 14:05:10

Priority: Major Regression? No

Status: Closed/Complete Components: Channels/chan_iax2

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) chan_iax2.iax_fr_ts.patch.txt

Description: No idea if this is a problem with ethereal or chan_iax.c but ethereal reports weird timestamps when sniffing between asterisk and iaxclient, when the asterisk is connected to another server with iax2 trunking.

Any comments / suggestions ?

We are trying to hunt down a situation where when trunking is enabled on iaxclient -> * -> iax2 trunk -> * -> pstn we get one way audio after approx 1 minute. (the pstn mic is no longer arriving at the iaxclient headset).

Both STABLE and HEAD are affected.

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

o. Time Source Destination Protocol Info
6870 60.886309 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 59980ms, GSM compression
6871 60.896304 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 59963ms, GSM compression
6872 60.906312 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60000ms, GSM compression
6873 60.916299 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 59983ms, GSM compression
6874 60.926354 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60020ms, GSM compression
6875 60.936796 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60003ms, GSM compression
6876 60.946369 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60040ms, GSM compression
6877 60.956303 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60023ms, GSM compression
6878 60.966353 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60060ms, GSM compression
6879 60.968323 10.3.3.6 10.3.3.100 IAX2 IAX, source call# 3, timestamp 4294961783ms PING
6880 60.968355 10.3.3.6 10.3.3.100 IAX2 IAX, source call# 3, timestamp 4294961786ms LAGRQ
6881 60.974320 10.3.3.100 10.3.3.6 IAX2 IAX, source call# 29199, timestamp 4294961783ms ACK
6882 60.974464 10.3.3.100 10.3.3.6 IAX2 IAX, source call# 29199, timestamp 4294961783ms PONG
6883 60.974808 10.3.3.6 10.3.3.100 IAX2 IAX, source call# 3, timestamp 4294961783ms ACK
6884 60.976287 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60043ms, GSM compression
6885 60.984643 10.3.3.100 10.3.3.6 IAX2 IAX, source call# 29199, timestamp 4294961786ms ACK
6886 60.986638 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60080ms, GSM compression
6887 60.994308 10.3.3.100 10.3.3.6 IAX2 IAX, source call# 29199, timestamp 4294961786ms LAGRP
6888 60.994783 10.3.3.6 10.3.3.100 IAX2 IAX, source call# 3, timestamp 4294961786ms ACK
6889 60.996270 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60063ms, GSM compression
6890 61.006123 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60100ms, GSM compression
6891 61.017294 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60083ms, GSM compression
6892 61.026170 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60120ms, GSM compression
6893 61.036299 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60103ms, GSM compression
6894 61.046193 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60140ms, GSM compression
6895 61.056791 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60123ms, GSM compression
6896 61.066196 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60160ms, GSM compression
6897 61.078287 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60143ms, GSM compression
6898 61.086198 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60180ms, GSM compression
6899 61.096286 10.3.3.6 10.3.3.100 IAX2 Mini packet, source call# 3, timestamp 60163ms, GSM compression
6900 61.106280 10.3.3.100 10.3.3.6 IAX2 Mini packet, source call# 29199, timestamp 60200ms, GSM compression

Comments: By: zoa (zoa) 2005-04-05 11:02:42

we suspect this does not cause any problems until later on the 15 bit timestamp overflows, the full frame is sent and the synching is redone.

Its always around the same time as the overflow (65sec) that we see one way audio. (cant pinpoint it exactly as we are too slow with hitting the stop button.)

How does this conspiracy theory sound ?
By: zoa (zoa) 2005-04-05 11:08:57

just to be clear, we are not using jitter buffer on the asterisk servers, and the jitter buffer in iaxclient is disabled.

If we disable the trunking between the two asterisk servers, sounds are perfect.
The ping timestamp is the only difference we can see with ethereal between iaxclient and asterisk when the trunking is enabled or disabled.

Please help, its kinda urgent for me here :/
By: zoa (zoa) 2005-04-05 11:24:02

From chan_iax2.c

/* What sort of frame do we have?: voice is self-explanatory
"genuine" means an IAX frame - things like LAGRQ/RP, PING/PONG, ACK
non-genuine frames are CONTROL frames [ringing etc], DTMF
The "genuine" distinction is needed because genuine frames must get a clock-based timestamp,
the others need a timestamp slaved to the voice frames so that they go in sequence
By: stevekstevek (stevekstevek) 2005-04-05 12:23:15

I'm guessing that 10.3.3.6 is asterisk, based on the source call no, and that 10.3.3.100 is an iaxclient.

asterisk is sending a PING with timestamp 4294961783. That is -5513, I think, expressed as a signed int.

That seems to be pretty wrong :)
By: zoa (zoa) 2005-04-05 12:28:05

quote from irc <stevek> iaxclient is going to use it to update last_ts (or lastts, something like that), and use it for the top bits of the short 16-bit timestamps for miniframes..

10.3.3.6 is indeed asterisk and 10.3.3.100 is an iaxclient
By: zoa (zoa) 2005-04-05 12:31:30

commenting the bridging optimization in chan_iax2.c seems to help.

(with yesterdays iaxclient cvs, but not todays cvs).

edited on: 04-05-05 12:52
By: stevekstevek (stevekstevek) 2005-04-05 12:43:57

When an IAX2 endpoint gets a full frame, that's not an ACK, PONG or LAGRQ (that is, any frame which has the remote's timestamp in it), it should update it's "last timestamp" memory, which it will use for the top 16 bits of timestamps that come from mini frames. Something like this:

iax.c
2122 if (ts > session->last_ts &&
2123 (fh->type == AST_FRAME_IAX &&
2124 subclass != IAX_COMMAND_ACK &&
2125 subclass != IAX_COMMAND_PONG &&
2126 subclass != IAX_COMMAND_LAGRP)) {
2127 session->last_ts = ts;
2128 }

chan_iax2 does this here:
7347 if (iaxs[fr.callno]->last < fr.ts) {
7348 iaxs[fr.callno]->last = fr.ts;

Which, I think, only happens for non-IAX frames; Therefore, chan_iax2 won't get screwed up by this particular nonsensical timestamp.

HOWEVER, it should update last based on PING; If it does not, it breaks when there is no voice transmitted for a call for a couple of minutes. Consider this situation (which is something I do frequently):

A call, using VAD and DTX, is going along, and maybe even transmitting audio, with audio timestamps around 30,000 (0x7530). Then, it becomes silent (perhaps it's listening to something, like a conference call or, it's in a long queue listening to music). Five minutes pass. The call now starts sending along voice frames, with timestamps around 180,000 (0x2bf20).

There's a few things that can go really wrong in this case:

1) The client may be broken (or have different ideas about when full voice frames are needed), and may not send a full voice frame. OR
2) The full voice frame may be delayed (i.e. lost and retransmitted or whatnot).

In either of these cases, the receiver is going to have a hard time recreating the full timestamp from what it's received.. It just has 0xbf20, and the top 16 bits of "last" are still zero.

However, if it updated it's "last" on PING, which happens every so often, the top 16 bits of it's "last" are probably going to be 0x0002, and it will be able to recreate the correct timestamp.

Anyway, the real bug here seems to be the incorrect timestamp that asterisk is putting on the PING..
By: stevekstevek (stevekstevek) 2005-04-05 12:52:42

We're going to investigate this, because our next JB patch includes this change in ts handling, and this bug will also break that..
By: Andrew Kohlsmith (akohlsmith) 2005-04-05 13:15:41

I've been working a little with zoa on this -- It is a little different from the problems I had with IAX2 trunking dying after 65s. I asked him to comment out the IAX2_OPTIMIAZTION define in chan_iax2.c but that didn't help either.

Zoa -- have have you found with respect to altering the ping requests? You mentioned on IRC that that helped some?
By: zoa (zoa) 2005-04-05 13:50:12

Disabling the bridging optimizations seems to help a lot.
There are no high ping timestamps when we comment it out.
By: Mark Spencer (markster) 2005-04-05 14:03:38

The bridge optimization code should probably be removed since we carry up timestamps already.
By: stevekstevek (stevekstevek) 2005-04-05 14:24:49

Wow. I didn't expect that answer from Mark..

If implemented right, it would save a few CPU cycles, though.. But not a whole lot. OTOH, it sure would clean up the code to remove the whole mess!
By: grolloj (grolloj) 2005-04-05 16:29:24

I have a patch included with bug 3965 that should prevent these weird timestamps from being passed. The relevant portion of the patch changes how AST_FRAME_IAX frames are handled in chan_iax2.c. As stevek mentions in his 04-05-05 12:43 comment, the last timestamp should be updated from the control frames. I've removed a schedule_delivery() call for AST_FRAME_IAX frames, since in that function, unwrap_timestamp() was being called, causing the frame's timestamp to be rolled over improperly.
By: zoa (zoa) 2005-04-07 04:21:14

I didnt have time to check out this patch, could you tell me if it will work with the jitter buffer disabled ? (as the rest of the patch is jitter buffer related).

Could the part for fixing the timestamps be isolated ? So that it can be backported to -stable ?

/Z
By: grolloj (grolloj) 2005-04-07 10:09:22

I've attached the fix for just the chan_iax2 timestamping here. It's short, but I checked it with HEAD and stable and it applies and builds without problems.

As mentioned in bug ASTERISK-3933965, there's a disclaimer on file for stevek that I believe covers this as well.

edited on: 04-12-05 12:56
By: zoa (zoa) 2005-04-07 10:49:28

will try to test it tonight. First trying to hunt down an iax2 memory leak.
By: zoa (zoa) 2005-04-08 02:54:17

we didnt manage to test it yesterday, but will do so today.

But we did track down the memory leak :)
By: Mark Spencer (markster) 2005-04-10 22:36:02

this is kinda a strange patch, but is it confirmed?
By: zoa (zoa) 2005-04-11 02:35:47

not yet, gimme some time, its on my todo list...
By: Andrew Kohlsmith (akohlsmith) 2005-04-11 13:20:57

I've uploaded my patch which removes all IAX2 bridge optimization code out of chan_iax2.c. Tested and appears to be working.

One source of fucked-up timestamps gone. :-)
By: zoa (zoa) 2005-04-12 09:33:54

hmm this would be the same as disabling briding optimizations in chan_iax2.c ?
By: Andrew Kohlsmith (akohlsmith) 2005-04-12 09:52:52

Yes; Mark said it should probably be removed, so I went ahead and made a patch that did just that.
By: zoa (zoa) 2005-04-12 13:26:02

aha, i will first try to find some time and servers to test the first patch before radically removing the optimization stuff :)
By: Andrew Kohlsmith (akohlsmith) 2005-04-12 15:39:24

:-) I always commented out the #define IAX2_BRIDGE_OPTIMIZATION anyway, as it caused issues, so in theory I've been running this software for about 2-3 months. I am running this patch in my active systems though so it is getting test time.

-A.
By: Michael Jerris (mikej) 2005-05-12 15:03:47

deleted bridge optimization patch from tzanger to be moved to another bug when it's ready. grolloj says this one is ready to go.
By: Michael Jerris (mikej) 2005-05-12 16:05:56

Tested by tzanger, signed off by grolloj. Should be ready to go.
By: Mark Spencer (markster) 2005-05-14 19:52:22

Fixed in CVS head.
By: Michael Jerris (mikej) 2005-05-16 10:12:33

This actually never got commited.
By: Mark Spencer (markster) 2005-05-18 19:28:10

okay, really this time.
By: Digium Subversion (svnbot) 2008-01-15 15:34:23.000-0600

Repository: asterisk
Revision: 5654

U trunk/channels/chan_iax2.c
U trunk/frame.c
U trunk/include/asterisk/frame.h
U trunk/rtp.c

------------------------------------------------------------------------
r5654 | markster | 2008-01-15 15:34:23 -0600 (Tue, 15 Jan 2008) | 2 lines

Add remainder of rtp fixes, iax2 patch (bug ASTERISK-3869)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=5654
By: Digium Subversion (svnbot) 2008-01-15 15:35:17.000-0600

Repository: asterisk
Revision: 5714

U trunk/channels/chan_iax2.c

------------------------------------------------------------------------
r5714 | markster | 2008-01-15 15:35:16 -0600 (Tue, 15 Jan 2008) | 2 lines

Actually apply timestamp bug (bug ASTERISK-3869)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=5714