[Home]

Summary:ASTERISK-16778: Playback of audio file (gsm,ulaw) audio and dialplan stops when caller is inbound over iax2
Reporter:Mark Seamans (n5yzv)Labels:
Date Opened:2010-10-07 11:34:59Date Closed:2011-07-27 13:55:14
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Inbound call that arrives from IAX2 channel, when call is answered by a sip phone (tested with polycom only) works fine.  No issues.  However if call is not answered, call is dumped to voicemail, about 1 - 3 seconds of the the greeting (The person at extension...) is played such as "The pers....".  This is also true for instead of sending call directly so a simple extension such as:
exten => 888,1,Playback(en/vm-theperson)
The same thing happens.  However, if a local sip phone calls the same extension or voicemail, everything works as expected.  I have been trying numerous 1.6.2.x versions and have had to downgrade every time to 1.6.1.12 in order to have a functional box.

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

Dialplan:
exten => 888,n,Playback(en/vm-theperson)

*Note:  I have tried the Answer and the Progress() as other posts have noted, but this does not work.  Also note that Jitterbuffer and Trunking is disabled on the IAX2 side of the house.

iax.conf:
Local
[general]
bindport = 4569
bindaddr = 0.0.0.0
allow=all
mailboxdetail=yes
iaxthreadcount=200
iaxmaxthreadcount=256

[PEER1]
type=peer
host=1.1.1.1
secret=xxxxx
context=MyContext
qualify=100
auth=plaintext
requirecalltoken=no
trunk=no
canreinvite=no
allow=all

[PEER1]
type=user
secret=xxxxx
auth=plaintext
context=incoming
qualify=100
trunk=no
canreinvite=no
allow=all


Provider:

[general]
bindport = 4569
bindaddr = 0.0.0.0
allow=all
mailboxdetail=yes
iaxthreadcount=200
iaxmaxthreadcount=1000
minregexpire = 500
maxregexpire = 500

[PEER1]
type=user
auth=plaintext
context=CUST1
secret=xxxxx
requirecalltoken=no
qualify=no
trunk=no
transfer=no
allow=all

[PEER1]
type=peer
auth=plaintext
context=incoming
secret=xxxxx
requirecalltoken=no
qualify=no
host=1.1.1.2
trunk=no
transfer=no
allow=all



IAX2 Debug:

lawoffice*CLI>

   -- Called 888@MyContext
   -- Executing [888@MyContext:1] Answer("Local/888@MyContext-eb52;2", "") in new stack
   -- Local/888@MyContext-eb52;1 answered IAX2/MyContext-1131
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
  Timestamp: 00036ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?)
  Timestamp: 00039ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 002 Type: CONTROL Subclass: (25?)
  Timestamp: 00042ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 002 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00045ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 002 Type: CONTROL Subclass: (255?)
  Timestamp: 00048ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 002 Type: CONTROL Subclass: (25?)
  Timestamp: 00051ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 00033ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00036ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 00039ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 00042ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 005 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00054ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00054ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 00045ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00057ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 00057ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 005 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00060ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 00060ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 006 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00063ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 00063ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 006 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00066ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 007 Type: IAX     Subclass: ACK    
  Timestamp: 00066ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 007 Type: IAX     Subclass: ACK    
  Timestamp: 00048ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 008 Type: IAX     Subclass: ACK    
  Timestamp: 00051ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 008 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00069ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 008 ISeqno: 008 Type: IAX     Subclass: ACK    
  Timestamp: 00069ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 008 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00072ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 008 ISeqno: 009 Type: IAX     Subclass: ACK    
  Timestamp: 00072ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 008 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00075ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 008 ISeqno: 010 Type: IAX     Subclass: ACK    
  Timestamp: 00075ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 008 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00078ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 008 ISeqno: 011 Type: IAX     Subclass: ACK    
  Timestamp: 00078ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 008 Type: VOICE   Subclass: 4
  Timestamp: 00197ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 008 ISeqno: 012 Type: IAX     Subclass: ACK    
  Timestamp: 00197ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
   -- Executing [888@My-Context:2] Playback("Local/888@My-Context-eb52;2", "en/vm-theperson") in new stack
   -- <Local/888@My-Context-eb52;2> Playing 'en/vm-theperson.ulaw' (language 'en')
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 012 Type: VOICE   Subclass: 4
  Timestamp: 00200ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 009 Type: IAX     Subclass: ACK    
  Timestamp: 00200ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 009 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10016ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 013 Type: IAX     Subclass: LAGRP  
  Timestamp: 10016ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 010 ISeqno: 013 Type: IAX     Subclass: LAGRQ  
  Timestamp: 09756ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 010 Type: IAX     Subclass: ACK    
  Timestamp: 10016ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 011 Type: IAX     Subclass: LAGRP  
  Timestamp: 09756ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 014 Type: IAX     Subclass: ACK    
  Timestamp: 09756ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 014 ISeqno: 011 Type: IAX     Subclass: LAGRQ  
  Timestamp: 20020ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 011 ISeqno: 015 Type: IAX     Subclass: LAGRP  
  Timestamp: 20020ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 015 Type: IAX     Subclass: LAGRQ  
  Timestamp: 19756ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 015 ISeqno: 012 Type: IAX     Subclass: ACK    
  Timestamp: 20020ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 015 ISeqno: 013 Type: IAX     Subclass: LAGRP  
  Timestamp: 19756ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 016 Type: IAX     Subclass: ACK    
  Timestamp: 19756ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 016 ISeqno: 013 Type: IAX     Subclass: PING  
  Timestamp: 21016ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 013 ISeqno: 017 Type: IAX     Subclass: PONG  
  Timestamp: 21016ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
  RR_JITTER       : 0
  RR_LOSS         : 0
  RR_PKTS         : 1
  RR_DELAY        : 40
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Rx-Frame Retry[ No] -- OSeqno: 017 ISeqno: 014 Type: IAX     Subclass: ACK    
  Timestamp: 21016ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 014 ISeqno: 017 Type: IAX     Subclass: PING  
  Timestamp: 20756ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 017 ISeqno: 015 Type: IAX     Subclass: PONG  
  Timestamp: 20756ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
  RR_JITTER       : 0
  RR_LOSS         : 0
  RR_PKTS         : 1
  RR_DELAY        : 40
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Tx-Frame Retry[-01] -- OSeqno: 015 ISeqno: 018 Type: IAX     Subclass: ACK    
  Timestamp: 20756ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 018 ISeqno: 015 Type: IAX     Subclass: LAGRQ  
  Timestamp: 30024ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 015 ISeqno: 019 Type: IAX     Subclass: LAGRP  
  Timestamp: 30024ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 016 ISeqno: 019 Type: IAX     Subclass: LAGRQ  
  Timestamp: 29756ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 019 ISeqno: 016 Type: IAX     Subclass: ACK    
  Timestamp: 30024ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 019 ISeqno: 017 Type: IAX     Subclass: LAGRP  
  Timestamp: 29756ms  SCall: 07418  DCall: 01131 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 017 ISeqno: 020 Type: IAX     Subclass: ACK    
  Timestamp: 29756ms  SCall: 01131  DCall: 07418 [1.1.1.1:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE  
  Timestamp: 00017ms  SCall: 12008  DCall: 00000 [1.1.1.1:4569]

Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG  
  Timestamp: 00017ms  SCall: 00001  DCall: 12008 [1.1.1.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK    
  Timestamp: 00017ms  SCall: 12008  DCall: 00001 [1.1.1.1:4569]



Comments:By: Mark Seamans (n5yzv) 2010-10-07 15:10:02

Please note, this has been an issue I have had across all the 1.6.2.x versions.  Also, the issue exists setting the IAX connection to trunking, jitter on/off and using the gsm & ulaw codecs.


By: Leif Madsen (lmadsen) 2010-10-12 11:13:41

Any chance you could try looking through changes to chan_iax2.c and testing the various changes beyond 1.6.2.12 to see if you can find which change exactly caused the regression?

If you do that then it should make it nearly trivial to resolve this issue. Thanks!
By: Russell Bryant (russell) 2010-10-12 14:39:40

What timing module do you have loaded here?
By: Mark Seamans (n5yzv) 2010-10-13 09:25:17

Thanks lmadsen & russell for taking this on.

As I had to downgrade this production box, we have setup another to deal with this issue.  I'll get it prepped with a very basic small setup so we can have exclusive access to resolve this.
By: Mark Seamans (n5yzv) 2010-10-13 16:04:21

Ok, system is setup.  Virgin, just an iax connection, trunk on (has no difference), just sending the call into the dialplan playing a stock audio file.  It is a VM, however I have had the issue on at least 7 systems, all 64 bit.  This VM is also 64 bit running on ESXi.

Setup is as such:
PRI--->Asterisk 1.6.1.12---IAX2--(FW)--->Asterisk 1.6.2.13

Note:  most of the deployments do not have the FW installed, which exhibit the same behavior.

lmadsen:  I'll pull up the changes from 1.6.1.13 forward to see if anything comes close, but I have had this issue from early 1.6.2.x releases.

russell:  timing module:
asterisk-test*CLI> module show like timing
Module                         Description                              Use Count
res_timing_timerfd.so          Timerfd Timing Interface                 1

^^So I would take it, it is using the new timer with 1.6.2.  I have had the same issues using DAHDI as the timer module.

When I call the number (which I can provide), the audio file attempts to play, which you would hear maybe 1 second.

Dialplan(extensions.conf):

PRI END:

exten => 5556399,1,Dial(IAX2/test-loonytoons@test-loonytoons/${EXTEN})


REMOTE(extensions.conf)

[general]
static=yes
writeprotect=yes
clearglobalvars=no

[globals]

[bogon-calls]
exten => _X.,1,Congestion

[incoming]
exten => 5556399,1,Answer
exten => 5556399,n,Playback(en/vm-theperson)
exten => 5556399,n,Wait(2)
exten => 5556399,n,Playback(en/vm-theperson)
exten => 5556399,n,Wait(2)
exten => 5556399,n,Playback(en/vm-theperson)
exten => 5556399,n,Hangup


IAX Info - PRI End (iax.conf)

[general]
bindport=4569
bindaddr=0.0.0.0
allow=all
jitterbuffer=no
mailboxdetail=yes
iaxthreadcount=200
iaxmaxthreadcount=256
trunk=no

[test-loonytoons]
type=user
auth=plaintext
context=test
secret=foobar
requirecalltoken=no
qualify=no
trunk=no
transfer=no
allow=all

[test-loonytoons]
type=peer
auth=plaintext
context=incoming
secret=foobar
requirecalltoken=no
qualify=no
host=xxx.xxx.xxx.xxx
trunk=no
transfer=no
allow=all


IAX Info - Remote End (iax.conf)

[general]
bindport=4569
bindaddr=0.0.0.0
allow=all
jitterbuffer=no
mailboxdetail=yes
iaxthreadcount=200
iaxmaxthreadcount=256
trunk=no

[test-loonytoons]
type=peer
host=xxx.xxx.xxx.xxx
secret=foobar
context=loonytoons
qualify=no
auth=plaintext
requirecalltoken=no
trunk=no
canreinvite=no
allow=all

[test-loonytoons]
type=user
secret=foobar
auth=plaintext
context=incoming
qualify=no
trunk=no
canreinvite=no
allow=all


CLI Output:

asterisk-test*CLI>
   -- Accepting AUTHENTICATED call from xxx.xxx.xxx.xxx:
      > requested format = ulaw,
      > requested prefs = (),
      > actual format = ulaw,
      > host prefs = (),
      > priority = mine
   -- Executing [5556399@incoming:1] Answer("IAX2/test-loonytoons-537", "") in new stack
   -- Executing [5556399@incoming:2] Playback("IAX2/test-loonytoons-537", "en/vm-theperson") in new stack
   -- <IAX2/test-loonytoons-537> Playing 'en/vm-theperson.gsm' (language 'en')
asterisk-test*CLI>

^^^ Note, the call stops.  It does not make any progress.  The call is connected and I have left it off hook for over ten minutes with no change (I was hoping for some sort of timeout that would give me a hint).

Below is the iax2 debug of the call: (note, I did a find replace of the ip address and borked and replaced the npa of the phone number involved.)

asterisk-test*CLI> iax2 set debug on
IAX2 Debugging Enabled
asterisk-test*CLI>
asterisk-test*CLI>
asterisk-test*CLI>
asterisk-test*CLI>
asterisk-test*CLI>
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW    
  Timestamp: 00003ms  SCall: 03940  DCall: 00000 [xxx.xxx.xxx.xxx:4569]
  VERSION         : 2
  CALLED NUMBER   : 5556399
  CODEC_PREFS     : ()
  CALLING NUMBER  : 8013
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 0
  CALLING TRANSIT : 0
  CALLING NAME    : Elmer Fudd
  LANGUAGE        : en
  USERNAME        : test-loonytoons
  ENCRYPTION      : 32768
  FORMAT          : 4
  CAPABILITY      : 209690623
  ADSICPE         : 2
  DATE TIME       : 2010-10-13  15:52:58

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW    
  Timestamp: 00006ms  SCall: 03940  DCall: 00000 [xxx.xxx.xxx.xxx:4569]
  VERSION         : 2
  CALLED NUMBER   : 5556399
  CODEC_PREFS     : ()
  CALLING NUMBER  : 8013
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 0
  CALLING TRANSIT : 0
  CALLING NAME    : Elmer Fudd
  LANGUAGE        : en
  USERNAME        : test-loonytoons
  ENCRYPTION      : 32768
  FORMAT          : 4
  CAPABILITY      : 209690623
  ADSICPE         : 2
  DATE TIME       : 2010-10-13  15:52:58
  Unknown IE 054  : Present

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00011ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
  AUTHMETHODS     : 1
  USERNAME        : test-loonytoons

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00015ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
  PASSWORD        : foobar

   -- Accepting AUTHENTICATED call from xxx.xxx.xxx.xxx:
      > requested format = ulaw,
      > requested prefs = (),
      > actual format = ulaw,
      > host prefs = (),
      > priority = mine
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 00019ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
  FORMAT          : 4

   -- Executing [5556399@incoming:1] Answer("IAX2/test-loonytoons-8880", "") in new stack
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 00019ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
  Timestamp: 00022ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?)
  Timestamp: 00025ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00022ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00018ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00018ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 00025ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00021ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 00021ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00024ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 00024ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: VOICE   Subclass: 4
  Timestamp: 00165ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 00165ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
   -- Executing [5556399@incoming:2] Playback("IAX2/test-loonytoons-8880", "en/vm-theperson") in new stack
   -- <IAX2/test-loonytoons-8880> Playing 'en/vm-theperson.gsm' (language 'en')
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 006 Type: VOICE   Subclass: 4
  Timestamp: 00180ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 00180ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10006ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 007 Type: IAX     Subclass: LAGRP  
  Timestamp: 10006ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 007 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10010ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 10006ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 007 Type: IAX     Subclass: LAGRP  
  Timestamp: 10010ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[-01] -- OSeqno: 007 ISeqno: 008 Type: IAX     Subclass: ACK    
  Timestamp: 10010ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 007 Type: IAX     Subclass: LAGRQ  
  Timestamp: 20010ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 009 Type: IAX     Subclass: LAGRP  
  Timestamp: 20010ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 009 Type: IAX     Subclass: LAGRQ  
  Timestamp: 20013ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 008 Type: IAX     Subclass: ACK    
  Timestamp: 20010ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 009 Type: IAX     Subclass: LAGRP  
  Timestamp: 20013ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 010 Type: IAX     Subclass: ACK    
  Timestamp: 20013ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 009 Type: IAX     Subclass: PING  
  Timestamp: 21006ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 011 Type: IAX     Subclass: PONG  
  Timestamp: 21006ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
  RR_JITTER       : 0
  RR_LOSS         : 0
  RR_PKTS         : 1
  RR_DELAY        : 40
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Tx-Frame Retry[000] -- OSeqno: 010 ISeqno: 011 Type: IAX     Subclass: PING  
  Timestamp: 21018ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 010 Type: IAX     Subclass: ACK    
  Timestamp: 21006ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 011 Type: IAX     Subclass: PONG  
  Timestamp: 21018ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
  RR_JITTER       : 0
  RR_LOSS         : 0
  RR_PKTS         : 1
  RR_DELAY        : 40
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 012 Type: IAX     Subclass: ACK    
  Timestamp: 21018ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 011 Type: IAX     Subclass: LAGRQ  
  Timestamp: 30014ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 011 ISeqno: 013 Type: IAX     Subclass: LAGRP  
  Timestamp: 30014ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 013 Type: IAX     Subclass: LAGRQ  
  Timestamp: 30017ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 012 Type: IAX     Subclass: ACK    
  Timestamp: 30014ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 013 Type: IAX     Subclass: LAGRP  
  Timestamp: 30017ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 014 Type: IAX     Subclass: ACK    
  Timestamp: 30017ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 014 ISeqno: 013 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 35448ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 015 Type: IAX     Subclass: ACK    
  Timestamp: 35448ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
Rx-Frame Retry[ No] -- OSeqno: 015 ISeqno: 013 Type: IAX     Subclass: HANGUP
  Timestamp: 35509ms  SCall: 03940  DCall: 08880 [xxx.xxx.xxx.xxx:4569]
  CAUSE CODE      : 16

Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 016 Type: IAX     Subclass: ACK    
  Timestamp: 35509ms  SCall: 08880  DCall: 03940 [xxx.xxx.xxx.xxx:4569]
 == Spawn extension (incoming, 5556399, 2) exited non-zero on 'IAX2/test-loonytoons-8880'
   -- Hungup 'IAX2/test-loonytoons-8880'
asterisk-test*CLI>
By: mdeneen (mdeneen) 2010-10-27 13:10:23

I have noticed this as well with 1.6.2.13.  In my situation, it happens during a Background() call with a WaitExten() at the end of the audio.  Even though the audio stops (and waits seemingly forever) I can press a button to send DTMF, and WaitExten() accepts the DTMF as if nothing unusual had happened.

I've experienced this both inside and outside of a VM.  I have an asterisk playground where I can monkey around as much as I want, so please let me know if there is anything I can do to debug this.

Here is my iax2 debug output:


   -- Accepting AUTHENTICATED call from 10.33.0.1:
      > requested format = g729,
      > requested prefs = (g729),
      > actual format = g729,
      > host prefs = (g729),
      > priority = mine
   -- Executing [2100@from-trusted-remote:1] Goto("IAX2/pbx-asterisk-dev-1089", "bus-intro,s,1") in new stack
   -- Goto (bus-intro,s,1)
   -- Executing [s@bus-intro:1] Answer("IAX2/pbx-asterisk-dev-1089", "") in new stack
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 00013ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
  FORMAT          : 256

Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
  Timestamp: 00016ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?)
  Timestamp: 00019ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 00013ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00016ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 00019ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00024ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 00024ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00027ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 00027ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00030ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 00030ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00033ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 00033ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00036ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 007 Type: IAX     Subclass: ACK    
  Timestamp: 00036ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00039ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 008 Type: IAX     Subclass: ACK    
  Timestamp: 00039ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 004 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 00042ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 009 Type: IAX     Subclass: ACK    
  Timestamp: 00042ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 004 Type: VOICE   Subclass: 136
  Timestamp: 00140ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 010 Type: IAX     Subclass: ACK    
  Timestamp: 00140ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
   -- Executing [s@bus-intro:2] AGI("IAX2/pbx-asterisk-dev-1089", "log_call_start.agi") in new stack
   -- Launched AGI Script /var/lib/asterisk/agi-bin/log_call_start.agi
   -- <IAX2/pbx-asterisk-dev-1089>AGI Script log_call_start.agi completed, returning 0
   -- Executing [s@bus-intro:3] Wait("IAX2/pbx-asterisk-dev-1089", "1") in new stack
   -- Executing [s@bus-intro:4] Set("IAX2/pbx-asterisk-dev-1089", "TIMEOUT(digit)=2") in new stack
   -- Digit timeout set to 2.000
   -- Executing [s@bus-intro:5] NoOp("IAX2/pbx-asterisk-dev-1089", "") in new stack
   -- Executing [s@bus-intro:6] Set("IAX2/pbx-asterisk-dev-1089", "invalidCt=0") in new stack
   -- Executing [s@bus-intro:7] AGI("IAX2/pbx-asterisk-dev-1089", "log_call_node_access.agi,"Intro"") in new stack
   -- Launched AGI Script /var/lib/asterisk/agi-bin/log_call_node_access.agi
   -- <IAX2/pbx-asterisk-dev-1089>AGI Script log_call_node_access.agi completed, returning 0
   -- Executing [s@bus-intro:8] NoOp("IAX2/pbx-asterisk-dev-1089", "") in new stack
   -- Executing [s@bus-intro:9] BackGround("IAX2/pbx-asterisk-dev-1089", "sounds/Intro") in new stack
   -- <IAX2/pbx-asterisk-dev-1089> Playing 'sounds/Intro.g729' (language 'en')
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 010 Type: VOICE   Subclass: 136
  Timestamp: 01280ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 01280ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 005 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10023ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 011 Type: IAX     Subclass: LAGRP  
  Timestamp: 10023ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 10023ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 011 Type: IAX     Subclass: LAGRQ  
  Timestamp: 10019ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 007 Type: IAX     Subclass: LAGRP  
  Timestamp: 10019ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 007 ISeqno: 012 Type: IAX     Subclass: ACK    
  Timestamp: 10019ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 007 Type: IAX     Subclass: LAGRQ  
  Timestamp: 20015ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 013 Type: IAX     Subclass: LAGRP  
  Timestamp: 20015ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 008 Type: IAX     Subclass: ACK    
  Timestamp: 20015ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 013 Type: IAX     Subclass: LAGRQ  
  Timestamp: 20018ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 009 Type: IAX     Subclass: LAGRP  
  Timestamp: 20018ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 014 Type: IAX     Subclass: ACK    
  Timestamp: 20018ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 014 ISeqno: 009 Type: IAX     Subclass: PING  
  Timestamp: 21014ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 015 Type: IAX     Subclass: PONG  
  Timestamp: 21014ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
  RR_JITTER       : 0
  RR_LOSS         : 0
  RR_PKTS         : 1
  RR_DELAY        : 40
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Rx-Frame Retry[ No] -- OSeqno: 015 ISeqno: 010 Type: IAX     Subclass: ACK    
  Timestamp: 21014ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 010 ISeqno: 015 Type: IAX     Subclass: PING  
  Timestamp: 21018ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 015 ISeqno: 011 Type: IAX     Subclass: PONG  
  Timestamp: 21018ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
  RR_JITTER       : 0
  RR_LOSS         : 0
  RR_PKTS         : 1
  RR_DELAY        : 40
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 016 Type: IAX     Subclass: ACK    
  Timestamp: 21018ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 016 ISeqno: 011 Type: IAX     Subclass: LAGRQ  
  Timestamp: 30015ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 011 ISeqno: 017 Type: IAX     Subclass: LAGRP  
  Timestamp: 30015ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 017 ISeqno: 012 Type: IAX     Subclass: ACK    
  Timestamp: 30015ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 017 Type: IAX     Subclass: LAGRQ  
  Timestamp: 30018ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 017 ISeqno: 013 Type: IAX     Subclass: LAGRP  
  Timestamp: 30018ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 018 Type: IAX     Subclass: ACK    
  Timestamp: 30018ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 018 ISeqno: 013 Type: CONTROL Subclass: SRCUPDT
  Timestamp: 32863ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 019 Type: IAX     Subclass: ACK    
  Timestamp: 32863ms  SCall: 01089  DCall: 17363 [10.33.0.1:4569]
