BlindTransfer Event not Fired

jerryriggin · 2018-10-05 07:41:17 UTC

I have a system that does not fire the BlindTransfer event. The transfer works perfectly, but from the CLI output below the transfer is happening in from-internal context and not “TRANSFER_CONTEXT = from-internal-xfer” as it says in extensions_additional.conf. Attended Transfer event fires and is in context from-internal-xfer.

[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] app_while.c: Jumping to priority 7
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("SIP/1184-00000010", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:9] Return("SIP/1184-00000010", "") in new stack
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] app_stack.c: Spawn extension (from-internal, 1184, 1) exited non-zero on 'SIP/1184-00000010'
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] app_stack.c: SIP/1184-00000010 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] app_dial.c: Called SIP/1184
[2018-10-05 01:57:48] VERBOSE[11712][C-00000005] app_queue.c: Local/1184@from-queue-0000000c;1 is ringing
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] app_dial.c: SIP/1184-00000010 answered Local/1184@from-queue-0000000c;2
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:1] ExecIf("SIP/1184-00000010", "0?Set(CDR(recordingfile)=.wav)") in new stack
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:2] Set("SIP/1184-00000010", "__MACRO_RESULT=") in new stack
[2018-10-05 01:57:48] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:3] Set("SIP/1184-00000010", "CFIGNORE=") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:4] Set("SIP/1184-00000010", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:5] Set("SIP/1184-00000010", "FORWARD_CONTEXT=from-internal") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:6] Set("SIP/1184-00000010", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:7] Macro("SIP/1184-00000010", "blkvm-clr,") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-blkvm-clr:1] Set("SIP/1184-00000010", "SHARED(BLKVM,SIP/switch-in-0000000f)=") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-blkvm-clr:2] Set("SIP/1184-00000010", "GOSUB_RETVAL=") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("SIP/1184-00000010", "") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:8] NoOp("SIP/1184-00000010", "[TRACE](3) DIALEDPEERNUMBER: 1184 CID: "Devin Murphy" <1184>") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:9] ExecIf("SIP/1184-00000010", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=1184)") in new stack
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-auto-blkvm:10] ExecIf("SIP/1184-00000010", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=Devin Murphy)") in new stack
[2018-10-05 01:57:49] VERBOSE[11712][C-00000005] app_queue.c: Local/1184@from-queue-0000000c;1 answered SIP/switch-in-0000000f
[2018-10-05 01:57:49] VERBOSE[11712][C-00000005] res_musiconhold.c: Stopped music on hold on SIP/switch-in-0000000f
[2018-10-05 01:57:49] VERBOSE[11730][C-00000005] bridge_channel.c: Channel SIP/1184-00000010 joined 'simple_bridge' basic-bridge <e714d32e-8a09-4e28-b6f5-efa29d0de1b1>
[2018-10-05 01:57:49] VERBOSE[11727][C-00000005] bridge_channel.c: Channel Local/1184@from-queue-0000000c;2 joined 'simple_bridge' basic-bridge <e714d32e-8a09-4e28-b6f5-efa29d0de1b1>
[2018-10-05 01:57:49] VERBOSE[11733][C-00000005] bridge_channel.c: Channel Local/1184@from-queue-0000000c;1 joined 'simple_bridge' basic-bridge <84e45c41-380d-45d8-b140-97ef1d879913>
[2018-10-05 01:57:49] VERBOSE[11712][C-00000005] bridge_channel.c: Channel SIP/switch-in-0000000f joined 'simple_bridge' basic-bridge <84e45c41-380d-45d8-b140-97ef1d879913>
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] bridge_channel.c: Channel SIP/switch-in-0000000f left 'simple_bridge' basic-bridge <84e45c41-380d-45d8-b140-97ef1d879913>
[2018-10-05 01:58:00] VERBOSE[11733][C-00000005] bridge_channel.c: Channel Local/1184@from-queue-0000000c;1 left 'simple_bridge' basic-bridge <84e45c41-380d-45d8-b140-97ef1d879913>
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-queue:1] Goto("SIP/switch-in-0000000f", "from-internal,,1") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx_builtins.c: Goto (from-internal,331333,1)
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] bridge_channel.c: Channel Local/1184@from-queue-0000000c;2 left 'simple_bridge' basic-bridge <e714d32e-8a09-4e28-b6f5-efa29d0de1b1>
[2018-10-05 01:58:00] VERBOSE[11730][C-00000005] bridge_channel.c: Channel SIP/1184-00000010 left 'simple_bridge' basic-bridge <e714d32e-8a09-4e28-b6f5-efa29d0de1b1>
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] app_macro.c: Spawn extension (macro-dial-one, s, 54) exited non-zero on 'Local/1184@from-queue-0000000c;2' in macro 'dial-one'
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:1] Macro("SIP/switch-in-0000000f", "user-callerid,") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] app_macro.c: Spawn extension (macro-exten-vm, s, 27) exited non-zero on 'Local/1184@from-queue-0000000c;2' in macro 'exten-vm'
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/switch-in-0000000f", "TOUCH_MONITOR=1538719059.39") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] pbx.c: Spawn extension (ext-local, 1184, 2) exited non-zero on 'Local/1184@from-queue-0000000c;2'
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/switch-in-0000000f", "AMPUSER=7277248006") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] pbx.c: Executing [h@ext-local:1] Macro("Local/1184@from-queue-0000000c;2", "hangupcall,") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/switch-in-0000000f", "0?report") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/switch-in-0000000f", "0?Set(REALCALLERIDNUM=7277248006)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/switch-in-0000000f", "AMPUSER=") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("Local/1184@from-queue-0000000c;2", "1?theend") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] pbx_builtins.c: Goto (macro-hangupcall,s,4)
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/switch-in-0000000f", "0?limit") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-hangupcall:4] ExecIf("Local/1184@from-queue-0000000c;2", "0?Set(CDR(recordingfile)=)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/switch-in-0000000f", "AMPUSERCIDNAME=") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] pbx.c: Executing [s@macro-hangupcall:5] Hangup("Local/1184@from-queue-0000000c;2", "") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] app_macro.c: Spawn extension (macro-hangupcall, s, 5) exited non-zero on 'Local/1184@from-queue-0000000c;2' in macro 'hangupcall'
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/switch-in-0000000f", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-10-05 01:58:00] VERBOSE[11727][C-00000005] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'Local/1184@from-queue-0000000c;2'
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/switch-in-0000000f", "1?report") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx_builtins.c: Goto (macro-user-callerid,s,17)
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:17] NoOp("SIP/switch-in-0000000f", "Macro Depth is 1") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/switch-in-0000000f", "1?report2:macroerror") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx_builtins.c: Goto (macro-user-callerid,s,19)
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("SIP/switch-in-0000000f", "0?continue") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:20] ExecIf("SIP/switch-in-0000000f", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:21] Set("SIP/switch-in-0000000f", "__TTL=63") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:22] GotoIf("SIP/switch-in-0000000f", "1?continue") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx_builtins.c: Goto (macro-user-callerid,s,38)
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:38] Set("SIP/switch-in-0000000f", "CALLERID(number)=7277248006") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:39] Set("SIP/switch-in-0000000f", "CALLERID(name)=TST7277248006") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:40] GotoIf("SIP/switch-in-0000000f", "0?cnum") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/switch-in-0000000f", "CDR(cnam)=TST7277248006") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:42] Set("SIP/switch-in-0000000f", "CDR(cnum)=7277248006") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:43] Set("SIP/switch-in-0000000f", "CHANNEL(language)=en") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-user-callerid:44] NoOp("SIP/switch-in-0000000f", "[TRACE](3) Using CallerID "TST7277248006" <7277248006>") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:2] Answer("SIP/switch-in-0000000f", "") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:3] Macro("SIP/switch-in-0000000f", "blkvm-set,reset") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-blkvm-set:1] ExecIf("SIP/switch-in-0000000f", "0?Set(__BLKVM_CHANNEL=SIP/switch-in-0000000f)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-blkvm-set:2] Set("SIP/switch-in-0000000f", "SHARED(BLKVM,SIP/switch-in-0000000f)=TRUE") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-blkvm-set:3] Set("SIP/switch-in-0000000f", "GOSUB_RETVAL=TRUE") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-blkvm-set:4] MacroExit("SIP/switch-in-0000000f", "") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:4] ExecIf("SIP/switch-in-0000000f", "0?Set(_DIAL_OPTIONS=TtrM(auto-blkvm)M(auto-blkvm))") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:5] Set("SIP/switch-in-0000000f", "__NODEST=331333") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:6] Set("SIP/switch-in-0000000f", "QCIDPP=TST") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:7] Set("SIP/switch-in-0000000f", "VQ_CIDPP=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:8] ExecIf("SIP/switch-in-0000000f", "1?Macro(prepend-cid,TST)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-prepend-cid:1] GotoIf("SIP/switch-in-0000000f", "0?REPCID") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-prepend-cid:2] GotoIf("SIP/switch-in-0000000f", "0?REPCID") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-prepend-cid:3] NoOp("SIP/switch-in-0000000f", "[TRACE](3) Current RGPREFIX is TST....stripping from CallerID") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-prepend-cid:4] Set("SIP/switch-in-0000000f", "CALLERID(name)=7277248006") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-prepend-cid:5] Set("SIP/switch-in-0000000f", "_RGPREFIX=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-prepend-cid:6] Set("SIP/switch-in-0000000f", "_RGPREFIX=TST") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@macro-prepend-cid:7] Set("SIP/switch-in-0000000f", "CALLERID(name)=TST7277248006") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:9] Set("SIP/switch-in-0000000f", "QAINFO=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:10] Set("SIP/switch-in-0000000f", "VQ_AINFO=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:11] ExecIf("SIP/switch-in-0000000f", "0?Set(__ALERT_INFO=)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:12] Set("SIP/switch-in-0000000f", "QJOINMSG=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:13] Set("SIP/switch-in-0000000f", "VQ_JOINMSG=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:14] Set("SIP/switch-in-0000000f", "QRETRY=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:15] Set("SIP/switch-in-0000000f", "VQ_RETRY=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:16] Set("SIP/switch-in-0000000f", "QOPTIONS=t") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:17] Set("SIP/switch-in-0000000f", "VQ_OPTIONS=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:18] Set("SIP/switch-in-0000000f", "QGOSUB=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:19] Set("SIP/switch-in-0000000f", "VQ_GOSUB=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:20] Set("SIP/switch-in-0000000f", "QAGI=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:21] Set("SIP/switch-in-0000000f", "VQ_AGI=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:22] Set("SIP/switch-in-0000000f", "QRULE=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:23] Set("SIP/switch-in-0000000f", "VQ_RULE=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:24] Set("SIP/switch-in-0000000f", "QPOSITION=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:25] Set("SIP/switch-in-0000000f", "VQ_POSITION=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:26] Gosub("SIP/switch-in-0000000f", "sub-record-check,s,1(q,331333,force)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/switch-in-0000000f", "10?initialized") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx_builtins.c: Goto (sub-record-check,s,10)
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/switch-in-0000000f", "Recordings initialized") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/switch-in-0000000f", "0?Set(ARG3=dontcare)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:12] Set("SIP/switch-in-0000000f", "REC_POLICY_MODE_SAVE=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/switch-in-0000000f", "0?Set(REC_STATUS=NO)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/switch-in-0000000f", "1?checkaction") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/switch-in-0000000f", "0?sub-record-check,q,1") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:18] NoOp("SIP/switch-in-0000000f", "Generic q Recording Check - 7277248006 331333") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:19] Gosub("SIP/switch-in-0000000f", "recordcheck,1(force,q,331333)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/switch-in-0000000f", "Starting recording check against force") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/switch-in-0000000f", "force") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx_builtins.c: Goto (sub-record-check,recordcheck,5)
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:5] Set("SIP/switch-in-0000000f", "__REC_POLICY_MODE=FORCE") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:6] GotoIf("SIP/switch-in-0000000f", "1?startrec") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp("SIP/switch-in-0000000f", "Starting recording: q, 331333") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:17] Set("SIP/switch-in-0000000f", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:18] Set("SIP/switch-in-0000000f", "__CALLFILENAME=q-331333-7277248006-20181005-015739-1538719059.39") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:19] MixMonitor("SIP/switch-in-0000000f", "2018/10/05/q-331333-7277248006-20181005-015739-1538719059.39.wav,abi(LOCAL_MIXMON_ID),/usr/local/parselog/update_mix_mixmonitor.pl ^{UNIQUEID} ^{MIXMONITOR_FILENAME}") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:20] Set("SIP/switch-in-0000000f", "__MIXMON_ID=0x7f01f40ddf20") in new stack
[2018-10-05 01:58:00] VERBOSE[11744][C-00000005] app_mixmonitor.c: Begin MixMonitor Recording SIP/switch-in-0000000f
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:21] Set("SIP/switch-in-0000000f", "__RECORD_ID=SIP/switch-in-0000000f") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:22] Set("SIP/switch-in-0000000f", "__REC_STATUS=RECORDING") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:23] Set("SIP/switch-in-0000000f", "CDR(recordingfile)=q-331333-7277248006-20181005-015739-1538719059.39.wav") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:24] Return("SIP/switch-in-0000000f", "") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [s@sub-record-check:20] Return("SIP/switch-in-0000000f", "") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:27] Set("SIP/switch-in-0000000f", "__CWIGNORE=TRUE") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:28] ExecIf("SIP/switch-in-0000000f", "0?Playback(, )") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:29] QueueLog("SIP/switch-in-0000000f", "331333,1538719059.39,NONE,DID,5134499884") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:30] Set("SIP/switch-in-0000000f", "QAANNOUNCE=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:31] Set("SIP/switch-in-0000000f", "VQ_AANNOUNCE=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:32] Set("SIP/switch-in-0000000f", "QMOH=nexthold-generic") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:33] Set("SIP/switch-in-0000000f", "VQ_MOH=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:34] ExecIf("SIP/switch-in-0000000f", "1?Set(__MOHCLASS=nexthold-generic)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:35] ExecIf("SIP/switch-in-0000000f", "1?Set(CHANNEL(musicclass)=nexthold-generic)") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:36] Set("SIP/switch-in-0000000f", "QMAXWAIT=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:37] Set("SIP/switch-in-0000000f", "VQ_MAXWAIT=") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:38] Set("SIP/switch-in-0000000f", "QUEUENUM=331333") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:39] Set("SIP/switch-in-0000000f", "QUEUEJOINTIME=1538719080") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] pbx.c: Executing [331333@from-internal:40] Queue("SIP/switch-in-0000000f", "331333,t,,,,,,,,") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] res_musiconhold.c: Started music on hold, class 'nexthold-generic', on channel 'SIP/switch-in-0000000f'
[2018-10-05 01:58:00] VERBOSE[11746][C-00000005] pbx.c: Executing [1162@from-queue:1] Set("Local/1162@from-queue-0000000d;2", "QAGENT=1162") in new stack
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] app_queue.c: Called Local/1162@from-queue/n
[2018-10-05 01:58:00] VERBOSE[11712][C-00000005] app_queue.c:     -- LazyMembers debugging - Numbusies: 0, Nummems: 1
[2018-10-05 01:58:00] VERBOSE[11746][C-00000005] pbx.c: Executing [1162@from-queue:2] Set("Local/1162@from-queue-0000000d;2", "__FROMQ=true") in new stack
[2018-10-05 01:58:00] VERBOSE[11746][C-00000005] pbx.c: Executing [1162@from-queue:3] GotoIf("Local/1162@from-queue-0000000d;2", "0?hangup") in new stack
[2018-10-05 01:58:00] VERBOSE[11746][C-00000005] pbx.c: Executing [1162@from-queue:4] GotoIf("Local/1162@from-queue-0000000d;2", "1?331333,1:hangup") in new stack
[2018-10-05 01:58:00] VERBOSE[11746][C-00000005] pbx_builtins.c: Goto (from-queue,331333,1)
[2018-10-05 01:58:00] VERBOSE[11746][C-00000005] pbx.c: Executing [331333@from-queue:1] Goto("Local/1162@from-queue-0000000d;2", "from-internal,1162,1") in new stack
[2018-10-05 01:58:00] VERBOSE[11746][C-00000005] pbx_builtins.c: Goto (from-internal,1162,1)

