Agentlogin hang after a while

EHLO

I am using Astersk 13.36.0 and after my agents log in using agentlogin application, the session hangs after X minutes. It could be 1 minute, or 13, or 45 minutes. Even hangs when it is with a customer.

I am using it like this:

exten => aglogin,1,noop(==Log agente ${agtolog}====)
exten => aglogin,n,agentlogin(${agtolog})
exten => aglogin,n,hangup

How can I fix this?

By finding the log entry explaining the cause!

When you find it, please remember that log and dialplan extracts needed to be marked up as preformatted text, when using this forum.

My guess is that you are suffering RTP timeouts, possibly as the result of a firewall or NAT rule timing out.

There is no firewall or anything involved with the server, just straight forward server connected to the LAN. This is the log before and after the hang:

<------------->
[2020-10-03 16:03:19] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK7a2b79a3;rport=5060
Contact: <sip:10001@192.168.0.201:20964>
To: <sip:10001@192.168.0.201:20964>;tag=3d68ae62
From: "Unknown"<sip:Unknown@192.168.0.210>;tag=as2b9981cc
Call-ID: NzgxZjVkNzNjNDQ1YWZkYTE5NGE5MDFlMmYwZjI4Yzk.
CSeq: 138 NOTIFY
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[2020-10-03 16:03:19] VERBOSE[23771] chan_sip.c: --- (9 headers 0 lines) ---
[2020-10-03 16:03:19] VERBOSE[23771] chan_sip.c: --- (9 headers 0 lines) ---
[2020-10-03 16:03:31] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[2020-10-03 16:03:31] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[2020-10-03 16:03:51] VERBOSE[23771] chan_sip.c: Really destroying SIP dialog 'ZjU0MDBkYWVmNTQxNTI5MmQ0OGM3OTk3OTU4NDE5YWI.' Method: REGISTER
[2020-10-03 16:03:51] VERBOSE[23771] chan_sip.c: Really destroying SIP dialog 'ZjU0MDBkYWVmNTQxNTI5MmQ0OGM3OTk3OTU4NDE5YWI.' Method: REGISTER
[2020-10-03 16:04:01] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[2020-10-03 16:04:01] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] res_musiconhold.c: Stopped music on hold on SIP/10001-00000002
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] res_musiconhold.c: Stopped music on hold on SIP/10001-00000002
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] bridge_channel.c: Channel SIP/10001-00000002 left 'holding_bridge' agent_hold-bridge <6e0a58c1-1289-44ce-9c82-bb1ca9008339>
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] bridge_channel.c: Channel SIP/10001-00000002 left 'holding_bridge' agent_hold-bridge <6e0a58c1-1289-44ce-9c82-bb1ca9008339>
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] app_agent_pool.c: Agent '2001' logged out.  Logged in for 92 seconds.
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] app_agent_pool.c: Agent '2001' logged out.  Logged in for 92 seconds.
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] pbx.c: Spawn extension (from-internal, 2222, 2) exited non-zero on 'SIP/10001-00000002'
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] pbx.c: Spawn extension (from-internal, 2222, 2) exited non-zero on 'SIP/10001-00000002'
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] pbx.c: Executing [h@from-internal:1] Hangup("SIP/10001-00000002", "") in new stack
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] pbx.c: Executing [h@from-internal:1] Hangup("SIP/10001-00000002", "") in new stack
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/10001-00000002'
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/10001-00000002'
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog 'ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.' in 6720 ms (Method: ACK)
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] chan_sip.c: Scheduling destruction of SIP dialog 'ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.' in 6720 ms (Method: ACK)
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
BYE sip:10001@192.168.0.201:20964 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK34b54357;rport
Max-Forwards: 70
From: "2222"<sip:2222@192.168.0.210>;tag=as1a29cca1
To: "10001"<sip:10001@192.168.0.210>;tag=7a5bd11f
Call-ID: ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.
CSeq: 102 BYE
User-Agent: FPBX-2.11.0(13.18.3)
Proxy-Authorization: Digest username="10001", realm="asterisk", algorithm=MD5, uri="sip:192.168.0.210", nonce="0905089d", response="05f61ba719fe757efd1d50c5fc953955"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2020-10-03 16:04:13] VERBOSE[24276][C-00000002] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
BYE sip:10001@192.168.0.201:20964 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK34b54357;rport
Max-Forwards: 70
From: "2222"<sip:2222@192.168.0.210>;tag=as1a29cca1
To: "10001"<sip:10001@192.168.0.210>;tag=7a5bd11f
Call-ID: ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.
CSeq: 102 BYE
User-Agent: FPBX-2.11.0(13.18.3)
Proxy-Authorization: Digest username="10001", realm="asterisk", algorithm=MD5, uri="sip:192.168.0.210", nonce="0905089d", response="05f61ba719fe757efd1d50c5fc953955"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: Retransmitting #1 (NAT) to 192.168.0.201:20964:
BYE sip:10001@192.168.0.201:20964 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK34b54357;rport
Max-Forwards: 70
From: "2222"<sip:2222@192.168.0.210>;tag=as1a29cca1
To: "10001"<sip:10001@192.168.0.210>;tag=7a5bd11f
Call-ID: ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.
CSeq: 102 BYE
User-Agent: FPBX-2.11.0(13.18.3)
Proxy-Authorization: Digest username="10001", realm="asterisk", algorithm=MD5, uri="sip:192.168.0.210", nonce="0905089d", response="05f61ba719fe757efd1d50c5fc953955"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: Retransmitting #1 (NAT) to 192.168.0.201:20964:
BYE sip:10001@192.168.0.201:20964 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK34b54357;rport
Max-Forwards: 70
From: "2222"<sip:2222@192.168.0.210>;tag=as1a29cca1
To: "10001"<sip:10001@192.168.0.210>;tag=7a5bd11f
Call-ID: ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.
CSeq: 102 BYE
User-Agent: FPBX-2.11.0(13.18.3)
Proxy-Authorization: Digest username="10001", realm="asterisk", algorithm=MD5, uri="sip:192.168.0.210", nonce="0905089d", response="05f61ba719fe757efd1d50c5fc953955"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK34b54357;rport=5060
Contact: <sip:10001@192.168.0.201:20964>
To: "10001"<sip:10001@192.168.0.210>;tag=7a5bd11f
From: "2222"<sip:2222@192.168.0.210>;tag=as1a29cca1
Call-ID: ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.
CSeq: 102 BYE
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK34b54357;rport=5060
Contact: <sip:10001@192.168.0.201:20964>
To: "10001"<sip:10001@192.168.0.210>;tag=7a5bd11f
From: "2222"<sip:2222@192.168.0.210>;tag=as1a29cca1
Call-ID: ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.
CSeq: 102 BYE
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: --- (9 headers 0 lines) ---
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: --- (9 headers 0 lines) ---
[2020-10-03 16:04:13] VERBOSE[23771][C-00000002] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived
[2020-10-03 16:04:13] VERBOSE[23771][C-00000002] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK34b54357;rport=5060
Contact: <sip:10001@192.168.0.201:20964>
To: "10001"<sip:10001@192.168.0.210>;tag=7a5bd11f
From: "2222"<sip:2222@192.168.0.210>;tag=as1a29cca1
Call-ID: ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.
CSeq: 102 BYE
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK34b54357;rport=5060
Contact: <sip:10001@192.168.0.201:20964>
To: "10001"<sip:10001@192.168.0.210>;tag=7a5bd11f
From: "2222"<sip:2222@192.168.0.210>;tag=as1a29cca1
Call-ID: ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.
CSeq: 102 BYE
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: --- (9 headers 0 lines) ---
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: --- (9 headers 0 lines) ---
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: Really destroying SIP dialog 'ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.' Method: ACK
[2020-10-03 16:04:13] VERBOSE[23771] chan_sip.c: Really destroying SIP dialog 'ZDViOWU0MTk2ODRiYzhlNGFiMzQyY2E4NTNmZGY2OWU.' Method: ACK
[2020-10-03 16:04:19] VERBOSE[23771] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
OPTIONS sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK7be2cbd3;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@192.168.0.210>;tag=as7b3a1c7f
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>
Contact: <sip:Unknown@192.168.0.210:5060>
Call-ID: 3936acce6a52de5a14ed8f7b5ddc4be0@192.168.0.210:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(13.18.3)
Date: Sat, 03 Oct 2020 21:04:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2020-10-03 16:04:19] VERBOSE[23771] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
OPTIONS sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK7be2cbd3;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@192.168.0.210>;tag=as7b3a1c7f
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>
Contact: <sip:Unknown@192.168.0.210:5060>
Call-ID: 3936acce6a52de5a14ed8f7b5ddc4be0@192.168.0.210:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(13.18.3)
Date: Sat, 03 Oct 2020 21:04:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[2020-10-03 16:04:19] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK7be2cbd3;rport=5060
Contact: <sip:192.168.0.201:20964>
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>;tag=ac5d7b0d
From: "Unknown"<sip:Unknown@192.168.0.210>;tag=as7b3a1c7f
Call-ID: 3936acce6a52de5a14ed8f7b5ddc4be0@192.168.0.210:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[2020-10-03 16:04:19] VERBOSE[23771] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK7be2cbd3;rport=5060
Contact: <sip:192.168.0.201:20964>
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>;tag=ac5d7b0d
From: "Unknown"<sip:Unknown@192.168.0.210>;tag=as7b3a1c7f
Call-ID: 3936acce6a52de5a14ed8f7b5ddc4be0@192.168.0.210:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0