Rx-Frame Retry[ No] -- OSeqno: 019 ISeqno: 013 Type: IAX     Subclass: HANGUP
  Timestamp: 32978ms  SCall: 17363  DCall: 01089 [10.33.0.1:4569]
  CAUSE CODE      : 16
By: mdeneen (mdeneen) 2010-10-27 13:26:52

iax2 show channels gives me this information:

IAX2/pbx-asterisk-de  10.33.0.1        pbx-asteri  00986/17004  00019/00024  00040ms  -0001ms  0000ms  g729    Rx:NEW      Tx:ACK
By: mdeneen (mdeneen) 2010-10-27 13:41:47

I also ran a wireshark trace on the interface.  While I do not know the guts of IAX2, nothing jumped out at me while looking through the trace.
By: Mark Seamans (n5yzv) 2010-11-10 12:15:48.000-0600

If something is waiting on me, please bump me.
By: Mark Seamans (n5yzv) 2010-11-12 11:36:21.000-0600

I will test this on asterisk 1.8 soon, fyi.
By: Mark Seamans (n5yzv) 2010-11-18 10:28:31.000-0600

I have tested this on 1.8.0 x86_64 and it has the issue too.  So if IAX is involved, in any manner, it happens.  DAHDI/SIP, no issues.
By: Tim King (timking) 2011-02-21 07:46:18.000-0600

