SUBSCRIBEs happening after Asterisk is notified that the refer Subscription-State is "terminated;reason=noresource"

Asterisk Asterisk Support
1

So here is our situation. We are using SIPp to test some call flows. The call flows involve screening and leverage an auto-attendant that is leveraging ari4Java. When we have screened the callee (transfer target) we do a refer with the ARI. We are able to get all the steps outlined in the RFC to work. However, after the last BYE/200 from transferor to transferee about 34 seconds elapse and then Asterisk (transferor) issues a SUBSCRIBE to the transferee. This is not illustrated in the RFC and we believe they should not be happening. The SUBSCRIBEs seem to be related directly to the refer because the Event header says “refer”. I am assuming there is some config I am missing or something simple and hoping you can help. Here is the entire log for the call flow from asterisk. I left the sip messages in-tact but deleted some logs before the refer and some duplicate SUBSCRIBEs at the end so I could get below 32k characters, otherwise the websit blocks me.

<— Received SIP request (570 bytes) from UDP:192.22.33.42:5060 —>
INVITE sip:19995551212@192.22.33.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.42:5060;branch=z9hG4bK-650-1-0
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188
Call-ID: 1-650@192.17.0.2
CSeq: 1 INVITE
Contact: “SIPpTest” sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188
Max-Forwards: 70
Subject: Performance Test
Content-Type: application/sdp
Content-Length: 123

v=0
o=19995551313 0 0 IN IP4 192.22.33.42
s=-
c=IN IP4 192.17.0.2
t=0 0
m=audio 6000 RTP/AVP 0
a=rtpmap:0 PCMU/8000

<— Transmitting SIP response (471 bytes) to UDP:192.22.33.42:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.22.33.42:5060;rport=5060;received=192.22.33.42;branch=z9hG4bK-650-1-0
Call-ID: 1-650@192.17.0.2
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188;tag=z9hG4bK-650-1-0
CSeq: 1 INVITE
WWW-Authenticate: Digest realm=“asterisk”,nonce=“1523032815/fe49c999a305e631534ab1dbbb95f8bd”,opaque=“164da8996bc530ae”,algorithm=md5,qop=“auth”
Server: Asterisk PBX 15.1.2
Content-Length: 0

<— Received SIP request (307 bytes) from UDP:192.22.33.42:5060 —>
ACK sip:19995551212@192.22.33.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.42:5060
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188:5060;tag=z9hG4bK-650-1-0
Call-ID: 1-650@192.17.0.2
CSeq: 1 ACK
Max-Forwards: 70
Subject: Performance Test
Content-Length: 0

<— Received SIP request (838 bytes) from UDP:192.22.33.42:5060 —>
INVITE sip:19995551212@192.22.33.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.42:5060;branch=z9hG4bK-650-1-3
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188
Call-ID: 1-650@192.17.0.2
CSeq: 2 INVITE
Contact: “SIPpTest” sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188
Authorization: Digest username=“19995551313”,realm=“asterisk”,cnonce=“6b8b4567”,nc=00000001,qop=auth,uri=“sip:192.22.33.188:5060”,nonce=“1523032815/fe49c999a305e631534ab1dbbb95f8bd”,response=“8fdf728d018307c9f8ec312b039f7a94”,algorithm=md5,opaque=“164da8996bc530ae”
Max-Forwards: 70
Subject: Performance Test
Content-Type: application/sdp
Content-Length: 123

v=0
o=19995551313 0 0 IN IP4 192.22.33.42
s=-
c=IN IP4 192.17.0.2
t=0 0
m=audio 6000 RTP/AVP 0
a=rtpmap:0 PCMU/8000

== Setting global variable ‘SIPDOMAIN’ to ‘192.22.33.188’
<— Transmitting SIP response (298 bytes) to UDP:192.22.33.42:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.22.33.42:5060;rport=5060;received=192.22.33.42;branch=z9hG4bK-650-1-3
Call-ID: 1-650@192.17.0.2
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188
CSeq: 2 INVITE
Server: Asterisk PBX 15.1.2
Content-Length: 0

<— Transmitting SIP response (728 bytes) to UDP:192.22.33.42:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.22.33.42:5060;rport=5060;received=192.22.33.42;branch=z9hG4bK-650-1-3
Call-ID: 1-650@192.17.0.2
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
CSeq: 2 INVITE
Server: Asterisk PBX 15.1.2
Contact: sip:192.22.33.188:5060
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length: 165

