[Home]

Summary:ASTERISK-14737: The order of the execution inside the Dial app is wrong
Reporter:Private Name (falves11)Labels:
Date Opened:2009-08-30 22:44:15Date Closed:2009-08-31 12:31:58
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_dial
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:As you can see in my dialplan, I have D(w${EXTEN}) and M(voicedetection)
No matter in what order I include these parameters, the macro executes first. It makes sense that the D() part executes first,because I need to use a macro to do human voice detection, but I am dialing with D() in a second stage, so unless I dial first I cannot do voice detection. I tried doing SendDTMF inside the macro, but the digits are heard in the calling side, when I need them to got to the called side.
In general, the order of execution of D() and M() should be given by the order in which we write them in the dial string. This bug may affect all versions.

dialplan show inbound                                                                                                                                                              
[ Context 'inbound' created by 'pbx_config' ]
 '_X.' =>          1. Set(CALLERPRES()=allowed)                  [pbx_config]                                                                                                                
                   2. Set(GROUP()=trunkgroup1)                   [pbx_config]
                   3. Verbose(0,ACTIVE CALLS ${GROUP_COUNT(trunkgroup1)} ${EXTEN}-ANI->${CALLERID(num)} IP:->${CHANNEL(recvip)}) [pbx_config]
                   4. Set(CALLERID(all)=${CALLERID(num)})        [pbx_config]
                   5. Dial(Sip/XXXX@XX.XX.XX.XX,25,L(1800000)D(w011${EXTEN}#)M(voicedetection))

[ Context 'macro-voicedetection' created by 'pbx_config' ]
 's' =>            1. NoCDR()                                    [pbx_config]
                   2. Set(MACHINE=0)                             [pbx_config]
                   3. verbose(0,Begin Answer)                    [pbx_config]
                   4. WaitForSilence(500,20)                     [pbx_config]
                   5. Verbose(0,WAITSTATUS 1 ${WAITSTATUS})      [pbx_config]
                   6. GotoIf($[${WAITSTATUS}=SILENCE]?SILENCE:TIMEOUT) [pbx_config]
    [TIMEOUT]      7. Verbose(0,DETECTED TIMEOUT)                [pbx_config]
    [SILENCE]      8. Verbose(0,DETECTED NOISE)                  [pbx_config]



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

[Aug 30 23:31:03] DEBUG[8170]: pbx.c:3182 pbx_extension_helper: Launching 'Set'
[Aug 30 23:31:03] DEBUG[8170]: pbx.c:3182 pbx_extension_helper: Launching 'Dial'
[Aug 30 23:31:03] DEBUG[8170]: chan_sip.c:21426 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)                                                                      
[Aug 30 23:31:03] DEBUG[8170]: chan_sip.c:6472 sip_alloc: Allocating new SIP dialog for 1601693e174d8d480e18f2af2ab5cfcb@sphone.vopr.vonage.net - INVITE (With RTP)                            
[Aug 30 23:31:03] DEBUG[8170]: chan_sip.c:4294 do_setnat: Setting NAT on RTP to On
[Aug 30 23:31:03] DEBUG[8170]: dsp.c:468 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21                                                                    
[Aug 30 23:31:03] DEBUG[8170]: dsp.c:468 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Aug 30 23:31:03] DEBUG[8170]: channel.c:4236 ast_channel_inherit_variables: Not copying variable DIALEDTIME.                                                                                  
[Aug 30 23:31:03] DEBUG[8170]: channel.c:4236 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Aug 30 23:31:03] DEBUG[8170]: channel.c:4236 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Aug 30 23:31:03] DEBUG[8170]: channel.c:4236 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Aug 30 23:31:03] DEBUG[8170]: channel.c:4236 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Aug 30 23:31:03] DEBUG[8170]: channel.c:4236 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Aug 30 23:31:03] DEBUG[8170]: channel.c:4236 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.                                                                                  
[Aug 30 23:31:03] DEBUG[8170]: channel.c:4236 ast_channel_inherit_variables: Not copying variable SIPURI.
[Aug 30 23:31:03] DEBUG[8170]: chan_sip.c:4690 sip_call: Outgoing Call for XXXXXXXXXXXXXX
[Aug 30 23:31:03] DEBUG[8170]: chan_sip.c:8902 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False                                                                      
[Aug 30 23:31:03] DEBUG[8170]: chan_sip.c:8903 add_sdp: ** Our prefcodec: 0x4 (ulaw)
[Aug 30 23:31:03] DEBUG[8170]: chan_sip.c:2624 initialize_initreq: Initializing initreq for method INVITE - callid 4d7c38896259ff10642146226bd2d68a@sphone.vopr.vonage.net                    
[Aug 30 23:31:03] DEBUG[8170]: chan_sip.c:2887 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for xx.xx.xx.xx:5060                                                        
[Aug 30 23:31:03] DEBUG[52663]: chan_sip.c:3473 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4d7c38896259ff10642146226bd2d68a@sphone.vopr.vonage.net' Request 102: Found
[Aug 30 23:31:06] DEBUG[52663]: chan_sip.c:3473 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4d7c38896259ff10642146226bd2d68a@sphone.vopr.vonage.net' Request 102: Found
[Aug 30 23:31:06] DEBUG[8170]: chan_sip.c:9233 transmit_response_with_sdp: Setting framing from config on incoming call                                                                        
[Aug 30 23:31:06] DEBUG[8170]: chan_sip.c:8902 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Aug 30 23:31:06] DEBUG[8170]: chan_sip.c:8903 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Aug 30 23:31:06] DEBUG[8170]: chan_sip.c:2887 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for xx.xx.xx.xx:46192                                                        
[Aug 30 23:31:06] DEBUG[8170]: rtp.c:3791 ast_rtp_write: Ooh, format changed from unknown to ulaw                                                                                              
[Aug 30 23:31:06] DEBUG[8170]: rtp.c:3807 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Aug 30 23:31:06] DEBUG[8170]: rtp.c:1229 ast_rtcp_read: RTCP NAT: Got RTCP from other end. Now sending to address xx.xx.xx.xx:55781                                                        
[Aug 30 23:31:06] DEBUG[8170]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 132 bytes
[Aug 30 23:31:06] DEBUG[8170]: rtp.c:1675 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address xx.xx.xx.xx:55780                                                          
[Aug 30 23:31:06] DEBUG[8170]: rtp.c:3791 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Aug 30 23:31:06] DEBUG[8170]: rtp.c:3807 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Aug 30 23:31:06] DEBUG[52663]: chan_sip.c:3395 __sip_ack: Acked pending invite 102                                                                                                            
[Aug 30 23:31:06] DEBUG[52663]: chan_sip.c:3432 __sip_ack: Stopping retransmission on '4d7c38896259ff10642146226bd2d68a@sphone.vopr.vonage.net' of Request 102: Match Found
[Aug 30 23:31:06] DEBUG[52663]: chan_sip.c:2887 __sip_xmit: Trying to put 'ACK sip:156' onto UDP socket destined for 208.51.238.80:5060                                                        
[Aug 30 23:31:06] DEBUG[8170]: pbx.c:3182 pbx_extension_helper: Launching 'NoCDR'                                                                                                              
[Aug 30 23:31:06] DEBUG[8170]: app_macro.c:361 _macro_exec: Executed application: NoCDR
[Aug 30 23:31:06] DEBUG[8170]: pbx.c:3182 pbx_extension_helper: Launching 'Set'
[Aug 30 23:31:06] DEBUG[8170]: app_macro.c:361 _macro_exec: Executed application: Set
[Aug 30 23:31:06] DEBUG[8170]: pbx.c:3182 pbx_extension_helper: Launching 'Verbose'                                                                                                            
Begin Answer
[Aug 30 23:31:06] DEBUG[8170]: app_macro.c:361 _macro_exec: Executed application: verbose
[Aug 30 23:31:06] DEBUG[8170]: pbx.c:3182 pbx_extension_helper: Launching 'WaitForSilence'
[Aug 30 23:31:06] DEBUG[8170]: channel.c:3633 set_format: Set channel SIP/208.51.238.80-b00c9788 to read format slin
[Aug 30 23:31:06] DEBUG[8170]: dsp.c:468 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21                                                                    
[Aug 30 23:31:06] DEBUG[8170]: dsp.c:468 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Aug 30 23:31:09] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes                                                                                                          
[Aug 30 23:31:12] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes                                                                                                          
[Aug 30 23:31:15] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes                                                                                                          
[Aug 30 23:31:18] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes                                                                                                          
[Aug 30 23:31:21] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes                                                                                                          
[Aug 30 23:31:24] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes                                                                                                          
[Aug 30 23:31:27] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes                                                                                                          
[Aug 30 23:31:30] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 176 bytes                                                                                                          
[Aug 30 23:31:32] DEBUG[8171]: rtp.c:1233 ast_rtcp_read: Got RTCP report of 160 bytes                                                                                                          
[Aug 30 23:31:32] DEBUG[52663]: chan_sip.c:2887 __sip_xmit: Trying to put 'SIP/2.0 487' onto UDP socket destined for xxx.xx.xx.xx:46192                                                      
[Aug 30 23:31:32] DEBUG[52663]: chan_sip.c:2887 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:46192                                                      
[Aug 30 23:31:32] DEBUG[52663]: chan_sip.c:3432 __sip_ack: Stopping retransmission on 'NTE5OWQ0Y2Y1NjdlZTgzODRiM2I1Y2NjNjA0YzhlNjA.' of Response 1: Match Found                                
nazon*CLI>                                                  
Comments:By: Leif Madsen (lmadsen) 2009-08-31 08:43:59

