[asterisk-dev] AMI ChanSpy SpyerChannel can't hang up
Daniel McFarlane
daniel at szeto.ca
Wed Jul 6 14:08:36 CDT 2016
Hi All,
I've written an AMI interface and it's been working for the last few
years. I am currently working on a new feature and came across an issue
where Asterisk stops processing AGI requests (issued via AMI), making it
impossible to then even physically hang up a channel (until the next
call comes in on that channel)!
The problem is that if I try to redirect a ChanSpy SpyerChannel to an
extension priority that should put the channel into AGI(agi:async) mode,
the redirect action never occurs. While I get the response that the
redirect is successful, the actual AGI(agi:async) event never
occurs/never shows up on either the CLI or within the AMI responses
(from Asterisk). The CLI shows the SpyerChannel to be stuck in ChanSpy
mode.
Note/In Addition: Although not in the output I'm currently providing,
after the redirect attempt (to redirect the SpyerChannel channel out of
ChanSpy mode) I've even tried issuing (via AMI): Command: EXEC
SoftHangup and Command: EXEC Hangup and when I do I just get a response
that the AGI command is queue'd and nothing further from the channel.
After a few issued Redirect commands (again after the attempt to
redirect the SpyerChannel channel out of ChanSpy mode), I've even gotten
some "Error" responses with "Message: Redirect failed, channel not up".
If I try physically hanging up the DAHDI trunk, after issuing the first
redirect request, that still doesn't hang up and/or cause the commands
to execute (per the CLI). However, if I physically hang up the
SpyerChannel DAHDI trunk without issuing any Redirect commands to it
then the ChanSpyEnd AMI command does come in and the channel does indeed
hangup. Also: If I put both channels into a MeetMe conference then the
ChanSpyEnd AMI command also comes in..but it would be rediculous to do
that just to the ends up then hanging up the SpyerChannel! That being
said: If I'm missing something then I'm open to suggestions.
Here are the relevant extensions you'll need to know what the priorities
I am redirecting to should do:
exten => testbox,6(abort_voice),Verbose(1,Abort Complete: ${CHANNEL})
exten => testbox,7,AGI(agi:async)
exten => testbox,77(one_way_conn),AGI(agi:async)
Here are the AMI commands I issued around the issue, with timestamps and
some inline comments:
2016-07-06 13:41:55.248900 ><<<<<<< Action: Redirect
2016-07-06 13:41:55.257217 ><<<<<<< Channel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.257217 ><<<<<<< Exten: testbox
2016-07-06 13:41:55.257217 ><<<<<<< Priority: one_way_conn
2016-07-06 13:41:55.257217 ><<<<<<< Context: phones-context
2016-07-06 13:41:55.257217 ><<<<<<< ActionID: 1811486554
2016-07-06 13:41:55.257217 ><<<<<<<
2016-07-06 13:41:55.257217 ><<<<<<< Action: AGI
2016-07-06 13:41:55.258040 ><<<<<<< Channel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.258040 ><<<<<<< Command: EXEC ChanSpy DAHDI/25-1,Bwq
2016-07-06 13:41:55.258040 ><<<<<<< Exten: testbox
2016-07-06 13:41:55.258040 ><<<<<<< Priority: 7
2016-07-06 13:41:55.258040 ><<<<<<< Context: phones-context
2016-07-06 13:41:55.258040 ><<<<<<< ActionID: 1811486555
2016-07-06 13:41:55.258040 ><<<<<<<
2016-07-06 13:41:55.258040 <>>>>>>> Response: Success
2016-07-06 13:41:55.258374 <>>>>>>> ActionID: 1811486554
2016-07-06 13:41:55.258374 <>>>>>>> Message: Redirect successful
2016-07-06 13:41:55.258374 <>>>>>>>
2016-07-06 13:41:55.258374 <>>>>>>> Event: AsyncAGI
2016-07-06 13:41:55.258374 <>>>>>>> Privilege: agi,all
2016-07-06 13:41:55.258374 <>>>>>>> SubEvent: Exec
2016-07-06 13:41:55.258374 <>>>>>>> Channel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.258374 <>>>>>>> Result: 200%20result%3D-1%0A
2016-07-06 13:41:55.258374 <>>>>>>>
2016-07-06 13:41:55.258374 <>>>>>>> Event: AsyncAGI
2016-07-06 13:41:55.258374 <>>>>>>> Privilege: agi,all
2016-07-06 13:41:55.258374 <>>>>>>> SubEvent: End
2016-07-06 13:41:55.258374 <>>>>>>> Channel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.258374 <>>>>>>>
2016-07-06 13:41:55.258374 <>>>>>>> Event: VarSet
2016-07-06 13:41:55.258374 <>>>>>>> Privilege: dialplan,all
2016-07-06 13:41:55.258374 <>>>>>>> Channel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.258374 <>>>>>>> Variable: AGISTATUS
2016-07-06 13:41:55.258374 <>>>>>>> Value: HANGUP
2016-07-06 13:41:55.258374 <>>>>>>> Uniqueid: 1467826896.691
2016-07-06 13:41:55.258374 <>>>>>>>
2016-07-06 13:41:55.258374 <>>>>>>> Event: Newexten
2016-07-06 13:41:55.258374 <>>>>>>> Privilege: dialplan,all
2016-07-06 13:41:55.258374 <>>>>>>> Channel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.258374 <>>>>>>> Context: phones-context
2016-07-06 13:41:55.258374 <>>>>>>> Extension: testbox
2016-07-06 13:41:55.258374 <>>>>>>> Priority: 77
2016-07-06 13:41:55.258374 <>>>>>>> Application: AGI
2016-07-06 13:41:55.258374 <>>>>>>> AppData: agi:async
2016-07-06 13:41:55.258374 <>>>>>>> Uniqueid: 1467826896.691
2016-07-06 13:41:55.258374 <>>>>>>>
2016-07-06 13:41:55.258374 <>>>>>>> Event: AsyncAGI
2016-07-06 13:41:55.258374 <>>>>>>> Privilege: agi,all
2016-07-06 13:41:55.258374 <>>>>>>> SubEvent: Start
2016-07-06 13:41:55.258374 <>>>>>>> Channel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.258374 <>>>>>>> Env:
agi_request%3A%20async%0Aagi_channel%3A%20DAHDI%2Fi1%2F5144213700-105%0Aagi_language%3A%20en%0Aagi_type%3A%20DAHDI%0Aagi_uniqueid%3A%201467826896.691%0Aagi_version%3A%2011.2.1%0Aagi_callerid%3A%205144213700%0Aagi_calleridname%3A%20unknown%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%201%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%207770002%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20phones-context%0Aagi_extension%3A%20testbox%0Aagi_priority%3A%2077%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139683789784832%0A%0A
2016-07-06 13:41:55.258374 <>>>>>>>
2016-07-06 13:41:55.258374 <>>>>>>> Response: Success
2016-07-06 13:41:55.258374 <>>>>>>> ActionID: 1811486555
2016-07-06 13:41:55.258374 <>>>>>>> Message: Added AGI command to queue
2016-07-06 13:41:55.258374 <>>>>>>>
2016-07-06 13:41:55.258374 <>>>>>>> Event: AGIExec
2016-07-06 13:41:55.268871 <>>>>>>> Privilege: agi,all
2016-07-06 13:41:55.268871 <>>>>>>> SubEvent: Start
2016-07-06 13:41:55.268871 <>>>>>>> Channel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.268871 <>>>>>>> CommandId: 474622134
2016-07-06 13:41:55.268871 <>>>>>>> Command: EXEC ChanSpy DAHDI/25-1,Bwq
2016-07-06 13:41:55.268871 <>>>>>>>
2016-07-06 13:41:55.268871 <>>>>>>> Event: ChanSpyStart
2016-07-06 13:41:55.369354 <>>>>>>> Privilege: call,all
2016-07-06 13:41:55.369354 <>>>>>>> SpyerChannel: DAHDI/i1/5144213700-105
2016-07-06 13:41:55.369354 <>>>>>>> SpyeeChannel: DAHDI/25-1
2016-07-06 13:41:55.369354 <>>>>>>>
2016-07-06 13:41:55.369354 ><<<<<<< Action: Redirect
2016-07-06 13:42:13.513395 ><<<<<<< Channel: DAHDI/25-1
2016-07-06 13:42:13.513395 ><<<<<<< Exten: operator
2016-07-06 13:42:13.513395 ><<<<<<< Priority: one_way_conn
2016-07-06 13:42:13.513395 ><<<<<<< Context: phones-context
2016-07-06 13:42:13.513395 ><<<<<<< ActionID: 1811486556
2016-07-06 13:42:13.513395 ><<<<<<<
Here's where I try to redirect SpyerChannel to AGI(agi:async), in order
to get it out of/end ChanSpy
(Note: I'm even redirecting the SpyeeChannel, as above, to no avail):
2016-07-06 13:42:13.513395 ><<<<<<< Action: Redirect
2016-07-06 13:42:13.514265 ><<<<<<< Channel: DAHDI/i1/5144213700-105
2016-07-06 13:42:13.514265 ><<<<<<< Exten: testbox
2016-07-06 13:42:13.514265 ><<<<<<< Priority: one_way_conn
2016-07-06 13:42:13.514265 ><<<<<<< Context: phones-context
2016-07-06 13:42:13.514265 ><<<<<<< ActionID: 1811486557
2016-07-06 13:42:13.514265 ><<<<<<<
2016-07-06 13:42:13.514265 <>>>>>>> Response: Success
2016-07-06 13:42:13.514384 <>>>>>>> ActionID: 1811486556
2016-07-06 13:42:13.514384 <>>>>>>> Message: Redirect successful
2016-07-06 13:42:13.514384 <>>>>>>>
2016-07-06 13:42:13.514384 <>>>>>>> Event: AsyncAGI
2016-07-06 13:42:13.514384 <>>>>>>> Privilege: agi,all
2016-07-06 13:42:13.514384 <>>>>>>> SubEvent: End
2016-07-06 13:42:13.514384 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.514384 <>>>>>>>
2016-07-06 13:42:13.514384 <>>>>>>> Event: VarSet
2016-07-06 13:42:13.514384 <>>>>>>> Privilege: dialplan,all
2016-07-06 13:42:13.514384 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.514384 <>>>>>>> Variable: AGISTATUS
2016-07-06 13:42:13.514384 <>>>>>>> Value: HANGUP
2016-07-06 13:42:13.514384 <>>>>>>> Uniqueid: 1467826872.690
2016-07-06 13:42:13.514384 <>>>>>>>
2016-07-06 13:42:13.514384 <>>>>>>> Event: Newexten
2016-07-06 13:42:13.514384 <>>>>>>> Privilege: dialplan,all
2016-07-06 13:42:13.514384 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.514384 <>>>>>>> Context: phones-context
2016-07-06 13:42:13.514384 <>>>>>>> Extension: operator
2016-07-06 13:42:13.514384 <>>>>>>> Priority: 77
2016-07-06 13:42:13.514384 <>>>>>>> Application: AGI
2016-07-06 13:42:13.514384 <>>>>>>> AppData: agi:async
2016-07-06 13:42:13.514384 <>>>>>>> Uniqueid: 1467826872.690
2016-07-06 13:42:13.514384 <>>>>>>>
2016-07-06 13:42:13.514384 <>>>>>>> Event: AsyncAGI
2016-07-06 13:42:13.514384 <>>>>>>> Privilege: agi,all
2016-07-06 13:42:13.514384 <>>>>>>> SubEvent: Start
2016-07-06 13:42:13.514384 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.514384 <>>>>>>> Env:
agi_request%3A%20async%0Aagi_channel%3A%20DAHDI%2F25-1%0Aagi_language%3A%20en%0Aagi_type%3A%20DAHDI%0Aagi_uniqueid%3A%201467826872.690%0Aagi_version%3A%2011.2.1%0Aagi_callerid%3A%205144213737%0Aagi_calleridname%3A%20Inbound%20Analog%20Channels%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20phones-context%0Aagi_extension%3A%20operator%0Aagi_priority%3A%2077%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139683790292736%0A%0A
2016-07-06 13:42:13.514384 <>>>>>>>
2016-07-06 13:42:13.514384 ><<<<<<< Action: Redirect
2016-07-06 13:42:13.520744 ><<<<<<< Channel: DAHDI/25-1
2016-07-06 13:42:13.520744 ><<<<<<< Exten: operator
2016-07-06 13:42:13.520744 ><<<<<<< Priority: abort_voice
2016-07-06 13:42:13.520744 ><<<<<<< Context: phones-context
2016-07-06 13:42:13.520744 ><<<<<<< ActionID: 1811486558
2016-07-06 13:42:13.520744 ><<<<<<<
2016-07-06 13:42:13.520744 <>>>>>>> Response: Success
2016-07-06 13:42:13.520852 <>>>>>>> ActionID: 1811486557
2016-07-06 13:42:13.520852 <>>>>>>> Message: Redirect successful
2016-07-06 13:42:13.520852 <>>>>>>>
2016-07-06 13:42:13.520852 <>>>>>>> Response: Success
2016-07-06 13:42:13.520852 <>>>>>>> ActionID: 1811486558
2016-07-06 13:42:13.520852 <>>>>>>> Message: Redirect successful
2016-07-06 13:42:13.521943 <>>>>>>>
2016-07-06 13:42:13.521943 <>>>>>>> Event: AsyncAGI
2016-07-06 13:42:13.521943 <>>>>>>> Privilege: agi,all
2016-07-06 13:42:13.521943 <>>>>>>> SubEvent: End
2016-07-06 13:42:13.521943 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.521943 <>>>>>>>
2016-07-06 13:42:13.521943 <>>>>>>> Event: VarSet
2016-07-06 13:42:13.521943 <>>>>>>> Privilege: dialplan,all
2016-07-06 13:42:13.521943 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.521943 <>>>>>>> Variable: AGISTATUS
2016-07-06 13:42:13.521943 <>>>>>>> Value: HANGUP
2016-07-06 13:42:13.521943 <>>>>>>> Uniqueid: 1467826872.690
2016-07-06 13:42:13.521943 <>>>>>>>
2016-07-06 13:42:13.521943 <>>>>>>> Event: Newexten
2016-07-06 13:42:13.521943 <>>>>>>> Privilege: dialplan,all
2016-07-06 13:42:13.521943 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.521943 <>>>>>>> Context: phones-context
2016-07-06 13:42:13.521943 <>>>>>>> Extension: operator
2016-07-06 13:42:13.521943 <>>>>>>> Priority: 6
2016-07-06 13:42:13.521943 <>>>>>>> Application: Verbose
2016-07-06 13:42:13.521943 <>>>>>>> AppData: 1,Abort Complete: DAHDI/25-1
2016-07-06 13:42:13.521943 <>>>>>>> Uniqueid: 1467826872.690
2016-07-06 13:42:13.521943 <>>>>>>>
2016-07-06 13:42:13.521943 <>>>>>>> Event: Newexten
2016-07-06 13:42:13.521943 <>>>>>>> Privilege: dialplan,all
2016-07-06 13:42:13.521943 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.521943 <>>>>>>> Context: phones-context
2016-07-06 13:42:13.521943 <>>>>>>> Extension: operator
2016-07-06 13:42:13.521943 <>>>>>>> Priority: 7
2016-07-06 13:42:13.521943 <>>>>>>> Application: AGI
2016-07-06 13:42:13.521943 <>>>>>>> AppData: agi:async
2016-07-06 13:42:13.521943 <>>>>>>> Uniqueid: 1467826872.690
2016-07-06 13:42:13.521943 <>>>>>>>
2016-07-06 13:42:13.521943 <>>>>>>> Event: AsyncAGI
2016-07-06 13:42:13.521943 <>>>>>>> Privilege: agi,all
2016-07-06 13:42:13.521943 <>>>>>>> SubEvent: Start
2016-07-06 13:42:13.521943 <>>>>>>> Channel: DAHDI/25-1
2016-07-06 13:42:13.521943 <>>>>>>> Env:
agi_request%3A%20async%0Aagi_channel%3A%20DAHDI%2F25-1%0Aagi_language%3A%20en%0Aagi_type%3A%20DAHDI%0Aagi_uniqueid%3A%201467826872.690%0Aagi_version%3A%2011.2.1%0Aagi_callerid%3A%205144213737%0Aagi_calleridname%3A%20Inbound%20Analog%20Channels%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%20unknown%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20phones-context%0Aagi_extension%3A%20operator%0Aagi_priority%3A%207%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20139683790292736%0A%0A
==> At this point it doesn't matter if I hang up the phone headset or
not, I get nothing further from Asterisk on the AMI connection.
Here is the output from the CLI, to go along with the above AMI logs:
-- Executing [testbox at phones-context:77]
AGI("DAHDI/i1/5144213700-105", "agi:async") in new stack
-- AGI Script Executing Application: (ChanSpy) Options:
(DAHDI/25-1,Bwq)
== Spying on channel DAHDI/25-1
[Jul 6 13:41:55] NOTICE[22720][C-0000020d]: app_chanspy.c:487
start_spying: Attaching DAHDI/i1/5144213700-105 to DAHDI/25-1
[Jul 6 13:41:55] NOTICE[22720][C-0000020d]: app_chanspy.c:487
start_spying: Attaching DAHDI/i1/5144213700-105 to DAHDI/25-1
== Spawn extension (phones-context, operator, 77) exited non-zero on
'DAHDI/25-1'
-- Executing [operator at phones-context:77] AGI("DAHDI/25-1",
"agi:async") in new stack
== Spawn extension (phones-context, operator, 6) exited non-zero on
'DAHDI/25-1'
-- Executing [operator at phones-context:6] Verbose("DAHDI/25-1",
"1,Abort Complete: DAHDI/25-1") in new stack
Abort Complete: DAHDI/25-1
-- Executing [operator at phones-context:7] AGI("DAHDI/25-1",
"agi:async") in new stack
-- Span 1: Channel 0/1 got hangup request, cause 16
-- Span 1: Channel 0/1 got hangup, cause 16
==> Notice how the "agi:async" (from the redirect) on "DAHDI/25-1"
SpyeeChannel occurs, but it never occurs on the DAHDI/i1/5144213700-105
channel (the SpyerChannel) despite having been issued back-to-back.
Here's the "core show channels" command I then issued, so you can see
that BOTH Spyee and Spyer channels are still active and the Spyer
channel (DAHDI/i1/5144213700-105) is still listed as being in ChanSpy
and listening to the SpyeeChannel (DAHDI/25-1) :
daniel*CLI> core show channels
Channel Location State Application(Data)
DAHDI/i1/5144213700- testbox at szeto-mailbox Up ChanSpy(DAHDI/25-1,Bwq)
DAHDI/25-1 operator at szeto-mailb Rsrvd AGI(agi:async)
2 active channels
Note: If you believe I should issue a bug report for this then please
let me know and I will put all this info into it. I just figured it
would be better to address this to this list first.
Thank You for all your help in advance,
Daniel
More information about the asterisk-dev
mailing list