v=0
o=- 0 2 IN IP4 192.22.33.188
s=Asterisk
c=IN IP4 192.22.33.188
t=0 0
m=audio 20512 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=ptime:20
a=maxptime:150
a=sendrecv

<— Received SIP request (702 bytes) from UDP:192.22.33.42:5060 —>
ACK sip:192.22.33.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.42:5060;branch=z9hG4bK-650-1-7
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.214;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
Call-ID: 1-650@192.17.0.2
CSeq: 2 ACK
Contact: “SIPpTest” sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188
Authorization: Digest username=“19995551313”,realm=“asterisk”,cnonce=“327b23c6”,nc=00000001,qop=auth,uri=“sip:192.22.33.188:5060”,nonce=“1523032815/fe49c999a305e631534ab1dbbb95f8bd”,response=“e6ec434c8f4e7230070456718082d29b”,algorithm=md5,opaque=“164da8996bc530ae”
Max-Forwards: 70
Subject: Performance Test
Content-Length: 0

<— Transmitting SIP request (986 bytes) to UDP:192.22.33.214:5060 —>
INVITE sip:19995551212@192.22.33.214:5060 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPjbfb4f7ea-74aa-4673-9504-715b3b98a17b
From: sip:19995551313@192.22.33.188;tag=8ef9e442-bb96-4014-88b6-932f9eb8bec0
To: sip:19995551212@192.22.33.214
Contact: sip:asterisk@192.22.33.188:5060
Call-ID: 30da62c5-00e5-444c-8fdf-1f8a625cdd07
CSeq: 17234 INVITE
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: Asterisk PBX 15.1.2
Content-Type: application/sdp
Content-Length: 310

v=0
o=- 246335027 246335027 IN IP4 192.22.33.188
s=Asterisk
c=IN IP4 192.22.33.188
t=0 0
m=audio 47690 RTP/AVP 0 8 3 97 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:97 iLBC/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<— Received SIP response (390 bytes) from UDP:192.22.33.214:5060 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPjbfb4f7ea-74aa-4673-9504-715b3b98a17b
From: sip:19995551313@192.22.33.188;tag=8ef9e442-bb96-4014-88b6-932f9eb8bec0
To: sip:19995551212@192.22.33.214;tag=184SIPpTag0143
Call-ID: 30da62c5-00e5-444c-8fdf-1f8a625cdd07
CSeq: 17234 INVITE
Contact: sip:192.22.33.214:5060;transport=UDP
Content-Length: 0

<— Received SIP response (801 bytes) from UDP:192.22.33.214:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPjbfb4f7ea-74aa-4673-9504-715b3b98a17b
From: sip:19995551313@192.22.33.188;tag=8ef9e442-bb96-4014-88b6-932f9eb8bec0
To: sip:19995551212@192.22.33.214;tag=184SIPpTag0143
Call-ID: 30da62c5-00e5-444c-8fdf-1f8a625cdd07
CSeq: 17234 INVITE
Server: DID Logic GW
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Contact: sip:192.22.33.214:5060;transport=UDP
Content-Type: application/sdp
Content-Length: 276

v=0
o=user1 53655765 2353687637 IN IP4 192.22.33.214
s=DID Logic MGW
c=IN IP4 192.38.11.230
t=0 0
m=audio 11512 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<— Transmitting SIP request (419 bytes) to UDP:192.22.33.214:5060 —>
ACK sip:192.22.33.214:5060;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPj9ea4b810-c7fc-4b83-85da-5e03462ac259
From: sip:19995551313@192.22.33.188;tag=8ef9e442-bb96-4014-88b6-932f9eb8bec0
To: sip:19995551212@192.22.33.214;tag=184SIPpTag0143
Call-ID: 30da62c5-00e5-444c-8fdf-1f8a625cdd07
CSeq: 17234 ACK
Max-Forwards: 70
User-Agent: Asterisk PBX 15.1.2
Content-Length: 0

