tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c01c6d0 from (udp/195.74.100.112:5060) has 940 bytes, veclen = 1 recv 940 bytes from udp/[87.127.251.183]:1277 at 14:17:57.950451: ------------------------------------------------------------------------ INVITE sip:03331019574@fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.151:5060;rport;branch=z9hG4bK1801519108 From: "1000" ;tag=1118572399 To: Call-ID: 2_1100593423@10.8.32.151 CSeq: 1 INVITE Contact: Content-Type: application/sdp Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.80.0.137 Allow-Events: talk,hold,conference,refer,check-sync Supported: replaces Content-Length: 304 v=0 o=- 20111 20111 IN IP4 10.8.32.151 s=SDP data c=IN IP4 10.8.32.151 t=0 0 m=audio 11930 RTP/AVP 9 0 8 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c01c6d0 (940 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INVITE sip:03331019574@fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 1) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3085 agent_recv_request() nta: INVITE (1) going to a default leg nta.c:1348 set_timeout() nta: timer shortened to 200 ms nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:899 nh_create() nua: nh_create: entering nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f812c001b10, 0x7f812c001310, 0x7f812c0116a0) called soa.c:403 soa_set_params() soa_set_params(static::0x7f812c011ee0, ...) called nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f812c00e0f0) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f812c011ee0) called soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f812c011ee0, (nil), 0x7f812c019a2c, 304) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f812c0116a0): adding session usage nua_stack.c:271 nua_stack_event() nua(0x7f812c0116a0): event i_invite 100 Trying nua_session.c:4139 signal_call_state_change() nua(0x7f812c0116a0): call state changed: init -> received, received offer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f812c011ee0, [0x7f813111b8d8], [0x7f813111b8e0], [(nil)]) called nua_stack.c:271 nua_stack_event() nua(0x7f812c0116a0): event i_state 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering 2017-09-05 14:17:57.946224 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 [b0c70bf2-9b56-4421-ab85-5336899fafdc] nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2017-09-05 14:17:57.946224 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Running State Change CS_NEW (Cur 1 Tot 7) nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:57.946224 [DEBUG] sofia.c:10067 sofia/internal/1000@fspbx1.evoip.enta.net:5060 receiving invite from 87.127.251.183:1277 version: 1.9.0 -556-68fc3b5 64bit 2017-09-05 14:17:57.946224 [DEBUG] sofia.c:10238 IP 87.127.251.183 Rejected by acl "domains". Falling back to Digest auth. nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c0116a0): recv signal r_respond 407 Proxy Authentication Required nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c011ee0, ...) called nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f812c011ee0) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 874 bytes of 874 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 874 send 874 bytes to udp/[87.127.251.183]:1277 at 14:17:57.954156: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.8.32.151:5060;rport=1277;branch=z9hG4bK1801519108;received=87.127.251.183 From: "1000" ;tag=1118572399 To: ;tag=m33NFK15p62yr Call-ID: 2_1100593423@10.8.32.151 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="fspbx1.evoip.enta.net", nonce="21e292a6-2542-4628-ae3f-2b3b4bcdee63", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (1) nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f812c0116a0): removing session usage nua_session.c:4139 signal_call_state_change() nua(0x7f812c0116a0): call state changed: received -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f812c0116a0): event i_state 407 Proxy Authentication Required nua_stack.c:271 nua_stack_event() nua(0x7f812c0116a0): event i_terminated 407 Proxy Authentication Required soa.c:356 soa_destroy() soa_destroy(static::0x7f812c011ee0) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f812c00e0f0) nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2017-09-05 14:17:57.946224 [DEBUG] sofia.c:2405 detaching session b0c70bf2-9b56-4421-ab85-5336899fafdc nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:529 nua_signal() nua(0x7f812c0116a0): sent signal r_destroy nua_stack.c:569 nua_stack_signal() nua(0x7f812c0116a0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) nua_stack.c:529 nua_signal() nua(0x7f812c0116a0): sent signal r_respond nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering 2017-09-05 14:17:57.946224 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State NEW tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c0126a0 from (udp/195.74.100.112:5060) has 326 bytes, veclen = 1 recv 326 bytes from udp/[87.127.251.183]:1277 at 14:17:57.960315: ------------------------------------------------------------------------ ACK sip:03331019574@fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.151:5060;rport;branch=z9hG4bK1801519108 From: "1000" ;tag=1118572399 To: ;tag=m33NFK15p62yr Call-ID: 2_1100593423@10.8.32.151 CSeq: 1 ACK Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c0126a0 (326 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received ACK sip:03331019574@fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 1) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3019 agent_recv_request() nta: ACK (1) is going to INVITE (1) tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c0126a0 from (udp/195.74.100.112:5060) has 1214 bytes, veclen = 1 recv 1214 bytes from udp/[87.127.251.183]:1277 at 14:17:57.967938: ------------------------------------------------------------------------ INVITE sip:03331019574@fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.151:5060;rport;branch=z9hG4bK4245134600 From: "1000" ;tag=1118572399 To: Call-ID: 2_1100593423@10.8.32.151 CSeq: 2 INVITE Contact: Proxy-Authorization: Digest username="1000", realm="fspbx1.evoip.enta.net", nonce="21e292a6-2542-4628-ae3f-2b3b4bcdee63", uri="sip:03331019574@fspbx1.evoip.enta.net:5060", response="5c8c1d3c1e93369dd6e29c7481d3e6fe", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000001 Content-Type: application/sdp Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.80.0.137 Allow-Events: talk,hold,conference,refer,check-sync Supported: replaces Content-Length: 304 v=0 o=- 20111 20111 IN IP4 10.8.32.151 s=SDP data c=IN IP4 10.8.32.151 t=0 0 m=audio 11930 RTP/AVP 9 0 8 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c0126a0 (1214 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INVITE sip:03331019574@fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 2) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3085 agent_recv_request() nta: INVITE (2) going to a default leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:899 nh_create() nua: nh_create: entering nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f812c001b10, 0x7f812c001310, 0x7f812c014200) called soa.c:403 soa_set_params() soa_set_params(static::0x7f812c0281e0, ...) called nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f812c0234c0) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f812c0281e0) called soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f812c0281e0, (nil), 0x7f812c012dde, 304) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f812c014200): adding session usage nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_invite 100 Trying nua_session.c:4139 signal_call_state_change() nua(0x7f812c014200): call state changed: init -> received, received offer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f812c0281e0, [0x7f813111b8d8], [0x7f813111b8e0], [(nil)]) called nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_state 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering 2017-09-05 14:17:57.966225 [DEBUG] sofia.c:2514 Re-attaching to session b0c70bf2-9b56-4421-ab85-5336899fafdc nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:57.966225 [DEBUG] sofia.c:10067 sofia/internal/1000@fspbx1.evoip.enta.net:5060 receiving invite from 87.127.251.183:1277 version: 1.9.0 -556-68fc3b5 64bit 2017-09-05 14:17:57.966225 [DEBUG] sofia.c:10238 IP 87.127.251.183 Rejected by acl "domains". Falling back to Digest auth. 2017-09-05 14:17:57.966225 [DEBUG] sofia.c:11366 Setting NAT mode based on nat.auto nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:57.966225 [DEBUG] sofia.c:7283 Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 entering state [received][100] 2017-09-05 14:17:57.966225 [DEBUG] sofia.c:7293 Remote SDP: v=0 o=- 20111 20111 IN IP4 10.8.32.151 s=SDP data c=IN IP4 10.8.32.151 t=0 0 m=audio 11930 RTP/AVP 9 0 8 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2017-09-05 14:17:57.966225 [DEBUG] sofia.c:7685 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State Change CS_NEW -> CS_INIT nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Running State Change CS_INIT (Cur 1 Tot 7) 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State INIT 2017-09-05 14:17:57.966225 [DEBUG] mod_sofia.c:93 sofia/internal/1000@fspbx1.evoip.enta.net:5060 SOFIA INIT 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Standard INIT 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State Change CS_INIT -> CS_ROUTING 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State INIT going to sleep 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Running State Change CS_ROUTING (Cur 1 Tot 7) 2017-09-05 14:17:57.966225 [DEBUG] switch_channel.c:2249 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Callstate Change DOWN -> RINGING 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State ROUTING nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c014200): recv signal r_respond 100 Trying nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c0281e0, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 362 bytes of 362 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 362 send 362 bytes to udp/[87.127.251.183]:1277 at 14:17:57.977325: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.8.32.151:5060;rport=1277;branch=z9hG4bK4245134600;received=87.127.251.183 From: "1000" ;tag=1118572399 To: Call-ID: 2_1100593423@10.8.32.151 CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (2) nua_stack.c:529 nua_signal() nua(0x7f812c014200): sent signal r_respond 2017-09-05 14:17:57.966225 [DEBUG] mod_sofia.c:154 sofia/internal/1000@fspbx1.evoip.enta.net:5060 SOFIA ROUTING 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Standard ROUTING 2017-09-05 14:17:57.966225 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->03331019574 in context public Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 parsing [public->unloop] continue=false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 parsing [public->outside_call] continue=true Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Absolute Condition [outside_call] Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Action set(outside_call=true) Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 parsing [public->call_debug] continue=true Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 parsing [public->public_extensions] continue=false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Regex (FAIL) [public_extensions] destination_number(03331019574) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 parsing [public->public_did] continue=false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Regex (FAIL) [public_did] destination_number(03331019574) =~ /^(5551212)$/ break=on-false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 parsing [public->ddi out] continue=false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Regex (PASS) [ddi out] destination_number(03331019574) =~ /^(\d{6,})$/ break=on-false Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Action set(effective_caller_id_number=441156870140) Dialplan: sofia/internal/1000@fspbx1.evoip.enta.net:5060 Action bridge(sofia/gateway/entanet/03331019574) 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State Change CS_ROUTING -> CS_EXECUTE 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State ROUTING going to sleep 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Running State Change CS_EXECUTE (Cur 1 Tot 7) 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State EXECUTE 2017-09-05 14:17:57.966225 [DEBUG] mod_sofia.c:209 sofia/internal/1000@fspbx1.evoip.enta.net:5060 SOFIA EXECUTE 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Standard EXECUTE EXECUTE sofia/internal/1000@fspbx1.evoip.enta.net:5060 set(outside_call=true) 2017-09-05 14:17:57.966225 [DEBUG] mod_dptools.c:1588 SET sofia/internal/1000@fspbx1.evoip.enta.net:5060 [outside_call]=[true] EXECUTE sofia/internal/1000@fspbx1.evoip.enta.net:5060 export(RFC2822_DATE=Tue, 05 Sep 2017 14:17:57 +0000) 2017-09-05 14:17:57.966225 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 05 Sep 2017 14:17:57 +0000] EXECUTE sofia/internal/1000@fspbx1.evoip.enta.net:5060 set(hangup_after_bridge=true) 2017-09-05 14:17:57.966225 [DEBUG] mod_dptools.c:1588 SET sofia/internal/1000@fspbx1.evoip.enta.net:5060 [hangup_after_bridge]=[true] EXECUTE sofia/internal/1000@fspbx1.evoip.enta.net:5060 set(effective_caller_id_number=441156870140) 2017-09-05 14:17:57.966225 [DEBUG] mod_dptools.c:1588 SET sofia/internal/1000@fspbx1.evoip.enta.net:5060 [effective_caller_id_number]=[441156870140] EXECUTE sofia/internal/1000@fspbx1.evoip.enta.net:5060 bridge(sofia/gateway/entanet/03331019574) 2017-09-05 14:17:57.966225 [DEBUG] switch_channel.c:1250 sofia/internal/1000@fspbx1.evoip.enta.net:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 05 Sep 2017 14:17:57 +0000] to event 2017-09-05 14:17:57.966225 [DEBUG] switch_ivr_originate.c:2157 Parsing global variables 2017-09-05 14:17:57.966225 [NOTICE] switch_channel.c:1104 New Channel sofia/external/03331019574 [123b8876-f919-45a4-80ac-7290fad950f6] 2017-09-05 14:17:57.966225 [DEBUG] mod_sofia.c:5026 (sofia/external/03331019574) State Change CS_NEW -> CS_INIT 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:584 (sofia/external/03331019574) Running State Change CS_INIT (Cur 2 Tot 8) 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:627 (sofia/external/03331019574) State INIT 2017-09-05 14:17:57.966225 [DEBUG] mod_sofia.c:93 sofia/external/03331019574 SOFIA INIT nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering 2017-09-05 14:17:57.966225 [DEBUG] sofia_glue.c:1299 sofia/external/03331019574 sending invite version: 1.9.0 -556-68fc3b5 64bit Local SDP: v=0 o=FreeSWITCH 1504592205 1504592206 IN IP4 195.74.100.112 s=FreeSWITCH c=IN IP4 195.74.100.112 t=0 0 m=audio 28872 RTP/AVP 9 0 8 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv nua.c:633 nua_invite() nua: nua_invite: entering nua_stack.c:569 nua_stack_signal() nua(0x7f8128007c00): recv signal r_invite nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f8118036f30, 0x7f8118004e40, 0x7f8128007c00) called soa.c:403 soa_set_params() soa_set_params(static::0x7f8118084a90, ...) called soa.c:403 soa_set_params() soa_set_params(static::0x7f8118084a90, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f8118084a90, (nil), 0x7f81280082ce, -1) called soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f8118084a90, (nil), 0x7f81280082ce, -1) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f8128007c00): adding session usage nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f8118084980) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f8118084a90) called soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7f8118084a90, 0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f8118084a90, soa_generate_offer): called soa_static.c:1189 offer_answer_step() soa_static(0x7f8118084a90, soa_generate_offer): generating local description soa_static.c:1217 offer_answer_step() soa_static(0x7f8118084a90, soa_generate_offer): upgrade with local description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f813165ba70, (nil), ""): called soa_static.c:1446 offer_answer_step() soa_static(0x7f8118084a90, soa_generate_offer): storing local description soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f8118084a90, [(nil)], [0x7f813165dbf8], [0x7f813165dbf4]) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, NAPTR, "EN33510464.voip-portal.co.uk.") called nta.c:10404 outgoing_query_naptr() nta: for "EN33510464.voip-portal.co.uk" query "EN33510464.voip-portal.co.uk" NAPTR sres.c:968 sres_query() sres_query(0x7f8118037e00, 0x7f8118080680, NAPTR, "EN33510464.voip-portal.co.uk") called sres.c:2730 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f811803d8d0) called sres.c:2819 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f811803d8d0) id=62402 NAPTR EN33510464.voip-portal.co.uk (to [195.74.100.89]:53) nua_session.c:4139 signal_call_state_change() nua(0x7f8128007c00): call state changed: init -> calling, sent offer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f8118084a90, [0x7f813165dbd8], [0x7f813165dbe0], [(nil)]) called nua_stack.c:269 nua_stack_event() nua(0x7f8128007c00): event i_state INVITE sent nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f8128007c00): sent signal r_invite 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:40 sofia/external/03331019574 Standard INIT 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:48 (sofia/external/03331019574) State Change CS_INIT -> CS_ROUTING 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:627 (sofia/external/03331019574) State INIT going to sleep 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:584 (sofia/external/03331019574) Running State Change CS_ROUTING (Cur 2 Tot 8) nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:57.966225 [DEBUG] sofia.c:7283 Channel sofia/external/03331019574 entering state [calling][0] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:643 (sofia/external/03331019574) State ROUTING 2017-09-05 14:17:57.966225 [DEBUG] mod_sofia.c:154 sofia/external/03331019574 SOFIA ROUTING 2017-09-05 14:17:57.966225 [DEBUG] switch_ivr_originate.c:67 (sofia/external/03331019574) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:643 (sofia/external/03331019574) State ROUTING going to sleep 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:584 (sofia/external/03331019574) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 8) 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:662 (sofia/external/03331019574) State CONSUME_MEDIA 2017-09-05 14:17:57.966225 [DEBUG] switch_core_state_machine.c:662 (sofia/external/03331019574) State CONSUME_MEDIA going to sleep sres.c:3467 sres_resolver_receive() sres_resolver_receive(0x7f8118037e00, 53) called sres.c:3781 sres_create_record() ANSWER RR received EN33510464.voip-portal.co.uk. CNAME IN 46 rdlen=10 sres.c:3781 sres_create_record() AUTHORITY RR received voip-portal.co.uk. SOA IN 10 rdlen=46 sres.c:3572 sres_log_response() sres_resolver_receive(0x7f8118037e00, 0x7f811803d8d0) id=62402 (from [195.74.100.89]:53) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, NAPTR, "sipgate.voip-portal.co.uk.") called sres.c:2730 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f811803f2d0) called sres.c:2819 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f811803f2d0) id=62403 NAPTR sipgate.voip-portal.co.uk. (to [195.74.100.89]:53) sres.c:3467 sres_resolver_receive() sres_resolver_receive(0x7f8118037e00, 53) called sres.c:3781 sres_create_record() AUTHORITY RR received voip-portal.co.uk. SOA IN 10 rdlen=46 sres.c:3572 sres_log_response() sres_resolver_receive(0x7f8118037e00, 0x7f811803f2d0) id=62403 (from [195.74.100.89]:53) sres.c:2987 sres_query_report_error() sres(q=0x7f811803f2d0): reporting error RECORD_ERR for NAPTR sipgate.voip-portal.co.uk. sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10604 outgoing_query_srv() nta: for "EN33510464.voip-portal.co.uk" query "_sip._udp.EN33510464.voip-portal.co.uk" SRV (cached) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10809 outgoing_query_a() nta: for "EN33510464.voip-portal.co.uk" query "EN33510464.voip-portal.co.uk" A (cached) nta.c:10862 outgoing_answer_a() nta: sipgate.voip-portal.co.uk. IN A 195.74.100.80 tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 1170 bytes of 1170 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1170 send 1170 bytes to udp/[195.74.100.80]:5060 at 14:17:57.986565: ------------------------------------------------------------------------ INVITE sip:03331019574@EN33510464.voip-portal.co.uk SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK5B8aH1gNg046H Max-Forwards: 69 From: "Extension 1000" ;tag=tFge5351jXBeH To: Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974474 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 272 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1000" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1504592205 1504592206 IN IP4 195.74.100.112 s=FreeSWITCH c=IN IP4 195.74.100.112 t=0 0 m=audio 28872 RTP/AVP 9 0 8 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent INVITE (111974474) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808fb60 for udp/195.74.100.112:5080 (already 0) nta.c:1350 set_timeout() nta: timer set to 32000 ms nta.c:1348 set_timeout() nta: timer shortened to 1000 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f811803e800 from (udp/195.74.100.112:5080) has 385 bytes, veclen = 1 recv 385 bytes from udp/[195.74.100.80]:5060 at 14:17:57.997273: ------------------------------------------------------------------------ SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bK5B8aH1gNg046H From: "Extension 1000" ;tag=tFge5351jXBeH To: Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974474 INVITE Server: Entanet SIP Proxy V8.24 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f811803e800 (385 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 100 Giving a try for INVITE (111974474) nta.c:3366 agent_recv_response() nta: 100 Giving a try is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 10.837 ms tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808fb60 by 0x7f8118080680 with 0x7f811803e800 (preliminary) tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f811803e800 from (udp/195.74.100.112:5080) has 1260 bytes, veclen = 1 recv 1260 bytes from udp/[195.74.100.80]:5060 at 14:17:58.116159: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bK5B8aH1gNg046H Record-Route: Record-Route: From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974474 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19-36-7a77e0b~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 X-FS-Display-Name: +443331019574 X-FS-Display-Number: sip:+443331019574@EN33510464.voip-portal.co.uk X-FS-Support: update_display,send_info Remote-Party-ID: "+443331019574" ;party=calling;privacy=off;screen=no ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f811803e800 (1260 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (111974474) nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808fb60 by 0x7f8118080680 with 0x7f811803e800 (preliminary) nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event r_invite 180 Ringing nua_session.c:4139 signal_call_state_change() nua(0x7f8128007c00): call state changed: calling -> proceeding nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event i_state 180 Ringing nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:58.106226 [INFO] sofia.c:1348 sofia/external/03331019574 Update Callee ID to "+443331019574" nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:58.106226 [DEBUG] sofia.c:7283 Channel sofia/external/03331019574 entering state [proceeding][180] 2017-09-05 14:17:58.106226 [NOTICE] sofia.c:7391 Ring-Ready sofia/external/03331019574! 2017-09-05 14:17:58.106226 [DEBUG] switch_channel.c:3354 (sofia/external/03331019574) Callstate Change DOWN -> RINGING nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c014200): recv signal r_respond 180 Ringing nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c0281e0, ...) called nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 895 bytes of 895 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 895 send 895 bytes to udp/[87.127.251.183]:1277 at 14:17:58.125140: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.8.32.151:5060;rport=1277;branch=z9hG4bK4245134600;received=87.127.251.183 From: "1000" ;tag=1118572399 To: ;tag=NcXeHej9KFSHm Call-ID: 2_1100593423@10.8.32.151 CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 Remote-Party-ID: "+443331019574" ;party=calling;privacy=off;screen=no ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 180 Ringing for INVITE (2) nua_session.c:4139 signal_call_state_change() nua(0x7f812c014200): call state changed: received -> early nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_state 180 Ringing nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f812c014200): sent signal r_respond 2017-09-05 14:17:58.106226 [NOTICE] mod_sofia.c:2417 Ring-Ready sofia/internal/1000@fspbx1.evoip.enta.net:5060! nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:58.106226 [DEBUG] sofia.c:7283 Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 entering state [early][180] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:17:58.106226 [NOTICE] switch_ivr_originate.c:527 Ring Ready sofia/internal/1000@fspbx1.evoip.enta.net:5060! nta.c:1296 agent_timer() nta: timer set next to 4809 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c029a30 from (udp/195.74.100.112:5060) has 4 bytes, veclen = 1 tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): bad msg 0x7f812c029a30 (4 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:1289 agent_timer() nta: timer not set nta.c:7140 _nta_incoming_timer() nta: timer I fired, terminate 407 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813111bc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/5 term, 1/6 free nta.c:1296 agent_timer() nta: timer set next to 6111 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c027dd0 from (udp/195.74.100.112:5060) has 844 bytes, veclen = 1 recv 844 bytes from udp/[87.127.251.183]:1272 at 14:18:07.068363: ------------------------------------------------------------------------ REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.108:5060;branch=z9hG4bK2822826693;rport From: "1001" ;tag=4288287416 To: "1001" Call-ID: 2_2750365493@10.8.32.108 CSeq: 119 REGISTER Contact: Authorization: Digest username="1001", realm="fspbx1.evoip.enta.net", nonce="c7cb569d-64b5-4376-be1f-14c4d91114db", uri="sip:fspbx1.evoip.enta.net:5060", response="cafb6465b6aab6c65c7621d73af79ba8", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000039 Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.81.0.70 Expires: 60 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c027dd0 (844 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 119) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3085 agent_recv_request() nta: REGISTER (119) going to a default leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:899 nh_create() nua: nh_create: entering nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f812c001b10, 0x7f812c001310, 0x7f812c0106e0) called soa.c:403 soa_set_params() soa_set_params(static::0x7f812c01c6d0, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f812c0106e0): event i_register 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c0106e0): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c01c6d0, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1272 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1272 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1272 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 613 bytes of 613 to udp/87.127.251.183:1272 tport.c:3492 tport_send_msg() tport_vsend returned 613 send 613 bytes to udp/[87.127.251.183]:1272 at 14:18:07.076645: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.8.32.108:5060;branch=z9hG4bK2822826693;rport=1272;received=87.127.251.183 From: "1001" ;tag=4288287416 To: "1001" ;tag=pNp7j92cHrF4F Call-ID: 2_2750365493@10.8.32.108 CSeq: 119 REGISTER Contact: ;expires=30 Date: Tue, 05 Sep 2017 14:18:07 GMT User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for REGISTER (119) nua_stack.c:529 nua_signal() nua(0x7f812c0106e0): sent signal r_respond nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f812c0106e0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7f812c01c6d0) called nua_stack.c:529 nua_signal() nua(0x7f812c0106e0): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c0197c0 from (udp/195.74.100.112:5060) has 4 bytes, veclen = 1 tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): bad msg 0x7f812c0197c0 (4 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813111bc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/5 term, 1/6 free nta.c:1296 agent_timer() nta: timer set next to 2711 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c017b90 from (udp/195.74.100.112:5060) has 846 bytes, veclen = 1 recv 846 bytes from udp/[87.127.251.183]:1277 at 14:18:09.785101: ------------------------------------------------------------------------ REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.151:5060;rport;branch=z9hG4bK3039063866 From: "1000" ;tag=964408845 To: "1000" Call-ID: 2_4292396569@10.8.32.151 CSeq: 229 REGISTER Contact: Authorization: Digest username="1000", realm="fspbx1.evoip.enta.net", nonce="9adf1b08-8976-4bbd-817c-d3dce30ac1dc", uri="sip:fspbx1.evoip.enta.net:5060", response="896cf9be928fef1c453cbecaaaed948e", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000020 Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.80.0.137 Expires: 3600 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c017b90 (846 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 229) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3085 agent_recv_request() nta: REGISTER (229) going to a default leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:899 nh_create() nua: nh_create: entering nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f812c001b10, 0x7f812c001310, 0x7f812c0197c0) called soa.c:403 soa_set_params() soa_set_params(static::0x7f812c020190, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f812c0197c0): event i_register 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c0197c0): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c020190, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 612 bytes of 612 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 612 send 612 bytes to udp/[87.127.251.183]:1277 at 14:18:09.800361: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.8.32.151:5060;rport=1277;branch=z9hG4bK3039063866;received=87.127.251.183 From: "1000" ;tag=964408845 To: "1000" ;tag=QyF0m4Kge15pB Call-ID: 2_4292396569@10.8.32.151 CSeq: 229 REGISTER Contact: ;expires=30 Date: Tue, 05 Sep 2017 14:18:09 GMT User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for REGISTER (229) nua_stack.c:529 nua_signal() nua(0x7f812c0197c0): sent signal r_respond nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f812c0197c0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7f812c020190) called nua_stack.c:529 nua_signal() nua(0x7f812c0197c0): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(sip:EN33510464.voip-portal.co.uk:c776fa8e8152b37e) = 3d06e695d593a7eac66b7bf7d73ab105 auth_digest.c:318 auth_digest_response() A2 = MD5(REGISTER:sip:EN33510464.voip-portal.co.uk;transport=udp) auth_digest.c:348 auth_digest_response() auth_response: 692f4d6290267e9166d17712d16e2b30 = MD5(3d06e695d593a7eac66b7bf7d73ab105:59aeb21600015ae65d051487785d822c9e76a5fbdb307e8b:e74b8fa4c49b2545abc7114a4258522e) (qop=NONE) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10604 outgoing_query_srv() nta: for "EN33510464.voip-portal.co.uk" query "_sip._udp.EN33510464.voip-portal.co.uk" SRV (cached) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10809 outgoing_query_a() nta: for "EN33510464.voip-portal.co.uk" query "EN33510464.voip-portal.co.uk" A (cached) nta.c:10862 outgoing_answer_a() nta: sipgate.voip-portal.co.uk. IN A 195.74.100.80 tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = udp/195.74.100.80:5060/sip tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name udp/195.74.100.80:5060/sip tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 874 bytes of 874 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 874 send 874 bytes to udp/[195.74.100.80]:5060 at 14:18:10.009051: ------------------------------------------------------------------------ REGISTER sip:EN33510464.voip-portal.co.uk;transport=udp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK6m13jv1rD9tSD Max-Forwards: 70 From: ;tag=KgZ0r6F96yFBg To: Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974228 REGISTER Contact: Expires: 3600 User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Authorization: Digest username="sip", realm="EN33510464.voip-portal.co.uk", nonce="59aeb21600015ae65d051487785d822c9e76a5fbdb307e8b", algorithm=MD5, uri="sip:EN33510464.voip-portal.co.uk;transport=udp", response="692f4d6290267e9166d17712d16e2b30" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent REGISTER (111974228) to udp/195.74.100.80:5060/sip tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f81180854c0 for udp/195.74.100.112:5080 (already 1) nta.c:1350 set_timeout() nta: timer set to 32000 ms nta.c:1348 set_timeout() nta: timer shortened to 1000 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f8118042100 from (udp/195.74.100.112:5080) has 537 bytes, veclen = 1 recv 537 bytes from udp/[195.74.100.80]:5060 at 14:18:10.018926: ------------------------------------------------------------------------ SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bK6m13jv1rD9tSD From: ;tag=KgZ0r6F96yFBg To: ;tag=a5e8f5e9ef62e93eca305ef64f43c9c0.c45e Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974228 REGISTER WWW-Authenticate: Digest realm="EN33510464.voip-portal.co.uk", nonce="59aeb23100015b0b3d886c2d1d8d590b7fea74c428d50eb6", stale=true Server: Entanet SIP Proxy V8.24 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f8118042100 (537 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 401 Unauthorized for REGISTER (111974228) nta.c:3366 agent_recv_response() nta: 401 Unauthorized is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 10.013 ms tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f81180854c0 by 0x7f81180f1130 with 0x7f8118042100 auth_digest.c:105 auth_digest_challenge_get() auth_digest_challenge_get(): got 3 auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(sip:EN33510464.voip-portal.co.uk:c776fa8e8152b37e) = 3d06e695d593a7eac66b7bf7d73ab105 auth_digest.c:318 auth_digest_response() A2 = MD5(REGISTER:sip:EN33510464.voip-portal.co.uk;transport=udp) auth_digest.c:348 auth_digest_response() auth_response: 48a53bf9f50d0fd1ab6486abd47d6a1c = MD5(3d06e695d593a7eac66b7bf7d73ab105:59aeb23100015b0b3d886c2d1d8d590b7fea74c428d50eb6:e74b8fa4c49b2545abc7114a4258522e) (qop=NONE) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10604 outgoing_query_srv() nta: for "EN33510464.voip-portal.co.uk" query "_sip._udp.EN33510464.voip-portal.co.uk" SRV (cached) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10809 outgoing_query_a() nta: for "EN33510464.voip-portal.co.uk" query "EN33510464.voip-portal.co.uk" A (cached) nta.c:10862 outgoing_answer_a() nta: sipgate.voip-portal.co.uk. IN A 195.74.100.80 tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = udp/195.74.100.80:5060/sip tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name udp/195.74.100.80:5060/sip tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 874 bytes of 874 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 874 send 874 bytes to udp/[195.74.100.80]:5060 at 14:18:10.019189: ------------------------------------------------------------------------ REGISTER sip:EN33510464.voip-portal.co.uk;transport=udp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK7XtvmQjvajHcS Max-Forwards: 70 From: ;tag=KgZ0r6F96yFBg To: Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974229 REGISTER Contact: Expires: 3600 User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Authorization: Digest username="sip", realm="EN33510464.voip-portal.co.uk", nonce="59aeb23100015b0b3d886c2d1d8d590b7fea74c428d50eb6", algorithm=MD5, uri="sip:EN33510464.voip-portal.co.uk;transport=udp", response="48a53bf9f50d0fd1ab6486abd47d6a1c" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent REGISTER (111974229) to udp/195.74.100.80:5060/sip tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f81180416f0 for udp/195.74.100.112:5080 (already 1) nua_stack.c:271 nua_stack_event() nua(0x7f812005c5d0): event r_register 100 Request Authorized by Cache nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f8118070990 from (udp/195.74.100.112:5080) has 481 bytes, veclen = 1 recv 481 bytes from udp/[195.74.100.80]:5060 at 14:18:10.032294: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bK7XtvmQjvajHcS From: ;tag=KgZ0r6F96yFBg To: ;tag=a5e8f5e9ef62e93eca305ef64f43c9c0.9d5c Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974229 REGISTER Contact: ;q=0;expires=60 Server: Entanet SIP Proxy V8.24 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f8118070990 (481 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for REGISTER (111974229) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 13.196 ms tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f81180416f0 by 0x7f8118065de0 with 0x7f8118070990 nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh register after 17 seconds (in [15..45]) nua_stack.c:271 nua_stack_event() nua(0x7f812005c5d0): event r_register 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:10.006225 [DEBUG] sofia_reg.c:2435 Changing expire time to 60 by request of proxy sip:EN33510464.voip-portal.co.uk nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nta.c:1296 agent_timer() nta: timer set next to 4010 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f81180664c0 from (udp/195.74.100.112:5080) has 1511 bytes, veclen = 1 recv 1511 bytes from udp/[195.74.100.80]:5060 at 14:18:11.410425: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bK5B8aH1gNg046H Record-Route: Record-Route: From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974474 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19-36-7a77e0b~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 222 X-FS-Display-Name: 443331019574 X-FS-Display-Number: sip:443331019574@EN33510464.voip-portal.co.uk X-FS-Support: update_display,send_info Remote-Party-ID: "443331019574" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1504601255 1504601256 IN IP4 195.74.100.81 s=FreeSWITCH c=IN IP4 195.74.100.81 t=0 0 m=audio 19836 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f81180664c0 (1511 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (111974474) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808fb60 by 0x7f8118080680 with 0x7f81180664c0 soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f8118084a90, (nil), 0x7f8118087b89, 222) called soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f8118084a90) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f8118084a90, soa_process_answer): called soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f811803df50, 0x7f8118082f70, ""): called soa_static.c:1304 offer_answer_step() soa_static(0x7f8118084a90, soa_process_answer): upgrade codecs with remote description soa_static.c:1446 offer_answer_step() soa_static(0x7f8118084a90, soa_process_answer): storing local description soa.c:1730 soa_activate() soa_activate(static::0x7f8118084a90, (nil)) called nua_session.c:988 nua_session_client_response() nua(0x7f8128007c00): INVITE: processed SDP answer in 200 OK nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event r_invite 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7f8128007c00): call state changed: proceeding -> completing, received answer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f8118084a90, [0x7f813165d608], [0x7f813165d610], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7f8118084a90, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event i_state 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.406226 [INFO] sofia.c:1348 sofia/external/03331019574 Update Callee ID to "443331019574" nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.406226 [DEBUG] sofia.c:7283 Channel sofia/external/03331019574 entering state [completing][200] 2017-09-05 14:18:11.406226 [DEBUG] sofia.c:7293 Remote SDP: v=0 o=FreeSWITCH 1504601255 1504601256 IN IP4 195.74.100.81 s=FreeSWITCH c=IN IP4 195.74.100.81 t=0 0 m=audio 19836 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 nua.c:639 nua_ack() nua: nua_ack: entering nua_stack.c:569 nua_stack_signal() nua(0x7f8128007c00): recv signal r_ack nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f8118084a90, ...) called soa.c:1730 soa_activate() soa_activate(static::0x7f8118084a90, (nil)) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 624 bytes of 624 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 624 send 624 bytes to udp/[195.74.100.80]:5060 at 14:18:11.413200: ------------------------------------------------------------------------ ACK sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK86KNpj3Z7t7ym Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974474 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent ACK (111974474) to */195.74.100.80:5060 nua_session.c:4139 signal_call_state_change() nua(0x7f8128007c00): call state changed: completing -> ready nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event i_state 200 ACK sent nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event i_active 200 Call active nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f8128007c00): sent signal r_ack nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.406226 [DEBUG] sofia.c:7283 Channel sofia/external/03331019574 entering state [ready][200] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5170 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5031 Set telephone-event payload to 101@8000 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:3430 Set Codec sofia/external/03331019574 G722/8000 20 ms 160 samples 64000 bits 1 channels 2017-09-05 14:18:11.406226 [DEBUG] switch_core_codec.c:111 sofia/external/03331019574 Original read codec set to G722:9 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5374 Set telephone-event payload to 101@8000 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5432 sofia/external/03331019574 Set 2833 dtmf send payload to 101 recv payload to 101 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8149 AUDIO RTP [sofia/external/03331019574] 195.74.100.112 port 28872 -> 195.74.100.81 port 19836 codec: 9 ms: 20 2017-09-05 14:18:11.406226 [DEBUG] switch_rtp.c:4164 Starting timer [soft] 160 bytes per 20ms 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8453 sofia/external/03331019574 Set 2833 dtmf send payload to 101 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8460 sofia/external/03331019574 Set 2833 dtmf receive payload to 101 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8483 sofia/external/03331019574 Set rtp dtmf delay to 40 2017-09-05 14:18:11.406226 [NOTICE] sofia.c:8419 Channel [sofia/external/03331019574] has been answered 2017-09-05 14:18:11.406226 [DEBUG] switch_channel.c:3781 (sofia/external/03331019574) Callstate Change RINGING -> ACTIVE nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5170 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5170 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5170 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5031 Set telephone-event payload to 101@8000 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:3430 Set Codec sofia/internal/1000@fspbx1.evoip.enta.net:5060 G722/8000 20 ms 160 samples 64000 bits 1 channels 2017-09-05 14:18:11.406226 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Original read codec set to G722:9 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5374 Set telephone-event payload to 101@8000 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:5432 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Set 2833 dtmf send payload to 101 recv payload to 101 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8149 AUDIO RTP [sofia/internal/1000@fspbx1.evoip.enta.net:5060] 195.74.100.112 port 21592 -> 10.8.32.151 port 11930 codec: 9 ms: 20 2017-09-05 14:18:11.406226 [DEBUG] switch_rtp.c:4164 Starting timer [soft] 160 bytes per 20ms 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8453 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Set 2833 dtmf send payload to 101 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8460 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Set 2833 dtmf receive payload to 101 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8483 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Set rtp dtmf delay to 40 2017-09-05 14:18:11.406226 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@fspbx1.evoip.enta.net:5060! 2017-09-05 14:18:11.406226 [DEBUG] switch_channel.c:3482 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Callstate Change RINGING -> EARLY 2017-09-05 14:18:11.406226 [DEBUG] switch_core_media.c:8132 Audio params are unchanged for sofia/internal/1000@fspbx1.evoip.enta.net:5060. 2017-09-05 14:18:11.406226 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/1000@fspbx1.evoip.enta.net:5060: v=0 o=FreeSWITCH 1504599499 1504599500 IN IP4 195.74.100.112 s=FreeSWITCH c=IN IP4 195.74.100.112 t=0 0 m=audio 21592 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c014200): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c0281e0, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f812c0281e0, (nil), 0x7f811c05b968, -1) called soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f812c0281e0, (nil), 0x7f811c05b968, -1) called nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7f812c0281e0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f812c0281e0, soa_generate_answer): called soa_static.c:1189 offer_answer_step() soa_static(0x7f812c0281e0, soa_generate_answer): generating local description soa_static.c:1230 offer_answer_step() soa_static(0x7f812c0281e0, soa_generate_answer): upgrade with remote description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f8131119ab0, 0x7f812c029350, ""): called soa_static.c:1446 offer_answer_step() soa_static(0x7f812c0281e0, soa_generate_answer): storing local description soa.c:1730 soa_activate() soa_activate(static::0x7f812c0281e0, (nil)) called soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f812c0281e0, [(nil)], [0x7f813111bc38], [0x7f813111bc34]) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 1186 bytes of 1186 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 1186 send 1186 bytes to udp/[87.127.251.183]:1277 at 14:18:11.427777: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.8.32.151:5060;rport=1277;branch=z9hG4bK4245134600;received=87.127.251.183 From: "1000" ;tag=1118572399 To: ;tag=NcXeHej9KFSHm Call-ID: 2_1100593423@10.8.32.151 CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Session-Expires: 120;refresher=uas Content-Type: application/sdp Content-Disposition: session Content-Length: 224 Remote-Party-ID: "443331019574" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1504599499 1504599500 IN IP4 195.74.100.112 s=FreeSWITCH c=IN IP4 195.74.100.112 t=0 0 m=audio 21592 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (2) nua_session.c:4139 signal_call_state_change() nua(0x7f812c014200): call state changed: early -> completed, sent answer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f812c0281e0, [0x7f813111bce8], [0x7f813111bcf0], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7f812c0281e0, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_state 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f812c014200): sent signal r_respond nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.406226 [DEBUG] sofia.c:7283 Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 entering state [completed][200] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.406226 [NOTICE] switch_ivr_originate.c:3662 Channel [sofia/internal/1000@fspbx1.evoip.enta.net:5060] has been answered 2017-09-05 14:18:11.406226 [DEBUG] switch_channel.c:3781 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Callstate Change EARLY -> ACTIVE 2017-09-05 14:18:11.406226 [DEBUG] switch_ivr_originate.c:3720 Originate Resulted in Success: [sofia/external/03331019574] 2017-09-05 14:18:11.406226 [DEBUG] switch_ivr_bridge.c:1744 (sofia/external/03331019574) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2017-09-05 14:18:11.406226 [DEBUG] switch_core_state_machine.c:584 (sofia/external/03331019574) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 8) 2017-09-05 14:18:11.406226 [DEBUG] switch_core_state_machine.c:653 (sofia/external/03331019574) State EXCHANGE_MEDIA 2017-09-05 14:18:11.406226 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c02ba00 from (udp/195.74.100.112:5060) has 705 bytes, veclen = 1 recv 705 bytes from udp/[87.127.251.183]:1277 at 14:18:11.448749: ------------------------------------------------------------------------ ACK sip:03331019574@195.74.100.112:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.8.32.151:5060;rport;branch=z9hG4bK2643518755 From: "1000" ;tag=1118572399 To: ;tag=NcXeHej9KFSHm Call-ID: 2_1100593423@10.8.32.151 CSeq: 2 ACK Contact: Proxy-Authorization: Digest username="1000", realm="fspbx1.evoip.enta.net", nonce="21e292a6-2542-4628-ae3f-2b3b4bcdee63", uri="sip:03331019574@fspbx1.evoip.enta.net:5060", response="5c8c1d3c1e93369dd6e29c7481d3e6fe", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000001 Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.80.0.137 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c02ba00 (705 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received ACK sip:03331019574@195.74.100.112:5060;transport=udp SIP/2.0 (CSeq 2) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3019 agent_recv_request() nta: ACK (2) is going to INVITE (2) nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f812c0281e0) called nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_ack 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7f812c014200): call state changed: completed -> ready nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_state 200 OK nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_active 200 Call active nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 57 seconds (in [55..65]) nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f8118088800 from (udp/195.74.100.112:5080) has 875 bytes, veclen = 1 recv 875 bytes from udp/[195.74.100.80]:5060 at 14:18:11.449867: ------------------------------------------------------------------------ INFO sip:gw+entanet@195.74.100.112:5080;transport=udp;gw=entanet SIP/2.0 Via: SIP/2.0/UDP 195.74.100.80:5060;branch=z9hG4bK0969.21fc5961.0;i=c35 Via: SIP/2.0/TCP 195.74.100.81:5080;rport=33158;received=195.74.100.81;branch=z9hG4bKFc5e9tK7gQK0p Max-Forwards: 69 From: ;tag=8F1FZ09KpjvNF To: "Extension 1000" ;tag=tFge5351jXBeH Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974481 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.19-36-7a77e0b~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: 443331019574 X-FS-Display-Number: 443331019574 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f8118088800 (875 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INFO sip:gw+entanet@195.74.100.112:5080;transport=udp;gw=entanet SIP/2.0 (CSeq 111974481) nta.c:3248 agent_aliases() nta: canonizing sip:gw+entanet@195.74.100.112:5080 with contact nta.c:3060 agent_recv_request() nta: INFO (111974481) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event i_info 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f8128007c00): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f8118084a90, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = UDP/195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name UDP/195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 612 bytes of 612 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 612 send 612 bytes to udp/[195.74.100.80]:5060 at 14:18:11.454996: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 195.74.100.80:5060;branch=z9hG4bK0969.21fc5961.0;i=c35 Via: SIP/2.0/TCP 195.74.100.81:5080;rport=33158;received=195.74.100.81;branch=z9hG4bKFc5e9tK7gQK0p From: ;tag=8F1FZ09KpjvNF To: "Extension 1000" ;tag=tFge5351jXBeH Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974481 INFO User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for INFO (111974481) nua_stack.c:529 nua_signal() nua(0x7f8128007c00): sent signal r_respond nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.446215 [DEBUG] sofia.c:7283 Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 entering state [ready][200] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:798 nua_info() nua: nua_info: entering nua_stack.c:569 nua_stack_signal() nua(0x7f8128007c00): recv signal r_info nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f8118084a90, ...) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:11.474910: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:1348 set_timeout() nta: timer shortened to 1000 ms nua_stack.c:529 nua_signal() nua(0x7f8128007c00): sent signal r_info nua.c:810 nua_update() nua: nua_update: entering nua_stack.c:569 nua_stack_signal() nua(0x7f812c014200): recv signal r_update nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c0281e0, ...) called soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f812c0281e0) called soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7f812c0281e0, 0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f812c0281e0, soa_generate_offer): called soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f812c029c40, (nil), ""): called soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f812c0281e0, [(nil)], [0x7f813111bc48], [0x7f813111bc44]) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = udp/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name udp/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 1013 bytes of 1013 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 1013 send 1013 bytes to udp/[87.127.251.183]:1277 at 14:18:11.484486: ------------------------------------------------------------------------ UPDATE sip:1000@10.8.32.151:5060 SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112;rport;branch=z9hG4bKpX7Nt1rXFZBQD Max-Forwards: 70 From: ;tag=NcXeHej9KFSHm To: "1000" ;tag=1118572399 Call-ID: 2_1100593423@10.8.32.151 CSeq: 111974481 UPDATE Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Session-Expires: 120;refresher=uac Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 224 P-Asserted-Identity: "443331019574" v=0 o=FreeSWITCH 1504599499 1504599500 IN IP4 195.74.100.112 s=FreeSWITCH c=IN IP4 195.74.100.112 t=0 0 m=audio 21592 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent UPDATE (111974481) to udp/87.127.251.183:1277 tport.c:4160 tport_pend() tport_pend(0x7f812c0045a0): pending 0x7f812c02bd10 for udp/195.74.100.112:5060 (already 0) nua_session.c:4145 signal_call_state_change() nua(0x7f812c014200): ready call updated: calling sent offer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f812c0281e0, [0x7f813111bc28], [0x7f813111bc30], [(nil)]) called nua_stack.c:269 nua_stack_event() nua(0x7f812c014200): event i_state UPDATE sent nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f812c014200): sent signal r_update nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.466214 [DEBUG] sofia.c:7283 Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 entering state [calling][0] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c02a390 from (udp/195.74.100.112:5060) has 625 bytes, veclen = 1 recv 625 bytes from udp/[87.127.251.183]:1277 at 14:18:11.510858: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 195.74.100.112;rport=5060;branch=z9hG4bKpX7Nt1rXFZBQD From: ;tag=NcXeHej9KFSHm To: "1000" ;tag=1118572399 Call-ID: 2_1100593423@10.8.32.151 CSeq: 111974481 UPDATE Contact: Content-Type: application/sdp User-Agent: Yealink SIP-T23G 44.80.0.137 Content-Length: 209 v=0 o=- 20111 20112 IN IP4 10.8.32.151 s=SDP data c=IN IP4 10.8.32.151 t=0 0 m=audio 11930 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c02a390 (625 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for UPDATE (111974481) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 26.475 ms tport.c:4222 tport_release() tport_release(0x7f812c0045a0): 0x7f812c02bd10 by 0x7f812c020d80 with 0x7f812c02a390 nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 57 seconds (in [55..65]) soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f812c0281e0, (nil), 0x7f812c02e750, 209) called soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f812c0281e0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f812c0281e0, soa_process_answer): called soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f812c029c40, 0x7f812c02d890, ""): called soa_static.c:1304 offer_answer_step() soa_static(0x7f812c0281e0, soa_process_answer): upgrade codecs with remote description soa.c:1730 soa_activate() soa_activate(static::0x7f812c0281e0, (nil)) called nua_session.c:988 nua_session_client_response() nua(0x7f812c014200): UPDATE: processed SDP answer in 200 OK nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event r_update 200 OK nua_session.c:4145 signal_call_state_change() nua(0x7f812c014200): ready call updated: ready received answer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f812c0281e0, [0x7f813111b6f8], [0x7f813111b700], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7f812c0281e0, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_state 200 OK nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_active 200 Call active nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:11.506225 [DEBUG] sofia.c:7283 Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 entering state [ready][200] 2017-09-05 14:18:11.506225 [DEBUG] sofia.c:7293 Remote SDP: v=0 o=- 20111 20112 IN IP4 10.8.32.151 s=SDP data c=IN IP4 10.8.32.151 t=0 0 m=audio 11930 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2017-09-05 14:18:11.506225 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-09-05 14:18:11.506225 [DEBUG] switch_core_media.c:5170 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match 2017-09-05 14:18:11.506225 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-09-05 14:18:11.506225 [DEBUG] switch_core_media.c:5115 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-09-05 14:18:11.506225 [DEBUG] switch_core_media.c:5031 Set telephone-event payload to 101@8000 2017-09-05 14:18:11.506225 [DEBUG] switch_core_media.c:5374 Set telephone-event payload to 101@8000 2017-09-05 14:18:11.506225 [DEBUG] switch_core_media.c:5432 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Set 2833 dtmf send payload to 101 recv payload to 101 2017-09-05 14:18:11.506225 [DEBUG] sofia.c:8262 Processing updated SDP 2017-09-05 14:18:11.506225 [DEBUG] switch_core_media.c:8132 Audio params are unchanged for sofia/internal/1000@fspbx1.evoip.enta.net:5060. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813111bc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/6 term, 1/6 free nta.c:1296 agent_timer() nta: timer set next to 4666 ms nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:12.475186: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/3 term, 0/5 free nta.c:1296 agent_timer() nta: timer set next to 2000 ms nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:14.478182: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/3 term, 0/5 free nta.c:1296 agent_timer() nta: timer set next to 543 ms nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate REGISTER (111974228) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813165dd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/1 resent, 0/2 tout, 1/3 term, 1/5 free nta.c:1296 agent_timer() nta: timer set next to 13 ms nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate REGISTER (111974229) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813165dd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/1 resent, 0/2 tout, 1/2 term, 1/4 free nta.c:1296 agent_timer() nta: timer set next to 3446 ms nta.c:7140 _nta_incoming_timer() nta: timer I fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813111bc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/5 term, 1/5 free nta.c:1296 agent_timer() nta: timer set next to 62 ms nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate UPDATE (111974481) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813111bd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta.c:1296 agent_timer() nta: timer set next to 7564 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c00d040 from (udp/195.74.100.112:5060) has 712 bytes, veclen = 1 recv 712 bytes from udp/[87.127.251.183]:1277 at 14:18:18.451073: ------------------------------------------------------------------------ BYE sip:03331019574@195.74.100.112:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.8.32.151:5060;rport;branch=z9hG4bK2284330756 From: "1000" ;tag=1118572399 To: ;tag=NcXeHej9KFSHm Call-ID: 2_1100593423@10.8.32.151 CSeq: 3 BYE Contact: Proxy-Authorization: Digest username="1000", realm="fspbx1.evoip.enta.net", nonce="21e292a6-2542-4628-ae3f-2b3b4bcdee63", uri="sip:03331019574@195.74.100.112:5060;transport=udp", response="fa0524a63033ac491b78e4372a25ccd6", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000002 Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.80.0.137 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c00d040 (712 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received BYE sip:03331019574@195.74.100.112:5060;transport=udp SIP/2.0 (CSeq 3) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3248 agent_aliases() nta: canonizing sip:03331019574@195.74.100.112:5060 with contact nta.c:3060 agent_recv_request() nta: BYE (3) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_bye 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:18.446227 [NOTICE] sofia.c:1079 Hangup sofia/internal/1000@fspbx1.evoip.enta.net:5060 [CS_EXECUTE] [NORMAL_CLEARING] nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c014200): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c0281e0, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 517 bytes of 517 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 517 send 517 bytes to udp/[87.127.251.183]:1277 at 14:18:18.466642: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.8.32.151:5060;rport=1277;branch=z9hG4bK2284330756;received=87.127.251.183 From: "1000" ;tag=1118572399 To: ;tag=NcXeHej9KFSHm Call-ID: 2_1100593423@10.8.32.151 CSeq: 3 BYE User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for BYE (3) nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f812c014200): removing session usage nua_session.c:4139 signal_call_state_change() nua(0x7f812c014200): call state changed: ready -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_state 200 Session Terminated nua_stack.c:271 nua_stack_event() nua(0x7f812c014200): event i_terminated 200 Session Terminated soa.c:356 soa_destroy() soa_destroy(static::0x7f812c0281e0) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f812c0234c0) nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f812c014200): sent signal r_respond nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f812c014200): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) nua_stack.c:529 nua_signal() nua(0x7f812c014200): sent signal r_destroy 2017-09-05 14:18:18.446227 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/1000@fspbx1.evoip.enta.net:5060] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering 2017-09-05 14:18:18.446227 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external/03331019574] 2017-09-05 14:18:18.446227 [NOTICE] switch_ivr_bridge.c:1034 Hangup sofia/external/03331019574 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:653 (sofia/external/03331019574) State EXCHANGE_MEDIA going to sleep 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:584 (sofia/external/03331019574) Running State Change CS_HANGUP (Cur 2 Tot 8) 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:850 (sofia/external/03331019574) Callstate Change ACTIVE -> HANGUP 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:852 (sofia/external/03331019574) State HANGUP 2017-09-05 14:18:18.446227 [DEBUG] mod_sofia.c:443 sofia/external/03331019574 Overriding SIP cause 480 with 200 from the other leg 2017-09-05 14:18:18.446227 [DEBUG] mod_sofia.c:449 Channel sofia/external/03331019574 hanging up, cause: NORMAL_CLEARING 2017-09-05 14:18:18.446227 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/external/03331019574 nua.c:645 nua_bye() nua: nua_bye: entering nua_stack.c:569 nua_stack_signal() nua(0x7f8128007c00): recv signal r_bye nua_stack.c:529 nua_signal() nua(0x7f8128007c00): sent signal r_bye 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:60 sofia/external/03331019574 Standard HANGUP, cause: NORMAL_CLEARING 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:852 (sofia/external/03331019574) State HANGUP going to sleep 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:619 (sofia/external/03331019574) State Change CS_HANGUP -> CS_REPORTING 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:584 (sofia/external/03331019574) Running State Change CS_REPORTING (Cur 2 Tot 8) 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:938 (sofia/external/03331019574) State REPORTING 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:174 sofia/external/03331019574 Standard REPORTING, cause: NORMAL_CLEARING 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:938 (sofia/external/03331019574) State REPORTING going to sleep 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:610 (sofia/external/03331019574) State Change CS_REPORTING -> CS_DESTROY 2017-09-05 14:18:18.446227 [DEBUG] switch_core_session.c:1713 Session 8 (sofia/external/03331019574) Locked, Waiting on external entities 2017-09-05 14:18:18.446227 [DEBUG] switch_ivr_bridge.c:1846 sofia/internal/1000@fspbx1.evoip.enta.net:5060 skip receive message [TRANSFER] (channel is hungup already) 2017-09-05 14:18:18.446227 [DEBUG] switch_core_session.c:2885 sofia/internal/1000@fspbx1.evoip.enta.net:5060 skip receive message [PHONE_EVENT] (channel is hungup already) 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State EXECUTE going to sleep 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Running State Change CS_HANGUP (Cur 2 Tot 8) 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Callstate Change ACTIVE -> HANGUP 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State HANGUP 2017-09-05 14:18:18.446227 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 hanging up, cause: NORMAL_CLEARING 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Standard HANGUP, cause: NORMAL_CLEARING 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State HANGUP going to sleep 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State Change CS_HANGUP -> CS_REPORTING nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:18.479508: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/1 term, 0/3 free nta.c:1296 agent_timer() nta: timer set next to 4001 ms 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Running State Change CS_REPORTING (Cur 2 Tot 8) 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State REPORTING 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Standard REPORTING, cause: NORMAL_CLEARING 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State REPORTING going to sleep 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State Change CS_REPORTING -> CS_DESTROY 2017-09-05 14:18:18.446227 [DEBUG] switch_core_session.c:1713 Session 7 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Locked, Waiting on external entities 2017-09-05 14:18:18.446227 [NOTICE] switch_core_session.c:1731 Session 7 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Ended 2017-09-05 14:18:18.446227 [NOTICE] switch_core_session.c:1735 Close Channel sofia/internal/1000@fspbx1.evoip.enta.net:5060 [CS_DESTROY] 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) Running State Change CS_DESTROY (Cur 1 Tot 8) 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State DESTROY 2017-09-05 14:18:18.446227 [DEBUG] mod_sofia.c:354 sofia/internal/1000@fspbx1.evoip.enta.net:5060 SOFIA DESTROY 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1000@fspbx1.evoip.enta.net:5060 Standard DESTROY 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@fspbx1.evoip.enta.net:5060) State DESTROY going to sleep 2017-09-05 14:18:18.446227 [NOTICE] switch_core_session.c:1731 Session 8 (sofia/external/03331019574) Ended 2017-09-05 14:18:18.446227 [NOTICE] switch_core_session.c:1735 Close Channel sofia/external/03331019574 [CS_DESTROY] 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:741 (sofia/external/03331019574) Running State Change CS_DESTROY (Cur 0 Tot 8) 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:751 (sofia/external/03331019574) State DESTROY 2017-09-05 14:18:18.446227 [DEBUG] mod_sofia.c:354 sofia/external/03331019574 SOFIA DESTROY 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:181 sofia/external/03331019574 Standard DESTROY 2017-09-05 14:18:18.446227 [DEBUG] switch_core_state_machine.c:751 (sofia/external/03331019574) State DESTROY going to sleep tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c014120 from (udp/195.74.100.112:5060) has 844 bytes, veclen = 1 recv 844 bytes from udp/[87.127.251.183]:1272 at 14:18:22.071898: ------------------------------------------------------------------------ REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.108:5060;branch=z9hG4bK1193402102;rport From: "1001" ;tag=4288287416 To: "1001" Call-ID: 2_2750365493@10.8.32.108 CSeq: 120 REGISTER Contact: Authorization: Digest username="1001", realm="fspbx1.evoip.enta.net", nonce="c7cb569d-64b5-4376-be1f-14c4d91114db", uri="sip:fspbx1.evoip.enta.net:5060", response="9a970e39e6013e4c083f1e9b95b0fed1", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000040 Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.81.0.70 Expires: 60 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c014120 (844 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 120) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3085 agent_recv_request() nta: REGISTER (120) going to a default leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:899 nh_create() nua: nh_create: entering nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f812c001b10, 0x7f812c001310, 0x7f812c028600) called soa.c:403 soa_set_params() soa_set_params(static::0x7f812c018150, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f812c028600): event i_register 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c028600): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c018150, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1272 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1272 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1272 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 613 bytes of 613 to udp/87.127.251.183:1272 tport.c:3492 tport_send_msg() tport_vsend returned 613 send 613 bytes to udp/[87.127.251.183]:1272 at 14:18:22.076159: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.8.32.108:5060;branch=z9hG4bK1193402102;rport=1272;received=87.127.251.183 From: "1001" ;tag=4288287416 To: "1001" ;tag=r78rpZ4KBav9p Call-ID: 2_2750365493@10.8.32.108 CSeq: 120 REGISTER Contact: ;expires=30 Date: Tue, 05 Sep 2017 14:18:22 GMT User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for REGISTER (120) nua_stack.c:529 nua_signal() nua(0x7f812c028600): sent signal r_respond nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f812c028600): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7f812c018150) called nua_stack.c:529 nua_signal() nua(0x7f812c028600): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:22.480610: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/1 term, 0/3 free nta.c:1296 agent_timer() nta: timer set next to 4001 ms nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813111bc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/6 term, 1/6 free nta.c:1296 agent_timer() nta: timer set next to 2710 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c00edb0 from (udp/195.74.100.112:5060) has 846 bytes, veclen = 1 recv 846 bytes from udp/[87.127.251.183]:1277 at 14:18:24.766719: ------------------------------------------------------------------------ REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.151:5060;rport;branch=z9hG4bK3781942151 From: "1000" ;tag=964408845 To: "1000" Call-ID: 2_4292396569@10.8.32.151 CSeq: 230 REGISTER Contact: Authorization: Digest username="1000", realm="fspbx1.evoip.enta.net", nonce="9adf1b08-8976-4bbd-817c-d3dce30ac1dc", uri="sip:fspbx1.evoip.enta.net:5060", response="451cf1a4135347fa74fae5cfbb9fcd3a", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000021 Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.80.0.137 Expires: 3600 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c00edb0 (846 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 230) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3085 agent_recv_request() nta: REGISTER (230) going to a default leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:899 nh_create() nua: nh_create: entering nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f812c001b10, 0x7f812c001310, 0x7f812c020690) called soa.c:403 soa_set_params() soa_set_params(static::0x7f812c027a00, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f812c020690): event i_register 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c020690): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c027a00, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 612 bytes of 612 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 612 send 612 bytes to udp/[87.127.251.183]:1277 at 14:18:24.770396: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.8.32.151:5060;rport=1277;branch=z9hG4bK3781942151;received=87.127.251.183 From: "1000" ;tag=964408845 To: "1000" ;tag=Sg2HrtNQ8jjvj Call-ID: 2_4292396569@10.8.32.151 CSeq: 230 REGISTER Contact: ;expires=30 Date: Tue, 05 Sep 2017 14:18:24 GMT User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for REGISTER (230) nua_stack.c:529 nua_signal() nua(0x7f812c020690): sent signal r_respond nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f812c020690): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7f812c027a00) called nua_stack.c:529 nua_signal() nua(0x7f812c020690): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:26.481660: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/1 term, 0/3 free nta.c:1296 agent_timer() nta: timer set next to 4001 ms nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813111bc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/6 term, 1/6 free nta.c:1296 agent_timer() nta: timer set next to 12290 ms auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(sip:EN33510464.voip-portal.co.uk:c776fa8e8152b37e) = 3d06e695d593a7eac66b7bf7d73ab105 auth_digest.c:318 auth_digest_response() A2 = MD5(REGISTER:sip:EN33510464.voip-portal.co.uk;transport=udp) auth_digest.c:348 auth_digest_response() auth_response: 48a53bf9f50d0fd1ab6486abd47d6a1c = MD5(3d06e695d593a7eac66b7bf7d73ab105:59aeb23100015b0b3d886c2d1d8d590b7fea74c428d50eb6:e74b8fa4c49b2545abc7114a4258522e) (qop=NONE) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10604 outgoing_query_srv() nta: for "EN33510464.voip-portal.co.uk" query "_sip._udp.EN33510464.voip-portal.co.uk" SRV (cached) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10809 outgoing_query_a() nta: for "EN33510464.voip-portal.co.uk" query "EN33510464.voip-portal.co.uk" A (cached) nta.c:10862 outgoing_answer_a() nta: sipgate.voip-portal.co.uk. IN A 195.74.100.80 tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = udp/195.74.100.80:5060/sip tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name udp/195.74.100.80:5060/sip tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 874 bytes of 874 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 874 send 874 bytes to udp/[195.74.100.80]:5060 at 14:18:27.020394: ------------------------------------------------------------------------ REGISTER sip:EN33510464.voip-portal.co.uk;transport=udp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bKaS66S8461cm4B Max-Forwards: 70 From: ;tag=KgZ0r6F96yFBg To: Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974230 REGISTER Contact: Expires: 3600 User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Authorization: Digest username="sip", realm="EN33510464.voip-portal.co.uk", nonce="59aeb23100015b0b3d886c2d1d8d590b7fea74c428d50eb6", algorithm=MD5, uri="sip:EN33510464.voip-portal.co.uk;transport=udp", response="48a53bf9f50d0fd1ab6486abd47d6a1c" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent REGISTER (111974230) to udp/195.74.100.80:5060/sip tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f8118070990 for udp/195.74.100.112:5080 (already 1) nta.c:1348 set_timeout() nta: timer shortened to 1000 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f81180854c0 from (udp/195.74.100.112:5080) has 537 bytes, veclen = 1 recv 537 bytes from udp/[195.74.100.80]:5060 at 14:18:27.029934: ------------------------------------------------------------------------ SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bKaS66S8461cm4B From: ;tag=KgZ0r6F96yFBg To: ;tag=a5e8f5e9ef62e93eca305ef64f43c9c0.dd82 Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974230 REGISTER WWW-Authenticate: Digest realm="EN33510464.voip-portal.co.uk", nonce="59aeb24200015b29b17b71d128a36a1a209d9aafd8adada9", stale=true Server: Entanet SIP Proxy V8.24 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f81180854c0 (537 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 401 Unauthorized for REGISTER (111974230) nta.c:3366 agent_recv_response() nta: 401 Unauthorized is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 9.653 ms tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f8118070990 by 0x7f81180897d0 with 0x7f81180854c0 auth_digest.c:105 auth_digest_challenge_get() auth_digest_challenge_get(): got 3 auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(sip:EN33510464.voip-portal.co.uk:c776fa8e8152b37e) = 3d06e695d593a7eac66b7bf7d73ab105 auth_digest.c:318 auth_digest_response() A2 = MD5(REGISTER:sip:EN33510464.voip-portal.co.uk;transport=udp) auth_digest.c:348 auth_digest_response() auth_response: da8af6400d62d434f6c40e1d001884b0 = MD5(3d06e695d593a7eac66b7bf7d73ab105:59aeb24200015b29b17b71d128a36a1a209d9aafd8adada9:e74b8fa4c49b2545abc7114a4258522e) (qop=NONE) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10604 outgoing_query_srv() nta: for "EN33510464.voip-portal.co.uk" query "_sip._udp.EN33510464.voip-portal.co.uk" SRV (cached) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10809 outgoing_query_a() nta: for "EN33510464.voip-portal.co.uk" query "EN33510464.voip-portal.co.uk" A (cached) nta.c:10862 outgoing_answer_a() nta: sipgate.voip-portal.co.uk. IN A 195.74.100.80 tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = udp/195.74.100.80:5060/sip tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name udp/195.74.100.80:5060/sip tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 874 bytes of 874 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 874 send 874 bytes to udp/[195.74.100.80]:5060 at 14:18:27.030132: ------------------------------------------------------------------------ REGISTER sip:EN33510464.voip-portal.co.uk;transport=udp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bKB2ZZU3NaZNaQQ Max-Forwards: 70 From: ;tag=KgZ0r6F96yFBg To: Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974231 REGISTER Contact: Expires: 3600 User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Authorization: Digest username="sip", realm="EN33510464.voip-portal.co.uk", nonce="59aeb24200015b29b17b71d128a36a1a209d9aafd8adada9", algorithm=MD5, uri="sip:EN33510464.voip-portal.co.uk;transport=udp", response="da8af6400d62d434f6c40e1d001884b0" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent REGISTER (111974231) to udp/195.74.100.80:5060/sip tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f81180415b0 for udp/195.74.100.112:5080 (already 1) nua_stack.c:271 nua_stack_event() nua(0x7f812005c5d0): event r_register 100 Request Authorized by Cache nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f8118092540 from (udp/195.74.100.112:5080) has 481 bytes, veclen = 1 recv 481 bytes from udp/[195.74.100.80]:5060 at 14:18:27.042697: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bKB2ZZU3NaZNaQQ From: ;tag=KgZ0r6F96yFBg To: ;tag=a5e8f5e9ef62e93eca305ef64f43c9c0.b0a5 Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974231 REGISTER Contact: ;q=0;expires=60 Server: Entanet SIP Proxy V8.24 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f8118092540 (481 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for REGISTER (111974231) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 12.657 ms tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f81180415b0 by 0x7f81180711c0 with 0x7f8118092540 nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh register after 17 seconds (in [15..45]) nua_stack.c:271 nua_stack_event() nua(0x7f812005c5d0): event r_register 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:27.006226 [DEBUG] sofia_reg.c:2435 Changing expire time to 60 by request of proxy sip:EN33510464.voip-portal.co.uk nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nta.c:1296 agent_timer() nta: timer set next to 2461 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c021f50 from (udp/195.74.100.112:5060) has 4 bytes, veclen = 1 tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): bad msg 0x7f812c021f50 (4 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:30.484788: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/3 term, 0/5 free nta.c:1296 agent_timer() nta: timer set next to 1548 ms nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate REGISTER (111974230) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813165dd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/1 resent, 0/2 tout, 1/3 term, 1/5 free nta.c:1296 agent_timer() nta: timer set next to 13 ms nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate REGISTER (111974231) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813165dd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/1 resent, 0/2 tout, 1/2 term, 1/4 free nta.c:1296 agent_timer() nta: timer set next to 2442 ms nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:34.485111: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/1 term, 0/3 free nta.c:1296 agent_timer() nta: timer set next to 4000 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c019250 from (udp/195.74.100.112:5060) has 844 bytes, veclen = 1 recv 844 bytes from udp/[87.127.251.183]:1272 at 14:18:37.066839: ------------------------------------------------------------------------ REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.108:5060;branch=z9hG4bK3443894051;rport From: "1001" ;tag=4288287416 To: "1001" Call-ID: 2_2750365493@10.8.32.108 CSeq: 121 REGISTER Contact: Authorization: Digest username="1001", realm="fspbx1.evoip.enta.net", nonce="c7cb569d-64b5-4376-be1f-14c4d91114db", uri="sip:fspbx1.evoip.enta.net:5060", response="d57b95a12dec41a911f87b6ab44b5cf9", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000041 Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.81.0.70 Expires: 60 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c019250 (844 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 121) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3085 agent_recv_request() nta: REGISTER (121) going to a default leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:899 nh_create() nua: nh_create: entering nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f812c001b10, 0x7f812c001310, 0x7f812c00f160) called soa.c:403 soa_set_params() soa_set_params(static::0x7f812c027a00, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f812c00f160): event i_register 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c00f160): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c027a00, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1272 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1272 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1272 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 613 bytes of 613 to udp/87.127.251.183:1272 tport.c:3492 tport_send_msg() tport_vsend returned 613 send 613 bytes to udp/[87.127.251.183]:1272 at 14:18:37.071187: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.8.32.108:5060;branch=z9hG4bK3443894051;rport=1272;received=87.127.251.183 From: "1001" ;tag=4288287416 To: "1001" ;tag=tSUatN6t5U8ee Call-ID: 2_2750365493@10.8.32.108 CSeq: 121 REGISTER Contact: ;expires=30 Date: Tue, 05 Sep 2017 14:18:37 GMT User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for REGISTER (121) nua_stack.c:529 nua_signal() nua(0x7f812c00f160): sent signal r_respond nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f812c00f160): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7f812c027a00) called nua_stack.c:529 nua_signal() nua(0x7f812c00f160): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:38.485132: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/1 term, 0/3 free nta.c:1296 agent_timer() nta: timer set next to 4000 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c01c080 from (udp/195.74.100.112:5060) has 4 bytes, veclen = 1 tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): bad msg 0x7f812c01c080 (4 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813111bc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/6 term, 1/6 free nta.c:1296 agent_timer() nta: timer set next to 2723 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f812c0045a0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f812c0045a0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f812c0045a0) msg 0x7f812c027d80 from (udp/195.74.100.112:5060) has 846 bytes, veclen = 1 recv 846 bytes from udp/[87.127.251.183]:1277 at 14:18:39.778241: ------------------------------------------------------------------------ REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 Via: SIP/2.0/UDP 10.8.32.151:5060;rport;branch=z9hG4bK1478111329 From: "1000" ;tag=964408845 To: "1000" Call-ID: 2_4292396569@10.8.32.151 CSeq: 231 REGISTER Contact: Authorization: Digest username="1000", realm="fspbx1.evoip.enta.net", nonce="9adf1b08-8976-4bbd-817c-d3dce30ac1dc", uri="sip:fspbx1.evoip.enta.net:5060", response="a406a91718c4c9729b05fe664fe8eddb", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000022 Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 70 User-Agent: Yealink SIP-T23G 44.80.0.137 Expires: 3600 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f812c0045a0): msg 0x7f812c027d80 (846 bytes) from udp/87.127.251.183:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received REGISTER sip:fspbx1.evoip.enta.net:5060 SIP/2.0 (CSeq 231) nta.c:3174 agent_check_request_via() nta: Via check: received=87.127.251.183 nta.c:3085 agent_recv_request() nta: REGISTER (231) going to a default leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:899 nh_create() nua: nh_create: entering nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f812c001b10, 0x7f812c001310, 0x7f812c010e20) called soa.c:403 soa_set_params() soa_set_params(static::0x7f812c0200e0, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f812c010e20): event i_register 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f812c010e20): recv signal r_respond 200 OK nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f812c0200e0, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f812c0045a0) tpn = UDP/87.127.251.183:1277 tport.c:4046 tport_resolve() tport_resolve addrinfo = 87.127.251.183:1277 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f812c0045a0): not found by name UDP/87.127.251.183:1277 tport.c:3594 tport_vsend() tport_vsend(0x7f812c0045a0): 612 bytes of 612 to udp/87.127.251.183:1277 tport.c:3492 tport_send_msg() tport_vsend returned 612 send 612 bytes to udp/[87.127.251.183]:1277 at 14:18:39.781639: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.8.32.151:5060;rport=1277;branch=z9hG4bK1478111329;received=87.127.251.183 From: "1000" ;tag=964408845 To: "1000" ;tag=U2m3UgQy24y1S Call-ID: 2_4292396569@10.8.32.151 CSeq: 231 REGISTER Contact: ;expires=30 Date: Tue, 05 Sep 2017 14:18:39 GMT User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6797 incoming_reply() nta: sent 200 OK for REGISTER (231) nua_stack.c:529 nua_signal() nua(0x7f812c010e20): sent signal r_respond nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f812c010e20): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7f812c0200e0) called nua_stack.c:529 nua_signal() nua(0x7f812c010e20): sent signal r_destroy nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813111bc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/6 term, 1/6 free nta.c:1296 agent_timer() nta: timer set next to 8667 ms nta.c:8899 _nta_outgoing_timer() nta: timer E fired, retransmit INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 916 bytes of 916 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 916 send 916 bytes to udp/[195.74.100.80]:5060 at 14:18:42.485140: ------------------------------------------------------------------------ INFO sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bK9FDerDm343XHg Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974475 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Extension 1000 X-FS-Display-Number: 441156870140 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: resent INFO (111974475) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811808d0a0 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 1/1 resent, 0/2 tout, 0/1 term, 0/3 free nta.c:1296 agent_timer() nta: timer set next to 926 ms nta.c:9107 outgoing_timer_dk() nta: timer D fired, terminate INVITE (111974474) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813165dd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/1 resent, 0/2 tout, 1/1 term, 1/3 free nta.c:1296 agent_timer() nta: timer set next to 2 ms nta.c:8988 outgoing_timer_bf() nta: timer F fired, terminating ACK (111974474) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813165dd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/1 resent, 1/2 tout, 0/0 term, 1/2 free nta.c:1296 agent_timer() nta: timer set next to 42 ms nta.c:7165 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f813165dc60) nta.c:7194 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta.c:1296 agent_timer() nta: timer set next to 20 ms nta.c:8988 outgoing_timer_bf() nta: timer F fired, timeout INFO (111974475) tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811808d0a0 by 0x7f811808de20 with (nil) nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event r_info 408 Request Timeout nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f8118084a90, ...) called soa.c:1784 soa_terminate() soa_terminate(static::0x7f8118084a90) called soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f8118084a90) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = */195.74.100.80:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name */195.74.100.80:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 781 bytes of 781 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 781 send 781 bytes to udp/[195.74.100.80]:5060 at 14:18:43.475866: ------------------------------------------------------------------------ BYE sip:03331019574@195.74.100.81:5080;transport=tcp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bKcBSrXy6Dvy09j Route: Route: Max-Forwards: 70 From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974476 BYE User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent BYE (111974476) to */195.74.100.80:5060 tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f8118085e20 for udp/195.74.100.112:5080 (already 0) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/1 resent, 1/1 tout, 0/0 term, 0/1 free nta.c:1296 agent_timer() nta: timer set next to 1000 ms nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f8118086ee0 from (udp/195.74.100.112:5080) has 559 bytes, veclen = 1 recv 559 bytes from udp/[195.74.100.80]:5060 at 14:18:43.509061: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bKcBSrXy6Dvy09j From: "Extension 1000" ;tag=tFge5351jXBeH To: ;tag=8F1FZ09KpjvNF Call-ID: db9ef20b-0ce7-1236-79a5-fa163e3b5224 CSeq: 111974476 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.19-36-7a77e0b~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f8118086ee0 (559 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (111974476) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 33.364 ms tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f8118085e20 by 0x7f8118080680 with 0x7f8118086ee0 nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event r_bye 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7f8128007c00): call state changed: terminating -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event i_state 200 to BYE nua_stack.c:271 nua_stack_event() nua(0x7f8128007c00): event i_terminated 200 to BYE nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f8128007c00): removing session usage soa.c:356 soa_destroy() soa_destroy(static::0x7f8118084a90) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f8118084980) nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f8128007c00 nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f8128007c00): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) nua_stack.c:529 nua_signal() nua(0x7f8128007c00): sent signal r_destroy auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(sip:EN33510464.voip-portal.co.uk:c776fa8e8152b37e) = 3d06e695d593a7eac66b7bf7d73ab105 auth_digest.c:318 auth_digest_response() A2 = MD5(REGISTER:sip:EN33510464.voip-portal.co.uk;transport=udp) auth_digest.c:348 auth_digest_response() auth_response: da8af6400d62d434f6c40e1d001884b0 = MD5(3d06e695d593a7eac66b7bf7d73ab105:59aeb24200015b29b17b71d128a36a1a209d9aafd8adada9:e74b8fa4c49b2545abc7114a4258522e) (qop=NONE) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") called nta.c:10604 outgoing_query_srv() nta: for "EN33510464.voip-portal.co.uk" query "_sip._udp.EN33510464.voip-portal.co.uk" SRV sres.c:968 sres_query() sres_query(0x7f8118037e00, 0x7f81180807e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk") called sres.c:2730 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f8118084610) called sres.c:2819 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f8118084610) id=62404 SRV _sip._udp.EN33510464.voip-portal.co.uk (to [195.74.100.89]:53) sres.c:3467 sres_resolver_receive() sres_resolver_receive(0x7f8118037e00, 53) called sres.c:3781 sres_create_record() ANSWER RR received _sip._udp.EN33510464.voip-portal.co.uk. CNAME IN 60 rdlen=10 sres.c:3781 sres_create_record() AUTHORITY RR received voip-portal.co.uk. SOA IN 24 rdlen=46 sres.c:3572 sres_log_response() sres_resolver_receive(0x7f8118037e00, 0x7f8118084610) id=62404 (from [195.74.100.89]:53) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "sipgate.voip-portal.co.uk.") called sres.c:2730 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f811808ffc0) called sres.c:2819 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f811808ffc0) id=62405 SRV sipgate.voip-portal.co.uk. (to [195.74.100.89]:53) sres.c:3467 sres_resolver_receive() sres_resolver_receive(0x7f8118037e00, 53) called sres.c:3781 sres_create_record() AUTHORITY RR received voip-portal.co.uk. SOA IN 24 rdlen=46 sres.c:3572 sres_log_response() sres_resolver_receive(0x7f8118037e00, 0x7f811808ffc0) id=62405 (from [195.74.100.89]:53) sres.c:2987 sres_query_report_error() sres(q=0x7f811808ffc0): reporting error RECORD_ERR for SRV sipgate.voip-portal.co.uk. sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") called nta.c:10809 outgoing_query_a() nta: for "EN33510464.voip-portal.co.uk" query "EN33510464.voip-portal.co.uk" A sres.c:968 sres_query() sres_query(0x7f8118037e00, 0x7f81180807e0, A, "EN33510464.voip-portal.co.uk") called sres.c:2730 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f811803b610) called sres.c:2819 sres_send_dns_query() sres_send_dns_query(0x7f8118037e00, 0x7f811803b610) id=62406 A EN33510464.voip-portal.co.uk (to [195.74.100.89]:53) sres.c:3467 sres_resolver_receive() sres_resolver_receive(0x7f8118037e00, 53) called sres.c:3781 sres_create_record() ANSWER RR received EN33510464.voip-portal.co.uk. CNAME IN 60 rdlen=10 sres.c:3781 sres_create_record() ANSWER RR received sipgate.voip-portal.co.uk. A IN 50 rdlen=4 sres.c:3781 sres_create_record() AUTHORITY RR received voip-portal.co.uk. NS IN 50 rdlen=14 sres.c:3781 sres_create_record() AUTHORITY RR received voip-portal.co.uk. NS IN 50 rdlen=6 sres.c:3781 sres_create_record() AUTHORITY RR received voip-portal.co.uk. NS IN 50 rdlen=5 sres.c:3781 sres_create_record() AUTHORITY RR received voip-portal.co.uk. NS IN 50 rdlen=6 sres.c:3572 sres_log_response() sres_resolver_receive(0x7f8118037e00, 0x7f811803b610) id=62406 (from [195.74.100.89]:53) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "sipgate.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "sipgate.voip-portal.co.uk.") returned 1 entries nta.c:10862 outgoing_answer_a() nta: sipgate.voip-portal.co.uk. IN A 195.74.100.80 tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = udp/195.74.100.80:5060/sip tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name udp/195.74.100.80:5060/sip tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 874 bytes of 874 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 874 send 874 bytes to udp/[195.74.100.80]:5060 at 14:18:44.048157: ------------------------------------------------------------------------ REGISTER sip:EN33510464.voip-portal.co.uk;transport=udp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bKDmjHZSQHS7pve Max-Forwards: 70 From: ;tag=KgZ0r6F96yFBg To: Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974232 REGISTER Contact: Expires: 3600 User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Authorization: Digest username="sip", realm="EN33510464.voip-portal.co.uk", nonce="59aeb24200015b29b17b71d128a36a1a209d9aafd8adada9", algorithm=MD5, uri="sip:EN33510464.voip-portal.co.uk;transport=udp", response="da8af6400d62d434f6c40e1d001884b0" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent REGISTER (111974232) to udp/195.74.100.80:5060/sip tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811803df50 for udp/195.74.100.112:5080 (already 0) tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f8118080200 from (udp/195.74.100.112:5080) has 537 bytes, veclen = 1 recv 537 bytes from udp/[195.74.100.80]:5060 at 14:18:44.056466: ------------------------------------------------------------------------ SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bKDmjHZSQHS7pve From: ;tag=KgZ0r6F96yFBg To: ;tag=a5e8f5e9ef62e93eca305ef64f43c9c0.a69e Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974232 REGISTER WWW-Authenticate: Digest realm="EN33510464.voip-portal.co.uk", nonce="59aeb25300015b3fd4d042892626cc270097244c4f408f21", stale=true Server: Entanet SIP Proxy V8.24 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f8118080200 (537 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 401 Unauthorized for REGISTER (111974232) nta.c:3366 agent_recv_response() nta: 401 Unauthorized is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 8.412 ms tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811803df50 by 0x7f81180807e0 with 0x7f8118080200 auth_digest.c:105 auth_digest_challenge_get() auth_digest_challenge_get(): got 3 auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(sip:EN33510464.voip-portal.co.uk:c776fa8e8152b37e) = 3d06e695d593a7eac66b7bf7d73ab105 auth_digest.c:318 auth_digest_response() A2 = MD5(REGISTER:sip:EN33510464.voip-portal.co.uk;transport=udp) auth_digest.c:348 auth_digest_response() auth_response: 1ddc4f38f975e0ffb1c9cf1f4e5fdcbd = MD5(3d06e695d593a7eac66b7bf7d73ab105:59aeb25300015b3fd4d042892626cc270097244c4f408f21:e74b8fa4c49b2545abc7114a4258522e) (qop=NONE) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, SRV, "_sip._udp.EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10604 outgoing_query_srv() nta: for "EN33510464.voip-portal.co.uk" query "_sip._udp.EN33510464.voip-portal.co.uk" SRV (cached) sres_cache.c:272 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") called sres_cache.c:318 sres_cache_get() sres_cache_get(0x7f81180262e0, A, "EN33510464.voip-portal.co.uk.") returned 1 entries nta.c:10809 outgoing_query_a() nta: for "EN33510464.voip-portal.co.uk" query "EN33510464.voip-portal.co.uk" A (cached) nta.c:10862 outgoing_answer_a() nta: sipgate.voip-portal.co.uk. IN A 195.74.100.80 tport.c:3257 tport_tsend() tport_tsend(0x7f81180397c0) tpn = udp/195.74.100.80:5060/sip tport.c:4046 tport_resolve() tport_resolve addrinfo = 195.74.100.80:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f81180397c0): not found by name udp/195.74.100.80:5060/sip tport.c:3594 tport_vsend() tport_vsend(0x7f81180397c0): 874 bytes of 874 to udp/195.74.100.80:5060 tport.c:3492 tport_send_msg() tport_vsend returned 874 send 874 bytes to udp/[195.74.100.80]:5060 at 14:18:44.056602: ------------------------------------------------------------------------ REGISTER sip:EN33510464.voip-portal.co.uk;transport=udp SIP/2.0 Via: SIP/2.0/UDP 195.74.100.112:5080;rport;branch=z9hG4bKeXBa1m8mpgDFa Max-Forwards: 70 From: ;tag=KgZ0r6F96yFBg To: Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974233 REGISTER Contact: Expires: 3600 User-Agent: FreeSWITCH-mod_sofia/1.9.0-556-68fc3b5~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Authorization: Digest username="sip", realm="EN33510464.voip-portal.co.uk", nonce="59aeb25300015b3fd4d042892626cc270097244c4f408f21", algorithm=MD5, uri="sip:EN33510464.voip-portal.co.uk;transport=udp", response="1ddc4f38f975e0ffb1c9cf1f4e5fdcbd" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8310 outgoing_send() nta: sent REGISTER (111974233) to udp/195.74.100.80:5060/sip tport.c:4160 tport_pend() tport_pend(0x7f81180397c0): pending 0x7f811803e7b0 for udp/195.74.100.112:5080 (already 0) nua_stack.c:271 nua_stack_event() nua(0x7f812005c5d0): event r_register 100 Request Authorized by Cache nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f81180397c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f81180397c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f81180397c0) msg 0x7f81180877d0 from (udp/195.74.100.112:5080) has 481 bytes, veclen = 1 recv 481 bytes from udp/[195.74.100.80]:5060 at 14:18:44.069049: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 195.74.100.112:5080;received=195.74.100.112;rport=5080;branch=z9hG4bKeXBa1m8mpgDFa From: ;tag=KgZ0r6F96yFBg To: ;tag=a5e8f5e9ef62e93eca305ef64f43c9c0.cfcf Call-ID: 50be4af2-ef74-4936-b532-330a3a739cd9 CSeq: 111974233 REGISTER Contact: ;q=0;expires=60 Server: Entanet SIP Proxy V8.24 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f81180397c0): msg 0x7f81180877d0 (481 bytes) from udp/195.74.100.80:5080/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for REGISTER (111974233) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 12.504 ms tport.c:4222 tport_release() tport_release(0x7f81180397c0): 0x7f811803e7b0 by 0x7f8118065830 with 0x7f81180877d0 nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh register after 40 seconds (in [15..45]) nua_stack.c:271 nua_stack_event() nua(0x7f812005c5d0): event r_register 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-09-05 14:18:44.066244 [DEBUG] sofia_reg.c:2435 Changing expire time to 60 by request of proxy sip:EN33510464.voip-portal.co.uk nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nta.c:1296 agent_timer() nta: timer set next to 4000 ms nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate INFO (111974475) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813165dd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/4 term, 1/4 free nta.c:1296 agent_timer() nta: timer set next to 33 ms nta.c:9107 outgoing_timer_dk() nta: timer K fired, terminate BYE (111974476) nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f813165dd40) nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/3 term, 1/3 free nta.c:1296 agent_timer() nta: timer set next to 548 ms