I don't necessarily agree this is a bug, but rather a feature request. The reason for that is that M() is executed prior to bridging, and I would image D() is executed after bridging (since that would be sending DTMF to the called party).

The M() specifically says it executes prior to bridging the calls. The order of flags in Dial() has never mattered.
By: Leif Madsen (lmadsen) 2009-08-31 08:44:30

Assigned to Tilghman for review, response, and set to appropriate resolution.
By: Private Name (falves11) 2009-08-31 08:51:20

I want to point out that we need a way to do Human Answer Supervision in Asterisk, as the old Dialogic-based products did.
I mean when I receive an inbound call and dial an outbound call, I need to understand what is picking up the call on the far end, and bridge the two channels together if it is acceptable. There is another flag in the Dial function, G(), but it is absurd that there is no way to bridge the channels after doing some processing. Maybe the solution to this puzzle would be to write a function to bridge the two channels in the dial plan. Then we could do some processing prior to the callers start talking.

By the way, I am paying customer (B.E) with a valid Digium Support contract.


By: Tilghman Lesher (tilghman) 2009-08-31 12:14:22

This is not the forum for paying customers.  You'll need to call in to support and file a ticket there.
By: Private Name (falves11) 2009-08-31 12:20:46

I am a paying customer but I only use the open source version. Please keep my bug open.
By: Jason Parker (jparker) 2009-08-31 12:31:57

Your status as a customer has no relevance here.  Do not reopen this issue.

You know the proper methods.  Please follow them.