You are going to need to increase the logging, as this just indicates a normal clearing. You will probably have to enable debugging on the agent code.

I’m a bit concerned that it needed to send BYE multiple times. Your network may be flakey.

This is the new log:


[Oct  3 20:00:23] VERBOSE[25355] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
OPTIONS sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK1730b5f7;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@192.168.0.210>;tag=as384c5880
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>
Contact: <sip:asterisk@192.168.0.210:5060>
Call-ID: 2dabe8721b97821137dc2ca96fff760e@192.168.0.210:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 13.36.0
Date: Sun, 04 Oct 2020 01:00:23 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Oct  3 20:00:23] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK1730b5f7;rport=5060
Contact: <sip:192.168.0.201:20964>
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>;tag=a8401f13
From: "asterisk"<sip:asterisk@192.168.0.210>;tag=as384c5880
Call-ID: 2dabe8721b97821137dc2ca96fff760e@192.168.0.210:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[Oct  3 20:00:23] VERBOSE[25355] chan_sip.c: --- (12 headers 0 lines) ---
[Oct  3 20:00:23] VERBOSE[25355] chan_sip.c: Really destroying SIP dialog '2dabe8721b97821137dc2ca96fff760e@192.168.0.210:5060' Method: OPTIONS
[Oct  3 20:00:25] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[Oct  3 20:00:37] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:00:40] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:00:43] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:00:46] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:00:49] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:00:52] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:00:55] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[Oct  3 20:00:55] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:00:59] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:02] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:05] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:08] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:11] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:14] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:17] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:20] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:23] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:23] VERBOSE[25355] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
OPTIONS sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK509a300a;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@192.168.0.210>;tag=as4977ac68
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>
Contact: <sip:asterisk@192.168.0.210:5060>
Call-ID: 3b50d4994bc3ed6225445025086ff6d6@192.168.0.210:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 13.36.0
Date: Sun, 04 Oct 2020 01:01:23 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Oct  3 20:01:24] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK509a300a;rport=5060
Contact: <sip:192.168.0.201:20964>
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>;tag=9462be3b
From: "asterisk"<sip:asterisk@192.168.0.210>;tag=as4977ac68
Call-ID: 3b50d4994bc3ed6225445025086ff6d6@192.168.0.210:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[Oct  3 20:01:24] VERBOSE[25355] chan_sip.c: --- (12 headers 0 lines) ---
[Oct  3 20:01:24] VERBOSE[25355] chan_sip.c: Really destroying SIP dialog '3b50d4994bc3ed6225445025086ff6d6@192.168.0.210:5060' Method: OPTIONS
[Oct  3 20:01:25] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[Oct  3 20:01:26] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:29] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:32] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:35] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:38] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:41] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:45] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:48] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:51] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:54] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:01:55] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[Oct  3 20:01:57] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:00] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:03] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:06] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:09] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:12] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:15] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:18] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:21] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:24] VERBOSE[25355] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
OPTIONS sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK4aae348b;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@192.168.0.210>;tag=as26c4e892
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>
Contact: <sip:asterisk@192.168.0.210:5060>
Call-ID: 781fae4a002593ea2b0a319f5ee2137c@192.168.0.210:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 13.36.0
Date: Sun, 04 Oct 2020 01:02:24 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Oct  3 20:02:24] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK4aae348b;rport=5060
Contact: <sip:192.168.0.201:20964>
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>;tag=37308f19
From: "asterisk"<sip:asterisk@192.168.0.210>;tag=as26c4e892
Call-ID: 781fae4a002593ea2b0a319f5ee2137c@192.168.0.210:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[Oct  3 20:02:24] VERBOSE[25355] chan_sip.c: --- (12 headers 0 lines) ---
[Oct  3 20:02:24] VERBOSE[25355] chan_sip.c: Really destroying SIP dialog '781fae4a002593ea2b0a319f5ee2137c@192.168.0.210:5060' Method: OPTIONS
[Oct  3 20:02:24] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:25] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[Oct  3 20:02:27] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:31] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:34] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:37] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:40] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:43] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:46] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:49] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:52] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:55] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[Oct  3 20:02:55] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:02:58] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:01] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:04] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:07] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:10] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:13] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:17] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:20] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:23] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:24] VERBOSE[25355] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
OPTIONS sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK1a1df363;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@192.168.0.210>;tag=as3a61012b
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>
Contact: <sip:asterisk@192.168.0.210:5060>
Call-ID: 38eef379706206c43dc59f5668c53120@192.168.0.210:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 13.36.0
Date: Sun, 04 Oct 2020 01:03:24 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Oct  3 20:03:24] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK1a1df363;rport=5060
Contact: <sip:192.168.0.201:20964>
To: <sip:10001@192.168.0.201:20964;rinstance=3a969dd936cdb9e2>;tag=7e0df03e
From: "asterisk"<sip:asterisk@192.168.0.210>;tag=as3a61012b
Call-ID: 38eef379706206c43dc59f5668c53120@192.168.0.210:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[Oct  3 20:03:24] VERBOSE[25355] chan_sip.c: --- (12 headers 0 lines) ---
[Oct  3 20:03:24] VERBOSE[25355] chan_sip.c: Really destroying SIP dialog '38eef379706206c43dc59f5668c53120@192.168.0.210:5060' Method: OPTIONS
[Oct  3 20:03:25] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[Oct  3 20:03:26] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:29] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:32] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:35] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:38] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:41] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:44] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:47] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:50] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:53] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:55] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->


