[Home]

Summary:ASTERISK-04426: iax2 indications not being followed
Reporter:Joe Antkowiak (antkojm1)Labels:
Date Opened:2005-06-17 02:44:32Date Closed:2011-06-07 14:02:58
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) iax_debugs_2.txt
Description:I know people have brought this up before but I believe I have found something new, and that it is simple to fix, so please hear me out

Here is our setup:

<pri circuits><* boxes (tandem switches)><customer * box><sip phones>

Now, when a call comes in to one of the pri's or from another customer box, and is directed to a customer * box, the customer * box does an answer, and then does a dial with an r specified in the dial command.  This works fine, the tandem switch, as it should with using iax, generates inband ringing to play on the pri channel, since the pri channel cannot be put back into a ringing state after an answer.

The problem is, when a customer * box, instead of performing an immediate dial after an answer, instead goes to an ivr, when an extension is dialed, and the dial command is then run, again with an r in the command, the tandem switch does *not* play inband ringing at that point to the pri channel, just dead silence.

the only thing I can see so far is that on the calls without ivr there are two requests for indication 3, but on the calls with ivr there is only one.

all of the "tandem" switches are running cvs head from today (wanted to make sure it wasn't fixed yet before I posted the bug), and the customer pbx's are running cvs head from yesterday and stable from yesterday. (several different customers with the same issue)  

unfortunately I cannot work on this during business hours, so if anyone needs to log in and look around, it will have to be at night.

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

Here is what it looks like when an ivr is used:

   -- Executing Dial("Zap/4-1", "IAX2/4435246540@jsci/14104671300") in new stack
   -- Called 4435246540@jsci/14104671300
   -- Call accepted by 72.1.157.37 (format g726)
   -- Format for call is g726
   -- IAX2/jsci-22 answered Zap/4-1
Jun 16 23:16:51 DEBUG[16716]: chan_zap.c:2426 zt_answer: Took Zap/4-1 off hook
Jun 16 23:16:51 DEBUG[28769]: chan_iax2.c:6478 socket_read: Ooh, voice format changed to 16
Jun 16 23:16:56 DEBUG[16716]: chan_zap.c:4267 zt_read: DTMF digit: 6 on Zap/4-1
Jun 16 23:16:56 DEBUG[16716]: chan_zap.c:4267 zt_read: DTMF digit: 1 on Zap/4-1
Jun 16 23:16:58 DEBUG[16716]: chan_zap.c:4267 zt_read: DTMF digit: 0 on Zap/4-1
Jun 16 23:16:58 DEBUG[16716]: chan_zap.c:4267 zt_read: DTMF digit: 2 on Zap/4-1
Jun 16 23:16:59 DEBUG[16716]: channel.c:2852 ast_generic_bridge: Got a FRAME_CONTROL (3) frame on channel IAX2/jsci-22
Jun 16 23:16:59 DEBUG[16716]: channel.c:3094 ast_channel_bridge: Bridge stops bridging channels Zap/4-1 and IAX2/jsci-22
Jun 16 23:16:59 DEBUG[16716]: chan_zap.c:4452 zt_indicate: Requested indication 3 on channel Zap/4-1   < ringing should begin to be heard on Zap/4-1 but is not
Jun 16 23:17:14 DEBUG[16716]: channel.c:2852 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel IAX2/jsci-22
Jun 16 23:17:14 DEBUG[16716]: channel.c:3094 ast_channel_bridge: Bridge stops bridging channels Zap/4-1 and IAX2/jsci-22
Jun 16 23:17:14 DEBUG[16716]: chan_zap.c:4452 zt_indicate: Requested indication -1 on channel Zap/4-1
Jun 16 23:17:17 DEBUG[16716]: chan_zap.c:3989 __zt_exception: Exception on 17, channel 4
Jun 16 23:17:17 DEBUG[16716]: chan_zap.c:3239 zt_handle_event: Got event On hook(1) on channel 4 (index 0)
Jun 16 23:17:17 DEBUG[16716]: chan_zap.c:1361 zt_disable_ec: disabled echo cancellation on channel 4
Jun 16 23:17:17 DEBUG[16716]: channel.c:2841 ast_generic_bridge: Didn't get a frame from channel: Zap/4-1
Jun 16 23:17:17 DEBUG[16716]: channel.c:3094 ast_channel_bridge: Bridge stops bridging channels Zap/4-1 and IAX2/jsci-22
Jun 16 23:17:17 DEBUG[16716]: chan_iax2.c:2971 iax2_hangup: We're hanging up IAX2/jsci-22 now...
   -- Hungup 'IAX2/jsci-22'
Jun 16 23:17:17 DEBUG[16716]: app_dial.c:1350 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
 == Spawn extension (joe-cordless, 14104671300, 1) exited non-zero on 'Zap/4-1'
Jun 16 23:17:17 DEBUG[16716]: chan_zap.c:2109 zt_hangup: Hangup: channel: 4 index = 0, normal = 17, callwait = -1, thirdcall = -1
Jun 16 23:17:17 DEBUG[16716]: chan_zap.c:1361 zt_disable_ec: disabled echo cancellation on channel 4
Jun 16 23:17:17 DEBUG[16716]: chan_zap.c:2518 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/4-1
Jun 16 23:17:17 DEBUG[16716]: chan_zap.c:1298 update_conf: Updated conferencing on 4, with 0 conference users
   -- Hungup 'Zap/4-1'


Here's what it looks like without an the ivr being used:

   -- Executing Dial("Zap/4-1", "IAX2/4435246540@jsci/14108894667") in new stack
   -- Called 4435246540@jsci/14108894667
   -- Call accepted by 72.1.157.37 (format g726)
   -- Format for call is g726
   -- IAX2/jsci-22 answered Zap/4-1
Jun 16 23:27:36 DEBUG[16804]: chan_zap.c:2426 zt_answer: Took Zap/4-1 off hook
Jun 16 23:27:36 DEBUG[16804]: channel.c:2852 ast_generic_bridge: Got a FRAME_CONTROL (3) frame on channel IAX2/jsci-22
Jun 16 23:27:36 DEBUG[16804]: channel.c:3094 ast_channel_bridge: Bridge stops bridging channels Zap/4-1 and IAX2/jsci-22
Jun 16 23:27:36 DEBUG[16804]: chan_zap.c:4452 zt_indicate: Requested indication 3 on channel Zap/4-1
Jun 16 23:27:36 DEBUG[16804]: channel.c:2852 ast_generic_bridge: Got a FRAME_CONTROL (3) frame on channel IAX2/jsci-22
Jun 16 23:27:36 DEBUG[16804]: channel.c:3094 ast_channel_bridge: Bridge stops bridging channels Zap/4-1 and IAX2/jsci-22
Jun 16 23:27:36 DEBUG[16804]: chan_zap.c:4452 zt_indicate: Requested indication 3 on channel Zap/4-1   < inband ringing actually plays at this point, coming from the last iax2 device in the call path, as it should be
Jun 16 23:27:53 DEBUG[28769]: chan_iax2.c:6478 socket_read: Ooh, voice format changed to 16
Jun 16 23:27:53 DEBUG[16804]: channel.c:2852 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel IAX2/jsci-22
Jun 16 23:27:53 DEBUG[16804]: channel.c:3094 ast_channel_bridge: Bridge stops bridging channels Zap/4-1 and IAX2/jsci-22
Jun 16 23:27:53 DEBUG[16804]: chan_zap.c:4452 zt_indicate: Requested indication -1 on channel Zap/4-1
Jun 16 23:27:56 DEBUG[16804]: chan_zap.c:3989 __zt_exception: Exception on 17, channel 4
Jun 16 23:27:56 DEBUG[16804]: chan_zap.c:3239 zt_handle_event: Got event On hook(1) on channel 4 (index 0)
Jun 16 23:27:56 DEBUG[16804]: chan_zap.c:1361 zt_disable_ec: disabled echo cancellation on channel 4
Jun 16 23:27:56 DEBUG[16804]: channel.c:2841 ast_generic_bridge: Didn't get a frame from channel: Zap/4-1
Jun 16 23:27:56 DEBUG[16804]: channel.c:3094 ast_channel_bridge: Bridge stops bridging channels Zap/4-1 and IAX2/jsci-22
Jun 16 23:27:56 DEBUG[16804]: chan_iax2.c:2971 iax2_hangup: We're hanging up IAX2/jsci-22 now...
   -- Hungup 'IAX2/jsci-22'
Jun 16 23:27:56 DEBUG[16804]: app_dial.c:1350 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
 == Spawn extension (joe-cordless, 14108894667, 1) exited non-zero on 'Zap/4-1'
Jun 16 23:27:56 DEBUG[16804]: chan_zap.c:2109 zt_hangup: Hangup: channel: 4 index = 0, normal = 17, callwait = -1, thirdcall = -1
Jun 16 23:27:56 DEBUG[16804]: chan_zap.c:1361 zt_disable_ec: disabled echo cancellation on channel 4
Jun 16 23:27:56 DEBUG[16804]: chan_zap.c:2518 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/4-1
Jun 16 23:27:56 DEBUG[16804]: chan_zap.c:1298 update_conf: Updated conferencing on 4, with 0 conference users
   -- Hungup 'Zap/4-1'
Comments:By: Joe Antkowiak (antkojm1) 2005-06-17 02:55:12

Please, before dropping this to a minor, understand why I reported it as major:

bug guidelines:

MAJOR: A bug which completely prevents Asterisk from operating in a method that it normally is expected to operate -- and particularly if it cannot be reasonably worked around -- is MAJOR.

This bug prevents asterisk from behaving in a manner in which it is expected.  it is expected that an asterisk tandem switch will generate inband ringing to non-iax channels when it is requested, and it is not.  dead silence as opposed to ringing tones seems like a big, but easy to fix, issue to me.
By: Joe Antkowiak (antkojm1) 2005-06-17 03:01:13

also, here are the dialplans for the customer box I am using as an example:

no ivr:

exten => 502,1,Answer
exten => 502,2,DigitTimeout,3
exten => 502,3,ResponseTimeout,15
exten => 502,4,Set(dialed=502)
exten => 502,5,noop
exten => 502,6,Queue(appraisal|r|||12)
exten => 502,7,Voicemail(u502)
exten => 502,8,Hangup

with ivr

exten => 504,1,Answer
exten => 504,2,DigitTimeout,3
exten => 504,3,ResponseTimeout,10
exten => 504,4,Set(CALLERID(name)=for Progressive)
exten => 504,5,Background(progressive3)
exten => 504,6,Wait,3
exten => 504,7,Background(progressive4)
exten => 504,8,Wait,3
exten => 504,9,Queue(progressive|r|||12)
exten => 504,10,Voicemail(u504)
exten => 504,11,Hangup

and this is the extension dialed in my example:

exten => 6102,1,Dial(SIP/61024|15|r)
exten => 6102,2,Voicemail(u6102)
exten => 6102,3,Hangup
By: Kevin P. Fleming (kpfleming) 2005-06-20 16:42:56

OK, this is an odd one :-)

