REFER handling problem
Thomas de Rooij | CM.com
Thomas.deRooij at cm.com
Mon Jun 13 08:20:24 UTC 2022
Hi all,
I'm having trouble with Freeswitch handing a REFER scenario.
The following flow is from an actual call where 10.10.10.10 is a Freeswitch machine that should handle the REFER message:
222.22.222.222:5060 10.10.10.10:5060 10.10.10.11:5060 10.10.10.12:5060
──────────┬───────── ──────────┬───────── ──────────┬───────── ──────────┬─────────
│ INVITE (SDP) │ │ │
│ ──────────────────────────> │ │ │
+0.001396 │ 100 Trying │ │ │
│ <────────────────────────── │ │ │
+0.000845 │ 180 Ringing │ │ │
│ <────────────────────────── │ │ │
+0.003244 │ │ INVITE (SDP) │ │
│ │ ──────────────────────────> │ │
+0.005757 │ │ 100 Trying │ │
│ │ <────────────────────────── │ │
+0.115697 │ │ 200 OK (SDP) │ │
│ │ <────────────────────────── │ │
+0.020056 │ 200 OK (SDP) │ │ │
│ <────────────────────────── │ │ │
+0.095132 │ ACK │ │ │
│ ──────────────────────────> │ │ │
+0.000696 │ │ ACK │ │
│ │ ──────────────────────────> │ │
+1.901472 │ │ REFER │ │
│ │ <────────────────────────── │ │
+0.000528 │ │ 202 Accepted │ │
│ │ ──────────────────────────> │ │
+0.000105 │ │ NOTIFY │ │
│ │ ──────────────────────────> │ │
+0.000198 │ INVITE (SDP) │ │ │
│ <────────────────────────── │ │ │
+0.003230 │ │ 200 OK │ │
│ │ <────────────────────────── │ │
+0.000296 │ │ BYE │ │
│ │ ──────────────────────────> │ │
+0.001659 │ 100 Trying │ │ │
│ ──────────────────────────> │ │ │
+0.019175 │ 200 OK (SDP) │ │ │
│ ──────────────────────────> │ │ │
+0.002738 │ ACK │ │ │
│ <────────────────────────── │ │ │
+0.000287 │ INVITE (SDP) │ │ │
│ <────────────────────────── │ │ │
+0.005444 │ 100 Trying │ │ │
│ ──────────────────────────> │ │ │
+0.021372 │ │ INVITE (SDP) │
│ │ ────────────────────────────────────────────────────────> │
+0.007074 │ │ 100 Trying │
│ │ <──────────────────────────────────────────────────────── │
+0.006919 │ │ 200 OK (SDP) │
│ │ <──────────────────────────────────────────────────────── │
+0.036307 │ 200 OK (SDP) │ │ │
│ ──────────────────────────> │ │ │
+0.005278 │ ACK │ │ │
│ <────────────────────────── │ │ │
+0.179349 │ INVITE │ │ │
│ <────────────────────────── │ │ │
+0.003849 │ 100 Trying │ │ │
│ ──────────────────────────> │ │ │
+0.002510 │ 200 OK (SDP) │ │ │
│ ──────────────────────────> │ │ │
+0.007616 │ │ 200 OK │ │
│ │ <────────────────────────── │ │
+0.265244 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.227210 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+0.772969 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.227103 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+1.772828 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.228480 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+3.770628 │ │ 200 OK (SDP) │
│ │ <──────────────────────────────────────────────────────── │
+0.228179 │ 200 OK (SDP) │ │ │
│ ──────────────────────────> │ │ │
+3.772980 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.227158 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+3.773918 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.225763 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+3.775424 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.224982 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+3.776155 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.223281 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+3.776986 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.223503 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+3.777505 │ │ 200 OK (SDP) │
│ │ <<<────────────────────────────────────────────────────── │
+0.223478 │ 200 OK (SDP) │ │ │
│ ────────────────────────>>> │ │ │
+0.271627 │ │ BYE │
│ │ <──────────────────────────────────────────────────────── │
+0.000958 │ │ 200 OK │
│ │ ────────────────────────────────────────────────────────> │
+0.000117 │ │ ACK │
│ │ ────────────────────────────────────────────────────────> │
+0.020239 │ BYE │ │ │
│ <────────────────────────── │ │ │
+0.008562 │ 200 OK │ │ │
│ ──────────────────────────> │ │ │
+0.000251 │ ACK │ │ │
│ <────────────────────────── │ │ │
As you can see the far end sends a BYE because of an ACK timeout.
The thing is, I can see in the Freeswitch debug logs that the 200 OK, from both legs, is received by Freeswitch (logs after the last 200 OK from the A leg):
tport.c:3052 tport_deliver() tport_deliver(0x7f17c00043d0): msg 0x7f17c0074950 (840 bytes) from udp/222.22.222.222:5060/sip next=(nil)
nta.c:3370 agent_recv_response() nta: received 200 OK for INVITE (52572546)
nta.c:3437 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9716 outgoing_duplicate() nta: 200 OK is duplicate response to 52572546 INVITE
nta.c:9723 outgoing_duplicate() Via: SIP/2.0/UDP 10.10.10.10 ;branch=z9hG4bKprBXUe0Xyc7eH
nta.c:7236 _nta_incoming_timer() nta: timer J fired, terminate 202 response
nta.c:5896 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f17e93b3c10)
nta.c:7265 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/9 term, 1/9 free
nta.c:1308 agent_timer() nta: timer set next to 20 ms
nta.c:7236 _nta_incoming_timer() nta: timer J fired, terminate 200 response
nta.c:5896 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f17e93b3c10)
nta.c:7265 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/8 term, 1/8 free
nta.c:1308 agent_timer() nta: timer set next to 5 ms
nta.c:9221 outgoing_timer_dk() nta: timer D fired, terminate INVITE (52572544)
nta.c:8893 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f17e93b3d00)
nta.c:9040 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/2 tout, 1/4 term, 1/6 free
nta.c:1308 agent_timer() nta: timer set next to 2 ms
nta.c:9102 outgoing_timer_bf() nta: timer F fired, terminating ACK (52572544)
nta.c:8893 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f17e93b3d00)
nta.c:9040 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/2 tout, 0/3 term, 1/5 free
nta.c:1308 agent_timer() nta: timer set next to 41 ms
In the end, after the 200 OK on the BYE transaction, the ACK that should follow the 200 OK for the INVITE transaction is sent.
nta.c:6868 incoming_reply() nta: sent 200 OK for BYE (52572561)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f17c0019a70): removing session usage
soa.c:1730 soa_activate() soa_activate(static::0x7f17c000e670, (nil)) called
nta.c:2707 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3286 tport_tsend() tport_tsend(0x7f17c00043d0) tpn = */10.10.10.12:5060
tport.c:4075 tport_resolve() tport_resolve addrinfo = 10.10.10.12:5060
tport.c:4709 tport_by_addrinfo() tport_by_addrinfo(0x7f17c00043d0): not found by name */10.10.10.12:5060
tport.c:3623 tport_vsend() tport_vsend(0x7f17c00043d0): 498 bytes of 498 to udp/10.10.10.12:5060
tport.c:3521 tport_send_msg() tport_vsend returned 498
2022-06-03 12:38:26.009764 [DEBUG] switch_core_state_machine.c:848 (sofia/Default/2398) Callstate Change ACTIVE -> HANGUP
send 498 bytes to udp/[10.10.10.12]:5060 at 12:38:26.027864:
------------------------------------------------------------------------
ACK sip:2398 at 10.10.10.50:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.10.10.10;rport;branch=z9hG4bKQ14NX9g1UNX1c
Route: <sip:10.10.10.12;lr=on;ftag=X8gN4t41XD8Dc;did=56a.da01>
Max-Forwards: 70
From: "31761234567" <sip:31761234567 at 10.10.10.10>;tag=X8gN4t41XD8Dc
To: <sip:2398 at 10.10.10.12:5060>;tag=F6g6a1UDjmBXB
Call-ID: 57ac2def-8718-4ea9-a70c-74c4acc3ab49
CSeq: 52572545 ACK
Contact: <sip:gw+fs at 10.10.10.10:5060;transport=udp;gw=fs>
Content-Length: 0
nta.c:8390 outgoing_send() nta: sent ACK (52572545) to */10.10.10.12:5060
nta.c:8816 outgoing_free() nta: outgoing_free(0x7f17c0016ef0)
nua_stack.c:301 nua_stack_event() nua(0x7f17c0019a70): event r_invite 481 Call/Transaction Does Not Exist
nua_session.c:4140 signal_call_state_change() nua(0x7f17c0019a70): call state changed: completing -> terminated
nua_stack.c:301 nua_stack_event() nua(0x7f17c0019a70): event i_state 200 Early Session Terminated
nua_stack.c:301 nua_stack_event() nua(0x7f17c0019a70): event i_terminated 200 Early Session Terminated
soa.c:356 soa_destroy() soa_destroy(static::0x7f17c000e670) called
nta.c:4541 nta_leg_destroy() nta_leg_destroy(0x7f17c0021720)
nua_stack.c:599 nua_stack_signal() nua(0x7f17c0019a70): recv signal r_destroy
nta.c:4541 nta_leg_destroy() nta_leg_destroy((nil))
2022-06-03 12:38:26.009764 [DEBUG] switch_core_state_machine.c:850 (sofia/Default/2398) State HANGUP
From the logs I can't figure out why the ACK is only sent AFTER the BYE and not immediately after the first 200 OK.
Any help would be greatly appreciated.
Kind regard,
Thomas
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20220613/de14ddab/attachment-0001.html>
More information about the FreeSWITCH-users
mailing list