Hello,
Very randomly we encounter an issue where the AGI is unable to handle the hangup.
The call flow is as follows.
- 09:49:19 - A customer calls 468XXXXXX
- 09:49:19 - The call is sent to AGI
- 09:49:46 - The AGI forwards the call to 468XXXXXXX@trunk-7
- 09:52:52 - A SIP BYE is received from the outbound leg.
- 09:52:52 - The calls ends for involved parties, but there’s still a channel open and the AGI hangup appears to be missing for the inbound leg. So why does not the AGI kill both?
Asterisk 20.5.2
Can someone give pointers, or a possible solution to what might be causing this? We would expect to see an AGI hangup but we’re not.
Is more info required by us to more elaborately explain the issue?
The Asterisk log for this call
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] pbx.c: Executing [468XXXXXX@from-voip-provider:1] NoOp("PJSIP/trunk-5-00000ba2", ""Incoming call from route 30 4673XXXXXX"") in new stack
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] pbx.c: Executing [468XXXXXX@from-voip-provider:2] Set("PJSIP/trunk-5-00000ba2", "__OrigOriginator=4673XXXXXX") in new stack
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] pbx.c: Executing [468XXXXXX@from-voip-provider:3] Set("PJSIP/trunk-5-00000ba2", "__OrigRecipient=468XXXXXX") in new stack
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] pbx.c: Executing [468XXXXXX@from-voip-provider:4] Set("PJSIP/trunk-5-00000ba2", "CallID=49618d7a255672d7358b795d284664dc@13.48.XXX.XXX:5060") in new stack
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] pbx.c: Executing [468XXXXXX@from-voip-provider:5] Set("PJSIP/trunk-5-00000ba2", "UniqueID=1711014559.5031") in new stack
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] pbx.c: Executing [468XXXXXX@from-voip-provider:6] Set("PJSIP/trunk-5-00000ba2", "LinkedID=1711014559.5031") in new stack
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] pbx.c: Executing [468XXXXXX@from-voip-provider:7] Set("PJSIP/trunk-5-00000ba2", "VoiceRouteID=30") in new stack
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] pbx.c: Executing [468XXXXXX@from-voip-provider:8] AGI("PJSIP/trunk-5-00000ba2", "agi://127.0.0.1:8018") in new stack
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: AGI Tx >> agi_network: yes
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_request: agi://127.0.0.1:8018
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_channel: PJSIP/trunk-5-00000ba2
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_language: en
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_type: PJSIP
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_uniqueid: 1711014559.5031
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_version: 20.5.2
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_callerid: 4673XXXXXX
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_calleridname: unknown
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_callingpres: 0
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_callingani2: 0
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_callington: 0
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_callingtns: 0
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_dnid: 468XXXXXX
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_rdnis: unknown
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_context: from-voip-provider
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_extension: 468XXXXXX
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_priority: 8
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_enhanced: 0.0
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_accountcode:
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> agi_threadid: 139621343581952
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >>
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << GET VARIABLE UniqueID
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=1 (1711014559.5031)
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << GET VARIABLE CallID
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=1 (49618d7a255672d7358b795d284664dc@13.48.XXX.XXX:5060)
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << GET VARIABLE VoiceRouteID
[Mar 21 09:49:19] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=1 (30)
[Mar 21 09:49:20] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << ANSWER
[Mar 21 09:49:20] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=0
[Mar 21 09:49:20] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << STREAM FILE "/opt/engine-asterisk-gateway/uploads/sounds/transcoded/4a52c025-f9b5-4aaa-b330-8c8cc583b1ce" "#"
[Mar 21 09:49:20] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2> Playing '/opt/engine-asterisk-gateway/uploads/sounds/transcoded/4a52c025-f9b5-4aaa-b330-8c8cc583b1ce.slin' (escape_digits=#) (sample_offset 0) (language 'en')
[Mar 21 09:49:29] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=0 endpos=72973
[Mar 21 09:49:29] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << GET DATA /opt/engine-asterisk-gateway/uploads/sounds/transcoded/0e162ff4-1601-4a4b-9aca-5f734cd62f86 30000 1
[Mar 21 09:49:29] VERBOSE[25566][C-000005c8] file.c: <PJSIP/trunk-5-00000ba2> Playing '/opt/engine-asterisk-gateway/uploads/sounds/transcoded/0e162ff4-1601-4a4b-9aca-5f734cd62f86.slin' (language 'en')
[Mar 21 09:49:44] DTMF[25566][C-000005c8] channel.c: DTMF begin '2' received on PJSIP/trunk-5-00000ba2
[Mar 21 09:49:44] DTMF[25566][C-000005c8] channel.c: DTMF begin ignored '2' on PJSIP/trunk-5-00000ba2
[Mar 21 09:49:44] DTMF[25566][C-000005c8] channel.c: DTMF end '2' received on PJSIP/trunk-5-00000ba2, duration 141 ms
[Mar 21 09:49:44] DTMF[25566][C-000005c8] channel.c: DTMF end passthrough '2' on PJSIP/trunk-5-00000ba2
[Mar 21 09:49:44] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=2
[Mar 21 09:49:44] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << SET VARIABLE language "2"
[Mar 21 09:49:44] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=1
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << SET CALLERID "+4673XXXXXX"
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=1
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Rx << EXEC DIAL PJSIP/468XXXXXXX@trunk-7,,b(SPECIALCASES^ADDPAI^1),
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] res_agi.c: AGI Script Executing Application: (DIAL) Options: (PJSIP/468XXXXXXX@trunk-7,,b(SPECIALCASES^ADDPAI^1),)
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] app_stack.c: PJSIP/trunk-7-00000ba4 Internal Gosub(SPECIALCASES,ADDPAI,1) start
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] pbx.c: Executing [ADDPAI@SPECIALCASES:1] Verbose("PJSIP/trunk-7-00000ba4", ""Running context SPECIALCASE exten ADDPAI"") in new stack
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] app_verbose.c: Running context SPECIALCASE exten ADDPAI
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] pbx.c: Executing [ADDPAI@SPECIALCASES:2] Set("PJSIP/trunk-7-00000ba4", "PJSIP_HEADER(add,P-Asserted-Identity)=<sip:468XXXXXX@sbc.xxxx.com>") in new stack
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] pbx.c: Executing [ADDPAI@SPECIALCASES:3] Return("PJSIP/trunk-7-00000ba4", "") in new stack
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] app_stack.c: Spawn extension (from-voip-provider, 468XXXXXX, 1) exited non-zero on 'PJSIP/trunk-7-00000ba4'
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] app_stack.c: PJSIP/trunk-7-00000ba4 Internal Gosub(SPECIALCASES,ADDPAI,1) complete GOSUB_RETVAL=
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] app_dial.c: Called PJSIP/468XXXXXXX@trunk-7
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] app_dial.c: PJSIP/trunk-7-00000ba4 is ringing
[Mar 21 09:49:45] VERBOSE[25566][C-000005c8] app_dial.c: PJSIP/trunk-7-00000ba4 is making progress passing it to PJSIP/trunk-5-00000ba2
[Mar 21 09:49:46] VERBOSE[25566][C-000005c8] app_dial.c: PJSIP/trunk-7-00000ba4 answered PJSIP/trunk-5-00000ba2
[Mar 21 09:49:46] VERBOSE[25576][C-000005c8] bridge_channel.c: Channel PJSIP/trunk-7-00000ba4 joined 'simple_bridge' basic-bridge <9e675ad3-5d7a-4061-b54b-2bae59eeb96d>
[Mar 21 09:49:46] VERBOSE[25566][C-000005c8] bridge_channel.c: Channel PJSIP/trunk-5-00000ba2 joined 'simple_bridge' basic-bridge <9e675ad3-5d7a-4061-b54b-2bae59eeb96d>
[Mar 21 09:52:52] VERBOSE[25576][C-000005c8] bridge_channel.c: Channel PJSIP/trunk-7-00000ba4 left 'native_rtp' basic-bridge <9e675ad3-5d7a-4061-b54b-2bae59eeb96d>
[Mar 21 09:52:52] VERBOSE[25566][C-000005c8] bridge_channel.c: Channel PJSIP/trunk-5-00000ba2 left 'native_rtp' basic-bridge <9e675ad3-5d7a-4061-b54b-2bae59eeb96d>
[Mar 21 09:52:52] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> 200 result=-1
The open channel, still alive
root@ip-ast-local:~# asterisk -rx 'core show channel PJSIP/trunk-5-00000ba2'
-- General --
Name: PJSIP/trunk-5-00000ba2
Type: PJSIP
UniqueID: 1711014559.5031
LinkedID: 1711014559.5031
Caller ID: +4673XXXXXX
Caller ID Name: (N/A)
Connected Line ID: 4634XXXXXX
Connected Line ID Name: (N/A)
Eff. Connected Line ID: 4634XXXXXX
Eff. Connected Line ID Name: (N/A)
DNID Digits: 4634XXXXXX
Language: en
State: Up (6)
NativeFormats: (alaw)
WriteFormat: alaw
ReadFormat: alaw
WriteTranscode: No
ReadTranscode: No
Time to Hangup: 0
Elapsed Time: 0h47m47s
Bridge ID: (Not bridged)
-- PBX --
Context: from-voip-provider
Extension: 4634XXXXXX
Priority: 8
Call Group: 0
Pickup Group: 0
Application: AGI
Data: agi://127.0.0.1:8018
Call Identifer: [C-000005c8]
Variables:
DIALSTATUS=ANSWER
DIALEDTIME_MS=212583
DIALEDTIME=212
ANSWEREDTIME_MS=211988
ANSWEREDTIME=211
DIALEDPEERNUMBER=468XXXXXXX@trunk-7
DIALEDPEERNAME=PJSIP/trunk-7-00000ba4
PROGRESSTIME_MS=643
PROGRESSTIME=0
RINGTIME_MS=377
RINGTIME=0
language=2
PLAYBACKSTATUS=SUCCESS
VoiceRouteID=30
LinkedID=1711014559.5031
UniqueID=1711014559.5031
CallID=49618d7a255672d7358b795d284664dc@13.48.XXX.XXX:5060
OrigRecipient=4634XXXXXX
OrigOriginator=4673XXXXXX
SIPDOMAIN=sip.xxxx.com
CDR Variables:
level 1: dnid=4634XXXXXX
level 1: clid="" <+4673XXXXXX>
level 1: src=+4673XXXXXX
level 1: dst=4634XXXXXX
level 1: dcontext=from-voip-provider
level 1: channel=PJSIP/trunk-5-00000ba2
level 1: dstchannel=PJSIP/trunk-7-00000ba4
level 1: lastapp=Dial
level 1: lastdata=PJSIP/468XXXXXXX@trunk-7,,b(SPECIALCASES^ADDPAI^1),
level 1: start=1711014559.760794
level 1: answer=1711014560.354890
level 1: end=1711014772.343308
level 1: duration=212
level 1: billsec=211
level 1: disposition=8
level 1: amaflags=3
level 1: uniqueid=1711014559.5031
level 1: linkedid=1711014559.5031
level 1: sequence=3547
The AMI event
[Mar 21 09:52:52] VERBOSE[755] manager.c: <-- Examining AMI event: -->
Event: HangupRequest
Privilege: call,all
SequenceNumber: 732996
File: manager_channels.c
Line: 798
Func: channel_hangup_request_cb
Channel: PJSIP/trunk-7-00000ba4
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 468XXXXXX
CallerIDName: <unknown>
ConnectedLineNum: +4673XXXXXX
ConnectedLineName: <unknown>
Language: en
AccountCode:
Context: from-voip-provider
Exten:
Priority: 1
Uniqueid: 1711014585.5033
Linkedid: 1711014559.5031
The SIP BYE
[Mar 21 09:52:52] VERBOSE[695] res_pjsip_logger.c: <--- Received SIP request (742 bytes) from UDP:3.64.XXX.XXX:5060 --->
BYE sip:468XXXXXXX@xxxx:5060 SIP/2.0
Via: SIP/2.0/UDP sbc.xxxx.com:5060;branch=z9hG4bK2df3.f52398d6ab63e5b24c84bbe42b3d5ae9.0
Via: SIP/2.0/UDP sip.xxxx.io:5060;received=35.156.XXX.XXX;branch=z9hG4bK2df3.eddea340fab24d0361df92e69bea4f46.0
Via: SIP/2.0/UDP 13.48.XXX.XXX:5060;branch=z9hG4bK0cf74307
Max-Forwards: 68
From: <sip:468XXXXXXX@sbc.xxxx.com>;tag=as341b3c5f
To: <sip:4673XXXXXX@xxxx>;tag=2b8f028a-3c5c-4250-a19c-4c9febb915f6
Call-ID: 4e0f78f1-5629-4b8a-b370-1c17d987c81b
CSeq: 102 BYE
User-Agent: UserAgentA
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0
[Mar 21 09:52:52] VERBOSE[7272] res_pjsip_logger.c: <--- Transmitting SIP response (621 bytes) to UDP:3.64.XXX.XXX:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP sbc.xxxx.com:5060;rport=5060;received=3.64.XXX.XXX;branch=z9hG4bK2df3.f52398d6ab63e5b24c84bbe42b3d5ae9.0
Via: SIP/2.0/UDP sip.xxxx.io:5060;received=35.156.XXX.XXX;branch=z9hG4bK2df3.eddea340fab24d0361df92e69bea4f46.0
Via: SIP/2.0/UDP 13.48.XXX.XXX:5060;branch=z9hG4bK0cf74307
Call-ID: 4e0f78f1-5629-4b8a-b370-1c17d987c81b
From: <sip:468XXXXXXX@sbc.xxxx.com>;tag=as341b3c5f
To: <sip:4673XXXXXX@xxxx>;tag=2b8f028a-3c5c-4250-a19c-4c9febb915f6
CSeq: 102 BYE
Server: Asterisk PBX 20.5.2
Content-Length: 0