[Apr 6 16:40:51] DEBUG[31832][C-00000002]: channel.c:3192 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 6 16:40:52] DEBUG[31832][C-00000002]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:52] DEBUG[31832][C-00000002]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:52] DEBUG[31832][C-00000002]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:52] DEBUG[31832][C-00000002]: channel.c:5551 set_format: Channel PJSIP/19995551313-00000001 setting write format path: ulaw -> ulaw
[Apr 6 16:40:55] DEBUG[31844]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:55] DEBUG[31844]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:55] DEBUG[31844]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:55] DEBUG[31844]: channel.c:5551 set_format: Channel PJSIP/192.22.33.214-00000002 setting write format path: ulaw -> ulaw
[Apr 6 16:40:55] DEBUG[31863]: http.c:1914 httpd_helper_thread: HTTP opening session. Top level
[Apr 6 16:40:55] DEBUG[31863]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1523032827.2/play?api_key=ari4java:1234&media=sound%3A%2Fvar%2Flib%2Fasterisk%2Fsounds%2Fen%2FPrivacyStar%2FSCR_caller_connect&offsetms=0&skipms=3000
[Apr 6 16:40:55] DEBUG[31863]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/play] with handler [httpstatus] len 10
[Apr 6 16:40:55] DEBUG[31863]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/play] with handler [static] len 6
[Apr 6 16:40:55] DEBUG[31863]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/play] with handler [ari] len 3
[Apr 6 16:40:55] DEBUG[31863]: http.c:1461 handle_uri: Match made with [ari]
[Apr 6 16:40:55] DEBUG[31863]: http.c:551 ast_http_send: HTTP keeping session open. status_code:201
[Apr 6 16:40:55] DEBUG[31844]: media_cache.c:250 ast_media_cache_retrieve: Failed to obtain media at ‘/var/lib/asterisk/sounds/en/PrivacyStar/SCR_caller_connect’
[Apr 6 16:40:55] DEBUG[31844]: media_cache.c:250 ast_media_cache_retrieve: Failed to obtain media at ‘/var/lib/asterisk/sounds/en/PrivacyStar/SCR_caller_connect’
[Apr 6 16:40:55] DEBUG[31844]: channel.c:5551 set_format: Channel PJSIP/192.22.33.214-00000002 setting write format path: gsm -> ulaw
[Apr 6 16:40:55] DEBUG[31844]: channel.c:3192 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 6 16:40:55] DEBUG[31863]: http.c:1971 httpd_helper_thread: HTTP closing session. Top level
[Apr 6 16:40:56] DEBUG[31844]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:56] DEBUG[31844]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:56] DEBUG[31844]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:40:56] DEBUG[31844]: channel.c:5551 set_format: Channel PJSIP/192.22.33.214-00000002 setting write format path: ulaw -> ulaw
[Apr 6 16:40:57] DEBUG[31866]: http.c:1914 httpd_helper_thread: HTTP opening session. Top level
[Apr 6 16:40:57] DEBUG[31866]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1523032827.2/variable?api_key=ari4java:1234&variable=CHANNEL%28pjsip%2Ccall-id%29
[Apr 6 16:40:57] DEBUG[31866]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [httpstatus] len 10
[Apr 6 16:40:57] DEBUG[31866]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [static] len 6
[Apr 6 16:40:57] DEBUG[31866]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [ari] len 3
[Apr 6 16:40:57] DEBUG[31866]: http.c:1461 handle_uri: Match made with [ari]
[Apr 6 16:40:57] DEBUG[31866]: http.c:551 ast_http_send: HTTP keeping session open. status_code:200
[Apr 6 16:40:57] DEBUG[31866]: http.c:1971 httpd_helper_thread: HTTP closing session. Top level
[Apr 6 16:40:57] DEBUG[31867]: http.c:1914 httpd_helper_thread: HTTP opening session. Top level
[Apr 6 16:40:57] DEBUG[31867]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1523032827.2/variable?api_key=ari4java:1234&variable=CHANNEL%28pjsip%2Clocal_tag%29
[Apr 6 16:40:57] DEBUG[31867]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [httpstatus] len 10
[Apr 6 16:40:57] DEBUG[31867]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [static] len 6
[Apr 6 16:40:57] DEBUG[31867]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [ari] len 3
[Apr 6 16:40:57] DEBUG[31867]: http.c:1461 handle_uri: Match made with [ari]
[Apr 6 16:40:57] DEBUG[31867]: http.c:551 ast_http_send: HTTP keeping session open. status_code:200
[Apr 6 16:40:57] DEBUG[31867]: http.c:1971 httpd_helper_thread: HTTP closing session. Top level
[Apr 6 16:40:57] DEBUG[31868]: http.c:1914 httpd_helper_thread: HTTP opening session. Top level
[Apr 6 16:40:57] DEBUG[31868]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1523032827.2/variable?api_key=ari4java:1234&variable=CHANNEL%28pjsip%2Cremote_tag%29
[Apr 6 16:40:57] DEBUG[31868]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [httpstatus] len 10
[Apr 6 16:40:57] DEBUG[31868]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [static] len 6
[Apr 6 16:40:57] DEBUG[31868]: http.c:1445 handle_uri: match request [ari/channels/1523032827.2/variable] with handler [ari] len 3
[Apr 6 16:40:57] DEBUG[31868]: http.c:1461 handle_uri: Match made with [ari]
[Apr 6 16:40:57] DEBUG[31868]: http.c:551 ast_http_send: HTTP keeping session open. status_code:200
[Apr 6 16:40:58] DEBUG[31868]: http.c:1971 httpd_helper_thread: HTTP closing session. Top level
[Apr 6 16:40:58] DEBUG[31869]: http.c:1914 httpd_helper_thread: HTTP opening session. Top level
[Apr 6 16:40:58] DEBUG[31869]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1523032815.1/redirect?api_key=ari4java:1234&endpoint=PJSIP%2Fsip%3A19995551212%40192.22.33.214%3FReplaces%3D30da62c5-00e5-444c-8fdf-1f8a625cdd07%253Bto-tag%253D184SIPpTag0143%253Bfrom-tag%253D8ef9e442-bb96-4014-88b6-932f9eb8bec0
[Apr 6 16:40:58] DEBUG[31869]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1/redirect] with handler [httpstatus] len 10
[Apr 6 16:40:58] DEBUG[31869]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1/redirect] with handler [static] len 6
[Apr 6 16:40:58] DEBUG[31869]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1/redirect] with handler [ari] len 3
[Apr 6 16:40:58] DEBUG[31869]: http.c:1461 handle_uri: Match made with [ari]
[Apr 6 16:40:58] DEBUG[31869]: http.c:551 ast_http_send: HTTP keeping session open. status_code:204
[Apr 6 16:40:58] DEBUG[31740]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target ‘192.22.33.42’
[Apr 6 16:40:58] DEBUG[31740]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target ‘192.22.33.42’ is ‘UDP’
[Apr 6 16:40:58] DEBUG[31740]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target ‘192.22.33.42’ is an IP address, skipping resolution

