Anyone knows why it took 3 hours to process the AMD

Anyone know why it took 3 hours to process the AMD?

Verbose log:

[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] pbx.c: Executing [817194159096@default:1] AGI("Local/817194159096@default-00005ac4;2", "agi://127.0.0.1:4577/call_log") in new stack
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=OUTSOURC))
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] res_agi.c: <Local/817194159096@default-00005ac4;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] pbx.c: Executing [817194159096@default:2] Set("Local/817194159096@default-00005ac4;2", "CallerIDString=7192805887") in new stack
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] pbx.c: Executing [817194159096@default:3] Set("Local/817194159096@default-00005ac4;2", "CALLERID(num)=+17192805887") in new stack
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] pbx.c: Executing [817194159096@default:4] NoOp("Local/817194159096@default-00005ac4;2", "CallerID : +17192805887") in new stack
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] pbx.c: Executing [817194159096@default:5] Dial("Local/817194159096@default-00005ac4;2", "SIP/magna1/17194159096,,tTo") in new stack
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] netsock2.c: Using SIP RTP CoS mark 5
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] chan_sip.c: Audio is at 14746
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] chan_sip.c: Adding codec ulaw to SDP
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] chan_sip.c: Reliably Transmitting (NAT) to 168.215.247.130:5060:
[Sep 26 12:26:57] VERBOSE[29974][C-0000a5d9] app_dial.c: Called SIP/magna1/17194159096
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] sip/route.c: sip_route_dump: route/path hop: <sip:168.215.247.130:5060;lr>
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] sip/route.c: sip_route_dump: route/path hop: <sip:sansay1773336743rdb162415@67.221.11.67:5060;lr;transport=udp>
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] chan_sip.c: Found RTP audio format 0
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] chan_sip.c: Found RTP audio format 101
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] chan_sip.c: Found audio description format PCMU for ID 0
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] chan_sip.c: Found audio description format telephone-event for ID 101
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] chan_sip.c: Capabilities: us - (ulaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw)
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] res_rtp_asterisk.c: 0x7f1e880e5e40 -- Strict RTP learning after remote address set to: 192.40.216.125:12312
[Sep 26 12:27:15] VERBOSE[4072][C-0000a5d9] chan_sip.c: Peer audio RTP is at port 192.40.216.125:12312
[Sep 26 12:27:15] VERBOSE[29974][C-0000a5d9] app_dial.c: SIP/magna1-00004da0 is making progress passing it to Local/817194159096@default-00005ac4;2
[Sep 26 12:27:19] VERBOSE[4072][C-0000a5d9] sip/route.c: sip_route_dump: route/path hop: <sip:168.215.247.130:5060;lr>
[Sep 26 12:27:19] VERBOSE[4072][C-0000a5d9] sip/route.c: sip_route_dump: route/path hop: <sip:sansay1773336743rdb162415@67.221.11.67:5060;lr;transport=udp>
[Sep 26 12:27:19] VERBOSE[4072][C-0000a5d9] chan_sip.c: Transmitting (NAT) to 168.215.247.130:5060:
[Sep 26 12:27:19] VERBOSE[29974][C-0000a5d9] app_dial.c: SIP/magna1-00004da0 answered Local/817194159096@default-00005ac4;2
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] bridge_channel.c: Channel SIP/magna1-00004da0 joined 'simple_bridge' basic-bridge <f0a91fb9-839f-41b7-b611-634166647178>
[Sep 26 12:27:19] VERBOSE[29974][C-0000a5d9] bridge_channel.c: Channel Local/817194159096@default-00005ac4;2 joined 'simple_bridge' basic-bridge <f0a91fb9-839f-41b7-b611-634166647178>
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] bridge_channel.c: Channel SIP/magna1-00004da0 left 'simple_bridge' basic-bridge <f0a91fb9-839f-41b7-b611-634166647178>
[Sep 26 12:27:19] VERBOSE[29974][C-0000a5d9] bridge_channel.c: Channel Local/817194159096@default-00005ac4;2 left 'simple_bridge' basic-bridge <f0a91fb9-839f-41b7-b611-634166647178>
[Sep 26 12:27:19] VERBOSE[29974][C-0000a5d9] pbx.c: Spawn extension (default, 817194159096, 5) exited non-zero on 'Local/817194159096@default-00005ac4;2'
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] pbx.c: Executing [8387@default:1] Playback("SIP/magna1-00004da0", "sip-silence") in new stack
[Sep 26 12:27:19] VERBOSE[29974][C-0000a5d9] pbx.c: Executing [h@default:1] AGI("Local/817194159096@default-00005ac4;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----22-----0-----SIP 200 OK)") in new stack
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] file.c: <SIP/magna1-00004da0> Playing 'sip-silence.gsm' (language 'en')
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] pbx.c: Executing [8387@default:2] AGI("SIP/magna1-00004da0", "agi://127.0.0.1:4577/call_log") in new stack
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=OUTSOURC))
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] res_agi.c: <SIP/magna1-00004da0>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] pbx.c: Executing [8387@default:3] AMD("SIP/magna1-00004da0", "2000,2000,1000,5000,120,50,4,256") in new stack
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] app_amd.c: AMD: SIP/magna1-00004da0 (N/A) (N/A) (Fmt: slin)
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] app_amd.c: AMD: initialSilence [2000] greeting [2000] afterGreetingSilence [1000] totalAnalysisTime [5000] minimumWordLength [120] betweenWordsSilence [50] maximumNumberOfWords [4] silenceThreshold [256] maximumWordLength [5000]
[Sep 26 12:27:20] VERBOSE[29974][C-0000a5d9] res_agi.c: <Local/817194159096@default-00005ac4;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----22-
[Sep 26 15:27:21] VERBOSE[4072][C-0000a5d9] chan_sip.c: Sending to 168.215.247.130:5060 (NAT)
[Sep 26 15:27:21] VERBOSE[4072][C-0000a5d9] chan_sip.c: Scheduling destruction of SIP dialog '683ef8e478cb5ad75cbc76e068767b3a@3.1.193.59:5060' in 13824 ms (Method: BYE)
[Sep 26 15:27:21] VERBOSE[4072][C-0000a5d9] chan_sip.c:
[Sep 26 15:27:21] VERBOSE[31234][C-0000a5d9] app_amd.c: AMD: Channel [SIP/magna1-00004da0]. HANGUP
[Sep 26 15:27:21] VERBOSE[31234][C-0000a5d9] pbx.c: Executing [h@default:1] AGI("SIP/magna1-00004da0", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------SIP 200 OK)") in new stack
[Sep 26 15:27:21] VERBOSE[31234][C-0000a5d9] res_agi.c: <SIP/magna1-00004da0>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------SIP 200 OK) completed, returning 0