Also, the uniqueid channel variable for the call is the same for the blind transferring agent and receiving agent for the call. BlindTransfer and AttendedTansfer both show up in CLI> manager show events, but the BlindTransfer event never fires. Does not matter if sent from phone with ## or AMI with Redirect.

Also, I get 2 CDR records with same uniqueid, and both have context “from-internal-xfer” but that context is NOT found anywhere in verbose CLI output above.

2018-10-05 03:17:37	"TST7277248006" <7277248006>	7277248006	331333	from-internal-xfer	SIP/switch-in-00000015	Local/1184@from-queue-00000010;1	Queue	331332,t,,,,,,,,	26	26	ANSWERED	3		1538723857.53		5134499884		7277248006	7277248006			
2018-10-05 03:18:03	"TST7277248006" <7277248006>	7277248006	331333	from-internal-xfer	SIP/switch-in-00000015	Local/1162@from-queue-00000011;1	Queue	331333,t,,,,,,,,	6	6	ANSWERED	3		1538723857.53		5134499884	q-331333-7277248006-20181005-031737-1538723857.53.wav	7277248006	TST7277248006

Can anyone help me get a BlindTransfer Event?

jerryriggin · 2018-10-05 07:44:06 UTC

BTW: There is no [from-queue-custom] context and nothing in globals_custom.conf.