First, can you change the customer's dialplan to always use Queue() or always use Dial(), so that we can eliminate any potential differences in the applications as the cause (even temporarily this would be helpful)?

Second, chan_iax2 calls ast_set_read_format() when it generates the "voice format changed" message, which generates a LOG_DEBUG message about having changed the channel's read format... but I don't see that message in your log. Please add 'set debug 4' to your session on the PRI server and generate another log.
By: Joe Antkowiak (antkojm1) 2005-06-20 21:16:37

Actually in this case I am using another box with a zaptel tdm card in it, but the result is the same whenever calls traverse iax and use zap or sip at the ends.

the result is also the same regardless of the use of queue or dial

attached more debug
By: Joe Antkowiak (antkojm1) 2005-06-20 21:39:13

this seems like it could be the cause of the complaints from bug 3765
By: Joe Antkowiak (antkojm1) 2005-06-20 21:41:00

another note...  even though you see format change messages, the call is always g726 and never changes
By: Joe Antkowiak (antkojm1) 2005-07-08 17:17:28

Anyone have any ideas about this?  ...
By: Joe Antkowiak (antkojm1) 2005-07-15 02:13:18

Can anyone/is anyone going to look at this?  I'll paypal $100 to whoever fixes it...
By: dbruce (dbruce) 2005-07-15 10:49:08

Similar situation was just handled in bug ASTERISK-4576...

It probably isn't the same problem, but you only posted a debug for the tandem system not for the terminal system so I can't be sure...

Make sure the terminating system has a valid indications.conf so that it can generate inband ring...


By: Paul Belanger (pabelanger) 2005-07-15 13:56:59

dbruce is right.  Check out your customers asterisk box and see if res_indications.so is loaded and configured properly.  Also, and chance of getting a debug of the customer box?
By: Joe Antkowiak (antkojm1) 2005-07-16 19:36:57

it is happening on multiple boxes, but just to be safe I grabbed the indications.conf from the asterisk sample configs and used that, with the same result.

What kind of debug do you want on the customer boxes?  I can get that pretty quickly.
By: Michael Jerris (mikej) 2005-07-28 16:27:38

and you verified that re_indications.so was not noloaded  in modules.conf?
By: Joe Antkowiak (antkojm1) 2005-08-08 00:42:02

Yes.  Strangely enough, this has been fixed in the 8/3/05 cvs head.  Anyone know what fixed it?
By: Mark Spencer (markster) 2005-08-08 02:28:28

Yes, it was almost certainly the work that was done on overlap dial on zap.