[asterisk-bugs] [Asterisk 0018105]: Playback of audio file (gsm, ulaw) audio and dialplan stops when caller is inbound over iax2

Asterisk Bug Tracker noreply at bugs.digium.com
Wed Oct 13 16:04:22 CDT 2010


A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=18105 
====================================================================== 
Reported By:                n5yzv
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   18105
Category:                   Channels/chan_iax2
Reproducibility:            always
Severity:                   major
Priority:                   normal
Status:                     acknowledged
Asterisk Version:           1.6.2.13 
JIRA:                       SWP-2349 
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2010-10-07 11:34 CDT
Last Modified:              2010-10-13 16:04 CDT
====================================================================== 
Summary:                    Playback of audio file (gsm,ulaw) audio and dialplan
stops when caller is inbound over iax2
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.
======================================================================
Relationships       ID      Summary
----------------------------------------------------------------------
related to          0018110 Playback stalls when playing demo-congr...
====================================================================== 

---------------------------------------------------------------------- 
 (0127986) n5yzv (reporter) - 2010-10-13 16:04
 https://issues.asterisk.org/view.php?id=18105#c127986 
---------------------------------------------------------------------- 
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 at 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 at incoming:1] Answer("IAX2/test-loonytoons-537",
"") in new stack
    -- Executing [5556399 at 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 at 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 at 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> 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2010-10-13 16:04 n5yzv          Note Added: 0127986                          
======================================================================




More information about the asterisk-bugs mailing list