This is happening to me as well in 1.6.2.1x, but it's more apparent when saving voicemail. If you have an incoming IAX (trunk) and jitter buffer enabled go directly to Voicemail then the message saved is garbled, and it sounds like it's been played back too fast (eg recorded too slowly). I have tried changing timing sources and it makes no difference. You can get back perfect recordings when your turn the jitterbuffer off. I didn't think jb was even in the loop in 1.6.2?
By: Jonas (jonascph) 2011-03-07 04:40:14.000-0600

I think we're seeing the same issue on 1.6.2.9 (Debian squeeze) we notice it when we use Background to play files in an IVR menu:

[sw-Menu]  
2 exten => 100,1,Answer  
3 exten => 100,2,Set(TIMEOUT(digit)=1)  
4 exten => 100,3,Set(TIMEOUT(response)=10)  
5 exten => 100,4,Background(sw/sw_dk_velkomst)  
6 ; IVR Menu - Tryk 1 for dk-kundeservice, 2 for se-kundeservice, 3 bogholderi, 4 for omstilling  
7 exten => 100,5,Background(silence/4)  
8 exten => 100,6,Goto(sw-Menu,100,4)  
9 exten => 100,7,Hangup()  

It often stops after Background(silence/4), and just does nothing. You can however still hit an extension and you will be sent to that extension, but the loop of repeating the menu stops.

