SIP Hangup Delay Issue

Asterisk Asterisk Support
1

Hello.

I’m running an Asterisk 11.25.3/Issabel 4 PBX system, which has been working just fine so far, except for this annoying behavoir detected a month ago. The problem is that all SIP calls (even between internal extensions) remain active at least 10 seconds after a party hangups. Sometimes the delay can reach 30 seconds until finally the channel is closed. Resources usage is rather low on the server and network conditions appear to be normal. I’ve been checking the logs with SIP debugging enabled and find out that there is a warning about destruction of the channel being delayed. I attached to this post the relevant part of the log.

Thanks in advance for your suggestions.

<------------>
– Executing [h@macro-dial-one:1] Macro(“SIP/7772-0000251b”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] GotoIf(“SIP/7772-0000251b”, “0?endmixmoncheck”) in new stack
– Executing [s@macro-hangupcall:2] Set(“SIP/7772-0000251b”, “MIXMON_CALLFILENAME=/var/spool/asterisk/monitor/exten-696-7772-20190228-220323-1551409403.11876.gsm”) in new stack
– Executing [s@macro-hangupcall:3] System(“SIP/7772-0000251b”, “test -e /var/spool/asterisk/monitor/exten-696-7772-20190228-220323-1551409403.11876.gsm”) in new stack

<— SIP read from UDP:192.168.1.183:60936 —>
REGISTER sip:192.168.1.102:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.183:60936;branch=z9hG4bK-d8754z-bd07d707db156f68-1—d8754z-;rport
Max-Forwards: 70
Contact: sip:509@192.168.1.183:60936;rinstance=593203c227498691
To: "hbuitrago"sip:509@192.168.1.102:5060
From: "hbuitrago"sip:509@192.168.1.102:5060;tag=be4b6f0a
Call-ID: YmJmODBmZGUwZWNjM2E2YjEyMDU1ZTA0ZjYyMmE3ZDI.
CSeq: 3561 REGISTER
Expires: 120
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Supported: replaces
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username=“509”,realm=“asterisk”,nonce=“26153607”,uri=“sip:192.168.1.102:5060”,response=“ad6cda60e987edcc2ad0ccf5944e2c65”,algorithm=MD5
Content-Length: 0

<------------->
— (14 headers 0 lines) —
Sending to 192.168.1.183:60936 (NAT)
Sending to 192.168.1.183:60936 (NAT)