BlazeStudios · 2018-10-05 12:41:04 UTC

OK, first don’t use the logs. They don’t have all the verbosity for this kind of debugging the call. Second, you need to understand the contexts and how Asterisk contexts work.

[from-internal]
include => from-internal-noxfer
include => from-internal-xfer
include => bad-number ; auto-generated
exten => h,1,Macro(hangupcall)

[from-internal-noxfer]
include => from-internal-noxfer-custom
include => from-internal-noxfer-additional ; auto-generated
exten => h,1,Macro(hangupcall)

[from-internal-xfer]
include => from-internal-custom
include => from-internal-additional ; auto-generated
exten => h,1,Macro(hangupcall)

Then the actual [from-internal-additional] has about 3 dozen include statements in it that list all the contexts a call would go through looking for matches. The log out will show you what context the call is in during the call. Using “from-internal” means all the available contexts will be checked for that call to match.

Do this again, make a blind transfer between two extensions but this time do: asterisk -rvvvvvvvvvvv

That will raise the verbosity during the call LIVE so you can see more details.

jerryriggin · 2018-10-06 16:37:32 UTC

Thanks, Tom.

I had channels confused when generating the ## redirect via AMI.

I have confirmed that when I use

$astman->Redirect($CallData[‘chan’],’’,$ext,‘from-queue’,‘1’);