Dialplan:

'8387' =>           1. Playback(sip-silence)                      [pbx_config]
                    2. AGI(agi://127.0.0.1:4577/call_log)         [pbx_config]
                    3. AMD(2000,2000,1000,5000,120,50,4,256)      [pbx_config]
                    4. AGI(VD_amd.agi,${EXTEN})                   [pbx_config]
                    5. AGI(agi-VDAD_ALL_outbound.agi,NORMAL-----LO) [pbx_config]
                    6. Hangup()                                   [pbx_config]

Hello,

Anyone know why the call was not able to proceed with the Step# 4 for this dialplan?

see sample:

[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] pbx.c: Executing [8387@default:1] Playback("SIP/magna1-00004da0", "sip-silence") in new stack
[Sep 26 12:27:19] VERBOSE[29974][C-0000a5d9] pbx.c: Executing [h@default:1] AGI("Local/817194159096@default-00005ac4;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----22-----0-----SIP 200 OK)") in new stack
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] file.c: <SIP/magna1-00004da0> Playing 'sip-silence.gsm' (language 'en')
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] pbx.c: Executing [8387@default:2] AGI("SIP/magna1-00004da0", "agi://127.0.0.1:4577/call_log") in new stack
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] res_agi.c: AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=OUTSOURC))
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] res_agi.c: <SIP/magna1-00004da0>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] pbx.c: Executing [8387@default:3] AMD("SIP/magna1-00004da0", "2000,2000,1000,5000,120,50,4,256") in new stack
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] app_amd.c: AMD: SIP/magna1-00004da0 (N/A) (N/A) (Fmt: slin)
[Sep 26 12:27:19] VERBOSE[31234][C-0000a5d9] app_amd.c: AMD: initialSilence [2000] greeting [2000] afterGreetingSilence [1000] totalAnalysisTime [5000] minimumWordLength [120] betweenWordsSilence [50] maximumNumberOfWords [4] silenceThreshold [256] maximumWordLength [5000]
[Sep 26 12:27:20] VERBOSE[29974][C-0000a5d9] res_agi.c: <Local/817194159096@default-00005ac4;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----22-
[Sep 26 15:27:21] VERBOSE[4072][C-0000a5d9] chan_sip.c: Sending to 168.215.247.130:5060 (NAT)
[Sep 26 15:27:21] VERBOSE[4072][C-0000a5d9] chan_sip.c: Scheduling destruction of SIP dialog '683ef8e478cb5ad75cbc76e068767b3a@3.1.193.59:5060' in 13824 ms (Method: BYE)
[Sep 26 15:27:21] VERBOSE[4072][C-0000a5d9] chan_sip.c:
[Sep 26 15:27:21] VERBOSE[31234][C-0000a5d9] app_amd.c: AMD: Channel [SIP/magna1-00004da0]. HANGUP
[Sep 26 15:27:21] VERBOSE[31234][C-0000a5d9] pbx.c: Executing [h@default:1] AGI("SIP/magna1-00004da0", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------SIP 200 OK)") in new stack
[Sep 26 15:27:21] VERBOSE[31234][C-0000a5d9] res_agi.c: <SIP/magna1-00004da0>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------------SIP 200 OK) completed, returning 0

Dialplan:

'8387' =>           1. Playback(sip-silence)                      [pbx_config]
                    2. AGI(agi://127.0.0.1:4577/call_log)         [pbx_config]
                    3. AMD(2000,2000,1000,5000,120,50,4,256)      [pbx_config]
                    4. AGI(VD_amd.agi,${EXTEN})                   [pbx_config]
                    5. AGI(agi-VDAD_ALL_outbound.agi,NORMAL-----LO) [pbx_config]
                    6. Hangup()                                   [pbx_config]

Not without seeing the AGI script and what it is doing. It’s lacking any real debug output when in the script.

Following the channel SIP/magna1-00004da0 the call is hangup once it reach the AMD app

[Sep 26 15:27:21] VERBOSE[31234][C-0000a5d9] app_amd.c: AMD: Channel [SIP/magna1-00004da0]. HANGUP

I think the problem being reported is that AMD is only being terminated by the hangup, not by the 5 seconds maximum analysis time.