Have nobody made any progress on this?
By: Mark Seamans (n5yzv) 2011-03-07 08:20:40.000-0600

Note:  Jitter buffer settings/on/off had no affect on my issue.  I wish it would have been that simple.  I am pretty sure it was the integration of the new timing "setup" introduced in 1.6.1.13 (as or last functional version was 1.6.1.12).

Ok, after being patient, we suspected that there was a patch in the works.  I have loaded and tested 1.8.2.4 on a x86_64 on Gentoo 2.6.34-hardened-r1.  All is fine.  The initial issue is gone.  I will be doing quite a bit of testing in the next week, so if the power that be can leave this open for a few more weeks that would be nice.  Looking good, thanks!  Oh, to those that are "not happy" to go to 1.8.x, it has been very stable for me in a production environment.  We have only delayed upgrading to it due to this issue.  I guess we have no more excuses.
By: Jonas (jonascph) 2011-03-07 08:22:54.000-0600

n5yzv: We just came from 1.8.3 and had to downgrade because of crashes related to the IAX channel, i hope you wont suffer from them.

Just to clear up, did you ever test for this bug, 001805, on a non 64bit machine?
By: Mark Seamans (n5yzv) 2011-03-07 08:30:46.000-0600

Good to know about 1.8.3, I'll test for sure.  On this issue on 32 bit, not yet.  I will be soon.
By: Tzafrir Cohen (tzafrir) 2011-03-07 10:50:28.000-0600

