Asterisk AGI not handling hangup

Hello,

Very randomly we encounter an issue where the AGI is unable to handle the hangup.

The call flow is as follows.

  1. 09:49:19 - A customer calls 468XXXXXX
  2. 09:49:19 - The call is sent to AGI
  3. 09:49:46 - The AGI forwards the call to 468XXXXXXX@trunk-7
  4. 09:52:52 - A SIP BYE is received from the outbound leg.
  5. 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

So here’s an update.

A couple of hours later the call is hung up, the other leg. Despite the call being terminate by the involved parties long time ago.

[Mar 21 12:11:33] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> HANGUP
[Mar 21 12:11:33] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Script agi://127.0.0.1:8018 completed, returning 4
[Mar 21 12:11:33] VERBOSE[25566][C-000005c8] res_agi.c: <PJSIP/trunk-5-00000ba2>AGI Tx >> HANGUP
[Mar 21 12:11:33] VERBOSE[25566][C-000005c8] pbx.c: Spawn extension (from-voip-provider, 463XXXXXXX, 8) exited non-zero on 'PJSIP/trunk-5-00000ba2'

SIP

[Mar 21 12:11:33] VERBOSE[695] res_pjsip_logger.c: <--- Received SIP request (683 bytes) from UDP:3.64.XXX.XXX:5060 --->
BYE sip:3.127.0.46:5060 SIP/2.0
Via: SIP/2.0/UDP sbc.xxxx.com:5060;branch=z9hG4bK640b.1e37dca702a3a5072ee68175e5bc3f44.0
Via: SIP/2.0/UDP sip.xxxx.io:5060;received=13.48.207.72;branch=z9hG4bK640b.4cc06545f8e5d963279b2c6c0ff410e8.0
Via: SIP/2.0/UDP 13.48.XXX.XXX:5060;branch=z9hG4bK79a9b1bf
Max-Forwards: 59
From: <sip:073XXXXXX@13.48.XXX.XXX>;tag=as138d3591
To: <sip:034XXXXXXX@sbc.xxxx.com>;tag=8336f3f2-e3e5-47cd-a87b-9d26385c3116
Call-ID: 49618d7a255672d7358b795d284664dc@13.48.XXX.XXX:5060
CSeq: 103 BYE
User-Agent: UserAgentA
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


[Mar 21 12:11:33] VERBOSE[19492] res_pjsip_logger.c: <--- Transmitting SIP response (600 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=z9hG4bK640b.1e37dca702a3a5072ee68175e5bc3f44.0
Via: SIP/2.0/UDP sip.xxxx.io:5060;received=13.48.207.72;branch=z9hG4bK640b.4cc06545f8e5d963279b2c6c0ff410e8.0
Via: SIP/2.0/UDP 13.48.XXX.XXX:5060;branch=z9hG4bK79a9b1bf
Call-ID: 49618d7a255672d7358b795d284664dc@13.48.XXX.XXX:5060
From: <sip:073XXXXXX@13.48.XXX.XXX>;tag=as138d3591
To: <sip:034XXXXXXX@sbc.xxxx.com>;tag=8336f3f2-e3e5-47cd-a87b-9d26385c3116
CSeq: 103 BYE
Server: Asterisk PBX 20.5.2
Content-Length:  0