[Home]

Summary:ASTERISK-13343: Random audio dropouts when jitterbuffer = yes
Reporter:Andrey Sofronov (andrey sofronov)Labels:
Date Opened:2009-01-12 10:02:02.000-0600Date Closed:2011-06-07 14:03:11
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Sometimes (couple times per month) I get one-way audio issue on IAX2 trunks.
iax.conf looks like:
[general]
autokill = yes

bindaddr = xx.xx.xx.xx
disallow = all

jitterbuffer = yes
maxjitterbuffer = 1000
trunktimestamps = yes
transfer = yes

[guest]
type = user
context = guest

[peer1]
type = user
allow = speex
auth = rsa
inkeys = ....
context = peer1_incoming

[peer2]
type = peer
username = tminsk_speex
host = xx.xx.xx.xx
allow = speex
trunk = yes
qualify = yes
auth = rsa
outkey = ....

When the issue occurs, the calling party can hear the remote party, but the remote party hears silence. The only way that helps is "unload module chan_iax2.so && load module chan_iax2.so". Also disabling jitterbuffer and "iax2 reload" helps.

http://bugs.digium.com/view.php?id=14044 - that patch doesn't help me
Comments:By: Andrey Sofronov (andrey sofronov) 2009-01-22 02:33:24.000-0600

UPDATE: it seems that only SMP systems affected.
By: Brett Matthews (brett matthews) 2009-02-04 16:24:17.000-0600

I added jitterbuffer=yes on one of our 3 office boxes which all have 1.4.21.2 on them. Since then I have had staff complaining about calls going back to one way audio. I have removed the jitterbuffer=yes since then and all seems ok. I have never had complaint of iax calls going to one way audio before now if it at all helps. Installed on Dell Poweredge 1850 with single Quad core CPU for additional info.
By: Andrey Sofronov (andrey sofronov) 2009-03-06 06:58:11.000-0600

I can confirm, that only adding "nosmp" to kernel cmdline solves this issue.
By: David Vossel (dvossel) 2009-04-14 16:21:45

Is is a hard one to reproduce.  Is there anyway I can get a 'core show locks' output and a gdb backtrace (thread apply all bt with gdb) of the issue when it occurs?
By: David Vossel (dvossel) 2009-04-28 10:30:27

Feel free to re-open this issue if more feedback can be provided.
By: Andrey Sofronov (andrey sofronov) 2009-05-08 06:33:09

Got "one way audio" at all trunks again.

core show locks:

=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <file> <line num> <function> <lock name> <lock addr> (times locked)
===
=======================================================================

iax2 show netstats:                                -------- LOCAL ---------------------  -------- REMOTE --------------------
Channel                    RTT  Jit  Del  Lost   %  Drop  OOO  Kpkts  Jit  Del Lost   %  Drop  OOO  Kpkts
IAX2/any_peer-4653        1000    3   83     0   0   688    0      0    0    0 0   0     0    0      0

iax2 set debug:
Rx-Frame Retry[ No] -- OSeqno: 071 ISeqno: 075 Type: IAX     Subclass: LAGRQ  
  Timestamp: 14960890ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 075 ISeqno: 072 Type: IAX     Subclass: LAGRP  
  Timestamp: 14960890ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 072 ISeqno: 076 Type: IAX     Subclass: ACK    
  Timestamp: 14960890ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW    
  Timestamp: 00016ms  SCall: 16384  DCall: 00000 [10.yy.yy.yy:4569]
  VERSION         : 2
  CALLED NUMBER   : 2092
  CODEC_PREFS     : (speex)
  CALLING NUMBER  : 1112
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 1
  CALLING TRANSIT : 0
  CALLING NAME    :
  LANGUAGE        : ru
  USERNAME        : any_peer
  FORMAT          : 512
  CAPABILITY      : 512
  ADSICPE         : 2
  DATE TIME       : 2009-05-08  15:59:02

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00008ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
  AUTHMETHODS     : 4
  CHALLENGE       : 398197436
  USERNAME        : any_peer

Rx-Frame Retry[ No] -- OSeqno: 113 ISeqno: 117 Type: IAX     Subclass: LAGRQ  
  Timestamp: 19440882ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 117 ISeqno: 114 Type: IAX     Subclass: LAGRP  
  Timestamp: 19440882ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 114 ISeqno: 118 Type: IAX     Subclass: ACK    
  Timestamp: 19440882ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 076 ISeqno: 072 Type: IAX     Subclass: LAGRQ  
  Timestamp: 14960508ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 072 ISeqno: 077 Type: IAX     Subclass: LAGRP  
  Timestamp: 14960508ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
