Asterisk22 Refer notify behaviour

TaMh · June 27, 2025, 10:30am

Hello,
I have problem is PJSIP Refer, notifies arrive fast (always containing 100 trying then 200OK).
and even before the other call established.
A Calls B
A REFERS B To C

1st leg
10.3.60.135:5060 10.3.60.205:5060 ──────────┬───────── ──────────┬───────── │ si
15:05:41.087055 │ INVITE (SDP) │
+0.005086 │ ──────────────────────────> │
15:05:41.092141 │ 401 Unauthorized │
+0.000539 │ <────────────────────────── │
15:05:41.092680 │ ACK │
+0.038407 │ ──────────────────────────> │
15:05:41.131087 │ INVITE (SDP) │
+0.005227 │ ──────────────────────────> │
15:05:41.136314 │ 100 Trying │
+0.180588 │ <────────────────────────── │
15:05:41.316902 │ 180 Ringing │
+1.138322 │ <────────────────────────── │
15:05:42.455224 │ 200 OK (SDP) │
+0.045571 │ <────────────────────────── │
15:05:42.500795 │ ACK │
+0.000546 │ ──────────────────────────> │
15:05:42.501341 │ ACK │
+7.173069 │ ────────────────────────>>> │
15:05:49.674410 │ REFER │
+0.000564 │ ──────────────────────────> │
15:05:49.674974 │ 202 Accepted │
+0.000585 │ <────────────────────────── │
15:05:49.675559 │ NOTIFY │
+0.000160 │ <────────────────────────── │
15:05:49.675719 │ NOTIFY │
+0.040009 │ <────────────────────────── │
15:05:49.715728 │ 200 OK │
+0.001244 │ ──────────────────────────> │
15:05:49.716972 │ 200 OK │
+0.008174 │ ──────────────────────────> │
15:05:49.725146 │ BYE │
+0.000499 │ ──────────────────────────> │
15:05:49.725645 │ 200 OK │
│ <────────────────────────── │
│ │
2nd
15:05:41.268998 │ INVITE (SDP) │
+0.001806 │ ──────────────────────────> │
15:05:41.270804 │ 100 trying – your call is │
+0.043874 │ <────────────────────────── │
15:05:41.314678 │ 180 Ringing │
+0.000835 │ <────────────────────────── │
15:05:41.315513 │ 180 Ringing │
+1.135833 │ <<<──────────────────────── │
15:05:42.451346 │ 200 OK (SDP) │
+0.000647 │ <────────────────────────── │
15:05:42.451993 │ ACK │
+7.338324 │ ──────────────────────────> │
15:05:49.790317 │ UPDATE │
+0.049221 │ ──────────────────────────> │
15:05:49.839538 │ 200 OK │
+2.857047 │ <────────────────────────── │
15:05:52.696585 │ BYE │
+0.047316 │ ──────────────────────────> │
15:05:52.743901 │ 200 OK │
│ <────────────────────────── │
│ │
3rd
15:05:49.789477 │ INVITE (SDP) │
+0.001807 │ ──────────────────────────> │
15:05:49.791284 │ 100 trying – your call is │
+0.050274 │ <────────────────────────── │
15:05:49.841558 │ 180 Ringing │
+2.849666 │ <────────────────────────── │
15:05:52.691224 │ 486 Busy Here │
+0.000352 │ <────────────────────────── │
15:05:52.691576 │ ACK │
│ ──────────────────────────> │
│ │

jcolp · June 27, 2025, 10:32am

You need to show the actual Asterisk console log and provide the configuration, because the NOTIFY requests from Asterisk convey whether the transferred party has reached somewhere in the dialplan that would be considered answered - not whether it has called another party and they have answered. There is also configuration to disable this and immediately say it has completed.

david551 · June 27, 2025, 10:41am

To add to Joshua’s reply, there seems to be a common misapprehension that dialplans should start with Answer().

TaMh · June 27, 2025, 12:20pm

