tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb1740454e0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb1740454e0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb1740454e0) msg 0x7fb174057f50 from (udp/192.168.10.185:5060) has 518 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb1740454e0): msg 0x7fb174057f50 (518 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received OPTIONS sip:192.168.10.185:5060 SIP/2.0 (CSeq 598435) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:192.168.10.185:5060 with contact freeswitch@freeswitch-1> nta.c:3085 agent_recv_request() nta: OPTIONS (598435) going to a default leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> nua_stack.c:899 nh_create() nua: nh_create: entering freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb1740509b0, 0x7fb174053d40, 0x7fb1740538b0) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb174058a30, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb1740538b0): event i_options 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb1740538b0): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb174058a30, ...) called freeswitch@freeswitch-1> soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0x7fb174058a30, [(nil)], [0x7fb13ca9fb48], [0x7fb13ca9fb44]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb1740454e0) tpn = UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb1740538b0): sent signal r_respond freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb1740454e0): not found by name UDP/10.0.0.56:5060 freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb1740538b0): sent signal r_destroy freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb1740454e0): 509 bytes of 509 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 509 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for OPTIONS (598435) freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb1740538b0): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb174058a30) called freeswitch@freeswitch-1> nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb13cadeb50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 30001 ms freeswitch@freeswitch-1> nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb13ca9fb50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 30000 ms freeswitch@freeswitch-1> nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb1b9cc7b50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free freeswitch@freeswitch-1> nta.c:1289 agent_timer() nta: timer not set freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:657 nua_options() nua: nua_options: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb19003cf00): sent signal r_options freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb19003cf00): recv signal r_options freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb18404a090, 0x7fb184192250, 0x7fb19003cf00) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1840520a0, ...) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1840520a0, ...) called freeswitch@freeswitch-1> nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb184085d40) tpn = udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb184085d40): not found by name udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb184085d40): 489 bytes of 489 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 489 freeswitch@freeswitch-1> nta.c:8310 outgoing_send() nta: sent OPTIONS (55916313) to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4164 tport_pend() tport_pend(0x7fb184085d40): pending 0x7fb1840702c0 for udp/192.168.10.186:5060 (already 0) freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 1000 ms freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb184085d40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb184085d40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb184085d40) msg 0x7fb184077fc0 from (udp/192.168.10.186:5060) has 558 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb184085d40): msg 0x7fb184077fc0 (558 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:3299 agent_recv_response() nta: received 500 Server Internal Error for OPTIONS (55916313) freeswitch@freeswitch-1> nta.c:3366 agent_recv_response() nta: 500 Server Internal Error is going to a transaction freeswitch@freeswitch-1> nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 147.543 ms freeswitch@freeswitch-1> tport.c:4226 tport_release() tport_release(0x7fb184085d40): 0x7fb1840702c0 by 0x7fb184052430 with 0x7fb184077fc0 freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb19003cf00): event r_options 500 Server Internal Error freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb19003cf00): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb1840520a0) called freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb19003cf00): sent signal r_destroy freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:657 nua_options() nua: nua_options: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb180051d10): sent signal r_options freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb180051d10): recv signal r_options freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb1740509b0, 0x7fb174053d40, 0x7fb180051d10) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1740535c0, ...) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1740535c0, ...) called freeswitch@freeswitch-1> nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb1740454e0) tpn = udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb1740454e0): not found by name udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb1740454e0): 489 bytes of 489 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 489 freeswitch@freeswitch-1> nta.c:8310 outgoing_send() nta: sent OPTIONS (55916309) to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4164 tport_pend() tport_pend(0x7fb1740454e0): pending 0x7fb17405c600 for udp/192.168.10.185:5060 (already 0) freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 1000 ms freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb1740454e0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb1740454e0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb1740454e0) msg 0x7fb1740494e0 from (udp/192.168.10.185:5060) has 545 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb1740454e0): msg 0x7fb1740494e0 (545 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (55916309) freeswitch@freeswitch-1> nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction freeswitch@freeswitch-1> nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 148.074 ms freeswitch@freeswitch-1> tport.c:4226 tport_release() tport_release(0x7fb1740454e0): 0x7fb17405c600 by 0x7fb1740538b0 with 0x7fb1740494e0 freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb180051d10): event r_options 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb180051d10): sent signal r_destroy freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb180051d10): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb1740535c0) called freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 4147 ms freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 4148 ms freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb170005ea0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb170005ea0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb170005ea0) msg 0x7fb170015610 from (udp/192.168.10.81:5060) has 939 bytes, veclen = 1 freeswitch@freeswitch-1> recv 939 bytes from udp/[192.168.56.190]:5060 at 17:03:56.378884: ------------------------------------------------------------------------ INVITE sip:+880022955@192.168.10.81 SIP/2.0 Via: SIP/2.0/UDP 192.168.56.190:5060;branch=z9hG4bK00d6417a6221ed11921ef04c14d7e9d8;rport From: "+210058571" ;tag=3901970572 To: Call-ID: 00D6417A-6221-ED11-921D-F04C14D7E9D8@192.168.56.190 CSeq: 3 INVITE Contact: Content-Type: application/sdp Allow: INVITE, ACK, BYE, CANCEL, INFO, MESSAGE, NOTIFY, OPTIONS, REFER, UPDATE, PRACK Max-Forwards: 70 User-Agent: PhonerLite 2.76 Session-Expires: 1800 Supported: 100rel, replaces, from-change, timer P-Preferred-Identity: Content-Length: 252 v=0 o=- 2398062351 1 IN IP4 192.168.56.190 s=PhonerLite 2.76 c=IN IP4 192.168.56.190 t=0 0 m=audio 5062 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ssrc:455652063 a=sendrecv freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb170005ea0): msg 0x7fb170015610 (939 bytes) from udp/192.168.56.190:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received INVITE sip:+880022955@192.168.10.81 SIP/2.0 (CSeq 3) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:+880022955@192.168.10.81 with contact freeswitch@freeswitch-1> nta.c:3085 agent_recv_request() nta: INVITE (3) going to a default leg freeswitch@freeswitch-1> nta.c:1350 set_timeout() nta: timer set to 200 ms freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> nua_stack.c:899 nh_create() nua: nh_create: entering freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb170002720, 0x7fb170001390, 0x7fb17000f6a0) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb170014ed0, ...) called freeswitch@freeswitch-1> nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fb170010d80) freeswitch@freeswitch-1> soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fb170014ed0) called freeswitch@freeswitch-1> soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fb170014ed0, (nil), 0x7fb17001dc0f, 252) called freeswitch@freeswitch-1> nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fb17000f6a0): adding session usage freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_invite 100 Trying freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb17000f6a0): call state changed: init -> received, received offer freeswitch@freeswitch-1> soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fb170014ed0, [0x7fb1b95d07a8], [0x7fb1b95d07b0], [(nil)]) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_state 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [NOTICE] switch_channel.c:1118 New Channel sofia/phonerlite_terminaison/+210058571@192.168.10.81 [cf4f323a-22f4-11ed-ac1f-bb9a32691bea] freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:585 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Running State Change CS_NEW (Cur 1 Tot 1339) freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] sofia.c:10243 sofia/phonerlite_terminaison/+210058571@192.168.10.81 receiving invite from 192.168.56.190:5060 version: 1.10.1-release git f999022 2019-08-20 16:54:04Z 64bit freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] sofia.c:10337 verifying acl "phonerlite" for ip/port 192.168.56.190:0. freeswitch@freeswitch-1> nua.c:610 nua_set_hparams() nua: nua_set_hparams: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb17000f6a0): sent signal r_set_params freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb17000f6a0): recv signal r_set_params freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb170014ed0, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event r_set_params 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] sofia.c:7290 Channel sofia/phonerlite_terminaison/+210058571@192.168.10.81 entering state [received][100] freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] sofia.c:7300 Remote SDP: v=0 o=- 2398062351 1 IN IP4 192.168.56.190 s=PhonerLite 2.76 c=IN IP4 192.168.56.190 t=0 0 m=audio 5062 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ssrc:455652063 freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] sofia.c:7703 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State Change CS_NEW -> CS_INIT freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:604 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State NEW freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:585 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Running State Change CS_INIT (Cur 1 Tot 1339) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:628 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State INIT freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_sofia.c:93 sofia/phonerlite_terminaison/+210058571@192.168.10.81 SOFIA INIT freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:40 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Standard INIT freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:48 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State Change CS_INIT -> CS_ROUTING freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:628 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State INIT going to sleep freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:585 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Running State Change CS_ROUTING (Cur 1 Tot 1339) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_channel.c:2332 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Callstate Change DOWN -> RINGING freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:644 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State ROUTING freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb17000f6a0): sent signal r_respond freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_sofia.c:154 sofia/phonerlite_terminaison/+210058571@192.168.10.81 SOFIA ROUTING freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:236 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Standard ROUTING freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb17000f6a0): recv signal r_respond 100 Trying freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb170014ed0, ...) called freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [INFO] mod_dialplan_xml.c:637 Processing +210058571 <+210058571>->+880022955 in context phonerlite2external freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb170005ea0) tpn = UDP/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb170005ea0): not found by name UDP/192.168.56.190:5060 freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 parsing [phonerlite2external->phonerlite2external] continue=false freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb170005ea0): 346 bytes of 346 to udp/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 346 freeswitch@freeswitch-1> send 346 bytes to udp/[192.168.56.190]:5060 at 17:03:56.380538: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.56.190:5060;branch=z9hG4bK00d6417a6221ed11921ef04c14d7e9d8;rport=5060 From: "+210058571" ;tag=3901970572 To: Call-ID: 00D6417A-6221-ED11-921D-F04C14D7E9D8@192.168.56.190 CSeq: 3 INVITE User-Agent: Freeswitch SBC Content-Length: 0 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (3) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (PASS) [phonerlite2external] ${sip_req_host}(192.168.10.81) =~ /192.168.10.81/ break=on-false freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (PASS) [phonerlite2external] destination_number(+880022955) =~ /^\+(\d{1,})$/ break=never freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_h_X-CarrierName) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_h_Allow-Events) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_rh_Allow-Events) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_ph_Allow-Events) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_rh_Allow) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_ph_Allow) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_h_Allow) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_bye_h_Allow) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_h_Supported) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_rh_Supported) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_ph_Supported) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_bye_h_Supported) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_h_Content-Disposition) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_h_Content-Disposition) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action unset(sip_h_Content-Disposition) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(sip_from_display= ) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(max_forwards=71) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(hangup_after_bridge=true) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(continue_on_fail=false) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(sip_h_Allow=INVITE, ACK, BYE, CANCEL, OPTIONS) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(sip_rh_Allow=INVITE, ACK, BYE, CANCEL, OPTIONS) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(sip_ph_Allow=INVITE, ACK, BYE, CANCEL, OPTIONS) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(sip_bye_h_Allow=INVITE, ACK, BYE, CANCEL, OPTIONS) freeswitch@freeswitch-1> Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action export(nolocal:sip_unhold_nosdp=true) freeswitch@freeswitch-1> |--- Dialplan: Processing recursive conditions level:1 [phonerlite2external_recur_1] require-nested=TRUE freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] ${sip_from_user}(+210058571) =~ /^(anonymous|Anonymous)/ break=never freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] caller_id_number(+210058571) =~ /^(0[1-9][0-9]{8})$/ break=never freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] caller_id_number(+210058571) =~ /^\+(?!33)(\d{1,})$/ break=never freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (PASS) [phonerlite2external_recur_1] caller_id_number(+210058571) =~ /^\+([1-9][0-9]{8})$/ break=never freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(effective_caller_id_number=0210058571) freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action set(effective_caller_id_name=0210058571) freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^\+9999([0-9]{10})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^\+9999([0-9]{9})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^(0[1-9][0-9]{8})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^(1[0-9]{1})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^([1-9][0-9]{2,3})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^(11[0-9]{4})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^00(\d{1,})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (FAIL) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^\+(?!33)(\d{1,})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Regex (PASS) [phonerlite2external_recur_1] destination_number(+880022955) =~ /^\+([1-9][0-9]{8})$/ break=on-true freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action bridge({sip_invite_domain=}sofia/gateway/${distributor(phonerlite_terminaison)}/0880022955) freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action transfer(480to503) freeswitch@freeswitch-1> |--- Dialplan: sofia/phonerlite_terminaison/+210058571@192.168.10.81 Action hangup(hangup_cause) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:287 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State Change CS_ROUTING -> CS_EXECUTE freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:644 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State ROUTING going to sleep freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:585 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Running State Change CS_EXECUTE (Cur 1 Tot 1339) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:651 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State EXECUTE freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_sofia.c:209 sofia/phonerlite_terminaison/+210058571@192.168.10.81 SOFIA EXECUTE freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:329 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Standard EXECUTE freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_h_X-CarrierName) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_h_X-CarrierName] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_h_Allow-Events) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_h_Allow-Events] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_rh_Allow-Events) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_rh_Allow-Events] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_ph_Allow-Events) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_ph_Allow-Events] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_rh_Allow) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_rh_Allow] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_ph_Allow) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_ph_Allow] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_h_Allow) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_h_Allow] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_bye_h_Allow) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_bye_h_Allow] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_h_Supported) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_h_Supported] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_rh_Supported) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_rh_Supported] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_ph_Supported) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_ph_Supported] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_bye_h_Supported) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_bye_h_Supported] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_h_Content-Disposition) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_h_Content-Disposition] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_h_Content-Disposition) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_h_Content-Disposition] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 unset(sip_h_Content-Disposition) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1817 UNSET [sip_h_Content-Disposition] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(sip_from_display= ) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [sip_from_display]=[ ] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(max_forwards=71) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [max_forwards]=[71] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(hangup_after_bridge=true) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [hangup_after_bridge]=[true] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(continue_on_fail=false) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [continue_on_fail]=[false] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(sip_h_Allow=INVITE, ACK, BYE, CANCEL, OPTIONS) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [sip_h_Allow]=[INVITE, ACK, BYE, CANCEL, OPTIONS] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(sip_rh_Allow=INVITE, ACK, BYE, CANCEL, OPTIONS) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [sip_rh_Allow]=[INVITE, ACK, BYE, CANCEL, OPTIONS] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(sip_ph_Allow=INVITE, ACK, BYE, CANCEL, OPTIONS) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [sip_ph_Allow]=[INVITE, ACK, BYE, CANCEL, OPTIONS] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(sip_bye_h_Allow=INVITE, ACK, BYE, CANCEL, OPTIONS) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [sip_bye_h_Allow]=[INVITE, ACK, BYE, CANCEL, OPTIONS] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 export(nolocal:sip_unhold_nosdp=true) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) (REMOTE ONLY) [sip_unhold_nosdp]=[true] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(effective_caller_id_number=0210058571) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [effective_caller_id_number]=[0210058571] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 set(effective_caller_id_name=0210058571) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_dptools.c:1672 SET sofia/phonerlite_terminaison/+210058571@192.168.10.81 [effective_caller_id_name]=[0210058571] freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 bridge({sip_invite_domain=}sofia/gateway/phonerlite/0880022955) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_channel.c:1264 sofia/phonerlite_terminaison/+210058571@192.168.10.81 EXPORTING[export_vars] [sip_unhold_nosdp]=[true] to event freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_ivr_originate.c:2212 Parsing global variables freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/0880022955 [cf503b58-22f4-11ed-ac3f-bb9a32691bea] freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_sofia.c:5096 (sofia/internal/0880022955) State Change CS_NEW -> CS_INIT freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/0880022955) Running State Change CS_INIT (Cur 2 Tot 1340) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/0880022955) State INIT freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_sofia.c:93 sofia/internal/0880022955 SOFIA INIT freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] sofia_glue.c:1618 sofia/internal/0880022955 sending invite version: 1.10.1-release git f999022 2019-08-20 16:54:04Z 64bit Local SDP: v=0 o=Freeswitch 1661250346 1661250347 IN IP4 192.168.9.88 s=Freeswitch c=IN IP4 192.168.9.88 t=0 0 m=audio 16690 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv freeswitch@freeswitch-1> nua.c:633 nua_invite() nua: nua_invite: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_invite freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:40 sofia/internal/0880022955 Standard INIT freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/0880022955) State Change CS_INIT -> CS_ROUTING freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/0880022955) State INIT going to sleep freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_invite freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb18c04e100, 0x7fb18c04eb90, 0x7fb16400fd40) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fb18c0c6090, (nil), 0x7fb16400c7cc, -1) called freeswitch@freeswitch-1> soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fb18c0c6090, (nil), 0x7fb16400c7cc, -1) called freeswitch@freeswitch-1> nua_dialog.c:338 nua_dialog_usage_add() nua(0x7fb16400fd40): adding session usage freeswitch@freeswitch-1> nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7fb18c0c2010) freeswitch@freeswitch-1> soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fb18c0c6090, 0) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb18c0c6090, soa_generate_offer): called freeswitch@freeswitch-1> soa_static.c:1189 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_offer): generating local description freeswitch@freeswitch-1> soa_static.c:1217 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_offer): upgrade with local description freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb1ba4419b0, (nil), ""): called freeswitch@freeswitch-1> soa_static.c:1446 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_offer): storing local description freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [(nil)], [0x7fb1ba443ae8], [0x7fb1ba443ae4]) called freeswitch@freeswitch-1> nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/0880022955) Running State Change CS_ROUTING (Cur 2 Tot 1340) freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = */192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name */192.168.9.215:5060 freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/0880022955) State ROUTING freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] mod_sofia.c:154 sofia/internal/0880022955 SOFIA ROUTING freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/0880022955) State Change CS_ROUTING -> CS_CONSUME_MEDIA freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/0880022955) State ROUTING going to sleep freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/0880022955) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 1340) freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 946 bytes of 946 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 946 freeswitch@freeswitch-1> send 946 bytes to udp/[192.168.9.215]:5060 at 17:03:56.386932: ------------------------------------------------------------------------ INVITE sip:0880022955@192.168.9.215 SIP/2.0 Via: SIP/2.0/UDP 192.168.9.88;rport;branch=z9hG4bKa6H6S2j6X5rFc Max-Forwards: 70 From: "0210058571" ;tag=2NKy5KmgUUrgB To: Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 56079726 INVITE Contact: User-Agent: Freeswitch SBC Allow: INVITE, ACK, BYE, CANCEL, OPTIONS Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Privacy: none Content-Type: application/sdp Content-Disposition: session Content-Length: 240 P-Asserted-Identity: "0210058571" v=0 o=Freeswitch 1661250346 1661250347 IN IP4 192.168.9.88 s=Freeswitch c=IN IP4 192.168.9.88 t=0 0 m=audio 16690 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 freeswitch@freeswitch-1> nta.c:8310 outgoing_send() nta: sent INVITE (56079726) to */192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4164 tport_pend() tport_pend(0x7fb18c050b40): pending 0x7fb18c056430 for udp/192.168.9.88:5060 (already 0) freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/0880022955) State CONSUME_MEDIA freeswitch@freeswitch-1> nta.c:1350 set_timeout() nta: timer set to 32000 ms freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/0880022955) State CONSUME_MEDIA going to sleep freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 1000 ms freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb16400fd40): call state changed: init -> calling, sent offer freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [0x7fb1ba443ac8], [0x7fb1ba443ad0], [(nil)]) called freeswitch@freeswitch-1> nua_stack.c:269 nua_stack_event() nua(0x7fb16400fd40): event i_state INVITE sent freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.374675 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [calling][0] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c067b90 from (udp/192.168.9.88:5060) has 365 bytes, veclen = 1 freeswitch@freeswitch-1> recv 365 bytes from udp/[192.168.9.215]:5060 at 17:03:56.414719: ------------------------------------------------------------------------ SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 192.168.9.88;rport=5060;branch=z9hG4bKa6H6S2j6X5rFc;received=192.168.9.88 From: "0210058571" ;tag=2NKy5KmgUUrgB To: Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 56079726 INVITE Server: Freeswitch (2.0) Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c067b90 (365 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:3299 agent_recv_response() nta: received 100 trying -- your call is important to us for INVITE (56079726) freeswitch@freeswitch-1> nta.c:3366 agent_recv_response() nta: 100 trying -- your call is important to us is going to a transaction freeswitch@freeswitch-1> nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 27.854 ms freeswitch@freeswitch-1> tport.c:4226 tport_release() tport_release(0x7fb18c050b40): 0x7fb18c056430 by 0x7fb18c08e8b0 with 0x7fb18c067b90 (preliminary) freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c063cc0 from (udp/192.168.9.88:5060) has 583 bytes, veclen = 1 freeswitch@freeswitch-1> recv 583 bytes from udp/[192.168.9.215]:5060 at 17:03:56.523576: ------------------------------------------------------------------------ SIP/2.0 180 Ringing From: "0210058571";tag=2NKy5KmgUUrgB To: ;tag=BN1748781788-0-1661267036-312861198 Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 56079726 INVITE Supported: X-cisco-srtp-fallback,timer,Geolocation Contact: Allow: INVITE,CANCEL,ACK,BYE,OPTIONS,INFO,REFER,NOTIFY Via: SIP/2.0/UDP 192.168.9.88;received=192.168.9.88;rport=5060;branch=z9hG4bKa6H6S2j6X5rFc Record-Route: Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c063cc0 (583 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (56079726) freeswitch@freeswitch-1> nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction freeswitch@freeswitch-1> tport.c:4226 tport_release() tport_release(0x7fb18c050b40): 0x7fb18c056430 by 0x7fb18c08e8b0 with 0x7fb18c063cc0 (preliminary) freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event r_invite 180 Ringing freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb16400fd40): call state changed: calling -> proceeding freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 180 Ringing freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.514684 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [proceeding][180] freeswitch@freeswitch-1> 2022-08-23 17:03:56.514684 [NOTICE] sofia.c:7401 Ring-Ready sofia/internal/0880022955! freeswitch@freeswitch-1> 2022-08-23 17:03:56.514684 [DEBUG] switch_channel.c:3437 (sofia/internal/0880022955) Callstate Change DOWN -> RINGING freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb17000f6a0): sent signal r_respond freeswitch@freeswitch-1> 2022-08-23 17:03:56.514684 [NOTICE] mod_sofia.c:2505 Ring-Ready sofia/phonerlite_terminaison/+210058571@192.168.10.81! freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb17000f6a0): recv signal r_respond 180 Ringing freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb170014ed0, ...) called freeswitch@freeswitch-1> nua_session.c:2324 nua_invite_server_respond() nua: nua_invite_server_respond: entering freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb170005ea0) tpn = UDP/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb170005ea0): not found by name UDP/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb170005ea0): 572 bytes of 572 to udp/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 572 freeswitch@freeswitch-1> send 572 bytes to udp/[192.168.56.190]:5060 at 17:03:56.527969: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.56.190:5060;branch=z9hG4bK00d6417a6221ed11921ef04c14d7e9d8;rport=5060 From: "+210058571" ;tag=3901970572 To: ;tag=F0jXK31p7QSpa Call-ID: 00D6417A-6221-ED11-921D-F04C14D7E9D8@192.168.56.190 CSeq: 3 INVITE Contact: User-Agent: Freeswitch SBC Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 180 Ringing for INVITE (3) freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb17000f6a0): call state changed: received -> early freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_state 180 Ringing freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.514684 [DEBUG] sofia.c:7290 Channel sofia/phonerlite_terminaison/+210058571@192.168.10.81 entering state [early][180] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.514684 [NOTICE] switch_ivr_originate.c:553 Ring Ready sofia/phonerlite_terminaison/+210058571@192.168.10.81! freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c067b90 from (udp/192.168.9.88:5060) has 801 bytes, veclen = 1 freeswitch@freeswitch-1> recv 801 bytes from udp/[192.168.9.215]:5060 at 17:03:56.576521: ------------------------------------------------------------------------ SIP/2.0 200 OK From: "0210058571";tag=2NKy5KmgUUrgB To: ;tag=BN1748781788-0-1661267036-312861198 Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 56079726 INVITE Supported: X-cisco-srtp-fallback,timer,Geolocation Contact: Allow: INVITE,CANCEL,ACK,BYE,OPTIONS,INFO,REFER,NOTIFY Via: SIP/2.0/UDP 192.168.9.88;received=192.168.9.88;rport=5060;branch=z9hG4bKa6H6S2j6X5rFc Record-Route: Content-Type: application/sdp Content-Length: 190 v=0 o=BN4000 2164730469 1 IN IP4 192.168.9.148 s=- c=IN IP4 192.168.9.149 t=0 0 m=audio 16134 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c067b90 (801 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (56079726) freeswitch@freeswitch-1> nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction freeswitch@freeswitch-1> tport.c:4226 tport_release() tport_release(0x7fb18c050b40): 0x7fb18c056430 by 0x7fb18c08e8b0 with 0x7fb18c067b90 freeswitch@freeswitch-1> soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fb18c0c6090, (nil), 0x7fb18c060bc3, 190) called freeswitch@freeswitch-1> soa.c:1595 soa_process_answer() soa_process_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb18c0c6090, soa_process_answer): called freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb18c05e880, 0x7fb18c0c47f0, ""): called freeswitch@freeswitch-1> soa_static.c:1304 offer_answer_step() soa_static(0x7fb18c0c6090, soa_process_answer): upgrade codecs with remote description freeswitch@freeswitch-1> soa_static.c:1446 offer_answer_step() soa_static(0x7fb18c0c6090, soa_process_answer): storing local description freeswitch@freeswitch-1> soa.c:1730 soa_activate() soa_activate(static::0x7fb18c0c6090, (nil)) called freeswitch@freeswitch-1> nua_session.c:992 nua_session_client_response() nua(0x7fb16400fd40): INVITE: processed SDP answer in 200 OK (200) freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event r_invite 200 OK freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb16400fd40): call state changed: proceeding -> completing, received answer freeswitch@freeswitch-1> soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fb18c0c6090, [0x7fb1ba443548], [0x7fb1ba443550], [(nil)]) called freeswitch@freeswitch-1> soa.c:616 soa_get_params() soa_get_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [completing][200] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] sofia.c:7300 Remote SDP: v=0 o=BN4000 2164730469 1 IN IP4 192.168.9.148 s=- c=IN IP4 192.168.9.149 t=0 0 m=audio 16134 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 freeswitch@freeswitch-1> nua.c:639 nua_ack() nua: nua_ack: entering freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_ack freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_ack freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> soa.c:1730 soa_activate() soa_activate(static::0x7fb18c0c6090, (nil)) called freeswitch@freeswitch-1> nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = */192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name */192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 527 bytes of 527 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 527 freeswitch@freeswitch-1> send 527 bytes to udp/[192.168.9.215]:5060 at 17:03:56.577577: ------------------------------------------------------------------------ ACK sip:192.168.9.148:5060;transport=UDP;oc-node=221;sdp_iwf SIP/2.0 Via: SIP/2.0/UDP 192.168.9.88;rport;branch=z9hG4bKBFBZUX39teF2Q Route: Max-Forwards: 70 From: "0210058571" ;tag=2NKy5KmgUUrgB To: ;tag=BN1748781788-0-1661267036-312861198 Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 56079726 ACK Contact: Content-Length: 0 freeswitch@freeswitch-1> nta.c:8310 outgoing_send() nta: sent ACK (56079726) to */192.168.9.215:5060 freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb16400fd40): call state changed: completing -> ready freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 ACK sent freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_active 200 Call active freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [ready][200] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:3834 Set Codec sofia/internal/0880022955 PCMA/8000 20 ms 160 samples 64000 bits 1 channels freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_codec.c:111 sofia/internal/0880022955 Original read codec set to PCMA:8 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5907 sofia/internal/0880022955 Set 2833 dtmf send payload to 101 recv payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/internal/0880022955] 192.168.9.88 port 16690 -> 192.168.9.149 port 16134 codec: 8 ms: 20 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_rtp.c:4408 Starting timer [soft] 160 bytes per 20ms freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 59949 ms freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:8972 sofia/internal/0880022955 Set 2833 dtmf send payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:8979 sofia/internal/0880022955 Set 2833 dtmf receive payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:9002 sofia/internal/0880022955 Set rtp dtmf delay to 40 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [NOTICE] sofia.c:8468 Channel [sofia/internal/0880022955] has been answered freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_channel.c:3865 (sofia/internal/0880022955) Callstate Change RINGING -> ACTIVE freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:3834 Set Codec sofia/phonerlite_terminaison/+210058571@192.168.10.81 PCMA/8000 20 ms 160 samples 64000 bits 1 channels freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_codec.c:111 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Original read codec set to PCMA:8 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:5907 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Set 2833 dtmf send payload to 101 recv payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/phonerlite_terminaison/+210058571@192.168.10.81] 192.168.10.81 port 25210 -> 192.168.56.190 port 5062 codec: 8 ms: 20 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_rtp.c:4408 Starting timer [soft] 160 bytes per 20ms freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:8972 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Set 2833 dtmf send payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:8979 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Set 2833 dtmf receive payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:9002 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Set rtp dtmf delay to 40 freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [NOTICE] sofia_media.c:92 Pre-Answer sofia/phonerlite_terminaison/+210058571@192.168.10.81! freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_channel.c:3565 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Callstate Change RINGING -> EARLY freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_media.c:8640 Audio params are unchanged for sofia/phonerlite_terminaison/+210058571@192.168.10.81. freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] mod_sofia.c:905 Local SDP sofia/phonerlite_terminaison/+210058571@192.168.10.81: v=0 o=Freeswitch 1661241826 1661241827 IN IP4 192.168.10.81 s=Freeswitch c=IN IP4 192.168.10.81 t=0 0 m=audio 25210 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb17000f6a0): sent signal r_respond freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb17000f6a0): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb170014ed0, ...) called freeswitch@freeswitch-1> soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fb170014ed0, (nil), 0x7fb168087ea3, -1) called freeswitch@freeswitch-1> soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7fb170014ed0, (nil), 0x7fb168087ea3, -1) called freeswitch@freeswitch-1> nua_session.c:2324 nua_invite_server_respond() nua: nua_invite_server_respond: entering freeswitch@freeswitch-1> soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7fb170014ed0) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb170014ed0, soa_generate_answer): called freeswitch@freeswitch-1> soa_static.c:1189 offer_answer_step() soa_static(0x7fb170014ed0, soa_generate_answer): generating local description freeswitch@freeswitch-1> soa_static.c:1230 offer_answer_step() soa_static(0x7fb170014ed0, soa_generate_answer): upgrade with remote description freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb1b95ce9e0, 0x7fb170034510, ""): called freeswitch@freeswitch-1> soa_static.c:1446 offer_answer_step() soa_static(0x7fb170014ed0, soa_generate_answer): storing local description freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [NOTICE] switch_ivr_originate.c:3748 Channel [sofia/phonerlite_terminaison/+210058571@192.168.10.81] has been answered freeswitch@freeswitch-1> soa.c:1730 soa_activate() soa_activate(static::0x7fb170014ed0, (nil)) called freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb170014ed0, [(nil)], [0x7fb1b95d0b18], [0x7fb1b95d0b14]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb170005ea0) tpn = UDP/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb170005ea0): not found by name UDP/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb170005ea0): 872 bytes of 872 to udp/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 872 freeswitch@freeswitch-1> send 872 bytes to udp/[192.168.56.190]:5060 at 17:03:56.591596: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.56.190:5060;branch=z9hG4bK00d6417a6221ed11921ef04c14d7e9d8;rport=5060 From: "+210058571" ;tag=3901970572 To: ;tag=F0jXK31p7QSpa Call-ID: 00D6417A-6221-ED11-921D-F04C14D7E9D8@192.168.56.190 CSeq: 3 INVITE Contact: User-Agent: Freeswitch SBC Allow: INVITE, ACK, BYE, CANCEL, OPTIONS Require: timer Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 214 v=0 o=Freeswitch 1661241826 1661241827 IN IP4 192.168.10.81 s=Freeswitch c=IN IP4 192.168.10.81 t=0 0 m=audio 25210 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (3) freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 500 ms freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb17000f6a0): call state changed: early -> completed, sent answer freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb170014ed0, [0x7fb1b95d0bc8], [0x7fb1b95d0bd0], [(nil)]) called freeswitch@freeswitch-1> soa.c:616 soa_get_params() soa_get_params(static::0x7fb170014ed0, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_channel.c:3865 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Callstate Change EARLY -> ACTIVE freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] sofia.c:7290 Channel sofia/phonerlite_terminaison/+210058571@192.168.10.81 entering state [completed][200] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_ivr_originate.c:3806 Originate Resulted in Success: [sofia/internal/0880022955] freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_ivr_bridge.c:1794 (sofia/internal/0880022955) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/0880022955) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 1340) freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] switch_core_state_machine.c:654 (sofia/internal/0880022955) State EXCHANGE_MEDIA freeswitch@freeswitch-1> 2022-08-23 17:03:56.574676 [DEBUG] mod_sofia.c:663 SOFIA EXCHANGE_MEDIA freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb170005ea0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb170005ea0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb170005ea0) msg 0x7fb1700222e0 from (udp/192.168.10.81:5060) has 440 bytes, veclen = 1 freeswitch@freeswitch-1> recv 440 bytes from udp/[192.168.56.190]:5060 at 17:03:56.598670: ------------------------------------------------------------------------ ACK sip:+880022955@192.168.10.81:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.56.190:5060;branch=z9hG4bK00d6417a6221ed11921ff04c14d7e9d8;rport From: "+210058571" ;tag=3901970572 To: ;tag=F0jXK31p7QSpa Call-ID: 00D6417A-6221-ED11-921D-F04C14D7E9D8@192.168.56.190 CSeq: 3 ACK Contact: Max-Forwards: 70 Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb170005ea0): msg 0x7fb1700222e0 (440 bytes) from udp/192.168.56.190:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received ACK sip:+880022955@192.168.10.81:5060;transport=udp SIP/2.0 (CSeq 3) freeswitch@freeswitch-1> nta.c:3019 agent_recv_request() nta: ACK (3) is going to INVITE (3) freeswitch@freeswitch-1> nua_session.c:2573 process_ack_or_cancel() nua: process_ack_or_cancel: entering freeswitch@freeswitch-1> soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fb170014ed0) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_ack 200 OK freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb17000f6a0): call state changed: completed -> ready freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_active 200 Call active freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768]) freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (55916313) freeswitch@freeswitch-1> nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fb13cadec20) freeswitch@freeswitch-1> nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 7947 ms freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.594666 [DEBUG] sofia.c:7290 Channel sofia/phonerlite_terminaison/+210058571@192.168.10.81 entering state [ready][200] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:03:56.974702 [DEBUG] switch_rtp.c:7720 Correct audio ip/port confirmed. freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 4507 ms freeswitch@freeswitch-1> nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (55916309) freeswitch@freeswitch-1> nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fb13ca9fc20) freeswitch@freeswitch-1> nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 8675 ms freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 31189 ms freeswitch@freeswitch-1> 2022-08-23 17:03:57.494681 [DEBUG] switch_rtp.c:7720 Correct audio ip/port confirmed. freeswitch@freeswitch-1> nta.c:7140 _nta_incoming_timer() nta: timer I fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb1b95d0b50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free freeswitch@freeswitch-1> nta.c:1289 agent_timer() nta: timer not set freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb184085d40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb184085d40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb184085d40) msg 0x7fb1840702c0 from (udp/192.168.10.186:5060) has 518 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb184085d40): msg 0x7fb1840702c0 (518 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received OPTIONS sip:192.168.10.186:5060 SIP/2.0 (CSeq 916830) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:192.168.10.186:5060 with contact freeswitch@freeswitch-1> nta.c:3085 agent_recv_request() nta: OPTIONS (916830) going to a default leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> nua_stack.c:899 nh_create() nua: nh_create: entering freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb18404a090, 0x7fb184192250, 0x7fb18408dd50) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1840520a0, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb18408dd50): event i_options 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb18408dd50): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1840520a0, ...) called freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb18408dd50): sent signal r_respond freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb18408dd50): sent signal r_destroy freeswitch@freeswitch-1> soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0x7fb1840520a0, [(nil)], [0x7fb13cadeb48], [0x7fb13cadeb44]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb184085d40) tpn = UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb184085d40): not found by name UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb184085d40): 509 bytes of 509 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 509 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for OPTIONS (916830) freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb18408dd50): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb1840520a0) called freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb1740454e0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb1740454e0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb1740454e0) msg 0x7fb17405c600 from (udp/192.168.10.185:5060) has 517 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb1740454e0): msg 0x7fb17405c600 (517 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received OPTIONS sip:192.168.10.185:5060 SIP/2.0 (CSeq 68665) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:192.168.10.185:5060 with contact freeswitch@freeswitch-1> nta.c:3085 agent_recv_request() nta: OPTIONS (68665) going to a default leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> nua_stack.c:899 nh_create() nua: nh_create: entering freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb1740509b0, 0x7fb174053d40, 0x7fb1740538b0) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb17404e7b0, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb1740538b0): event i_options 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb1740538b0): sent signal r_respond freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb1740538b0): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb17404e7b0, ...) called freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb1740538b0): sent signal r_destroy freeswitch@freeswitch-1> soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0x7fb17404e7b0, [(nil)], [0x7fb13ca9fb48], [0x7fb13ca9fb44]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb1740454e0) tpn = UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb1740454e0): not found by name UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb1740454e0): 508 bytes of 508 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 508 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for OPTIONS (68665) freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb1740538b0): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb17404e7b0) called freeswitch@freeswitch-1> nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb13cadeb50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 30000 ms freeswitch@freeswitch-1> nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb13ca9fb50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 30001 ms freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb1680052c0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb1680052c0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb1680052c0) msg 0x7fb168081bc0 from (udp/192.168.9.177:5060) has 367 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb1680052c0): msg 0x7fb168081bc0 (367 bytes) from udp/10.80.2.6:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received OPTIONS sip:origination.trunk:5060 SIP/2.0 (CSeq 91714) freeswitch@freeswitch-1> nta.c:3085 agent_recv_request() nta: OPTIONS (91714) going to a default leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> nua_stack.c:899 nh_create() nua: nh_create: entering freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb168001b90, 0x7fb168001390, 0x7fb168037500) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb16803bc40, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb168037500): event i_options 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb168037500): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb16803bc40, ...) called freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb168037500): sent signal r_respond freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0x7fb16803bc40, [(nil)], [0x7fb1b9cc7b48], [0x7fb1b9cc7b44]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb1680052c0) tpn = UDP/10.80.2.6:5060 freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb168037500): sent signal r_destroy freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.80.2.6:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb1680052c0): not found by name UDP/10.80.2.6:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb1680052c0): 557 bytes of 557 to udp/10.80.2.6:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 557 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for OPTIONS (91714) freeswitch@freeswitch-1> nta.c:1350 set_timeout() nta: timer set to 32000 ms freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb168037500): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb16803bc40) called freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c0600f0 from (udp/192.168.9.88:5060) has 1147 bytes, veclen = 1 freeswitch@freeswitch-1> recv 1147 bytes from udp/[192.168.9.215]:5060 at 17:04:10.233931: ------------------------------------------------------------------------ INVITE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 Record-Route: From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 1 INVITE Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bK0d76.d93c53dc1efc95843d6bdb5a977aa2c8.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-4fc6934a-11d1c57-59b6b65d-7f08664782f0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sb0o2on21.1 Supported: resource-priority,timer,X-cisco-srtp-fallback,Geolocation Max-Forwards: 62 Contact: Allow: INVITE,CANCEL,ACK,BYE,OPTIONS,INFO,REFER,NOTIFY Session-Expires: 1800;refresher=uac Min-SE: 1800 Content-Type: application/sdp Content-Length: 207 v=0 o=BN4000 2164730469 2 IN IP4 192.168.9.148 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 16134 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=inactive a=ptime:20 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c0600f0 (1147 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received INVITE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 1) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:gw+phonerlite@192.168.9.88:5060 with contact freeswitch@freeswitch-1> nta.c:3060 agent_recv_request() nta: INVITE (1) going to existing leg freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 200 ms freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fb18c0c6090, (nil), 0x7fb18c05914c, 207) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_invite 100 Trying freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: received received offer freeswitch@freeswitch-1> soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fb18c0c6090, [0x7fb1ba4437a8], [0x7fb1ba4437b0], [(nil)]) called freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 100 Trying freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 360 bytes of 360 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 360 freeswitch@freeswitch-1> send 360 bytes to udp/[192.168.9.215]:5060 at 17:04:10.238605: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bK0d76.d93c53dc1efc95843d6bdb5a977aa2c8.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 1 INVITE User-Agent: Freeswitch SBC Content-Length: 0 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (1) freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:10.234681 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [received][100] freeswitch@freeswitch-1> 2022-08-23 17:04:10.234681 [DEBUG] sofia.c:7300 Remote SDP: v=0 o=BN4000 2164730469 2 IN IP4 192.168.9.148 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 16134 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=inactive a=ptime:20 freeswitch@freeswitch-1> 2022-08-23 17:04:10.234681 [WARNING] switch_core_media.c:4980 RFC2543 from March 1999 called; They want their 0.0.0.0 hold method back..... freeswitch@freeswitch-1> 2022-08-23 17:04:10.234681 [DEBUG] switch_channel.c:1927 (sofia/internal/0880022955) Callstate Change ACTIVE -> HELD freeswitch@freeswitch-1> 2022-08-23 17:04:10.374695 [DEBUG] switch_ivr.c:632 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Command Execute [depth=0] playback(local_stream://moh) freeswitch@freeswitch-1> EXECUTE [depth=0] sofia/phonerlite_terminaison/+210058571@192.168.10.81 playback(local_stream://moh) freeswitch@freeswitch-1> 2022-08-23 17:04:10.374695 [WARNING] mod_local_stream.c:868 Unknown source moh, trying 'default' freeswitch@freeswitch-1> 2022-08-23 17:04:10.374695 [ERR] mod_local_stream.c:876 Unknown source default freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 18143 ms freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000 freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000 freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:5907 sofia/internal/0880022955 Set 2833 dtmf send payload to 101 recv payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:8646 Audio params changed for sofia/internal/0880022955 from 192.168.9.149:16134 to 0.0.0.0:16134 freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/internal/0880022955] 192.168.9.88 port 16690 -> 0.0.0.0 port 16134 codec: 8 ms: 20 freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] switch_core_media.c:8687 AUDIO RTP CHANGING DEST TO: [0.0.0.0:16134] freeswitch@freeswitch-1> 2022-08-23 17:04:10.474678 [DEBUG] sofia.c:8239 Processing updated SDP freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fb18c0c6090, (nil), 0x7fb16400a660, -1) called freeswitch@freeswitch-1> nua_session.c:2324 nua_invite_server_respond() nua: nua_invite_server_respond: entering freeswitch@freeswitch-1> soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb18c0c6090, soa_generate_answer): called freeswitch@freeswitch-1> soa_static.c:1230 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_answer): upgrade with remote description freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb1ba4419e0, 0x7fb18c0630b0, ""): called freeswitch@freeswitch-1> soa_static.c:1446 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_answer): storing local description freeswitch@freeswitch-1> soa.c:1730 soa_activate() soa_activate(static::0x7fb18c0c6090, (nil)) called freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [(nil)], [0x7fb1ba443b18], [0x7fb1ba443b14]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 1180 bytes of 1180 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 1180 freeswitch@freeswitch-1> send 1180 bytes to udp/[192.168.9.215]:5060 at 17:04:10.491015: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bK0d76.d93c53dc1efc95843d6bdb5a977aa2c8.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-4fc6934a-11d1c57-59b6b65d-7f08664782f0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sb0o2on21.1 Record-Route: From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 1 INVITE Contact: User-Agent: Freeswitch SBC Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 228 v=0 o=Freeswitch 1661250346 1661250348 IN IP4 192.168.9.88 s=Freeswitch c=IN IP4 192.168.9.88 t=0 0 m=audio 16690 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=inactive a=ptime:20 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (1) freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 500 ms freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: completed sent answer freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [0x7fb1ba443bc8], [0x7fb1ba443bd0], [(nil)]) called freeswitch@freeswitch-1> soa.c:616 soa_get_params() soa_get_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c06b380 from (udp/192.168.9.88:5060) has 587 bytes, veclen = 1 freeswitch@freeswitch-1> recv 587 bytes from udp/[192.168.9.215]:5060 at 17:04:10.494240: ------------------------------------------------------------------------ ACK sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 1 ACK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bK0d76.0e0dbc9ce9fddda8ebb403d48697bafd.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-2e02ef82-11d1c57-59b6b765-7f08657e0580 Max-Forwards: 69 Contact: Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c06b380 (587 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received ACK sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 1) freeswitch@freeswitch-1> nta.c:3019 agent_recv_request() nta: ACK (1) is going to INVITE (1) freeswitch@freeswitch-1> nua_session.c:2573 process_ack_or_cancel() nua: process_ack_or_cancel: entering freeswitch@freeswitch-1> soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_ack 200 OK freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: ready freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_active 200 Call active freeswitch@freeswitch-1> nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768]) freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:10.494683 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [completed][200] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:10.494683 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [ready][200] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c0648d0 from (udp/192.168.9.88:5060) has 907 bytes, veclen = 1 freeswitch@freeswitch-1> recv 907 bytes from udp/[192.168.9.215]:5060 at 17:04:10.790414: ------------------------------------------------------------------------ INVITE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 Record-Route: From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 2 INVITE Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKdc76.2aa39b20fdc0c09c30745130aac49d2f.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-138337a7-11d1c58-59b6b889-7f0869e120a0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sb0o2o731.1 Supported: resource-priority,timer,X-cisco-srtp-fallback,Geolocation Max-Forwards: 62 Contact: Allow: INVITE,CANCEL,ACK,BYE,OPTIONS,INFO,REFER,NOTIFY Session-Expires: 1800;refresher=uac Min-SE: 1800 Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c0648d0 (907 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received INVITE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 2) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:gw+phonerlite@192.168.9.88:5060 with contact freeswitch@freeswitch-1> nta.c:3060 agent_recv_request() nta: INVITE (2) going to existing leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_invite 100 Trying freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: received freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 100 Trying freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 360 bytes of 360 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 360 freeswitch@freeswitch-1> send 360 bytes to udp/[192.168.9.215]:5060 at 17:04:10.792202: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKdc76.2aa39b20fdc0c09c30745130aac49d2f.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 2 INVITE User-Agent: Freeswitch SBC Content-Length: 0 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (2) freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:10.774691 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [received][100] freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fb18c0c6090, (nil), 0x7fb16400a660, -1) called freeswitch@freeswitch-1> nua_session.c:2324 nua_invite_server_respond() nua: nua_invite_server_respond: entering freeswitch@freeswitch-1> soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fb18c0c6090, 0) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb18c0c6090, soa_generate_offer): called freeswitch@freeswitch-1> soa_static.c:1217 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_offer): upgrade with local description freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb1ba4419e0, (nil), ""): called freeswitch@freeswitch-1> soa_static.c:1446 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_offer): storing local description freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [(nil)], [0x7fb1ba443b18], [0x7fb1ba443b14]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 1168 bytes of 1168 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 1168 freeswitch@freeswitch-1> send 1168 bytes to udp/[192.168.9.215]:5060 at 17:04:10.793065: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKdc76.2aa39b20fdc0c09c30745130aac49d2f.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-138337a7-11d1c58-59b6b889-7f0869e120a0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sb0o2o731.1 Record-Route: From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 2 INVITE Contact: User-Agent: Freeswitch SBC Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 216 v=0 o=Freeswitch 1661250346 1661250349 IN IP4 192.168.9.88 s=Freeswitch c=IN IP4 192.168.9.88 t=0 0 m=audio 16690 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (2) freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: completed sent offer freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [0x7fb1ba443bc8], [0x7fb1ba443bd0], [(nil)]) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:10.794703 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [completed][200] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c08e2b0 from (udp/192.168.9.88:5060) has 839 bytes, veclen = 1 freeswitch@freeswitch-1> recv 839 bytes from udp/[192.168.9.215]:5060 at 17:04:10.845091: ------------------------------------------------------------------------ ACK sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 2 ACK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKdc76.bc874517b876009bf7c50a38cdfe3d7e.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-12d53f85-11d1c58-59b6b8c3-7f086b792fd0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK1lc3fe30b0rsrr70nc30.1 Max-Forwards: 62 Contact: Content-Type: application/sdp Content-Length: 146 v=0 o=BN4000 2164730469 3 IN IP4 192.168.9.148 s=- c=IN IP4 192.168.9.149 t=0 0 m=audio 16134 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=ptime:20 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c08e2b0 (839 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received ACK sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 2) freeswitch@freeswitch-1> nta.c:3019 agent_recv_request() nta: ACK (2) is going to INVITE (2) freeswitch@freeswitch-1> nua_session.c:2573 process_ack_or_cancel() nua: process_ack_or_cancel: entering freeswitch@freeswitch-1> soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fb18c0c6090, (nil), 0x7fb18c0c7a15, 146) called freeswitch@freeswitch-1> soa.c:1595 soa_process_answer() soa_process_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb18c0c6090, soa_process_answer): called freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb18c062440, 0x7fb18c0c2480, ""): called freeswitch@freeswitch-1> soa_static.c:1304 offer_answer_step() soa_static(0x7fb18c0c6090, soa_process_answer): upgrade codecs with remote description freeswitch@freeswitch-1> soa.c:1730 soa_activate() soa_activate(static::0x7fb18c0c6090, (nil)) called freeswitch@freeswitch-1> soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_ack 200 OK freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: ready received answer freeswitch@freeswitch-1> soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fb18c0c6090, [0x7fb1ba4438c8], [0x7fb1ba4438d0], [(nil)]) called freeswitch@freeswitch-1> soa.c:616 soa_get_params() soa_get_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_active 200 Call active freeswitch@freeswitch-1> nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768]) freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [ready][200] freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] sofia.c:7300 Remote SDP: v=0 o=BN4000 2164730469 3 IN IP4 192.168.9.148 s=- c=IN IP4 192.168.9.149 t=0 0 m=audio 16134 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=ptime:20 freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:5878 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:5907 sofia/internal/0880022955 Set 2833 dtmf send payload to 101 recv payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:8646 Audio params changed for sofia/internal/0880022955 from 0.0.0.0:16134 to 192.168.9.149:16134 freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/internal/0880022955] 192.168.9.88 port 16690 -> 192.168.9.149 port 16134 codec: 8 ms: 20 freeswitch@freeswitch-1> 2022-08-23 17:04:10.834689 [DEBUG] switch_core_media.c:8687 AUDIO RTP CHANGING DEST TO: [192.168.9.149:16134] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 4503 ms freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c054bc0 from (udp/192.168.9.88:5060) has 1091 bytes, veclen = 1 freeswitch@freeswitch-1> recv 1091 bytes from udp/[192.168.9.215]:5060 at 17:04:14.502626: ------------------------------------------------------------------------ INVITE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 Record-Route: From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 3 INVITE Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKec76.0023f753c848f25bad2b7848b0ff9482.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-24431c92-11d1c5b-59b6c709-7f08650260b0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sb0o2on31.1 Supported: resource-priority,timer,X-cisco-srtp-fallback,Geolocation Max-Forwards: 62 Contact: Allow: INVITE,CANCEL,ACK,BYE,OPTIONS,INFO,REFER,NOTIFY Session-Expires: 1800;refresher=uac Min-SE: 1800 Content-Type: application/sdp Content-Length: 151 v=0 o=BN4000 2164730469 4 IN IP4 192.168.9.148 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 16134 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=inactive a=ptime:20 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c054bc0 (1091 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received INVITE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 3) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:gw+phonerlite@192.168.9.88:5060 with contact freeswitch@freeswitch-1> nta.c:3060 agent_recv_request() nta: INVITE (3) going to existing leg freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 200 ms freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fb18c0c6090, (nil), 0x7fb18c090eec, 151) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_invite 100 Trying freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: received received offer freeswitch@freeswitch-1> soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fb18c0c6090, [0x7fb1ba4437a8], [0x7fb1ba4437b0], [(nil)]) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 100 Trying freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 360 bytes of 360 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 360 freeswitch@freeswitch-1> send 360 bytes to udp/[192.168.9.215]:5060 at 17:04:14.513883: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKec76.0023f753c848f25bad2b7848b0ff9482.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 3 INVITE User-Agent: Freeswitch SBC Content-Length: 0 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (3) freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [received][100] freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] sofia.c:7300 Remote SDP: v=0 o=BN4000 2164730469 4 IN IP4 192.168.9.148 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 16134 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=inactive a=ptime:20 freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [WARNING] switch_core_media.c:4980 RFC2543 from March 1999 called; They want their 0.0.0.0 hold method back..... freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:5878 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:5907 sofia/internal/0880022955 Set 2833 dtmf send payload to 101 recv payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:8646 Audio params changed for sofia/internal/0880022955 from 192.168.9.149:16134 to 0.0.0.0:16134 freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/internal/0880022955] 192.168.9.88 port 16690 -> 0.0.0.0 port 16134 codec: 8 ms: 20 freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] switch_core_media.c:8687 AUDIO RTP CHANGING DEST TO: [0.0.0.0:16134] freeswitch@freeswitch-1> 2022-08-23 17:04:14.494685 [DEBUG] sofia.c:8239 Processing updated SDP freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fb18c0c6090, (nil), 0x7fb16400a660, -1) called freeswitch@freeswitch-1> nua_session.c:2324 nua_invite_server_respond() nua: nua_invite_server_respond: entering freeswitch@freeswitch-1> soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb18c0c6090, soa_generate_answer): called freeswitch@freeswitch-1> soa_static.c:1230 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_answer): upgrade with remote description freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb1ba4419e0, 0x7fb18c064500, ""): called freeswitch@freeswitch-1> soa_static.c:1446 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_answer): storing local description freeswitch@freeswitch-1> soa.c:1730 soa_activate() soa_activate(static::0x7fb18c0c6090, (nil)) called freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [(nil)], [0x7fb1ba443b18], [0x7fb1ba443b14]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 1180 bytes of 1180 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 1180 freeswitch@freeswitch-1> send 1180 bytes to udp/[192.168.9.215]:5060 at 17:04:14.514682: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKec76.0023f753c848f25bad2b7848b0ff9482.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-24431c92-11d1c5b-59b6c709-7f08650260b0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sb0o2on31.1 Record-Route: From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 3 INVITE Contact: User-Agent: Freeswitch SBC Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 228 v=0 o=Freeswitch 1661250346 1661250350 IN IP4 192.168.9.88 s=Freeswitch c=IN IP4 192.168.9.88 t=0 0 m=audio 16690 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=inactive a=ptime:20 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (3) freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: completed sent answer freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [0x7fb1ba443bc8], [0x7fb1ba443bd0], [(nil)]) called freeswitch@freeswitch-1> soa.c:616 soa_get_params() soa_get_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c0ab850 from (udp/192.168.9.88:5060) has 587 bytes, veclen = 1 freeswitch@freeswitch-1> recv 587 bytes from udp/[192.168.9.215]:5060 at 17:04:14.517657: ------------------------------------------------------------------------ ACK sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 3 ACK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKec76.72fe410b6b4f782abbc8c9192ffd7cf2.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-33b83bde-11d1c5b-59b6c71c-7f086abe00a0 Max-Forwards: 69 Contact: Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c0ab850 (587 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received ACK sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 3) freeswitch@freeswitch-1> nta.c:3019 agent_recv_request() nta: ACK (3) is going to INVITE (3) freeswitch@freeswitch-1> nua_session.c:2573 process_ack_or_cancel() nua: process_ack_or_cancel: entering freeswitch@freeswitch-1> soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_ack 200 OK freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: ready freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_active 200 Call active freeswitch@freeswitch-1> nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768]) freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:14.534693 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [completed][200] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:14.534693 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [ready][200] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c067310 from (udp/192.168.9.88:5060) has 907 bytes, veclen = 1 freeswitch@freeswitch-1> recv 907 bytes from udp/[192.168.9.215]:5060 at 17:04:14.572659: ------------------------------------------------------------------------ INVITE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 Record-Route: From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 4 INVITE Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKbc76.f55dce699779e6554ce291fbeea3b47b.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-79e98055-11d1c5b-59b6c750-7f0868a1ddc0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sb0o2o741.1 Supported: resource-priority,timer,X-cisco-srtp-fallback,Geolocation Max-Forwards: 62 Contact: Allow: INVITE,CANCEL,ACK,BYE,OPTIONS,INFO,REFER,NOTIFY Session-Expires: 1800;refresher=uac Min-SE: 1800 Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c067310 (907 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received INVITE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 4) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:gw+phonerlite@192.168.9.88:5060 with contact freeswitch@freeswitch-1> nta.c:3060 agent_recv_request() nta: INVITE (4) going to existing leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_invite 100 Trying freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: received freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 100 Trying freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 360 bytes of 360 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 360 freeswitch@freeswitch-1> send 360 bytes to udp/[192.168.9.215]:5060 at 17:04:14.575142: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKbc76.f55dce699779e6554ce291fbeea3b47b.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 4 INVITE User-Agent: Freeswitch SBC Content-Length: 0 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (4) freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:14.574683 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [received][100] freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7fb18c0c6090, (nil), 0x7fb16400a660, -1) called freeswitch@freeswitch-1> nua_session.c:2324 nua_invite_server_respond() nua: nua_invite_server_respond: entering freeswitch@freeswitch-1> soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7fb18c0c6090, 0) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb18c0c6090, soa_generate_offer): called freeswitch@freeswitch-1> soa_static.c:1217 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_offer): upgrade with local description freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb1ba4419e0, (nil), ""): called freeswitch@freeswitch-1> soa_static.c:1446 offer_answer_step() soa_static(0x7fb18c0c6090, soa_generate_offer): storing local description freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [(nil)], [0x7fb1ba443b18], [0x7fb1ba443b14]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 1168 bytes of 1168 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 1168 freeswitch@freeswitch-1> send 1168 bytes to udp/[192.168.9.215]:5060 at 17:04:14.575579: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKbc76.f55dce699779e6554ce291fbeea3b47b.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-79e98055-11d1c5b-59b6c750-7f0868a1ddc0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sb0o2o741.1 Record-Route: From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 4 INVITE Contact: User-Agent: Freeswitch SBC Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Require: timer Supported: timer, path, replaces Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 216 v=0 o=Freeswitch 1661250346 1661250351 IN IP4 192.168.9.88 s=Freeswitch c=IN IP4 192.168.9.88 t=0 0 m=audio 16690 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (4) freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: completed sent offer freeswitch@freeswitch-1> soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7fb18c0c6090, [0x7fb1ba443bc8], [0x7fb1ba443bd0], [(nil)]) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:14.594713 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [completed][200] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c055970 from (udp/192.168.9.88:5060) has 883 bytes, veclen = 1 freeswitch@freeswitch-1> recv 883 bytes from udp/[192.168.9.215]:5060 at 17:04:14.628676: ------------------------------------------------------------------------ ACK sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 4 ACK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKbc76.819858dfbf7978ead380ccffdf74c411.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-58b15ca1-11d1c5c-59b6c78b-7f08651393f0 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bKo1t61m00807kslbil9d0.1 Max-Forwards: 62 Contact: Content-Type: application/sdp Content-Length: 190 v=0 o=BN4000 2164730469 5 IN IP4 192.168.9.148 s=- c=IN IP4 192.168.9.149 t=0 0 m=audio 16134 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c055970 (883 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received ACK sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 4) freeswitch@freeswitch-1> nta.c:3019 agent_recv_request() nta: ACK (4) is going to INVITE (4) freeswitch@freeswitch-1> nua_session.c:2573 process_ack_or_cancel() nua: process_ack_or_cancel: entering freeswitch@freeswitch-1> soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7fb18c0c6090, (nil), 0x7fb18c0ad985, 190) called freeswitch@freeswitch-1> soa.c:1595 soa_process_answer() soa_process_answer(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7fb18c0c6090, soa_process_answer): called freeswitch@freeswitch-1> soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7fb18c066c80, 0x7fb18c0669f0, ""): called freeswitch@freeswitch-1> soa_static.c:1304 offer_answer_step() soa_static(0x7fb18c0c6090, soa_process_answer): upgrade codecs with remote description freeswitch@freeswitch-1> soa.c:1730 soa_activate() soa_activate(static::0x7fb18c0c6090, (nil)) called freeswitch@freeswitch-1> soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_ack 200 OK freeswitch@freeswitch-1> nua_session.c:4149 signal_call_state_change() nua(0x7fb16400fd40): ready call updated: ready received answer freeswitch@freeswitch-1> soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7fb18c0c6090, [0x7fb1ba4438c8], [0x7fb1ba4438d0], [(nil)]) called freeswitch@freeswitch-1> soa.c:616 soa_get_params() soa_get_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 OK freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_active 200 Call active freeswitch@freeswitch-1> nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768]) freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] sofia.c:7290 Channel sofia/internal/0880022955 entering state [ready][200] freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] sofia.c:7300 Remote SDP: v=0 o=BN4000 2164730469 5 IN IP4 192.168.9.148 s=- c=IN IP4 192.168.9.149 t=0 0 m=audio 16134 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000 freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000 freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:5907 sofia/internal/0880022955 Set 2833 dtmf send payload to 101 recv payload to 101 freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:8646 Audio params changed for sofia/internal/0880022955 from 0.0.0.0:16134 to 192.168.9.149:16134 freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/internal/0880022955] 192.168.9.88 port 16690 -> 192.168.9.149 port 16134 codec: 8 ms: 20 freeswitch@freeswitch-1> 2022-08-23 17:04:14.614750 [DEBUG] switch_core_media.c:8687 AUDIO RTP CHANGING DEST TO: [192.168.9.149:16134] freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 791 ms freeswitch@freeswitch-1> 2022-08-23 17:04:14.794699 [DEBUG] switch_rtp.c:7720 Correct audio ip/port confirmed. freeswitch@freeswitch-1> nta.c:7140 _nta_incoming_timer() nta: timer I fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb1ba443b50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/4 term, 1/4 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 351 ms freeswitch@freeswitch-1> nta.c:7140 _nta_incoming_timer() nta: timer I fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb1ba443b50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/3 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 3673 ms freeswitch@freeswitch-1> nta.c:7140 _nta_incoming_timer() nta: timer I fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb1ba443b50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 110 ms freeswitch@freeswitch-1> nta.c:7140 _nta_incoming_timer() nta: timer I fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb1ba443b50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 8948 ms freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:657 nua_options() nua: nua_options: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb19003d380): sent signal r_options freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb19003d380): recv signal r_options freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb18404a090, 0x7fb184192250, 0x7fb19003d380) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1840520a0, ...) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1840520a0, ...) called freeswitch@freeswitch-1> nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb184085d40) tpn = udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb184085d40): not found by name udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb184085d40): 489 bytes of 489 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 489 freeswitch@freeswitch-1> nta.c:8310 outgoing_send() nta: sent OPTIONS (55916314) to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4164 tport_pend() tport_pend(0x7fb184085d40): pending 0x7fb184093da0 for udp/192.168.10.186:5060 (already 0) freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 1000 ms freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb184085d40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb184085d40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb184085d40) msg 0x7fb184072f30 from (udp/192.168.10.186:5060) has 558 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb184085d40): msg 0x7fb184072f30 (558 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:3299 agent_recv_response() nta: received 500 Server Internal Error for OPTIONS (55916314) freeswitch@freeswitch-1> nta.c:3366 agent_recv_response() nta: 500 Server Internal Error is going to a transaction freeswitch@freeswitch-1> nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 147.867 ms freeswitch@freeswitch-1> tport.c:4226 tport_release() tport_release(0x7fb184085d40): 0x7fb184093da0 by 0x7fb184055a30 with 0x7fb184072f30 freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb19003d380): event r_options 500 Server Internal Error freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb19003d380): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb1840520a0) called freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb19003d380): sent signal r_destroy freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:657 nua_options() nua: nua_options: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb180051d10): sent signal r_options freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb180051d10): recv signal r_options freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb1740509b0, 0x7fb174053d40, 0x7fb180051d10) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb17404e7b0, ...) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb17404e7b0, ...) called freeswitch@freeswitch-1> nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb1740454e0) tpn = udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb1740454e0): not found by name udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb1740454e0): 489 bytes of 489 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 489 freeswitch@freeswitch-1> nta.c:8310 outgoing_send() nta: sent OPTIONS (55916310) to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4164 tport_pend() tport_pend(0x7fb1740454e0): pending 0x7fb174057f50 for udp/192.168.10.185:5060 (already 0) freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 1000 ms freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb1740454e0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb1740454e0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb1740454e0) msg 0x7fb1740494e0 from (udp/192.168.10.185:5060) has 545 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb1740454e0): msg 0x7fb1740494e0 (545 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (55916310) freeswitch@freeswitch-1> nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction freeswitch@freeswitch-1> nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 148.006 ms freeswitch@freeswitch-1> tport.c:4226 tport_release() tport_release(0x7fb1740454e0): 0x7fb174057f50 by 0x7fb1740538b0 with 0x7fb1740494e0 freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb180051d10): event r_options 200 OK freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb180051d10): sent signal r_destroy freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb180051d10): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb17404e7b0) called freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 4147 ms freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 4148 ms freeswitch@freeswitch-1> nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (55916314) freeswitch@freeswitch-1> nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fb13cadec20) freeswitch@freeswitch-1> nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 7893 ms freeswitch@freeswitch-1> nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (55916310) freeswitch@freeswitch-1> nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fb13ca9fc20) freeswitch@freeswitch-1> nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 8623 ms freeswitch@freeswitch-1> nta.c:9107 outgoing_timer_dk() nta: timer D fired, terminate INVITE (56079726) freeswitch@freeswitch-1> nta.c:8988 outgoing_timer_bf() nta: timer F fired, terminating ACK (56079726) freeswitch@freeswitch-1> nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fb1ba443c20) freeswitch@freeswitch-1> nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 1/1 term, 2/2 free freeswitch@freeswitch-1> nta.c:1289 agent_timer() nta: timer not set freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb18c050b40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb18c050b40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb18c050b40) msg 0x7fb18c05d870 from (udp/192.168.9.88:5060) has 631 bytes, veclen = 1 freeswitch@freeswitch-1> recv 631 bytes from udp/[192.168.9.215]:5060 at 17:04:31.850074: ------------------------------------------------------------------------ BYE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 5 BYE Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKcc76.5a0e8dac78036aeb99b0760911e9e812.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-47b68cba-11d1c6d-59b70ace-7f086635e140 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sd0o2on41.1 Max-Forwards: 62 Reason: Q.850;cause=16 Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb18c050b40): msg 0x7fb18c05d870 (631 bytes) from udp/192.168.9.215:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received BYE sip:gw+phonerlite@192.168.9.88:5060;transport=udp;gw=phonerlite SIP/2.0 (CSeq 5) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:gw+phonerlite@192.168.9.88:5060 with contact freeswitch@freeswitch-1> nta.c:3060 agent_recv_request() nta: BYE (5) going to existing leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_bye 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_channel.c:2112 (sofia/internal/0880022955) Callstate Change HELD -> UNHELD freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [NOTICE] sofia.c:1084 Hangup sofia/internal/0880022955 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_respond freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb16400fd40): sent signal r_destroy freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb18c0c6090, ...) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb18c050b40) tpn = UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb18c050b40): not found by name UDP/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb18c050b40): 662 bytes of 662 to udp/192.168.9.215:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 662 freeswitch@freeswitch-1> send 662 bytes to udp/[192.168.9.215]:5060 at 17:04:31.865409: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.9.215;branch=z9hG4bKcc76.5a0e8dac78036aeb99b0760911e9e812.0 Via: SIP/2.0/UDP 192.168.9.148:5060;rport=5060;branch=z9hG4bK-47b68cba-11d1c6d-59b70ace-7f086635e140 Via: SIP/2.0/UDP 10.1.0.69:5060;branch=z9hG4bK6mccbk1070re50p1ojt0sd0o2on41.1 From: ;tag=BN1748781788-0-1661267036-312861198 To: "0210058571";tag=2NKy5KmgUUrgB Call-ID: a6ae9d3d-9d97-123b-4c89-005056b958a7 CSeq: 5 BYE User-Agent: Freeswitch SBC Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for BYE (5) freeswitch@freeswitch-1> nta.c:1350 set_timeout() nta: timer set to 32000 ms freeswitch@freeswitch-1> nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fb16400fd40): removing session usage freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb16400fd40): call state changed: ready -> terminated freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_state 200 Session Terminated freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb16400fd40): event i_terminated 200 Session Terminated freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb18c0c6090) called freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fb18c0c2010) freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb16400fd40): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_ivr_bridge.c:916 BRIDGE THREAD DONE [sofia/internal/0880022955] freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [NOTICE] switch_ivr_bridge.c:931 Hangup sofia/phonerlite_terminaison/+210058571@192.168.10.81 [CS_EXECUTE] [NORMAL_CLEARING] freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:654 (sofia/internal/0880022955) State EXCHANGE_MEDIA going to sleep freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/0880022955) Running State Change CS_HANGUP (Cur 2 Tot 1340) freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/0880022955) Callstate Change UNHELD -> HANGUP freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/0880022955) State HANGUP freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] mod_sofia.c:460 Channel sofia/internal/0880022955 hanging up, cause: NORMAL_CLEARING freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:60 sofia/internal/0880022955 Standard HANGUP, cause: NORMAL_CLEARING freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/0880022955) State HANGUP going to sleep freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/0880022955) State Change CS_HANGUP -> CS_REPORTING freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/0880022955) Running State Change CS_REPORTING (Cur 2 Tot 1340) freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/0880022955) State REPORTING freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_ivr_bridge.c:830 sofia/phonerlite_terminaison/+210058571@192.168.10.81 ending bridge by request from read function freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_ivr_bridge.c:916 BRIDGE THREAD DONE [sofia/phonerlite_terminaison/+210058571@192.168.10.81] freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_ivr_bridge.c:1893 sofia/internal/0880022955 skip receive message [UNBRIDGE] (channel is hungup already) freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_ivr_bridge.c:1896 sofia/phonerlite_terminaison/+210058571@192.168.10.81 skip receive message [UNBRIDGE] (channel is hungup already) freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_session.c:2905 sofia/phonerlite_terminaison/+210058571@192.168.10.81 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:651 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State EXECUTE going to sleep freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:585 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Running State Change CS_HANGUP (Cur 2 Tot 1340) freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:848 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Callstate Change ACTIVE -> HANGUP freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:850 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State HANGUP freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] mod_sofia.c:454 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Overriding SIP cause 480 with 200 from the other leg freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] mod_sofia.c:460 Channel sofia/phonerlite_terminaison/+210058571@192.168.10.81 hanging up, cause: NORMAL_CLEARING freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] mod_sofia.c:514 Sending BYE to sofia/phonerlite_terminaison/+210058571@192.168.10.81 freeswitch@freeswitch-1> nua.c:645 nua_bye() nua: nua_bye: entering freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb17000f6a0): recv signal r_bye freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb17000f6a0): sent signal r_bye freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb170014ed0, ...) called freeswitch@freeswitch-1> soa.c:1784 soa_terminate() soa_terminate(static::0x7fb170014ed0) called freeswitch@freeswitch-1> soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7fb170014ed0) called freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:60 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Standard HANGUP, cause: NORMAL_CLEARING freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:850 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State HANGUP going to sleep freeswitch@freeswitch-1> nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb170005ea0) tpn = UDP/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb170005ea0): not found by name UDP/192.168.56.190:5060 freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:620 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State Change CS_HANGUP -> CS_REPORTING freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:585 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Running State Change CS_REPORTING (Cur 2 Tot 1340) freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb170005ea0): 485 bytes of 485 to udp/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 485 freeswitch@freeswitch-1> send 485 bytes to udp/[192.168.56.190]:5060 at 17:04:31.870286: ------------------------------------------------------------------------ BYE sip:+210058571@192.168.56.190:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.10.81;rport;branch=z9hG4bK1Ut9Bc8NFg4jF Max-Forwards: 70 From: ;tag=F0jXK31p7QSpa To: "+210058571" ;tag=3901970572 Call-ID: 00D6417A-6221-ED11-921D-F04C14D7E9D8@192.168.56.190 CSeq: 56079743 BYE User-Agent: Freeswitch SBC Allow: INVITE, ACK, BYE, CANCEL, OPTIONS Supported: timer, path, replaces Reason: Q.850;cause=16 Content-Length: 0 freeswitch@freeswitch-1> nta.c:8310 outgoing_send() nta: sent BYE (56079743) to UDP/192.168.56.190:5060 freeswitch@freeswitch-1> tport.c:4164 tport_pend() tport_pend(0x7fb170005ea0): pending 0x7fb1700139b0 for udp/192.168.10.81:5060 (already 0) freeswitch@freeswitch-1> nta.c:1350 set_timeout() nta: timer set to 32000 ms freeswitch@freeswitch-1> nta.c:1348 set_timeout() nta: timer shortened to 1000 ms freeswitch@freeswitch-1> 2022-08-23 17:04:31.854700 [DEBUG] switch_core_state_machine.c:936 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State REPORTING freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb170005ea0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb170005ea0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb170005ea0) msg 0x7fb170020aa0 from (udp/192.168.10.81:5060) has 387 bytes, veclen = 1 freeswitch@freeswitch-1> recv 387 bytes from udp/[192.168.56.190]:5060 at 17:04:31.874865: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.10.81;rport=5060;branch=z9hG4bK1Ut9Bc8NFg4jF From: ;tag=F0jXK31p7QSpa To: "+210058571" ;tag=3901970572 Call-ID: 00D6417A-6221-ED11-921D-F04C14D7E9D8@192.168.56.190 CSeq: 56079743 BYE Contact: Server: PhonerLite 2.76 Content-Length: 0 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb170005ea0): msg 0x7fb170020aa0 (387 bytes) from udp/192.168.56.190:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (56079743) freeswitch@freeswitch-1> nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction freeswitch@freeswitch-1> nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 4.651 ms freeswitch@freeswitch-1> tport.c:4226 tport_release() tport_release(0x7fb170005ea0): 0x7fb1700139b0 by 0x7fb170022c10 with 0x7fb170020aa0 freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event r_bye 200 OK freeswitch@freeswitch-1> nua_session.c:4143 signal_call_state_change() nua(0x7fb17000f6a0): call state changed: terminating -> terminated freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_state 200 to BYE freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb17000f6a0): event i_terminated 200 to BYE freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7fb17000f6a0): removing session usage freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb170014ed0) called freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7fb170010d80) freeswitch@freeswitch-1> nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7fb17000f6a0 freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb17000f6a0): sent signal r_destroy freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb17000f6a0): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] switch_core_state_machine.c:174 sofia/internal/0880022955 Standard REPORTING, cause: NORMAL_CLEARING freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/0880022955) State REPORTING going to sleep freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/0880022955) State Change CS_REPORTING -> CS_DESTROY freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] switch_core_session.c:1726 Session 1340 (sofia/internal/0880022955) Locked, Waiting on external entities freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [NOTICE] switch_core_session.c:1744 Session 1340 (sofia/internal/0880022955) Ended freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/0880022955 [CS_DESTROY] freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/0880022955) Running State Change CS_DESTROY (Cur 1 Tot 1340) freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/0880022955) State DESTROY freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] mod_sofia.c:365 sofia/internal/0880022955 SOFIA DESTROY freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] switch_core_state_machine.c:181 sofia/internal/0880022955 Standard DESTROY freeswitch@freeswitch-1> 2022-08-23 17:04:32.014713 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/0880022955) State DESTROY going to sleep freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] switch_core_state_machine.c:174 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Standard REPORTING, cause: NORMAL_CLEARING freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] switch_core_state_machine.c:936 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State REPORTING going to sleep freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] switch_core_state_machine.c:611 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State Change CS_REPORTING -> CS_DESTROY freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] switch_core_session.c:1726 Session 1339 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Locked, Waiting on external entities freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [NOTICE] switch_core_session.c:1744 Session 1339 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Ended freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [NOTICE] switch_core_session.c:1748 Close Channel sofia/phonerlite_terminaison/+210058571@192.168.10.81 [CS_DESTROY] freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] switch_core_state_machine.c:739 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) Running State Change CS_DESTROY (Cur 0 Tot 1340) freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] switch_core_state_machine.c:749 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State DESTROY freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] mod_sofia.c:365 sofia/phonerlite_terminaison/+210058571@192.168.10.81 SOFIA DESTROY freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] switch_core_state_machine.c:181 sofia/phonerlite_terminaison/+210058571@192.168.10.81 Standard DESTROY freeswitch@freeswitch-1> 2022-08-23 17:04:32.154688 [DEBUG] switch_core_state_machine.c:749 (sofia/phonerlite_terminaison/+210058571@192.168.10.81) State DESTROY going to sleep freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb184085d40): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb184085d40) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb184085d40) msg 0x7fb184093da0 from (udp/192.168.10.186:5060) has 518 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb184085d40): msg 0x7fb184093da0 (518 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received OPTIONS sip:192.168.10.186:5060 SIP/2.0 (CSeq 200673) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:192.168.10.186:5060 with contact freeswitch@freeswitch-1> nta.c:3085 agent_recv_request() nta: OPTIONS (200673) going to a default leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> nua_stack.c:899 nh_create() nua: nh_create: entering freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb18404a090, 0x7fb184192250, 0x7fb18408dd50) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1840520a0, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb18408dd50): event i_options 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb18408dd50): sent signal r_respond freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb18408dd50): sent signal r_destroy freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb18408dd50): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb1840520a0, ...) called freeswitch@freeswitch-1> soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0x7fb1840520a0, [(nil)], [0x7fb13cadeb48], [0x7fb13cadeb44]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb184085d40) tpn = UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb184085d40): not found by name UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb184085d40): 509 bytes of 509 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 509 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for OPTIONS (200673) freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb18408dd50): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb1840520a0) called freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 4004 ms freeswitch@freeswitch-1> tport.c:2753 tport_wakeup_pri() tport_wakeup_pri(0x7fb1740454e0): events IN freeswitch@freeswitch-1> tport.c:2868 tport_recv_event() tport_recv_event(0x7fb1740454e0) freeswitch@freeswitch-1> tport.c:3209 tport_recv_iovec() tport_recv_iovec(0x7fb1740454e0) msg 0x7fb174057f50 from (udp/192.168.10.185:5060) has 518 bytes, veclen = 1 freeswitch@freeswitch-1> tport.c:3027 tport_deliver() tport_deliver(0x7fb1740454e0): msg 0x7fb174057f50 (518 bytes) from udp/10.0.0.56:5060/sip next=(nil) freeswitch@freeswitch-1> nta.c:2880 agent_recv_request() nta: received OPTIONS sip:192.168.10.185:5060 SIP/2.0 (CSeq 673332) freeswitch@freeswitch-1> nta.c:3248 agent_aliases() nta: canonizing sip:192.168.10.185:5060 with contact freeswitch@freeswitch-1> nta.c:3085 agent_recv_request() nta: OPTIONS (673332) going to a default leg freeswitch@freeswitch-1> nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering freeswitch@freeswitch-1> nua_stack.c:899 nh_create() nua: nh_create: entering freeswitch@freeswitch-1> nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:280 soa_clone() soa_clone(static::0x7fb1740509b0, 0x7fb174053d40, 0x7fb1740535c0) called freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb174048500, ...) called freeswitch@freeswitch-1> nua_stack.c:271 nua_stack_event() nua(0x7fb1740535c0): event i_options 100 Trying freeswitch@freeswitch-1> nua_stack.c:359 nua_application_event() nua: nua_application_event: entering freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:879 nua_respond() nua: nua_respond: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb1740535c0): sent signal r_respond freeswitch@freeswitch-1> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering freeswitch@freeswitch-1> nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering freeswitch@freeswitch-1> nua_stack.c:529 nua_signal() nua(0x7fb1740535c0): sent signal r_destroy freeswitch@freeswitch-1> nua_stack.c:573 nua_stack_signal() nua(0x7fb1740535c0): recv signal r_respond 200 OK freeswitch@freeswitch-1> nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering freeswitch@freeswitch-1> soa.c:403 soa_set_params() soa_set_params(static::0x7fb174048500, ...) called freeswitch@freeswitch-1> soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0x7fb174048500, [(nil)], [0x7fb13ca9fb48], [0x7fb13ca9fb44]) called freeswitch@freeswitch-1> tport.c:3261 tport_tsend() tport_tsend(0x7fb1740454e0) tpn = UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4050 tport_resolve() tport_resolve addrinfo = 10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:4684 tport_by_addrinfo() tport_by_addrinfo(0x7fb1740454e0): not found by name UDP/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3598 tport_vsend() tport_vsend(0x7fb1740454e0): 509 bytes of 509 to udp/10.0.0.56:5060 freeswitch@freeswitch-1> tport.c:3496 tport_send_msg() tport_vsend returned 509 freeswitch@freeswitch-1> nta.c:6797 incoming_reply() nta: sent 200 OK for OPTIONS (673332) freeswitch@freeswitch-1> nua_stack.c:569 nua_stack_signal() nua(0x7fb1740535c0): recv signal r_destroy freeswitch@freeswitch-1> nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) freeswitch@freeswitch-1> soa.c:356 soa_destroy() soa_destroy(static::0x7fb174048500) called freeswitch@freeswitch-1> nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response freeswitch@freeswitch-1> nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fb13cadeb50) freeswitch@freeswitch-1> nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free freeswitch@freeswitch-1> nta.c:1296 agent_timer() nta: timer set next to 29999 ms freeswitch@freeswitch-1>