<— Transmitting (no NAT) to 192.168.1.183:60936 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.183:60936;branch=z9hG4bK-d8754z-bd07d707db156f68-1—d8754z-;received=192.168.1.183;rport=60936
From: "hbuitrago"sip:509@192.168.1.102:5060;tag=be4b6f0a
To: "hbuitrago"sip:509@192.168.1.102:5060;tag=as076a59c4
Call-ID: YmJmODBmZGUwZWNjM2E2YjEyMDU1ZTA0ZjYyMmE3ZDI.
CSeq: 3561 REGISTER
Server: FPBX-2.11.0(11.25.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“13485044”
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘YmJmODBmZGUwZWNjM2E2YjEyMDU1ZTA0ZjYyMmE3ZDI.’ in 32000 ms (Method: REGISTER)
– Executing [s@macro-hangupcall:4] NoOp(“SIP/7772-0000251b”, “SYSTEMSTATUS = APPERROR”) in new stack
– Executing [s@macro-hangupcall:5] GotoIf(“SIP/7772-0000251b”, “0?finalcdr”) in new stack
– Executing [s@macro-hangupcall:6] Set(“SIP/7772-0000251b”, “MIXMON_CALLFILENAME=/var/spool/asterisk/monitor/2019/02/28/exten-696-7772-20190228-220323-1551409403.11876.gsm”) in new stack
– Executing [s@macro-hangupcall:7] System(“SIP/7772-0000251b”, “test -e /var/spool/asterisk/monitor/2019/02/28/exten-696-7772-20190228-220323-1551409403.11876.gsm”) in new stack
– Executing [s@macro-hangupcall:8] NoOp(“SIP/7772-0000251b”, “SYSTEMSTATUS = SUCCESS”) in new stack
– Executing [s@macro-hangupcall:9] GotoIf(“SIP/7772-0000251b”, “1?mmtestsuccess1”) in new stack
– Goto (macro-hangupcall,s,11)
– Executing [s@macro-hangupcall:11] Set(“SIP/7772-0000251b”, “CDR(recordingfile)=/var/spool/asterisk/monitor/2019/02/28/exten-696-7772-20190228-220323-1551409403.11876.gsm”) in new stack
– Executing [s@macro-hangupcall:12] Goto(“SIP/7772-0000251b”, “finalcdr”) in new stack
– Goto (macro-hangupcall,s,63)
– Executing [s@macro-hangupcall:63] NoOp(“SIP/7772-0000251b”, “CDR recordingfile set to: /var/spool/asterisk/monitor/2019/02/28/exten-696-7772-20190228-220323-1551409403.11876.gsm”) in new stack
– Executing [s@macro-hangupcall:64] GotoIf(“SIP/7772-0000251b”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,67)
– Executing [s@macro-hangupcall:67] GotoIf(“SIP/7772-0000251b”, “1?skipblkvm”) in new stack
– Goto (macro-hangupcall,s,70)
– Executing [s@macro-hangupcall:70] GotoIf(“SIP/7772-0000251b”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,72)
– Executing [s@macro-hangupcall:72] AGI(“SIP/7772-0000251b”, “hangup.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/hangup.agi

<— SIP read from UDP:192.168.1.183:60936 —>
REGISTER sip:192.168.1.102:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.183:60936;branch=z9hG4bK-d8754z-8e1ffe0cfc6a655d-1—d8754z-;rport
Max-Forwards: 70
Contact: sip:509@192.168.1.183:60936;rinstance=593203c227498691
To: "hbuitrago"sip:509@192.168.1.102:5060
From: "hbuitrago"sip:509@192.168.1.102:5060;tag=be4b6f0a
Call-ID: YmJmODBmZGUwZWNjM2E2YjEyMDU1ZTA0ZjYyMmE3ZDI.
CSeq: 3562 REGISTER
Expires: 120
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Supported: replaces
User-Agent: 3CXPhone 6.0.26523.0
Authorization: Digest username=“509”,realm=“asterisk”,nonce=“13485044”,uri=“sip:192.168.1.102:5060”,response=“ece25a66e05790a2ae5ea4f8e8b36fa0”,algorithm=MD5
Content-Length: 0

<------------->
— (14 headers 0 lines) —
Sending to 192.168.1.183:60936 (no NAT)
Reliably Transmitting (no NAT) to 192.168.1.183:60936:
OPTIONS sip:509@192.168.1.183:60936;rinstance=593203c227498691 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK1c78c09d
Max-Forwards: 70
From: “Unknown” sip:Unknown@192.168.1.102;tag=as12498cd8
To: sip:509@192.168.1.183:60936;rinstance=593203c227498691
Contact: sip:Unknown@192.168.1.102:5060
Call-ID: 015c721a6b3a15d91c9e67a76fd06f68@192.168.1.102:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.25.3)
Date: Fri, 01 Mar 2019 03:03:54 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<— Transmitting (no NAT) to 192.168.1.183:60936 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.183:60936;branch=z9hG4bK-d8754z-8e1ffe0cfc6a655d-1—d8754z-;received=192.168.1.183;rport=60936
From: "hbuitrago"sip:509@192.168.1.102:5060;tag=be4b6f0a
To: "hbuitrago"sip:509@192.168.1.102:5060;tag=as076a59c4
Call-ID: YmJmODBmZGUwZWNjM2E2YjEyMDU1ZTA0ZjYyMmE3ZDI.
CSeq: 3562 REGISTER
Server: FPBX-2.11.0(11.25.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 120
Contact: sip:509@192.168.1.183:60936;rinstance=593203c227498691;expires=120
Date: Fri, 01 Mar 2019 03:03:54 GMT
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘796b02e0344dce541ad02d6c2bcd8f8f@192.168.1.102:5060’ in 6656 ms (Method: NOTIFY)
Reliably Transmitting (no NAT) to 192.168.1.183:60936:
NOTIFY sip:509@192.168.1.183:60936;rinstance=593203c227498691 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK73475c23
Max-Forwards: 70
From: “Unknown” sip:Unknown@192.168.1.102;tag=as2e81f13d
To: sip:509@192.168.1.183:60936;rinstance=593203c227498691
Contact: sip:Unknown@192.168.1.102:5060
Call-ID: 796b02e0344dce541ad02d6c2bcd8f8f@192.168.1.102:5060
CSeq: 102 NOTIFY
User-Agent: FPBX-2.11.0(11.25.3)
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 88

Messages-Waiting: no
Message-Account: sip:#97@192.168.1.102
Voice-Message: 0/0 (0/0)

Scheduling destruction of SIP dialog ‘YmJmODBmZGUwZWNjM2E2YjEyMDU1ZTA0ZjYyMmE3ZDI.’ in 32000 ms (Method: REGISTER)
Retransmitting #1 (no NAT) to 192.168.1.183:60936:
NOTIFY sip:509@192.168.1.183:60936;rinstance=593203c227498691 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK73475c23
Max-Forwards: 70
From: “Unknown” sip:Unknown@192.168.1.102;tag=as2e81f13d
To: sip:509@192.168.1.183:60936;rinstance=593203c227498691
Contact: sip:Unknown@192.168.1.102:5060
Call-ID: 796b02e0344dce541ad02d6c2bcd8f8f@192.168.1.102:5060
CSeq: 102 NOTIFY
User-Agent: FPBX-2.11.0(11.25.3)
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 88

Messages-Waiting: no
Message-Account: sip:#97@192.168.1.102
Voice-Message: 0/0 (0/0)

<— SIP read from UDP:192.168.1.183:60936 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK1c78c09d
Contact: sip:192.168.1.183:60936
To: sip:509@192.168.1.183:60936;rinstance=593203c227498691;tag=b12f092e
From: "Unknown"sip:Unknown@192.168.1.102;tag=as12498cd8
Call-ID: 015c721a6b3a15d91c9e67a76fd06f68@192.168.1.102:5060
CSeq: 102 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Supported: replaces
Allow-Events: presence, message-summary, tunnel-info
Content-Length: 0

<------------->
— (13 headers 0 lines) —
Really destroying SIP dialog ‘015c721a6b3a15d91c9e67a76fd06f68@192.168.1.102:5060’ Method: OPTIONS

<— SIP read from UDP:192.168.1.183:60936 —>
SIP/2.0 405 Method Not Allowed
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK73475c23
To: sip:509@192.168.1.183:60936;rinstance=593203c227498691;tag=5e48e362
From: "Unknown"sip:Unknown@192.168.1.102;tag=as2e81f13d
Call-ID: 796b02e0344dce541ad02d6c2bcd8f8f@192.168.1.102:5060
CSeq: 102 NOTIFY
Content-Length: 0

<------------->
— (7 headers 0 lines) —

<— SIP read from UDP:192.168.1.183:60936 —>
SIP/2.0 405 Method Not Allowed
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK73475c23
To: sip:509@192.168.1.183:60936;rinstance=593203c227498691;tag=5e48e362
From: "Unknown"sip:Unknown@192.168.1.102;tag=as2e81f13d
Call-ID: 796b02e0344dce541ad02d6c2bcd8f8f@192.168.1.102:5060
CSeq: 102 NOTIFY
Content-Length: 0

<------------->
— (7 headers 0 lines) —
[2019-02-28 22:03:55] ERROR[23105]: tcptls.c:908 ast_tcptls_client_start: Unable to connect SIP socket to 192.168.1.81:5060: No route to host
Really destroying SIP dialog ‘42a11c1f73ecb4fd3ccf6d85489b0dd9@192.168.1.102:5060’ Method: OPTIONS
Really destroying SIP dialog ‘1bd5e3c2a9094347c4c1ebba2db807fe020080upl3300@10.175.141.41’ Method: OPTIONS
Really destroying SIP dialog ‘796b02e0344dce541ad02d6c2bcd8f8f@192.168.1.102:5060’ Method: NOTIFY

<— SIP read from UDP:192.168.1.183:60936 —>

<------------->
Reliably Transmitting (NAT) to 10.212.134.2:2422:
OPTIONS sip:7772@10.212.134.2:2422;rinstance=d376c4e890ac083c SIP/2.0
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK2cadeae3;rport
Max-Forwards: 70
From: “Unknown” sip:Unknown@192.168.1.102;tag=as3cfe5803
To: sip:7772@10.212.134.2:2422;rinstance=d376c4e890ac083c
Contact: sip:Unknown@192.168.1.102:5060
Call-ID: 294355a62dd11f7e16588734519cf0cf@192.168.1.102:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.25.3)
Date: Fri, 01 Mar 2019 03:04:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<— SIP read from UDP:10.212.134.2:2422 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK2cadeae3;rport=5060
Contact: sip:10.212.134.2:2422
To: sip:7772@10.212.134.2:2422;rinstance=d376c4e890ac083c;tag=32711e0e
From: "Unknown"sip:Unknown@192.168.1.102;tag=as3cfe5803
Call-ID: 294355a62dd11f7e16588734519cf0cf@192.168.1.102: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 1103d stamp 53117
Content-Length: 0

<------------->
— (12 headers 0 lines) —
Really destroying SIP dialog ‘294355a62dd11f7e16588734519cf0cf@192.168.1.102:5060’ Method: OPTIONS
[2019-02-28 22:04:03] WARNING[2601]: chan_sip.c:4271 __sip_autodestruct: Autodestruct on dialog ‘NWVjYTY0OTg5MjlmZTI4YjNmNjU1ZDJjZWVhOWYzZWY.’ with owner SIP/7772-0000251b in place (Method: BYE). Rescheduling destruction for 10000 ms

<— SIP read from UDP:192.168.1.143:50602 —>

<------------->
Reliably Transmitting (NAT) to 192.168.1.81:5060:
OPTIONS sip:192.168.1.81 SIP/2.0
Via: SIP/2.0/TCP 192.168.1.102:5060;branch=z9hG4bK074a9381;rport
Max-Forwards: 70
From: “Unknown” sip:Unknown@192.168.1.102;tag=as013a48a6
To: sip:192.168.1.81
Contact: sip:Unknown@192.168.1.102:5060;transport=TCP
Call-ID: 60b365c257abe6373c59c4b16146b2ae@192.168.1.102:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.25.3)
Date: Fri, 01 Mar 2019 03:04:06 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