<— Transmitting SIP request (853 bytes) to UDP:192.22.33.42:5060 —>
REFER sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPj6ea9cf0f-1649-4cfd-9037-e7c4560ffcdc
From: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
To: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
Contact: sip:192.22.33.188:5060
Call-ID: 1-650@192.17.0.2
CSeq: 5948 REFER
Event: refer
Expires: 600
Supported: 100rel, timer, replaces, norefersub
Accept: message/sipfrag;version=2.0
Allow-Events: presence, dialog, message-summary, refer
Refer-To: sip:19995551212@192.22.33.214?Replaces=30da62c5-00e5-444c-8fdf-1f8a625cdd07%3Bto-tag%3D184SIPpTag0143%3Bfrom-tag%3D8ef9e442-bb96-4014-88b6-932f9eb8bec0
Referred-By: sip:19995551212@192.22.33.188
Max-Forwards: 70
User-Agent: Asterisk PBX 15.1.2
Content-Length: 0

<— Received SIP response (493 bytes) from UDP:192.22.33.42:5060 —>
SIP/2.0 202 Accepted
CSeq: 5948 REFER
Call-ID: 1-650@192.17.0.2
From: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
To: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPj6ea9cf0f-1649-4cfd-9037-e7c4560ffcdc;received=192.22.33.188
Contact: “SIPpTest” sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188
Subject: Performance Test
Content-Length: 0

[Apr 6 16:40:58] DEBUG[31740]: res_pjsip_session.c:3565 session_inv_on_tsx_state_changed: REFER received final response code 202
<— Received SIP request (906 bytes) from UDP:192.22.33.42:5060 —>
NOTIFY sip:192.22.33.188:5060 SIP/2.0
CSeq: 5949 NOTIFY
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
Call-ID: 1-650@192.17.0.2
Max-Forwards: 70
Via: SIP/2.0/UDP 192.22.33.42:5060;branch=z9hG4bKPj6ea9cf0f-1649-4cfd-9037-e7c4560ffcdc
Contact: “SIPpTest” sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY
Authorization: Digest username=“19995551313”,realm=“asterisk”,cnonce=“643c9869”,nc=00000001,qop=auth,uri=“sip:192.22.33.188:5060”,nonce=“1523032815/fe49c999a305e631534ab1dbbb95f8bd”,response=“3825a6c9890f85ce911f946e9053fc06”,algorithm=md5,opaque=“164da8996bc530ae”
Event: refer
Subscription-State: active;expires=60
Content-Type: message/sipfrag
Subject: Performance Test
Content-Length: 20