As you can see in the logs Even Thought the channel status ended up busy I got the notify containg 200OK
– Executing [301@TestTakwa:1] NoOp(“PJSIP/ta.mh.Test-00000073”, "exten 301) ") in new stack
– Executing [301@TestTakwa:2] Dial(“PJSIP/ta.mh.Test-00000073”, “PJSIP/ne.fa.Test,20,tT”) in new stack
– Called PJSIP/ne.fa.Test
– PJSIP/ne.fa.Test-00000074 is ringing
> 0x7ff61461e380 – Strict RTP learning after remote address set to: x.x.x.x:27718
– PJSIP/ne.fa.Test-00000074 answered PJSIP/ta.mh.Test-00000073
> 0x7ff6145e37c0 – Strict RTP learning after remote address set to: x.x.x.x:27700
– Channel PJSIP/ne.fa.Test-00000074 joined ‘simple_bridge’ basic-bridge
– Channel PJSIP/ta.mh.Test-00000073 joined ‘simple_bridge’ basic-bridge
> 0x7ff61461e380 – Strict RTP switching to RTP target address x.x.x.x:27718 as source
> 0x7ff6145e37c0 – Strict RTP switching to RTP target address x.x.x.x:27700 as source
> 0x7ff61461e380 – Strict RTP learning complete - Locking on source address x.x.x.x:27718
> 0x7ff6145e37c0 – Strict RTP learning complete - Locking on source address x.x.x.x:27700
– Channel PJSIP/ta.mh.Test-00000073 left ‘simple_bridge’ basic-bridge
== Spawn extension (TestTakwa, 301, 2) exited non-zero on ‘PJSIP/ta.mh.Test-00000073’
– Channel PJSIP/ne.fa.Test-00000074 left ‘simple_bridge’ basic-bridge
– Executing [302@TestTakwa:1] NoOp(“PJSIP/ne.fa.Test-00000074”, “exten 302”) in new stack
– Executing [302@TestTakwa:2] Dial(“PJSIP/ne.fa.Test-00000074”, “PJSIP/fa.zr.Test,20,tT”) in new stack
– Called PJSIP/fa.zr.Test
– PJSIP/fa.zr.Test-00000075 is ringing
– PJSIP/fa.zr.Test-00000075 is ringing
== Everyone is busy/congested at this time (1:1/0/0)
– Auto fallthrough, channel ‘PJSIP/ne.fa.Test-00000074’ status is ‘BUSY’

jcolp · June 27, 2025, 12:57pm

You did not provide the PJSIP configuration, and you didn’t originally provide the actual contents of the NOTIFY requests.

TaMh · June 27, 2025, 1:35pm