the transfer works fine but I do not get the event.

If I use

$astman->PlayDTMF($CallData[‘AgentChan’],$digit); and send ##$ext

it works and I get the event.

At least I did on a few tests. Working more on it today.

Now, I am suspicious that this may possibly have some relationship to changes I made to php-asmanager.php. But playing DTMFs down the agent channel seems to be the only way I can reliably control transfers via AMI.

Here’s what I inserted at line 1330:

// BEGIN Added by Jerry Riggin 2018-07-19 ============================
function Atxfer($channel, $exten, $context, $priority) {
return $this-&gt;send_request('Atxfer', array('Channel'=&gt;$channel, 'Exten'=&gt;$exten,
'Context'=&gt;$context, 'Priority'=&gt;$priority));
}
function CancelAtxfer($channel) {
return $this-&gt;send_request('CancelAtxfer', array('Channel'=&gt;$channel));
}
function PlayDTMF($channel, $digit) {
return $this-&gt;send_request('PlayDTMF', array('Channel'=&gt;$channel, 'Digit'=&gt;$digit));
}
function QueuePause($interface,$paused,$reason) {
return $this-&gt;send_request('QueuePause', array('Channel'=&gt;$channel, 'Interface'=&gt;$interface, 'Paused'=&gt;$paused, 'Reason'=&gt;$reason));
}
/* 
function ExtensionState($exten,$context) {
return $this-&gt;send_request('ExtensionState', array('Exten'=&gt;$exten, 'Context'=&gt;$Context));
}
*/
// END Added by Jerry Riggin 2018-07-19 ============================