-- <SIP/7772-0000251b>AGI Script hangup.agi completed, returning 0
-- Executing [s@macro-hangupcall:73] Hangup("SIP/7772-0000251b", "") in new stack

== Spawn extension (macro-hangupcall, s, 73) exited non-zero on ‘SIP/7772-0000251b’ in macro ‘hangupcall’
== Spawn extension (macro-dial-one, h, 1) exited non-zero on ‘SIP/7772-0000251b’
Scheduling destruction of SIP dialog ‘3c9088f76aa49cc559bb14fa21cfd801@192.168.1.102:5060’ in 6400 ms (Method: INVITE)
set_destination: Parsing sip:696@10.212.134.2:50460 for address/port to send to
set_destination: set destination to 10.212.134.2:50460
Reliably Transmitting (NAT) to 10.212.134.2:50460:
BYE sip:696@10.212.134.2:50460 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK5a08a0ff;rport
Max-Forwards: 70
From: “User1” sip:7772@192.168.1.102;tag=as57e49987
To: sip:696@10.212.134.2:50460;rinstance=9be153e276bd30ab;transport=UDP;tag=192c1236
Call-ID: 3c9088f76aa49cc559bb14fa21cfd801@192.168.1.102:5060
CSeq: 103 BYE
User-Agent: FPBX-2.11.0(11.25.3)
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