SIP/2.0 100 Trying

<— Transmitting SIP response (562 bytes) to UDP:192.22.33.42:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.22.33.42:5060;rport=5060;received=192.22.33.42;branch=z9hG4bKPj6ea9cf0f-1649-4cfd-9037-e7c4560ffcdc
Call-ID: 1-650@192.17.0.2
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
CSeq: 5949 NOTIFY
Contact: sip:192.22.33.188:5060
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub
Server: Asterisk PBX 15.1.2
Content-Length: 0

[Apr 6 16:40:58] DEBUG[31869]: http.c:1971 httpd_helper_thread: HTTP closing session. Top level
[Apr 6 16:41:04] DEBUG[31799]: db.c:429 ast_db_del: Unable to find key ‘6001;@0236855fa4aec8cf6581e6b184d7b6c9’ in family ‘registrar/contact’
<— Received SIP request (371 bytes) from UDP:192.22.33.214:5060 —>
BYE sip:asterisk@192.22.33.188:5060 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.214:5060
From: sip:19995551212@192.22.33.214;tag=184SIPpTag0143
To: sip:19995551313@192.22.33.188;tag=8ef9e442-bb96-4014-88b6-932f9eb8bec0
Call-ID: 30da62c5-00e5-444c-8fdf-1f8a625cdd07
Cseq: 1 BYE
Contact: sip:sipp@192.22.33.214:5060;transport=UDP
Max-Forwards: 70
Content-Length: 0

<— Transmitting SIP response (334 bytes) to UDP:192.22.33.214:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.22.33.214:5060;rport=5060;received=192.22.33.214
Call-ID: 30da62c5-00e5-444c-8fdf-1f8a625cdd07
From: sip:19995551212@192.22.33.214;tag=184SIPpTag0143
To: sip:19995551313@192.22.33.188;tag=8ef9e442-bb96-4014-88b6-932f9eb8bec0
CSeq: 1 BYE
Server: Asterisk PBX 15.1.2
Content-Length: 0

[Apr 6 16:41:13] DEBUG[31844]: channel.c:2587 ast_hangup: Channel 0x7f08801eef98 ‘PJSIP/192.22.33.214-00000002’ hanging up. Refs: 2
[Apr 6 16:41:13] DEBUG[31844]: chan_pjsip.c:2251 hangup_cause2sip: AST hangup cause 16 (no match found in PJSIP)
[Apr 6 16:41:13] DEBUG[31740]: rtp_engine.c:414 instance_destructor: Destroyed RTP instance ‘0x7f087800b758’
[Apr 6 16:41:13] DEBUG[31740]: channel.c:2222 ast_channel_destructor: Channel 0x7f08801eef98 ‘PJSIP/192.22.33.214-00000002’ destroying
[Apr 6 16:41:13] DEBUG[31732]: cdr.c:1289 cdr_object_finalize: Finalized CDR for PJSIP/192.22.33.214-00000002 - start 1523032827.246045 answer 1523032827.249382 end 1523032873.257398 dispo ANSWERED
[Apr 6 16:41:13] DEBUG[31878]: http.c:1914 httpd_helper_thread: HTTP opening session. Top level
[Apr 6 16:41:13] DEBUG[31878]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1523032815.1/play?api_key=ari4java:1234&media=sound%3A%2Fvar%2Flib%2Fasterisk%2Fsounds%2Fen%2FPrivacyStar%2FSCR_caller_calledhangup&offsetms=0&skipms=3000
[Apr 6 16:41:13] DEBUG[31878]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1/play] with handler [httpstatus] len 10
[Apr 6 16:41:13] DEBUG[31878]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1/play] with handler [static] len 6
[Apr 6 16:41:13] DEBUG[31878]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1/play] with handler [ari] len 3
[Apr 6 16:41:13] DEBUG[31878]: http.c:1461 handle_uri: Match made with [ari]
[Apr 6 16:41:13] DEBUG[31878]: http.c:551 ast_http_send: HTTP keeping session open. status_code:201
[Apr 6 16:41:13] DEBUG[31832][C-00000002]: media_cache.c:250 ast_media_cache_retrieve: Failed to obtain media at ‘/var/lib/asterisk/sounds/en/PrivacyStar/SCR_caller_calledhangup’
[Apr 6 16:41:13] DEBUG[31832][C-00000002]: media_cache.c:250 ast_media_cache_retrieve: Failed to obtain media at ‘/var/lib/asterisk/sounds/en/PrivacyStar/SCR_caller_calledhangup’
[Apr 6 16:41:13] DEBUG[31832][C-00000002]: channel.c:5551 set_format: Channel PJSIP/19995551313-00000001 setting write format path: gsm -> ulaw
[Apr 6 16:41:13] DEBUG[31832][C-00000002]: channel.c:3192 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Apr 6 16:41:13] DEBUG[31878]: http.c:1971 httpd_helper_thread: HTTP closing session. Top level
<— Received SIP request (646 bytes) from UDP:192.22.33.42:5060 —>
NOTIFY sip:192.22.33.188:5060 SIP/2.0
CSeq: 5950 NOTIFY
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
Call-ID: 1-650@192.17.0.2
Max-Forwards: 70
Via: SIP/2.0/UDP 192.22.33.42:5060;branch=z9hG4bKPj6ea9cf0f-1649-4cfd-9037-e7c4560ffcdc
Contact: “SIPpTest” sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY
Event: refer
Subscription-State: terminated;reason=noresource
Content-Type: message/sipfrag
Subject: Performance Test
Content-Length: 16