PJSIP Same for all endpoints
100rel : no
accept_multiple_sdp_answers : false
accountcode :
acl :
aggregate_mwi : true
allow : (codec2|g723|ulaw|alaw|gsm|g726|g726aal2|adpcm|slin|slin12|slin16|slin24|slin32|slin44|slin48|slin96|slin192|lpc10|g729|speex|speex16|speex32|ilbc|g722|siren7|siren14|g719|opus|jpeg|png|h261|h263|h263p|h264|h265|mpeg4|vp8|vp9|red|t140|t38|silk8|silk12|silk16|silk24)
allow_overlap : true
allow_subscribe : true
allow_transfer : true
allow_unauthenticated_options : false
aors : ta.mh.Test
asymmetric_rtp_codec : false
auth : ta.mh.Test
bind_rtp_to_media_address : false
bundle : false
call_group :
callerid :
callerid_privacy : allowed_not_screened
callerid_tag :
codec_prefs_incoming_answer : prefer:pending, operation:intersect, keep:all, transcode:allow
codec_prefs_incoming_offer : prefer:pending, operation:intersect, keep:all, transcode:allow
codec_prefs_outgoing_answer : prefer:pending, operation:intersect, keep:all, transcode:allow
codec_prefs_outgoing_offer : prefer:pending, operation:union, keep:all, transcode:allow
connected_line_method : invite
contact_acl :
context : Test
cos_audio : 0
cos_video : 0
device_state_busy_at : 0
direct_media : false
direct_media_glare_mitigation : none
direct_media_method : invite
disable_direct_media_on_nat : true
dtls_auto_generate_cert : No
dtls_ca_file :
dtls_ca_path :
dtls_cert_file :
dtls_cipher :
dtls_fingerprint : SHA-256
dtls_private_key :
dtls_rekey : 0
dtls_setup : active
dtls_verify : No
dtmf_mode : rfc4733
fax_detect : false
fax_detect_timeout : 0
follow_early_media_fork : true
force_avp : false
force_rport : true
from_domain :
from_user :
g726_non_standard : false
geoloc_incoming_call_profile :
geoloc_outgoing_call_profile :
ice_support : false
identify_by : username,ip
ignore_183_without_sdp : false
inband_progress : false
incoming_call_offer_pref : local
incoming_mwi_mailbox :
language :
mailboxes :
max_audio_streams : 1
max_video_streams : 1
media_address :
media_encryption : no
media_encryption_optimistic : false
media_use_received_transport : false
message_context :
moh_passthrough : false
moh_suggest : default
mwi_from_user :
mwi_subscribe_replaces_unsolicited : no
named_call_group :
named_pickup_group :
notify_early_inuse_ringing : false
one_touch_recording : false
outbound_auth :
outbound_proxy :
outgoing_call_offer_pref : remote_merge
overlap_context :
pickup_group :
preferred_codec_only : false
record_off_feature : automixmon
record_on_feature : automixmon
refer_blind_progress : false
rewrite_contact : false
rpid_immediate : false
rtcp_mux : false
rtp_engine : asterisk
rtp_ipv6 : false
rtp_keepalive : 0
rtp_symmetric : false
rtp_timeout : 0
rtp_timeout_hold : 0
sdp_owner : ASTERISK
sdp_session : ASTERISK PBX
security_negotiation : no
send_aoc : false
send_connected_line : yes
send_diversion : true
send_history_info : false
send_pai : true
send_rpid : true
set_var :
srtp_tag_32 : false
stir_shaken : no
stir_shaken_profile :
sub_min_expiry : 0
subscribe_context :
suppress_moh_on_sendonly : false
suppress_q850_reason_headers : false
t38_bind_udptl_to_media_address : false
t38_udptl : false
t38_udptl_ec : none
t38_udptl_ipv6 : false
t38_udptl_maxdatagram : 0
t38_udptl_nat : false
tenantid :
timers : yes
timers_min_se : 90
timers_sess_expires : 1800
tone_zone : fr
tos_audio : 0
tos_video : 0
transport : transport-udp
trust_connected_line : yes
trust_id_inbound : false
trust_id_outbound : true
use_avpf : false
use_ptime : false
user_eq_phone : false
voicemail_extension :
webrtc : no

Notify Contents:
1st notify
Content-Type: message/sipfrag;version=2.0
Content-Length: 20

SIP/2.0 100 Trying
2nd notify
Content-Type: message/sipfrag;version=2.0
Content-Length: 16

SIP/2.0 200 OK

jcolp · June 27, 2025, 1:39pm

Support for blind progress has been disabled[1].

[1] res_pjsip - Asterisk Documentation

TaMh · June 27, 2025, 1:48pm

I changed refer_blind_progress to true
the only thing that changed is that i get 3 notifies instead of 2
15:42:40.964524 │ REFER │
+0.000813 │ ──────────────────────────> │
15:42:40.965337 │ 202 Accepted │
+0.053739 │ <────────────────────────── │
15:42:41.019076 │ NOTIFY │
+0.000190 │ <────────────────────────── │
15:42:41.019266 │ NOTIFY │
+0.019952 │ <────────────────────────── │
15:42:41.039218 │ NOTIFY │
+0.020277 │ <────────────────────────── │