Tx-Frame Retry[-01] -- OSeqno: 077 ISeqno: 073 Type: IAX     Subclass: ACK    
  Timestamp: 14960508ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00008ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
  AUTHMETHODS     : 4
  CHALLENGE       : 398197436
  USERNAME        : any_peer

Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW    
  Timestamp: 00016ms  SCall: 16384  DCall: 00000 [10.yy.yy.yy:4569]
  VERSION         : 2
  CALLED NUMBER   : 2092
  CODEC_PREFS     : (speex)
  CALLING NUMBER  : 1112
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 1
  CALLING TRANSIT : 0
  CALLING NAME    :
  LANGUAGE        : ru
  USERNAME        : any_peer
  FORMAT          : 512
  CAPABILITY      : 512
  ADSICPE         : 2
  DATE TIME       : 2009-05-08  15:59:02

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00017ms  SCall: 12758  DCall: 16384 [10.yy.yy.yy:4569]
  AUTHMETHODS     : 4
  CHALLENGE       : 724485669
  USERNAME        : any_peer

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 02203ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
  RSA RESULT      :
sdGzns4m/s2GUojF/5Vc4uCR02LEYyY1W9ncQlwoSnRuE3mtATsTQcVKKkgDh1gVqr9tH7bDQMrC0f8mRaCN+zPC/GfD3+5kWaGOcTy3YDm2JFYcCsdodD5s9q8/Wdt52bGK2aEl3yP+bfI4jyREdwq/68z62D+Ke1jIkPG8XDY=

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 02196ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
  FORMAT          : 512

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL  
  Timestamp: 00000ms  SCall: 16384  DCall: 12758 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 137
  Timestamp: 02220ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: PROCDNG
  Timestamp: 02243ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 002 Type: CONTROL Subclass: RINGING
  Timestamp: 02246ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 118 ISeqno: 114 Type: IAX     Subclass: LAGRQ  
  Timestamp: 19440601ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 02196ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 114 ISeqno: 119 Type: IAX     Subclass: LAGRP  
  Timestamp: 19440601ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