== Spawn extension (macro-dial-one, s, 43) exited non-zero on ‘SIP/7772-0000251b’ in macro ‘dial-one’
== Spawn extension (macro-exten-vm, s, 7) exited non-zero on ‘SIP/7772-0000251b’ in macro ‘exten-vm’
== Spawn extension (from-internal, 696, 2) exited non-zero on ‘SIP/7772-0000251b’
== MixMonitor close filestream (mixed)
== End MixMonitor Recording SIP/7772-0000251b

<— SIP read from UDP:10.212.134.2:50460 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.102:5060;branch=z9hG4bK5a08a0ff;rport=5060
Contact: sip:696@10.212.134.2:50460
To: sip:696@10.212.134.2:50460;rinstance=9be153e276bd30ab;transport=UDP;tag=192c1236
From: “User1” sip:7772@192.168.1.102;tag=as57e49987
Call-ID: 3c9088f76aa49cc559bb14fa21cfd801@192.168.1.102:5060
CSeq: 103 BYE
User-Agent: Z 3.9.32144 r32121
Content-Length: 0

<------------->
— (9 headers 0 lines) —
Really destroying SIP dialog ‘3c9088f76aa49cc559bb14fa21cfd801@192.168.1.102:5060’ Method: INVITE

<— SIP read from UDP:10.212.134.2:50460 —>
PUBLISH sip:696@192.168.1.102;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.212.134.2:50460;branch=z9hG4bK-524287-1—b7ffe91ef19082e3
Max-Forwards: 70
Contact: sip:696@10.212.134.2:50460;transport=UDP
To: "User2"sip:696@192.168.1.102;transport=UDP
From: "User2"sip:696@192.168.1.102;transport=UDP;tag=08088c1a
Call-ID: ksJGXAcnH_E7WMFHr9CJHA…
CSeq: 1 PUBLISH
Expires: 600
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/pidf+xml
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence
Allow-Events: presence, kpml
Content-Length: 259