that none of them really reflects the other leg.
1st:
Content-Type: message/sipfrag;version=2.0
Content-Length: 20

SIP/2.0 100 Trying

2nd:
Content-Type: message/sipfrag;version=2.0
Content-Length: 21

SIP/2.0 180 Ringing

3rd:
Content-Type: message/sipfrag;version=2.0
Content-Length: 16

SIP/2.0 200 OK

this is the console output.

– Executing [301@TestTakwa:1] NoOp(“PJSIP/ta.mh.Test-00000079”, “exten 301)”) in new stack
– Executing [301@TestTakwa:2] Dial(“PJSIP/ta.mh.Test-00000079”, “PJSIP/ne.fa.Test,20,tT”) in new stack
– Called PJSIP/ne.fa.Test
– PJSIP/ne.fa.Test-0000007a is ringing
> 0x7ff615845eb0 – Strict RTP learning after remote address set to: x.x.x.x:28338
– PJSIP/ne.fa.Test-0000007a answered PJSIP/ta.mh.Test-00000079
> 0x7ff615834820 – Strict RTP learning after remote address set to: x.x.x.x:28318
– Channel PJSIP/ne.fa.Test-0000007a joined ‘simple_bridge’ basic-bridge
– Channel PJSIP/ta.mh.Test-00000079 joined ‘simple_bridge’ basic-bridge
> 0x7ff615845eb0 – Strict RTP switching to RTP target address x.x.x.x:28338 as source
> 0x7ff615834820 – Strict RTP switching to RTP target address x.x.x.x:28318 as source
> 0x7ff615845eb0 – Strict RTP learning complete - Locking on source address x.x.x.x:28338
> 0x7ff615834820 – Strict RTP learning complete - Locking on source address x.x.x.x:28318
– Channel PJSIP/ta.mh.Test-00000079 left ‘simple_bridge’ basic-bridge
– Channel PJSIP/ne.fa.Test-0000007a left ‘simple_bridge’ basic-bridge
– Executing [302@TestTakwa:1] NoOp(“PJSIP/ne.fa.Test-0000007a”, “exten 302”) in new stack
– Executing [302@TestTakwa:2] Dial(“PJSIP/ne.fa.Test-0000007a”, “PJSIP/fa.zr.Test,20,tT”) in new stack
== Spawn extension (TestTakwa, 301, 2) exited non-zero on ‘PJSIP/ta.mh.Test-00000079’
– Called PJSIP/fa.zr.Test
– PJSIP/fa.zr.Test-0000007b is ringing
== Everyone is busy/congested at this time (1:1/0/0)
– Auto fallthrough, channel ‘PJSIP/ne.fa.Test-0000007a’ status is ‘BUSY’

can you please see what wrong

jcolp · June 27, 2025, 2:01pm

Not really, I don’t know why it’s behaving like that - turning on core debug[1] would probably show it. I have a suspicion, though, that the way you want things to work won’t happen all the time though regardless. What is the end goal here/reason?

[1] Collecting Debug Information - Asterisk Documentation

TaMh · June 27, 2025, 2:10pm

I took some logs earlier

what i want is when refferred to party is busy or unavailable, the first call continues and when the channel is Answered the first call hung up. i was hoping to use the refer notify system for that.

[Jun 27 11:39:28] DEBUG[2062211]: res_pjsip/pjsip_distributor.c:499 distributor: Searching for serializer associated with dialog dlg0x7ff650e8c0e8 for Request msg REFER/cseq=23018 (rdata0x7ff650f661b8)