<------------->
[Oct  3 20:03:56] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:03:59] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:04:02] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:04:06] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:04:09] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:04:12] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:04:15] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:04:15] VERBOSE[25762][C-00000016] frame.c: << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/10001-0000000d]
[Oct  3 20:04:15] VERBOSE[25762][C-00000016] frame.c: << [ HANGUP (NULL) ] [SIP/10001-0000000d]
[Oct  3 20:04:15] VERBOSE[25762][C-00000016] bridge_channel.c: Channel SIP/10001-0000000d left 'simple_bridge' basic-bridge <546799b1-ad45-4ff9-aff3-0a4f8b43e7ad>
[Oct  3 20:04:15] VERBOSE[25762][C-00000016] app_agent_pool.c: Agent '2001' logged out.  Logged in for 258 seconds.
[Oct  3 20:04:15] VERBOSE[25762][C-00000016] pbx.c: Spawn extension (from-internal, 2222, 2) exited non-zero on 'SIP/10001-0000000d'
[Oct  3 20:04:15] VERBOSE[25762][C-00000016] chan_sip.c: Scheduling destruction of SIP dialog 'MmE0YzgwYzk3ZmMxNWE5OTMwMzIwMmZjYjQ5MWI5NjU.' in 6976 ms (Method: ACK)
[Oct  3 20:04:15] VERBOSE[25762][C-00000016] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.201:20964:
BYE sip:10001@192.168.0.201:20964 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK0e692ca0;rport
Max-Forwards: 70
From: "2222"<sip:2222@192.168.0.210>;tag=as1176f61f
To: "10001"<sip:10001@192.168.0.210>;tag=8c043636
Call-ID: MmE0YzgwYzk3ZmMxNWE5OTMwMzIwMmZjYjQ5MWI5NjU.
CSeq: 102 BYE
User-Agent: Asterisk PBX 13.36.0
Proxy-Authorization: Digest username="10001", realm="asterisk", algorithm=MD5, uri="sip:192.168.0.210", nonce="626f2f6e", response="fde1358bf045555d5bbe254e7c67191d"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[Oct  3 20:04:15] VERBOSE[25761][C-00000015] bridge_channel.c: Channel IAX2/doradotoisa-2764 left 'simple_bridge' basic-bridge <546799b1-ad45-4ff9-aff3-0a4f8b43e7ad>
[Oct  3 20:04:15] VERBOSE[25761][C-00000015] pbx.c: Spawn extension (from-internal, 800, 3) exited non-zero on 'IAX2/doradotoisa-2764'
[Oct  3 20:04:15] VERBOSE[25761][C-00000015] chan_iax2.c: Hungup 'IAX2/doradotoisa-2764'
[Oct  3 20:04:15] VERBOSE[25355] chan_sip.c: 
<--- SIP read from UDP:192.168.0.201:20964 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.210:5060;branch=z9hG4bK0e692ca0;rport=5060
Contact: <sip:10001@192.168.0.201:20964>
To: "10001"<sip:10001@192.168.0.210>;tag=8c043636
From: "2222"<sip:2222@192.168.0.210>;tag=as1176f61f
Call-ID: MmE0YzgwYzk3ZmMxNWE5OTMwMzIwMmZjYjQ5MWI5NjU.
CSeq: 102 BYE
User-Agent: X-Lite release 1006e stamp 34025
Content-Length: 0

<------------->
[Oct  3 20:04:15] VERBOSE[25355] chan_sip.c: --- (9 headers 0 lines) ---
[Oct  3 20:04:15] VERBOSE[25355][C-00000016] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived
[Oct  3 20:04:15] VERBOSE[25355] chan_sip.c: Really destroying SIP dialog 'MmE0YzgwYzk3ZmMxNWE5OTMwMzIwMmZjYjQ5MWI5NjU.' Method: ACK



It went wrong slightly before this line (which still shows a normal hangup, but you don’t have any debug level logging, and without that you won’t see messages like this one at this point in the code:

This particular message is also a secondary one. You should probably start by limiting debugging to just app_agent_pool.so, but you may have to extend it to other places. app_agent_pool doesn’t generate a lot of debugging, so you shouldn’t get overwhelmed by selectively enabling debugging for it.

You mean activating core set debug? If not please give me a hint of how to activate it

core set debug, with a module name, and making sure that debugging is enabled in logger.conf. Typically I would enable the full log.