Of the added functions, only PlayDTMF and QueuePause work correctly. Atxfer does a successful transfer but it cannot cancelled with CancelAtxfer or PlayDTMF *5. So I make the attended transfer by sending DTMFs down agent channel, and then CancelAtxfer then up everybody. So I cancel the transfer with PlayDTMF *5 and it works correctly.

So, I have a workaround to control transfers successfully via AMI, but it is not exactly eleagant.

tm1000 · 2018-10-06 16:51:35 UTC

Why don’t you ask for these functions to be added to the underlying library?

jerryriggin · 2018-10-06 16:56:41 UTC

Thanks, Andrew. I will make a feature request for the transfer functions. It is apparently more complex than I anticipated. At least PlayDTMF is working to control transers and QueuePause works as expected.

BlazeStudios · 2018-10-06 20:27:22 UTC

@jerryriggin I think I see the problem here. While Redirect does “transfer” a call, it is not a really a transfer and therefore also not a BlindTransfer. Redirect causes the Rename and Newexten events to be triggered. You were looking for the wrong event.

jerryriggin · 2018-10-06 21:01:31 UTC

Yes, excellent point. I also discovered that if I use Action: BlindTransfer instead of Action: Redirect I get BlindTransfer event. Who would have thought? I should really stop writing code after 1:00 AM.