[Jun 27 11:39:28] DEBUG[2062211]: res_pjsip/pjsip_distributor.c:507 distributor: Found serializer pjsip/distributor-000000c8 associated with dialog dlg0x7ff650e8c0e8

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4306 session_on_rx_request: PJSIP/ta.mh.Test-00000045 Request: REFER

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4325 session_on_rx_request: PJSIP/ta.mh.Test-00000045 Handled request REFER ? yes

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4831 session_inv_on_tsx_state_changed: PJSIP/ta.mh.Test-00000045 TSX State: Trying Inv State: CONFIRMED

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4496 handle_incoming_request: PJSIP/ta.mh.Test-00000045: Method is REFER

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_refer.c:407 refer_progress_alloc: Created progress monitor ‘0x7ff6880e97e8’ for transfer occurring from channel ‘PJSIP/ta.mh.Test-00000045’ and endpoint ‘ta.mh.Test’

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_refer.c:445 refer_progress_alloc: Accepting REFER request for progress monitor ‘0x7ff650bf22b0’

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4597 handle_outgoing_response: PJSIP/ta.mh.Test-00000045: Method is REFER, Response is 202 Accepted

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4616 handle_outgoing_response: PJSIP/ta.mh.Test-00000045

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to x.x.x.x:5060 (this may be re-written again later)

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4831 session_inv_on_tsx_state_changed: PJSIP/ta.mh.Test-00000045 TSX State: Completed Inv State: CONFIRMED

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:5020 session_inv_on_tsx_state_changed: Nothing delayed

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4251 session_on_tsx_state: PJSIP/ta.mh.Test-00000045 TSX State: Completed Inv State: CONFIRMED

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4255 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (alaw)>

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4260 session_on_tsx_state:

[Jun 27 11:39:28] DEBUG[2080382]: parking/parking_bridge_features.c:304 parking_is_exten_park: Checking if 302@TestTakwa is a parking exten

[Jun 27 11:39:28] DEBUG[2080382]: bridge.c:1964 ast_bridge_remove: Removing channel PJSIP/ta.mh.Test-00000045 from bridge 3cb48900-0d8b-4ccd-b08d-5be8fb6786ac

[Jun 27 11:39:28] DEBUG[2080382]: bridge_channel.c:299 ast_bridge_channel_leave_bridge_nolock: Setting 0x7ff68400d570(PJSIP/ta.mh.Test-00000045) state from:0 to:2

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4506 handle_incoming_request: PJSIP/ta.mh.Test-00000045

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:5020 session_inv_on_tsx_state_changed: Nothing delayed

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4251 session_on_tsx_state: PJSIP/ta.mh.Test-00000045 TSX State: Completed Inv State: CONFIRMED

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4255 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (alaw)>

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4260 session_on_tsx_state:

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_refer.c:165 refer_progress_notify: Sending initial 100 Trying NOTIFY for progress monitor ‘0x7ff650bf22b0’

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip/pjsip_resolver.c:475 sip_resolve: Performing SIP DNS resolution of target ‘x.x.x.x’

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip/pjsip_resolver.c:502 sip_resolve: Transport type for target ‘x.x.x.x’ is ‘UDP transport’

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip/pjsip_resolver.c:523 sip_resolve: Target ‘x.x.x.x’ is an IP address, skipping resolution

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip/pjsip_message_filter.c:298 filter_on_tx_message: Re-wrote Contact URI host/port to x.x.x.x:5060 (this may be re-written again later)

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4831 session_inv_on_tsx_state_changed: PJSIP/ta.mh.Test-00000045 TSX State: Calling Inv State: CONFIRMED

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:5020 session_inv_on_tsx_state_changed: Nothing delayed

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4251 session_on_tsx_state: PJSIP/ta.mh.Test-00000045 TSX State: Calling Inv State: CONFIRMED

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4255 session_on_tsx_state: Topology: Pending: (null topology) Active: <0:audio-0:audio:sendrecv (alaw)>

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_session.c:4260 session_on_tsx_state:

[Jun 27 11:39:28] DEBUG[2080382]: res_pjsip_refer.c:173 refer_progress_notify: Sending NOTIFY with response ‘200’ and state ‘5’ on subscription ‘0x7ff650e98220’ and progress monitor ‘0x7ff650bf22b0’