SIP/2.0 200 OK

<— Transmitting SIP response (562 bytes) to UDP:192.22.33.42:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.22.33.42:5060;rport=5060;received=192.22.33.42;branch=z9hG4bKPj6ea9cf0f-1649-4cfd-9037-e7c4560ffcdc
Call-ID: 1-650@192.17.0.2
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
CSeq: 5949 NOTIFY
Contact: sip:192.22.33.188:5060
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub
Server: Asterisk PBX 15.1.2
Content-Length: 0

[Apr 6 16:41:18] DEBUG[31832][C-00000002]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:41:18] DEBUG[31832][C-00000002]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:41:18] DEBUG[31832][C-00000002]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Apr 6 16:41:18] DEBUG[31832][C-00000002]: channel.c:5551 set_format: Channel PJSIP/19995551313-00000001 setting write format path: ulaw -> ulaw
[Apr 6 16:41:18] DEBUG[31881]: http.c:1914 httpd_helper_thread: HTTP opening session. Top level
[Apr 6 16:41:18] DEBUG[31881]: http.c:1390 handle_uri: HTTP Request URI is /ari/channels/1523032815.1?api_key=ari4java:1234
[Apr 6 16:41:18] DEBUG[31881]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1] with handler [httpstatus] len 10
[Apr 6 16:41:18] DEBUG[31881]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1] with handler [static] len 6
[Apr 6 16:41:18] DEBUG[31881]: http.c:1445 handle_uri: match request [ari/channels/1523032815.1] with handler [ari] len 3
[Apr 6 16:41:18] DEBUG[31881]: http.c:1461 handle_uri: Match made with [ari]
[Apr 6 16:41:18] DEBUG[31881]: channel.c:2496 ast_softhangup_nolock: Soft-Hanging (0x20) up channel ‘PJSIP/19995551313-00000001’
[Apr 6 16:41:18] DEBUG[31832][C-00000002]: pbx.c:4365 __ast_pbx_run: Extension 19995551212, priority 3 returned normally even though call was hung up
[Apr 6 16:41:18] DEBUG[31832][C-00000002]: channel.c:2496 ast_softhangup_nolock: Soft-Hanging (0x10) up channel ‘PJSIP/19995551313-00000001’
[Apr 6 16:41:18] DEBUG[31832][C-00000002]: channel.c:2587 ast_hangup: Channel 0x7f0878021ad8 ‘PJSIP/19995551313-00000001’ hanging up. Refs: 3
[Apr 6 16:41:18] DEBUG[31832][C-00000002]: chan_pjsip.c:2251 hangup_cause2sip: AST hangup cause 16 (no match found in PJSIP)
[Apr 6 16:41:18] DEBUG[31740]: rtp_engine.c:414 instance_destructor: Destroyed RTP instance ‘0x7f087800bcd8’
[Apr 6 16:41:18] DEBUG[31740]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target ‘192.22.33.42’
[Apr 6 16:41:18] DEBUG[31740]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target ‘192.22.33.42’ is ‘UDP’
[Apr 6 16:41:18] DEBUG[31740]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target ‘192.22.33.42’ is an IP address, skipping resolution
<— Transmitting SIP request (460 bytes) to UDP:192.22.33.42:5060 —>
BYE sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPj2024d904-a0ce-473f-afe1-fe34980486d5
From: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
To: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
Call-ID: 1-650@192.17.0.2
CSeq: 5949 BYE
Reason: Q.850;cause=16
Max-Forwards: 70
User-Agent: Asterisk PBX 15.1.2
Content-Length: 0