Tx-Frame Retry[-01] -- OSeqno: 119 ISeqno: 115 Type: IAX     Subclass: ACK    
  Timestamp: 19440601ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 137
  Timestamp: 02440ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 02440ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 02220ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 02243ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 02246ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE  
  Timestamp: 00006ms  SCall: 01442  DCall: 00000 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK    
  Timestamp: 00189ms  SCall: 01442  DCall: 00001 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE  
  Timestamp: 00018ms  SCall: 10081  DCall: 00000 [10.yy.yy.yy:4569]
Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG  
  Timestamp: 00000ms  SCall: 00001  DCall: 10081 [10.yy.yy.yy:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK    
  Timestamp: 00278ms  SCall: 10081  DCall: 00001 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 115 ISeqno: 119 Type: IAX     Subclass: PING  
  Timestamp: 19446535ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 119 ISeqno: 116 Type: IAX     Subclass: PONG  
  Timestamp: 19446535ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
  RR_JITTER       : 3
  RR_LOSS         : 16777228
  RR_PKTS         : 6130
  RR_DELAY        : 135
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Rx-Frame Retry[ No] -- OSeqno: 116 ISeqno: 120 Type: IAX     Subclass: ACK    
  Timestamp: 19446535ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 003 Type: CONTROL Subclass: (255?)
  Timestamp: 07543ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 003 Type: CONTROL Subclass: ANSWER
  Timestamp: 07546ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 003 Type: CONTROL Subclass: (255?)
  Timestamp: 07549ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 003 Type: CONTROL Subclass: (20?)
  Timestamp: 07552ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 07543ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 007 Type: IAX     Subclass: ACK    
  Timestamp: 07546ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 008 Type: IAX     Subclass: ACK    
  Timestamp: 07549ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 009 Type: IAX     Subclass: ACK    
  Timestamp: 07552ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 009 Type: CONTROL Subclass: RINGING
  Timestamp: 08063ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 08063ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 009 Type: CONTROL Subclass: (20?)
  Timestamp: 08066ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 08066ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 009 Type: CONTROL Subclass: (20?)
  Timestamp: 08069ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 08069ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 009 Type: CONTROL Subclass: (20?)
  Timestamp: 08072ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 007 Type: IAX     Subclass: ACK    
  Timestamp: 08072ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 120 ISeqno: 116 Type: IAX     Subclass: PING  
  Timestamp: 19446595ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 116 ISeqno: 121 Type: IAX     Subclass: PONG  
  Timestamp: 19446595ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
  RR_JITTER       : 5
  RR_LOSS         : 16777226
  RR_PKTS         : 6144
  RR_DELAY        : 158
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Tx-Frame Retry[-01] -- OSeqno: 121 ISeqno: 117 Type: IAX     Subclass: ACK    
  Timestamp: 19446595ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 073 ISeqno: 077 Type: IAX     Subclass: LAGRQ  
  Timestamp: 14970890ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 077 ISeqno: 074 Type: IAX     Subclass: LAGRP  
  Timestamp: 14970890ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 074 ISeqno: 078 Type: IAX     Subclass: ACK    
  Timestamp: 14970890ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 007 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10011ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 009 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10019ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 010 ISeqno: 008 Type: IAX     Subclass: LAGRP  
  Timestamp: 10019ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 010 Type: IAX     Subclass: LAGRP  
  Timestamp: 10011ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Tx-Frame Retry[-01] -- OSeqno: 010 ISeqno: 009 Type: IAX     Subclass: ACK    
  Timestamp: 10011ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 011 Type: IAX     Subclass: ACK    
  Timestamp: 10019ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 117 ISeqno: 121 Type: IAX     Subclass: LAGRQ  
  Timestamp: 19450883ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 121 ISeqno: 118 Type: IAX     Subclass: LAGRP  
  Timestamp: 19450883ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 118 ISeqno: 122 Type: IAX     Subclass: ACK    
  Timestamp: 19450883ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE  
  Timestamp: 00006ms  SCall: 12864  DCall: 00000 [10.8.240.3:4569]
Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG  
  Timestamp: 00000ms  SCall: 00001  DCall: 12864 [10.8.240.3:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK    
  Timestamp: 00041ms  SCall: 12864  DCall: 00001 [10.8.240.3:4569]
Tx-Frame Retry[000] -- OSeqno: 078 ISeqno: 074 Type: IAX     Subclass: LAGRQ  
  Timestamp: 14970508ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 074 ISeqno: 079 Type: IAX     Subclass: LAGRP  
  Timestamp: 14970508ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
Tx-Frame Retry[-01] -- OSeqno: 079 ISeqno: 075 Type: IAX     Subclass: ACK    
  Timestamp: 14970508ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 075 ISeqno: 079 Type: IAX     Subclass: PING  
  Timestamp: 14973444ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 079 ISeqno: 076 Type: IAX     Subclass: PONG  
  Timestamp: 14973444ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
  RR_JITTER       : 7
  RR_LOSS         : 33554448
  RR_PKTS         : 1158
  RR_DELAY        : 127
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Rx-Frame Retry[ No] -- OSeqno: 076 ISeqno: 080 Type: IAX     Subclass: ACK    
  Timestamp: 14973444ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 122 ISeqno: 118 Type: IAX     Subclass: LAGRQ  
  Timestamp: 19450601ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 118 ISeqno: 123 Type: IAX     Subclass: LAGRP  
  Timestamp: 19450601ms  SCall: 12341  DCall: 09994 [10.xx.xx.xx:4569]
Tx-Frame Retry[-01] -- OSeqno: 123 ISeqno: 119 Type: IAX     Subclass: ACK    
  Timestamp: 19450601ms  SCall: 09994  DCall: 12341 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 080 ISeqno: 076 Type: IAX     Subclass: PING  
  Timestamp: 14973465ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
Rx-Frame Retry[ No] -- OSeqno: 076 ISeqno: 081 Type: IAX     Subclass: PONG  
  Timestamp: 14973465ms  SCall: 02415  DCall: 04746 [10.xx.xx.xx:4569]
  RR_JITTER       : 7
  RR_LOSS         : 16777232
  RR_PKTS         : 1159
  RR_DELAY        : 136
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Tx-Frame Retry[-01] -- OSeqno: 081 ISeqno: 077 Type: IAX     Subclass: ACK    
  Timestamp: 14973465ms  SCall: 04746  DCall: 02415 [10.xx.xx.xx:4569]
Tx-Frame Retry[000] -- OSeqno: 011 ISeqno: 009 Type: CONTROL Subclass: (20?)
  Timestamp: 16423ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 009 Type: CONTROL Subclass: BUSY  
  Timestamp: 16426ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 012 Type: IAX     Subclass: ACK    
  Timestamp: 16423ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 013 Type: IAX     Subclass: ACK    
  Timestamp: 16426ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 013 Type: CONTROL Subclass: (20?)
  Timestamp: 16943ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 010 Type: IAX     Subclass: ACK    
  Timestamp: 16943ms  SCall: 12494  DCall: 16384 [10.yy.yy.yy:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 013 Type: IAX     Subclass: HANGUP
  Timestamp: 16946ms  SCall: 16384  DCall: 12494 [10.yy.yy.yy:4569]
  CAUSE CODE      : 17

At that time on another asterisk (connected through IAX2 trunk) was:
[May  8 15:03:55] WARNING[4447]: chan_iax2.c:797 jb_warning_output: Resyncing the jb. last_delay 0, this delay 4983, threshold 1000, new offset -4983

The only way to recover - iax2 unload && iax2 load.




By: Digium Subversion (svnbot) 2009-05-21 14:04:59

Repository: asterisk
Revision: 195991

U   branches/1.4/channels/chan_iax2.c

------------------------------------------------------------------------
r195991 | dvossel | 2009-05-21 14:04:57 -0500 (Thu, 21 May 2009) | 14 lines

Sign problem calculating timestamp for iax frame leads to no audio on the receiving peer.

There are rare cases in which a frame's delivery timestamp is slightly less than the iax2_pvt's offset.  This causes the pvt's timestamp to be a small negative number, but since the timestamp value is unsigned it looks like a huge positive number.  This patch checks for this negative case and sets the ms to zero.  A similar check is already done right below this one in the 'else' statement.

(closes issue ASTERISK-14066)
Reported by: guillecabeza
Patches:
     chan_iax2.c.patch_timestamp uploaded by guillecabeza (license 380)
Tested by: guillecabeza

(closes issue ASTERISK-13343)
Reported by: Andrey Sofronov


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

http://svn.digium.com/view/asterisk?view=rev&revision=195991
By: Digium Subversion (svnbot) 2009-05-21 14:11:51

Repository: asterisk
Revision: 195995

_U  trunk/
U   trunk/channels/chan_iax2.c

------------------------------------------------------------------------
r195995 | dvossel | 2009-05-21 14:11:50 -0500 (Thu, 21 May 2009) | 20 lines

Merged revisions 195991 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r195991 | dvossel | 2009-05-21 14:04:56 -0500 (Thu, 21 May 2009) | 14 lines
 
 Sign problem calculating timestamp for iax frame leads to no audio on the receiving peer.
 
 There are rare cases in which a frame's delivery timestamp is slightly less than the iax2_pvt's offset.  This causes the pvt's timestamp to be a small negative number, but since the timestamp value is unsigned it looks like a huge positive number.  This patch checks for this negative case and sets the ms to zero.  A similar check is already done right below this one in the 'else' statement.
 
 (closes issue ASTERISK-14066)
 Reported by: guillecabeza
 Patches:
       chan_iax2.c.patch_timestamp uploaded by guillecabeza (license 380)
 Tested by: guillecabeza
 
 (closes issue ASTERISK-13343)
 Reported by: Andrey Sofronov
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=195995
By: Digium Subversion (svnbot) 2009-05-21 14:12:56

Repository: asterisk
Revision: 195997

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_iax2.c

------------------------------------------------------------------------
r195997 | dvossel | 2009-05-21 14:12:55 -0500 (Thu, 21 May 2009) | 27 lines

Merged revisions 195995 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r195995 | dvossel | 2009-05-21 14:11:49 -0500 (Thu, 21 May 2009) | 20 lines
 
 Merged revisions 195991 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r195991 | dvossel | 2009-05-21 14:04:56 -0500 (Thu, 21 May 2009) | 14 lines
   
   Sign problem calculating timestamp for iax frame leads to no audio on the receiving peer.
   
   There are rare cases in which a frame's delivery timestamp is slightly less than the iax2_pvt's offset.  This causes the pvt's timestamp to be a small negative number, but since the timestamp value is unsigned it looks like a huge positive number.  This patch checks for this negative case and sets the ms to zero.  A similar check is already done right below this one in the 'else' statement.
   
   (closes issue ASTERISK-14066)
   Reported by: guillecabeza
   Patches:
         chan_iax2.c.patch_timestamp uploaded by guillecabeza (license 380)
   Tested by: guillecabeza
   
   (closes issue ASTERISK-13343)
   Reported by: Andrey Sofronov
 ........
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=195997
By: Digium Subversion (svnbot) 2009-05-21 14:13:46

Repository: asterisk
Revision: 195998

_U  branches/1.6.1/
U   branches/1.6.1/channels/chan_iax2.c

------------------------------------------------------------------------
r195998 | dvossel | 2009-05-21 14:13:45 -0500 (Thu, 21 May 2009) | 27 lines

Merged revisions 195995 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r195995 | dvossel | 2009-05-21 14:11:49 -0500 (Thu, 21 May 2009) | 20 lines
 
 Merged revisions 195991 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r195991 | dvossel | 2009-05-21 14:04:56 -0500 (Thu, 21 May 2009) | 14 lines
   
   Sign problem calculating timestamp for iax frame leads to no audio on the receiving peer.
   
   There are rare cases in which a frame's delivery timestamp is slightly less than the iax2_pvt's offset.  This causes the pvt's timestamp to be a small negative number, but since the timestamp value is unsigned it looks like a huge positive number.  This patch checks for this negative case and sets the ms to zero.  A similar check is already done right below this one in the 'else' statement.
   
   (closes issue ASTERISK-14066)
   Reported by: guillecabeza
   Patches:
         chan_iax2.c.patch_timestamp uploaded by guillecabeza (license 380)
   Tested by: guillecabeza
   
   (closes issue ASTERISK-13343)
   Reported by: Andrey Sofronov
 ........
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=195998
By: Digium Subversion (svnbot) 2009-05-21 14:15:07

Repository: asterisk
Revision: 196000

_U  branches/1.6.2/
U   branches/1.6.2/channels/chan_iax2.c

------------------------------------------------------------------------
r196000 | dvossel | 2009-05-21 14:15:06 -0500 (Thu, 21 May 2009) | 27 lines

Merged revisions 195995 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r195995 | dvossel | 2009-05-21 14:11:49 -0500 (Thu, 21 May 2009) | 20 lines
 
 Merged revisions 195991 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r195991 | dvossel | 2009-05-21 14:04:56 -0500 (Thu, 21 May 2009) | 14 lines
   
   Sign problem calculating timestamp for iax frame leads to no audio on the receiving peer.
   
   There are rare cases in which a frame's delivery timestamp is slightly less than the iax2_pvt's offset.  This causes the pvt's timestamp to be a small negative number, but since the timestamp value is unsigned it looks like a huge positive number.  This patch checks for this negative case and sets the ms to zero.  A similar check is already done right below this one in the 'else' statement.
   
   (closes issue ASTERISK-14066)
   Reported by: guillecabeza
   Patches:
         chan_iax2.c.patch_timestamp uploaded by guillecabeza (license 380)
   Tested by: guillecabeza
   
   (closes issue ASTERISK-13343)
   Reported by: Andrey Sofronov
 ........
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=196000
By: Andrey Sofronov (andrey sofronov) 2009-06-11 03:15:33

Unfortunately this happens again. Again - on single core boxes it does not occurs.

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW    
  Timestamp: 00015ms  SCall: 16385  DCall: 00000 [10.XX.XX.XX:4569]
  VERSION         : 2
  CALLED NUMBER   : 3245
  CODEC_PREFS     : (speex)
  CALLING NUMBER  : 3036
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 1
  CALLING TRANSIT : 0
  CALLING NAME    :
  LANGUAGE        : ru
  USERNAME        : tpeer2_speex
  FORMAT          : 512
  CAPABILITY      : 512
  ADSICPE         : 2
  DATE TIME       : 2009-06-11  09:28:28

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00014ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
  AUTHMETHODS     : 4
  CHALLENGE       : 129046211
  USERNAME        : tpeer2_speex

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00029ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
  RSA RESULT      : tFbuzgBnY05tHHa1OrzzDqVmMvM6/TxdfXbMxeRFxRE5dNUXY0b3AZ0+VX2jSvA2mwC7bqpUh8gwghsDq2CewoOtUph5xJ98xPNmkT+Dz3MarqdiiykZgL+6Z4xFy5TwPrKQtB20s6Ja+ZEyCwacgm5r5FenvHhsG2CbBv7F9kk=

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 00027ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
  FORMAT          : 512

Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 00027ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 137
  Timestamp: 00060ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00060ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: PROCDNG
  Timestamp: 00030ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 003 Type: CONTROL Subclass: RINGING
  Timestamp: 00033ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 003 Type: VOICE   Subclass: 137
  Timestamp: 00100ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00030ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 00033ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 00100ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 003 Type: CONTROL Subclass: (255?)
  Timestamp: 02043ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 003 Type: CONTROL Subclass: ANSWER
  Timestamp: 02046ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 003 Type: CONTROL Subclass: (255?)
  Timestamp: 02049ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 003 Type: CONTROL Subclass: (20?)
  Timestamp: 02052ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 02043ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 007 Type: IAX     Subclass: ACK    
  Timestamp: 02046ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 008 Type: IAX     Subclass: ACK    
  Timestamp: 02049ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 009 Type: IAX     Subclass: ACK    
  Timestamp: 02052ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 009 Type: CONTROL Subclass: RINGING
  Timestamp: 02263ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 02263ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 009 Type: CONTROL Subclass: (20?)
  Timestamp: 02266ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 02266ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 009 Type: CONTROL Subclass: (20?)
  Timestamp: 02269ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 02269ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 009 Type: CONTROL Subclass: (20?)
  Timestamp: 02272ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 007 Type: IAX     Subclass: ACK    
  Timestamp: 02272ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE  
  Timestamp: 00007ms  SCall: 11384  DCall: 00000 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK    
  Timestamp: 00017ms  SCall: 11384  DCall: 00001 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW    
  Timestamp: 00015ms  SCall: 16386  DCall: 00000 [10.XX.XX.XX:4569]
  VERSION         : 2
  CALLED NUMBER   : 3036
  CODEC_PREFS     : (speex)
  CALLING NUMBER  : 3235
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 1
  CALLING TRANSIT : 0
  CALLING NAME    :
  LANGUAGE        : ru
  USERNAME        : tpeer1_speex
  FORMAT          : 512
  CAPABILITY      : 512
  ADSICPE         : 2
  DATE TIME       : 2009-06-11  11:04:16

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00004ms  SCall: 12263  DCall: 16386 [10.XX.XX.XX:4569]
  AUTHMETHODS     : 4
  CHALLENGE       : 134495387
  USERNAME        : tpeer1_speex

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00025ms  SCall: 16386  DCall: 12263 [10.XX.XX.XX:4569]
  RSA RESULT      : hNjJ4hw8zXc04pM3HOmFYIWcFYX9WOha7TazlJYcrfMnn91X1tiZ9gH9hcOajmw0EoMHWzPyBHdp/m8GcOzsWUd3dGbKUhiu1MLU/vtdQElDPW9LDQs9xndjZ8tLiv+SlpfuW8Wpct4tSwBZwpP9ZMR6vl1up9vVRmG1cZwJi5w=

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 00016ms  SCall: 12263  DCall: 16386 [10.XX.XX.XX:4569]
  FORMAT          : 512

Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 00016ms  SCall: 16386  DCall: 12263 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 137
  Timestamp: 00060ms  SCall: 16386  DCall: 12263 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00060ms  SCall: 12263  DCall: 16386 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: BUSY  
  Timestamp: 00019ms  SCall: 12263  DCall: 16386 [10.XX.XX.XX:4569]
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00019ms  SCall: 16386  DCall: 12263 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 009 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10025ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 008 Type: IAX     Subclass: LAGRP  
  Timestamp: 10025ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 010 Type: IAX     Subclass: ACK    
  Timestamp: 10025ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
ippbx*CLI> iax2 show netstats
                          -------- LOCAL ---------------------  -------- REMOTE --------------------
Channel               RTT  Jit  Del  Lost   %  Drop  OOO  Kpkts  Jit  Del  Lost   %  Drop  OOO  Kpkts FirstMsg    LastMsg
IAX2/tpeer2_speex-5242 1000    8  128     0   0   528    0      0    0    0     0   0     0    0      0 Rx:NEW      Rx:ACK    
(None)               1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:HANGUP
(None)               1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:HANGUP
IAX2/tpeer1_speex-16386 1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:ACK    
4 active IAX channels
ippbx*CLI> iax2 show netstats
                          -------- LOCAL ---------------------  -------- REMOTE --------------------
Channel               RTT  Jit  Del  Lost   %  Drop  OOO  Kpkts  Jit  Del  Lost   %  Drop  OOO  Kpkts FirstMsg    LastMsg
IAX2/tpeer2_speex-5242 1000    8  128     0   0   714    0      0    0    0     0   0     0    0      0 Rx:NEW      Rx:ACK    
(None)               1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:HANGUP
(None)               1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:HANGUP
IAX2/tpeer1_speex-16386 1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:ACK    
4 active IAX channels
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10004ms  SCall: 12263  DCall: 16386 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: LAGRP  
  Timestamp: 10004ms  SCall: 16386  DCall: 12263 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 10004ms  SCall: 12263  DCall: 16386 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 010 Type: IAX     Subclass: LAGRQ  
  Timestamp: 20027ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 010 ISeqno: 009 Type: IAX     Subclass: LAGRP  
  Timestamp: 20027ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 011 Type: IAX     Subclass: ACK    
  Timestamp: 20027ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 011 Type: IAX     Subclass: PING  
  Timestamp: 21027ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 011 ISeqno: 010 Type: IAX     Subclass: PONG  
  Timestamp: 21027ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
  RR_JITTER       : 8
  RR_LOSS         : 0
  RR_PKTS         : 50
  RR_DELAY        : 128
  RR_DROPPED      : 1002
  RR_OUTOFORDER   : 0

Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 012 Type: IAX     Subclass: ACK    
  Timestamp: 21027ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
ippbx*CLI> iax2 show netstats
                          -------- LOCAL ---------------------  -------- REMOTE --------------------
Channel               RTT  Jit  Del  Lost   %  Drop  OOO  Kpkts  Jit  Del  Lost   %  Drop  OOO  Kpkts FirstMsg    LastMsg
IAX2/tpeer2_speex-5242 1000    8  128     0   0  1004    0      0    0    0     0   0     0    0      0 Rx:NEW      Rx:ACK    
(None)               1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:HANGUP
(None)               1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:HANGUP
IAX2/tpeer1_speex-16386 1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Rx:ACK    
4 active IAX channels
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: HANGUP
  Timestamp: 15159ms  SCall: 16386  DCall: 12263 [10.XX.XX.XX:4569]
  CAUSE CODE      : 17

Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 15159ms  SCall: 12263  DCall: 16386 [10.XX.XX.XX:4569]
ippbx*CLI> iax2 show netstats
                          -------- LOCAL ---------------------  -------- REMOTE --------------------
Channel               RTT  Jit  Del  Lost   %  Drop  OOO  Kpkts  Jit  Del  Lost   %  Drop  OOO  Kpkts FirstMsg    LastMsg
IAX2/tpeer2_speex-5242 1000    8  128     0   0  1445    0      0    0    0     0   0     0    0      0 Rx:NEW      Rx:ACK    
(None)               1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:HANGUP
(None)               1000    0  120     0   0     0    0      0    0    0     0   0     0    0      0 Tx:NEW      Tx:HANGUP
3 active IAX channels
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 012 Type: IAX     Subclass: LAGRQ  
  Timestamp: 30029ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 011 Type: IAX     Subclass: LAGRP  
  Timestamp: 30029ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 013 Type: IAX     Subclass: ACK    
  Timestamp: 30029ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW    
  Timestamp: 00018ms  SCall: 16387  DCall: 00000 [10.XX.XX.XX:4569]
  VERSION         : 2
  CALLED NUMBER   : 3036
  CODEC_PREFS     : (speex)
  CALLING NUMBER  : 3235
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 1
  CALLING TRANSIT : 0
  CALLING NAME    :
  LANGUAGE        : ru
  USERNAME        : tpeer1_speex
  FORMAT          : 512
  CAPABILITY      : 512
  ADSICPE         : 2
  DATE TIME       : 2009-06-11  11:04:44

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00004ms  SCall: 04676  DCall: 16387 [10.XX.XX.XX:4569]
  AUTHMETHODS     : 4
  CHALLENGE       : 255995562
  USERNAME        : tpeer1_speex

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00030ms  SCall: 16387  DCall: 04676 [10.XX.XX.XX:4569]
  RSA RESULT      : akkDyUkKpDYikgmx+ZLk3WDHdK8REaGeTGeGTJaYMKF0oNPu98Bn9EWKd5VJUZSKjK25PwvyOfDs9WMPPpxCxeZwmRMYmJ0+1LODe8TuEKO5XgpP6BuWRgZwRgGGwTQmwrUTgh1XUzdniB5U/TqRhBDuW7DiboyKKpFWdoLbM/M=

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 00016ms  SCall: 04676  DCall: 16387 [10.XX.XX.XX:4569]
  FORMAT          : 512

Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 00016ms  SCall: 16387  DCall: 04676 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: VOICE   Subclass: 137
  Timestamp: 00060ms  SCall: 16387  DCall: 04676 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00060ms  SCall: 04676  DCall: 16387 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: BUSY  
  Timestamp: 00576ms  SCall: 04676  DCall: 16387 [10.XX.XX.XX:4569]
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00576ms  SCall: 16387  DCall: 04676 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 013 Type: IAX     Subclass: LAGRQ  
  Timestamp: 40031ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 013 ISeqno: 012 Type: IAX     Subclass: LAGRP  
  Timestamp: 40031ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 014 Type: IAX     Subclass: ACK    
  Timestamp: 40031ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 014 Type: IAX     Subclass: PING  
  Timestamp: 42031ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 014 ISeqno: 013 Type: IAX     Subclass: PONG  
  Timestamp: 42031ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
  RR_JITTER       : 8
  RR_LOSS         : 0
  RR_PKTS         : 50
  RR_DELAY        : 128
  RR_DROPPED      : 2052
  RR_OUTOFORDER   : 0

Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 015 Type: IAX     Subclass: ACK    
  Timestamp: 42031ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: HANGUP
  Timestamp: 07719ms  SCall: 16387  DCall: 04676 [10.XX.XX.XX:4569]
  CAUSE CODE      : 17

Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 07719ms  SCall: 04676  DCall: 16387 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 015 Type: IAX     Subclass: LAGRQ  
  Timestamp: 50033ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]
Tx-Frame Retry[000] -- OSeqno: 015 ISeqno: 014 Type: IAX     Subclass: LAGRP  
  Timestamp: 50033ms  SCall: 05242  DCall: 16385 [10.XX.XX.XX:4569]
Rx-Frame Retry[ No] -- OSeqno: 014 ISeqno: 016 Type: IAX     Subclass: ACK    
  Timestamp: 50033ms  SCall: 16385  DCall: 05242 [10.XX.XX.XX:4569]

By: Andrey Sofronov (andrey sofronov) 2009-06-11 03:17:43

NOTE: I'm using asterisk 1.4.26-rc1
By: David Vossel (dvossel) 2009-06-11 09:58:51

I'll continue to look into this.  This is kind of puzzling.  Your first debug output before I closed the issue contained elements that pointed directly to a negative timestamp (timestamps are unsigned, so a negative time stamp just looks like a huge positive one) causing the issue.

Example: Timestamp: 19450601ms SCall: 12341 DCall: 09994 [10.xx.xx.xx:4569]

The timestamp should never be that big, especially at the beginning of a call.  The patch I committed seems to have fixed that as I don't see any evidence of this in the new output you provided.
By: David Vossel (dvossel) 2009-06-11 12:49:46

Are you aware of any previous 1.4 versions in which this did not occur?  Also, I assume you update both sides of the iax trunk correct?


By: Guillermo Winkler (guillecabeza) 2009-06-17 18:04:30

dvossel, 19450601ms are 324 minutes, it doesn't look like a sign problem. just by looking at it seems more like a bug on the timestamp calculation.

the problem may be on the originating peer (maybe a sip carrier?) and not on the asterisk side, because the audio frames timestamp is forwarded as-it-comes.

andrey, can you please specify what technology are you using on the originating peer? are incoming or outgoing calls?
By: Andrey Sofronov (andrey sofronov) 2009-06-18 02:23:40

First time this occurred with 1.4.21, but I'm not sure. Yes, I updated both sides.

My scheme:
Panasonic KX-TDA -> Digium TEXXX -> * <->(IAX2 trunk)<-> * -> Digium TEXXX -> Panasonic KX-TDA

I'm not using SIP.
By: David Vossel (dvossel) 2009-06-18 09:26:30

guillecabeza is right about the timestamp, This does not appear to be related to the negative timestamp patch.   I miss interpreted the debug output to believe that timestamp was associated with the new call when in fact it wasn't.
By: sebycarta (sebycarta) 2009-06-22 01:45:31

I have the same problem, also on single core boxes. I tried asterisk 1.4.25.1 and 1.6.0.10, the problem is the same, randomly the call is dropped out, but i noticed that waiting for 1 or 2 minutes the call return and i can continue to speak.

I can say a stupid thing, but why the call is stopped when is received a bad timestamp? Is not be possible to trash that frame and continue?

Please resolve this issue because jitter buffer is very important on slow link like adsl connection.

Thank you for your work.


By: sebycarta (sebycarta) 2009-06-26 07:01:23

After a lot of try i report this:

I have this architecture:

[FXS]<---SIP(ulaw)-->[asterisk box 1] <---IAX2 (g729) JB----> [asterisk box 2] <--SIP(ulaw)---> [FXS]

and the problem of the dropped calls.

I modified the architecture in this way:

[FXS]<---SIP(g729)-->[asterisk box 1] <---IAX2 (g729) JB ----> [asterisk box 2] <--SIP(g729)---> [fxs]

I modified only the codec of the FXSs and the problem disappear!! Then i think the problem is in the codec translation of the timestamps.

I hope this can help you.
By: Faris Raouf (faris1) 2009-07-03 07:06:37

I can confirm also experiencing this issue with Asterisk <- IAX2 -> Asterisk  links. In my case I'm using a single multi-core CPU, asterisk 1.6.0.10 on Centos 4 64-bit, with g.711a codecs and jitterbuffer=yes.

I have no evidence to support it, but if memory serves me, I did not have the problem with Asterisk < 1.6.0.4 and it got particularly bad after Asterisk > 1.6.0.8

The problem sometimes, but not always, goes away for a while after restarting asterisk.

I have set jitterbuffer=no and so far no problems but it has only been 24 hours and as I say, sometimes after a restart things are OK anyway.


By: David Vossel (dvossel) 2009-07-14 15:22:08

I've continued to investigated this issue have very little leads on what could be causing it.  Can anyone experiencing this provide specific steps to reproduce it.
By: Faris Raouf (faris1) 2009-07-16 07:39:29

Unfortunately not only can I not reproduce it on demand, I've found that jitterbuffer=no didn't seem to resolve things 100% reliably but does seem to have made things a lot better.

The real problem we have is that it happens far to infrequently, and the number of calls we make/receive is very low, so it is hard to tell what's happening.


One tiny tiny snippet of info that I can add is this (when we experience the problem):

When we make outbound calls via IAX, if the problem happens we stop being able to hear the person we have called after a few mins.

In contrast, when we get incoming calls, the caller can't hear us after a few mins.

(And just as the original poster said, if you wait a little while without hanging up, the audio returns to normal).


In all cases the connection has a latency of 10ms or less. It is from our own co-lo Asterisk box to a highly respected PSTN gateway provider - not cheap and cheerful. I've managed to ping the gateway provider when the problem was in progress, and there was nothing obvious going on. Still 10ms or less.

I do, in theory, have a TCPdump that covers a call when the problem was happening, but I don't want to post it anywhere public. I also need to double-check I still have it. It is quite big -- could be as much as 10Mb as I had it running constantly. I would not be able to point to the exact place in the dump that relates to when the problem happened either. So not all that useful I suppose :-(


By: David Vossel (dvossel) 2009-07-20 18:38:17

With the current information provided, I am unable to move this issue forward.  Feel free to reopen this issue if you can provide concrete information as to exactly what is causing this or provide precise steps to reproduce it.