Stupid question: does the same happen when the pthread timing module is used?
By: Jonas (jonascph) 2011-03-07 11:07:18.000-0600

For me swithing from res_timing_timerfd.so to res_timing_pthread.so makes the problem disapear, so thats indeed a working fix for us.

This is on 1.6.2.9 (Debian squeeze) and a 64bit virtual machine running under xenserver 5.6fp1

Hope this helps somebody either fix it or atleast get around the bug on their installation.
By: Grant Emsley (grantemsley) 2011-05-18 13:34:21

Same problem for me on Ubuntu xen virtual machine with Asterisk 1.6.2.11 (compiled from source)

Adding "noload => res_timing_timerfd.so" to modules.conf corrected it.  Asterisk is now using DAHDI for timing and playback works properly, even on longer messages.

Thank you jonascph!  I've been bashing my head against my desk for 3 days trying to figure this one out!
By: Leif Madsen (lmadsen) 2011-06-04 10:25:21

The usage of res_timing_timerfd should be fixed upon the closure and commit of code in ASTERISK-16711
By: Russell Bryant (russell) 2011-07-27 13:55:14.697-0500

I'm pretty sure this got fixed in later versions of Asterisk.  If this happens in the latest versions of 1.8, feel free to open a new issue.  Thanks
By: Jonas (jonascph) 2011-08-10 09:56:47.211-0500

I'm not the familiar with the jira/issues system.

But is it correct that the patch/change that you say fix this, will not be backported/fixed in 1.6.2 ?