[asterisk-dev] AMI ChanSpy SpyerChannel can't hang up (Please ignore my last email)

Daniel McFarlane daniel at szeto.ca
Wed Jul 6 14:15:52 CDT 2016


Hi All,

I missed some details in my last email, so please ignore that one and 
read this one instead.  Thank You.

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. Also 
notice that the hangup CLI output occurred AFTER I physically hung up 
the headset, yet nothing showed up in the AMI communication and the 
SpyerChannel still shows up in the CLI output (see below) after this occurs!

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 phones-context Up ChanSpy(DAHDI/25-1,Bwq)
DAHDI/25-1           operator at phones-context 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

-- 
Daniel McFarlane
Szeto Technologies Inc.
885 Ellingham Ave
Pointe Claire, Québec
Canada, H9R 5E8
tel: (514) 630-7878
fax: (514) 630-6394
http://www.szeto.ca




More information about the asterisk-dev mailing list