[Apr 6 16:41:18] DEBUG[31881]: channel.c:2222 ast_channel_destructor: Channel 0x7f0878021ad8 ‘PJSIP/19995551313-00000001’ destroying
[Apr 6 16:41:18] DEBUG[31732]: cdr.c:1289 cdr_object_finalize: Finalized CDR for PJSIP/19995551313-00000001 - start 1523032815.807337 answer 1523032815.807631 end 1523032878.625770 dispo ANSWERED
[Apr 6 16:41:18] DEBUG[31881]: http.c:551 ast_http_send: HTTP keeping session open. status_code:204
[Apr 6 16:41:18] DEBUG[31881]: http.c:1971 httpd_helper_thread: HTTP closing session. Top level
<— Transmitting SIP request (460 bytes) to UDP:192.22.33.42:5060 —>
BYE sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPj2024d904-a0ce-473f-afe1-fe34980486d5
From: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
To: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
Call-ID: 1-650@192.17.0.2
CSeq: 5949 BYE
Reason: Q.850;cause=16
Max-Forwards: 70
User-Agent: Asterisk PBX 15.1.2
Content-Length: 0

<— Received SIP response (357 bytes) from UDP:192.22.33.42:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPj2024d904-a0ce-473f-afe1-fe34980486d5
From: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
To: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
Call-ID: 1-650@192.17.0.2
CSeq: 5949 BYE
Contact: sip:192.22.33.42:5060;transport=UDP
Content-Length: 0

[Apr 6 16:41:19] DEBUG[31740]: res_pjsip_session.c:3565 session_inv_on_tsx_state_changed: BYE received final response code 200
[Apr 6 16:41:34] DEBUG[31799]: db.c:429 ast_db_del: Unable to find key ‘6001;@0236855fa4aec8cf6581e6b184d7b6c9’ in family ‘registrar/contact’
[Apr 6 16:41:38] DEBUG[31833]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying.
[Apr 6 16:41:53] DEBUG[31790]: res_pjsip/pjsip_resolver.c:477 sip_resolve: Performing SIP DNS resolution of target ‘192.22.33.42’
[Apr 6 16:41:53] DEBUG[31790]: res_pjsip/pjsip_resolver.c:504 sip_resolve: Transport type for target ‘192.22.33.42’ is ‘UDP’
[Apr 6 16:41:53] DEBUG[31790]: res_pjsip/pjsip_resolver.c:525 sip_resolve: Target ‘192.22.33.42’ is an IP address, skipping resolution
<— Transmitting SIP request (652 bytes) to UDP:192.22.33.42:5060 —>
SUBSCRIBE sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPj8652030f-9438-4fdb-8b77-565e08efefd4
From: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
To: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
Contact: sip:192.22.33.188:5060
Call-ID: 1-650@192.17.0.2
CSeq: 5950 SUBSCRIBE
Event: refer
Expires: 600
Supported: 100rel, timer, replaces, norefersub
Accept: message/sipfrag;version=2.0
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: Asterisk PBX 15.1.2
Content-Length: 0

<— Transmitting SIP request (652 bytes) to UDP:192.22.33.42:5060 —>
SUBSCRIBE sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188 SIP/2.0
Via: SIP/2.0/UDP 192.22.33.188:5060;rport;branch=z9hG4bKPj8652030f-9438-4fdb-8b77-565e08efefd4
From: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
To: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
Contact: sip:192.22.33.188:5060
Call-ID: 1-650@192.17.0.2
CSeq: 5950 SUBSCRIBE
Event: refer
Expires: 600
Supported: 100rel, timer, replaces, norefersub
Accept: message/sipfrag;version=2.0
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: Asterisk PBX 15.1.2
Content-Length: 0

…more identical SUBSCRIBES but I need to cut down on my character count…

2

It appears the NOTIFY’s sip frag 200 OK arrives after receiving a BYE from the transferer. Maybe because of this the subscribe doesn’t get terminated as it should?

From the log it appears you are running Asterisk 15.1.2 correct? If so you might try upgrading to the latest version, 15.3.0. If I recall at least one, if not more, issues were fixed involving timing issues and the reception of an “early” BYE.

