Summary:ASTERISK-03869: iax2 trunking ping timestamp problem
Reporter:zoa (zoa)Labels:
Date Opened:2005-04-05 10:51:11Date Closed:2011-06-07 14:05:10
Versions:Frequency of
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.


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

 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 ?


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.


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)



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)