<?xml version="1.0" encoding="UTF-8"?>



open
Online

<------------->
— (16 headers 8 lines) —
Sending to 10.212.134.2:50460 (NAT)

<— Transmitting (NAT) to 10.212.134.2:50460 —>
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 10.212.134.2:50460;branch=z9hG4bK-524287-1—b7ffe91ef19082e3;received=10.212.134.2;rport=50460
From: "User2"sip:696@192.168.1.102;transport=UDP;tag=08088c1a
To: "User2"sip:696@192.168.1.102;transport=UDP;tag=as54462c08
Call-ID: ksJGXAcnH_E7WMFHr9CJHA…
CSeq: 1 PUBLISH
Server: FPBX-2.11.0(11.25.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>
Really destroying SIP dialog ‘ksJGXAcnH_E7WMFHr9CJHA…’ Method: PUBLISH

<— SIP read from UDP:10.212.134.2:50460 —>
SUBSCRIBE sip:696@192.168.1.102;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.212.134.2:50460;branch=z9hG4bK-524287-1—4d63b039224dcfa1
Max-Forwards: 70
Contact: sip:696@10.212.134.2:50460;transport=UDP
To: "User2"sip:696@192.168.1.102;transport=UDP
From: "User2"sip:696@192.168.1.102;transport=UDP;tag=67029047
Call-ID: kNRoFWBHvFlArM49BUI9QQ…
CSeq: 1 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0

<------------->
— (16 headers 0 lines) —
Sending to 10.212.134.2:50460 (NAT)
Creating new subscription
Sending to 10.212.134.2:50460 (NAT)
list_route: hop: sip:696@10.212.134.2:50460;transport=UDP
Found peer ‘696’ for ‘696’ from 10.212.134.2:50460

<— Transmitting (NAT) to 10.212.134.2:50460 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.212.134.2:50460;branch=z9hG4bK-524287-1—4d63b039224dcfa1;received=10.212.134.2;rport=50460
From: "User2"sip:696@192.168.1.102;transport=UDP;tag=67029047
To: "User2"sip:696@192.168.1.102;transport=UDP;tag=as63a3faa1
Call-ID: kNRoFWBHvFlArM49BUI9QQ…
CSeq: 1 SUBSCRIBE
Server: FPBX-2.11.0(11.25.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“2526da41”
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘kNRoFWBHvFlArM49BUI9QQ…’ in 6400 ms (Method: SUBSCRIBE)

<— SIP read from UDP:10.212.134.2:50460 —>
SUBSCRIBE sip:696@192.168.1.102;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.212.134.2:50460;branch=z9hG4bK-524287-1—2f89cf8dbb59d906
Max-Forwards: 70
Contact: sip:696@10.212.134.2:50460;transport=UDP
To: "User2"sip:696@192.168.1.102;transport=UDP
From: “User2"sip:696@192.168.1.102;transport=UDP;tag=67029047
Call-ID: kNRoFWBHvFlArM49BUI9QQ…
CSeq: 2 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Authorization: Digest username=“696”,realm=“asterisk”,nonce=“2526da41”,uri="sip:696@192.168.1.102;transport=UDP”,response=“1d2a379c751531b215e79ad8ca3d44b3”,algorithm=MD5
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0

<------------->
— (17 headers 0 lines) —
Creating new subscription
Sending to 10.212.134.2:50460 (NAT)
Found peer ‘696’ for ‘696’ from 10.212.134.2:50460

<— Transmitting (NAT) to 10.212.134.2:50460 —>
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 10.212.134.2:50460;branch=z9hG4bK-524287-1—2f89cf8dbb59d906;received=10.212.134.2;rport=50460
From: "User2"sip:696@192.168.1.102;transport=UDP;tag=67029047
To: "User2"sip:696@192.168.1.102;transport=UDP;tag=as63a3faa1
Call-ID: kNRoFWBHvFlArM49BUI9QQ…
CSeq: 2 SUBSCRIBE
Server: FPBX-2.11.0(11.25.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>
Really destroying SIP dialog ‘kNRoFWBHvFlArM49BUI9QQ…’ Method: SUBSCRIBE
[2019-02-28 22:04:09] ERROR[23110]: tcptls.c:908 ast_tcptls_client_start: Unable to connect SIP socket to 192.168.1.81:5060: No route to host
Really destroying SIP dialog ‘60b365c257abe6373c59c4b16146b2ae@192.168.1.102:5060’ Method: OPTIONS
Really destroying SIP dialog ‘NWVjYTY0OTg5MjlmZTI4YjNmNjU1ZDJjZWVhOWYzZWY.’ Method: BYE
Reliably Transmitting (NAT) to 192.168.1.81:5060:
OPTIONS sip:192.168.1.81 SIP/2.0
Via: SIP/2.0/TCP 192.168.1.102:5060;branch=z9hG4bK795008f6;rport
Max-Forwards: 70
From: “Unknown” sip:Unknown@192.168.1.102;tag=as030d6f89
To: sip:192.168.1.81
Contact: sip:Unknown@192.168.1.102:5060;transport=TCP
Call-ID: 5537eb785922dd797d3f969d73f8a471@192.168.1.102:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.25.3)
Date: Fri, 01 Mar 2019 03:04:20 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

2

Please do not screen scrape, especially when discussing timing. The log files include timestamps.

Please do edit out irrelevant transactions and point out the part of the log that you think indicates an error.

Your log does not contain “delay” at all. The Rescheduling message happens after the SIP hangup has completed and indicates the Asterisk channel still exists and might reference the SIP channel, so it is unsafe to release the memory. Have you got a long running hangup handler?

3

Thanks for your answer.

I don’t use any hangup handler at this time. This was confirmed by using command “core show hanguphandlers all”. We use the Issabel PBX system as it comes by default. Also we don’t use any h extension.
It seems like the standard Issabel hangup.agi script has issues to finish, but it is not clear why.
Any other suggestion?