Also, if doing a blind transfer you could try setting the ‘refer_blind_progress’ to ‘no’ as this should disable progress monitoring, which should make it so it’s never subscribed to in the first place (although maybe you would want/need that).

1 Like
3

Thank you @kharwell for looking into this! I tried the refer_blind_progress suggestion and that didn’t seem to have any affect. I will look into upgrading Asterisk but on your first comment…shouldn’t a 200 OK come after the BYE? I may be misunderstanding your observation. Also, how should the subscribe get terminated? We are currently sending this NOTIFY to indicate termination:

<— Received SIP request (646 bytes) from UDP:192.22.33.42:5060 —>
NOTIFY sip:192.22.33.188:5060 SIP/2.0
CSeq: 5950 NOTIFY
From: “SIPpTest” sip:19995551313@192.22.33.42;tag=1
To: sip:19995551212@192.22.33.188;tag=fa6b1828-e64b-41c2-8f71-6ae090ab309d
Call-ID: 1-650@192.17.0.2
Max-Forwards: 70
Via: SIP/2.0/UDP 192.22.33.42:5060;branch=z9hG4bKPj6ea9cf0f-1649-4cfd-9037-e7c4560ffcdc
Contact: “SIPpTest” sip:19995551313@192.22.33.42:5060;transport=udp;registering_acc=192_22_33_188
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY
Event: refer
Subscription-State: terminated;reason=noresource
Content-Type: message/sipfrag
Subject: Performance Test
Content-Length: 16

SIP/2.0 200 OK

4

shouldn’t a 200 OK come after the BYE?

Yes, you should receive a 200 OK after a BYE. And in this case you do. For instance for the first BYE (Call-ID: 30da62c5-00e5-444c-8fdf-1f8a625cdd07) the 200 OK is received immediately afterwards.

However what I am referring to is the sipfrag described in the NOTIFY. Upon a REFER an implicit subscription is setup. Each NOTIFY must contain a body of type “message/sipfrag”, which describes the status of the referred action. For instance, in the first NOTIFY in your log it has a body (sipfrag) of:

SIP/2.0 100 Trying

The second NOTIFY has a body (sipfrag) of:

SIP/2.0 200 OK

Which is the correct sequence. However, most endpoints wait to “hangup” upon receiving the NOTIFY with the sipfrag of 200 OK. I’ve seen a few initiate the “hangup” right after receiving the sipfrag 100 Trying. Which is what appears to be happening here. From the log sequence you can see that a BYE (and its associated 200 OK) were received before receiving the second NOTIFY with the sipfrag of 200 OK.

I’m not sure if upgrading will fix your problem, but in the past Asterisk has had issues with the particular scenario your log files are describing (receiving a BYE before the NOTIFY sipfrag 200 OK). Those particular problems were fixed, but it’s possible a path was missed.

Also, how should the subscribe get terminated?

The subscription is implicitly created by Asterisk in order to monitor progress for the REFER. It’s suppose to automatically be terminated once the REFER process has completed. In your case for some reason the SUBSCRIBE never gets terminated like it should.

If upgrading doesn’t fix it, then I would suggest creating an issue on the Asterisk issue tracker. If you need to create an issue and have never done so before please also check out the Asterisk Issues Guidelines wiki for help, and more information about submitting an issue.

5

Ok, we will look at upgrading. Again thanks for the help! It may be a moot point but the “transferee” 192.22.33.42 is not hanging up right after the 100 Trying. The “transfer target” 192.22.33.214 is the one that is hanging up per the sequence of the following spec.

https://tools.ietf.org/html/rfc5589#page-24

Perhaps I should ask this question…does Asterisk support the type of REFER diagrammed in “Figure 7: Attended Transfer Call Flow”?

1 Like
6

Perhaps I should ask this question…does Asterisk support the type of REFER diagrammed in “Figure 7: Attended Transfer Call Flow”?

Asterisk should support that call flow, yes. No matter what the subscription for the REFER should be terminated. What you are seeing is a bug.

If it still persists in the latest version then as I mentioned please create an issue on the tracker and attach a full debug log with the SIP trace of the failing scenario (see Collecting Debug Information for more on that). Also go ahead and include the link you gave here to the RFC and mention the Figure 7 diagram as the scenario that’s occurring.

Hopefully all that won’t be needed and upgrading will fix things.

Thanks!

7

Thank you so much! You have been very helpful!