tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0018400 from (udp/10.3.2.4:5060) has 500 bytes, veclen = 1 recv 500 bytes from udp/[10.95.2.2]:5060 at 17:20:41.280764: ------------------------------------------------------------------------ INVITE sip:30161@10.3.2.4 SIP/2.0 Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 Max-Forwards: 70 From: "100201" ;tag=123447 To: Contact: Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE User-Agent: TATTILE PBX v.3.4 Content-Type: application/sdp Content-Length: 143 v=0 o=root 1 2 IN IP4 10.95.2.2 s=SIP Call c=IN IP4 10.95.2.2 t=0 0 m=audio 7068 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0018400 (500 bytes) from udp/10.95.2.2:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INVITE sip:30161@10.3.2.4 SIP/2.0 (CSeq 13) nta.c:3248 agent_aliases() nta: canonizing sip:30161@10.3.2.4 with contact nta.c:3085 agent_recv_request() nta: INVITE (13) 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:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0da00130b0) called soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017b10, ...) called nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da0022e90) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f0da0017b10) called soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f0da0017b10, (nil), 0x7f0da0013f85, 143) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f0da00130b0): adding session usage tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 243 bytes of 243 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 243 send 243 bytes to udp/[10.95.2.2]:5060 at 17:20:41.280927: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE User-Agent: ECSCore Content-Length: 0 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (13) nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_invite 100 Trying nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: init -> received, received offer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f0da0017b10, [0x7f0daedef8c8], [0x7f0daedef8d0], [(nil)]) called nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): 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-10-17 17:20:41.272585 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/100201@10.95.2.2 [523d784a-72fd-46f0-9ddd-408bc71763eb] nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_NEW (Cur 1 Tot 25) nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:9834 sofia/internal/100201@10.95.2.2 receiving invite from 10.95.2.2:5060 version: 1.6.17 git eb93b81 2017-05-08 21:44:33Z 64bit 2017-10-17 17:20:41.272585 [ALERT] switch_core_media.c:447 Looking for zrtp-hash 2017-10-17 17:20:41.272585 [ALERT] switch_core_media.c:402 Deciding whether to pass zrtp-hash between legs 2017-10-17 17:20:41.272585 [ALERT] switch_core_media.c:404 CF_ZRTP_PASSTHRU_REQ not set, so not propagating zrtp-hash 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:9950 IP 10.95.2.2 Approved by acl "domains[]". Access Granted. nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:7048 Channel sofia/internal/100201@10.95.2.2 entering state [received][100] 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=root 1 2 IN IP4 10.95.2.2 s=SIP Call c=IN IP4 10.95.2.2 t=0 0 m=audio 7068 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:7450 (sofia/internal/100201@10.95.2.2) State Change CS_NEW -> CS_INIT nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/100201@10.95.2.2) State NEW 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_INIT (Cur 1 Tot 25) 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100201@10.95.2.2) State INIT 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:90 sofia/internal/100201@10.95.2.2 SOFIA INIT 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:40 sofia/internal/100201@10.95.2.2 Standard INIT 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/100201@10.95.2.2) State Change CS_INIT -> CS_ROUTING 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/100201@10.95.2.2) State INIT going to sleep 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_ROUTING (Cur 1 Tot 25) 2017-10-17 17:20:41.272585 [DEBUG] switch_channel.c:2249 (sofia/internal/100201@10.95.2.2) Callstate Change DOWN -> RINGING 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100201@10.95.2.2) State ROUTING 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:143 sofia/internal/100201@10.95.2.2 SOFIA ROUTING 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:236 sofia/internal/100201@10.95.2.2 Standard ROUTING 2017-10-17 17:20:41.272585 [INFO] mod_dialplan_xml.c:637 Processing 100201 <100201>->30161 in context blackhole Dialplan: sofia/internal/100201@10.95.2.2 parsing [blackhole->test] continue=false Dialplan: sofia/internal/100201@10.95.2.2 Regex (PASS) [test] destination_number(30161) =~ /.*/ break=on-false Dialplan: sofia/internal/100201@10.95.2.2 Action bridge(user/1001) 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/100201@10.95.2.2) State Change CS_ROUTING -> CS_EXECUTE 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/100201@10.95.2.2) State ROUTING going to sleep 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_EXECUTE (Cur 1 Tot 25) 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/100201@10.95.2.2) State EXECUTE 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:198 sofia/internal/100201@10.95.2.2 SOFIA EXECUTE 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:328 sofia/internal/100201@10.95.2.2 Standard EXECUTE EXECUTE sofia/internal/100201@10.95.2.2 bridge(user/1001) 2017-10-17 17:20:41.272585 [ALERT] switch_core_session.c:2799 sofia/internal/100201@10.95.2.2 receive message [APPLICATION_EXEC] 2017-10-17 17:20:41.272585 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2017-10-17 17:20:41.272585 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2017-10-17 17:20:41.272585 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@10.95.2.81:50461 [dd008d70-5ef3-4627-9a5f-af27f10d512f] 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:4819 (sofia/internal/1001@10.95.2.81:50461) State Change CS_NEW -> CS_INIT 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_INIT (Cur 2 Tot 26) 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@10.95.2.81:50461) State INIT 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:90 sofia/internal/1001@10.95.2.81:50461 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-10-17 17:20:41.272585 [DEBUG] sofia_glue.c:1295 sofia/internal/1001@10.95.2.81:50461 sending invite version: 1.6.17 git eb93b81 2017-05-08 21:44:33Z 64bit Local SDP: v=0 o=ECSCore 1508231095 1508231096 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 26146 RTP/AVP 0 101 a=rtpmap:0 PCMU/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(0x7f0d98031830): recv signal r_invite nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0d98031830) called soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017760, ...) called soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017760, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f0da0017760, (nil), 0x7f0d9803426f, -1) called soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f0da0017760, (nil), 0x7f0d9803426f, -1) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f0d98031830): adding session usage nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da001c9f0) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f0da0017760) called soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7f0da0017760, 0) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f0da0017760, soa_generate_offer): called soa_static.c:1189 offer_answer_step() soa_static(0x7f0da0017760, soa_generate_offer): generating local description soa_static.c:1217 offer_answer_step() soa_static(0x7f0da0017760, soa_generate_offer): upgrade with local description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f0daededac0, (nil), ""): called soa_static.c:1446 offer_answer_step() soa_static(0x7f0da0017760, soa_generate_offer): storing local description soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f0da0017760, [(nil)], [0x7f0daedefbf8], [0x7f0daedefbf4]) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.81:50461 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.81:50461 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 1087 bytes of 1087 to udp/10.95.2.81:50461 tport.c:3492 tport_send_msg() tport_vsend returned 1087 send 1087 bytes to udp/[10.95.2.81]:50461 at 17:20:41.285391: ------------------------------------------------------------------------ INVITE sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7 SIP/2.0 Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bK9vy19Z6831rmB Max-Forwards: 69 From: "100201" ;tag=6KaSUSSQarNHD To: Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c CSeq: 113792556 INVITE Contact: User-Agent: ECSCore 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: 206 Remote-Party-ID: "100201" ;party=calling;screen=yes;privacy=off v=0 o=ECSCore 1508231095 1508231096 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 26146 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent INVITE (113792556) to */10.95.2.81:50461 tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da0016d00 for udp/10.3.2.4:5060 (already 0) nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: init -> calling, sent offer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f0da0017760, [0x7f0daedefbd8], [0x7f0daedefbe0], [(nil)]) called nua_stack.c:269 nua_stack_event() nua(0x7f0d98031830): event i_state INVITE sent nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f0d98031830): sent signal r_invite 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@10.95.2.81:50461 Standard INIT 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@10.95.2.81:50461) State Change CS_INIT -> CS_ROUTING 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@10.95.2.81:50461) State INIT going to sleep 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_ROUTING (Cur 2 Tot 26) nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.272585 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@10.95.2.81:50461 entering state [calling][0] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@10.95.2.81:50461) State ROUTING 2017-10-17 17:20:41.272585 [DEBUG] mod_sofia.c:143 sofia/internal/1001@10.95.2.81:50461 SOFIA ROUTING 2017-10-17 17:20:41.272585 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@10.95.2.81:50461) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@10.95.2.81:50461) State ROUTING going to sleep 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 26) 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@10.95.2.81:50461) State CONSUME_MEDIA 2017-10-17 17:20:41.272585 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@10.95.2.81:50461) State CONSUME_MEDIA going to sleep 2017-10-17 17:20:41.272585 [ALERT] switch_core_state_machine.c:701 sofia/internal/1001@10.95.2.81:50461 session thread sleep state: CS_CONSUME_MEDIA! tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0011bf0 from (udp/10.3.2.4:5060) has 294 bytes, veclen = 1 recv 294 bytes from udp/[10.95.2.81]:50461 at 17:20:41.370194: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bK9vy19Z6831rmB To: From: "100201" ;tag=6KaSUSSQarNHD Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c CSeq: 113792556 INVITE Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0011bf0 (294 bytes) from udp/10.95.2.81:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (113792556) nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 84.931 ms tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0016d00 by 0x7f0da0026140 with 0x7f0da0011bf0 (preliminary) tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0011bf0 from (udp/10.3.2.4:5060) has 445 bytes, veclen = 1 recv 445 bytes from udp/[10.95.2.81]:50461 at 17:20:41.420582: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bK9vy19Z6831rmB Contact: To: ;tag=48e7bf7e From: "100201" ;tag=6KaSUSSQarNHD Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c CSeq: 113792556 INVITE User-Agent: Bria 4 release 4.8.2 stamp 85656 Allow-Events: talk, hold Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0011bf0 (445 bytes) from udp/10.95.2.81:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 180 Ringing for INVITE (113792556) nta.c:3366 agent_recv_response() nta: 180 Ringing is going to a transaction tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0016d00 by 0x7f0da0026140 with 0x7f0da0011bf0 (preliminary) nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event r_invite 180 Ringing nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: calling -> proceeding nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): 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 2017-10-17 17:20:41.412599 [ALERT] switch_core_state_machine.c:705 sofia/internal/1001@10.95.2.81:50461 session thread wake state: CS_CONSUME_MEDIA! nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.412599 [ALERT] sofia.c:1274 sofia/internal/1001@10.95.2.81:50461 Same Callee ID "Outbound Call" <1001> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.412599 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@10.95.2.81:50461 entering state [proceeding][180] 2017-10-17 17:20:41.412599 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/1001@10.95.2.81:50461! 2017-10-17 17:20:41.412599 [DEBUG] switch_channel.c:3345 (sofia/internal/1001@10.95.2.81:50461) Callstate Change DOWN -> RINGING 2017-10-17 17:20:41.412599 [ALERT] sofia.c:7156 sofia/internal/1001@10.95.2.81:50461 receive message [RING_EVENT] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.412599 [ALERT] switch_core_state_machine.c:701 sofia/internal/1001@10.95.2.81:50461 session thread sleep state: CS_CONSUME_MEDIA! 2017-10-17 17:20:41.412599 [ALERT] switch_ivr_originate.c:525 sofia/internal/100201@10.95.2.2 receive message [RINGING] nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f0da00130b0): recv signal r_respond 180 Ringing nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017b10, ...) called nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 652 bytes of 652 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 652 send 652 bytes to udp/[10.95.2.2]:5060 at 17:20:41.430051: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 180 Ringing for INVITE (13) nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: received -> early nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_state 180 Ringing nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f0da00130b0): sent signal r_respond 2017-10-17 17:20:41.412599 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/internal/100201@10.95.2.2! 2017-10-17 17:20:41.412599 [ALERT] mod_sofia.c:2273 sofia/internal/100201@10.95.2.2 receive message [RING_EVENT] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.412599 [DEBUG] sofia.c:7048 Channel sofia/internal/100201@10.95.2.2 entering state [early][180] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:41.412599 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/internal/100201@10.95.2.2! nta.c:1296 agent_timer() nta: timer set next to 450 ms nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f0daedefc60) nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/3 free nta.c:1296 agent_timer() nta: timer set next to 30852 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0010400 from (udp/10.3.2.4:5060) has 4 bytes, veclen = 1 tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): bad msg 0x7f0da0010400 (4 bytes) from udp/10.95.2.81:5060/sip next=(nil) tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0010400 from (udp/10.3.2.4:5060) has 749 bytes, veclen = 1 recv 749 bytes from udp/[10.95.2.81]:50461 at 17:20:45.955214: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bK9vy19Z6831rmB Contact: To: ;tag=48e7bf7e From: "100201" ;tag=6KaSUSSQarNHD Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c CSeq: 113792556 INVITE Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, MESSAGE Content-Type: application/sdp Supported: replaces User-Agent: Bria 4 release 4.8.2 stamp 85656 Content-Length: 198 v=0 o=- 2169747360 3 IN IP4 10.95.2.81 s=Bria 4 release 4.8.2 stamp 85656 c=IN IP4 10.95.2.81 t=0 0 m=audio 58876 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0010400 (749 bytes) from udp/10.95.2.81:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (113792556) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0016d00 by 0x7f0da0026140 with 0x7f0da0010400 soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f0da0017760, (nil), 0x7f0da0014247, 198) called soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f0da0017760) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f0da0017760, soa_process_answer): called soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f0da0023340, 0x7f0da0013350, ""): called soa_static.c:1304 offer_answer_step() soa_static(0x7f0da0017760, soa_process_answer): upgrade codecs with remote description soa.c:1730 soa_activate() soa_activate(static::0x7f0da0017760, (nil)) called nua_session.c:988 nua_session_client_response() nua(0x7f0d98031830): INVITE: processed SDP answer in 200 OK nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event r_invite 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: proceeding -> completing, received answer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f0da0017760, [0x7f0daedef648], [0x7f0daedef650], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7f0da0017760, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): 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 2017-10-17 17:20:45.952567 [ALERT] switch_core_state_machine.c:705 sofia/internal/1001@10.95.2.81:50461 session thread wake state: CS_CONSUME_MEDIA! nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:447 Looking for zrtp-hash 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:402 Deciding whether to pass zrtp-hash between legs 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:410 Found peer channel; propagating zrtp-hash if set 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg 2017-10-17 17:20:45.952567 [ALERT] sofia.c:1274 sofia/internal/1001@10.95.2.81:50461 Same Callee ID "Outbound Call" <1001> nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:45.952567 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@10.95.2.81:50461 entering state [completing][200] 2017-10-17 17:20:45.952567 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=- 2169747360 3 IN IP4 10.95.2.81 s=Bria 4 release 4.8.2 stamp 85656 c=IN IP4 10.95.2.81 t=0 0 m=audio 58876 RTP/AVP 0 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 nua.c:639 nua_ack() nua: nua_ack: entering nua_stack.c:569 nua_stack_signal() nua(0x7f0d98031830): recv signal r_ack nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017760, ...) called soa.c:1730 soa_activate() soa_activate(static::0x7f0da0017760, (nil)) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.81:50461 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.81:50461 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 403 bytes of 403 to udp/10.95.2.81:50461 tport.c:3492 tport_send_msg() tport_vsend returned 403 send 403 bytes to udp/[10.95.2.81]:50461 at 17:20:45.956375: ------------------------------------------------------------------------ ACK sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7 SIP/2.0 Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKa6QtBUQc1aF7p Max-Forwards: 70 From: "100201" ;tag=6KaSUSSQarNHD To: ;tag=48e7bf7e Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c CSeq: 113792556 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent ACK (113792556) to */10.95.2.81:50461 nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: completing -> ready nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_state 200 ACK sent nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): 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(0x7f0d98031830): 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-10-17 17:20:45.952567 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@10.95.2.81:50461 entering state [ready][200] 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:447 Looking for zrtp-hash 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:402 Deciding whether to pass zrtp-hash between legs 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:410 Found peer channel; propagating zrtp-hash if set 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/1001@10.95.2.81:50461 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-10-17 17:20:45.952567 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@10.95.2.81:50461 Original read codec set to PCMU:0 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4754 sofia/internal/1001@10.95.2.81:50461 Set 2833 dtmf send payload to 101 recv payload to 101 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/1001@10.95.2.81:50461] 10.3.2.4 port 26146 -> 10.95.2.81 port 58876 codec: 0 ms: 20 2017-10-17 17:20:45.952567 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7166 sofia/internal/1001@10.95.2.81:50461 Set 2833 dtmf send payload to 101 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7173 sofia/internal/1001@10.95.2.81:50461 Set 2833 dtmf receive payload to 101 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7196 sofia/internal/1001@10.95.2.81:50461 Set rtp dtmf delay to 40 2017-10-17 17:20:45.952567 [NOTICE] sofia.c:8182 Channel [sofia/internal/1001@10.95.2.81:50461] has been answered 2017-10-17 17:20:45.952567 [DEBUG] switch_channel.c:3772 (sofia/internal/1001@10.95.2.81:50461) Callstate Change RINGING -> ACTIVE 2017-10-17 17:20:45.952567 [ALERT] sofia.c:8182 sofia/internal/1001@10.95.2.81:50461 receive message [ANSWER_EVENT] 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-10-17 17:20:45.952567 [ALERT] switch_core_state_machine.c:701 sofia/internal/1001@10.95.2.81:50461 session thread sleep state: CS_CONSUME_MEDIA! 2017-10-17 17:20:45.952567 [ALERT] switch_ivr_originate.c:3632 sofia/internal/100201@10.95.2.2 receive message [ANSWER] 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:447 Looking for zrtp-hash 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:402 Deciding whether to pass zrtp-hash between legs 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:410 Found peer channel; propagating zrtp-hash if set 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg 2017-10-17 17:20:45.952567 [ALERT] switch_core_media.c:325 Deciding whether to pass zrtp-hash between a-leg and b-leg 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/100201@10.95.2.2 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-10-17 17:20:45.952567 [DEBUG] switch_core_codec.c:111 sofia/internal/100201@10.95.2.2 Original read codec set to PCMU:0 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4725 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:4754 sofia/internal/100201@10.95.2.2 Set 2833 dtmf send payload to 101 recv payload to 101 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/100201@10.95.2.2] 10.3.2.4 port 18162 -> 10.95.2.2 port 7068 codec: 0 ms: 20 2017-10-17 17:20:45.952567 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7166 sofia/internal/100201@10.95.2.2 Set 2833 dtmf send payload to 101 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7173 sofia/internal/100201@10.95.2.2 Set 2833 dtmf receive payload to 101 2017-10-17 17:20:45.952567 [DEBUG] switch_core_media.c:7196 sofia/internal/100201@10.95.2.2 Set rtp dtmf delay to 40 2017-10-17 17:20:45.952567 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/100201@10.95.2.2! 2017-10-17 17:20:45.972802 [DEBUG] switch_channel.c:3473 (sofia/internal/100201@10.95.2.2) Callstate Change RINGING -> EARLY 2017-10-17 17:20:45.972802 [ALERT] sofia_media.c:92 sofia/internal/100201@10.95.2.2 receive message [PROGRESS_EVENT] 2017-10-17 17:20:45.972802 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/100201@10.95.2.2. 2017-10-17 17:20:45.972802 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/100201@10.95.2.2: v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/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(0x7f0da00130b0): recv signal r_respond 200 OK nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017b10, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f0da0017b10, (nil), 0x7f0da401c658, -1) called soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f0da0017b10, (nil), 0x7f0da401c658, -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::0x7f0da0017b10) called soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f0da0017b10, soa_generate_answer): called soa_static.c:1189 offer_answer_step() soa_static(0x7f0da0017b10, soa_generate_answer): generating local description soa_static.c:1230 offer_answer_step() soa_static(0x7f0da0017b10, soa_generate_answer): upgrade with remote description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f0daededb00, 0x7f0da00262b0, ""): called soa_static.c:1446 offer_answer_step() soa_static(0x7f0da0017b10, soa_generate_answer): storing local description soa.c:1730 soa_activate() soa_activate(static::0x7f0da0017b10, (nil)) called soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f0da0017b10, [(nil)], [0x7f0daedefc38], [0x7f0daedefc34]) called tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:45.973386: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (13) nta.c:1348 set_timeout() nta: timer shortened to 500 ms nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: early -> completed, sent answer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f0da0017b10, [0x7f0daedefce8], [0x7f0daedefcf0], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7f0da0017b10, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_state 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:529 nua_signal() nua(0x7f0da00130b0): sent signal r_respond nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:45.972802 [DEBUG] sofia.c:7048 Channel sofia/internal/100201@10.95.2.2 entering state [completed][200] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:20:45.972802 [NOTICE] switch_ivr_originate.c:3632 Channel [sofia/internal/100201@10.95.2.2] has been answered 2017-10-17 17:20:45.972802 [DEBUG] switch_channel.c:3772 (sofia/internal/100201@10.95.2.2) Callstate Change EARLY -> ACTIVE 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:3632 sofia/internal/100201@10.95.2.2 receive message [ANSWER_EVENT] 2017-10-17 17:20:45.972802 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1001@10.95.2.81:50461] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:4026 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC] 2017-10-17 17:20:45.972802 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1001@10.95.2.81:50461] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:4026 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:4023 sofia/internal/1001@10.95.2.81:50461 receive message [AUDIO_SYNC] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_originate.c:4023 sofia/internal/1001@10.95.2.81:50461 receive message [AUDIO_SYNC] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_bridge.c:1462 sofia/internal/1001@10.95.2.81:50461 receive message [AUDIO_SYNC] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr.c:217 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_bridge.c:1461 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_bridge.c:1561 sofia/internal/1001@10.95.2.81:50461 receive message [BRIDGE] 2017-10-17 17:20:45.972802 [ALERT] switch_ivr_bridge.c:1569 sofia/internal/100201@10.95.2.2 receive message [BRIDGE] 2017-10-17 17:20:45.972802 [DEBUG] switch_ivr_bridge.c:1601 (sofia/internal/1001@10.95.2.81:50461) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2017-10-17 17:20:45.972802 [ALERT] switch_core_state_machine.c:705 sofia/internal/1001@10.95.2.81:50461 session thread wake state: CS_CONSUME_MEDIA! 2017-10-17 17:20:45.972802 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 26) 2017-10-17 17:20:45.972802 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1001@10.95.2.81:50461) State EXCHANGE_MEDIA 2017-10-17 17:20:45.972802 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0012d00 from (udp/10.3.2.4:5060) has 326 bytes, veclen = 1 recv 326 bytes from udp/[10.95.2.2]:5060 at 17:20:45.977755: ------------------------------------------------------------------------ ACK sip:30161@10.3.2.4:5060 SIP/2.0 Contact: User-Agent: TATTILE PBX v.3.4 To: ;tag=5aH0Sy8KDFZyH From: "100201" ;tag=123447 Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0012d00 (326 bytes) from udp/10.95.2.2:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received ACK sip:30161@10.3.2.4:5060 SIP/2.0 (CSeq 13) nta.c:2931 agent_recv_request() nta: ACK (13) failed sanity check 2017-10-17 17:20:46.032697 [DEBUG] switch_rtp.c:7231 Correct audio ip/port confirmed. 2017-10-17 17:20:46.212568 [DEBUG] switch_rtp.c:7231 Correct audio ip/port confirmed. 2017-10-17 17:20:46.352697 [WARNING] switch_core_media.c:2475 [CBR]: Asynchronous PTIME not supported, changing our end from 20 to 10 2017-10-17 17:20:46.372602 [DEBUG] switch_core_media.c:2954 Changing Codec from PCMU@20ms@8000hz to PCMU@10ms@8000hz 2017-10-17 17:20:46.412568 [DEBUG] switch_rtp.c:3974 RE-Starting timer [soft] 80 bytes per 10ms 2017-10-17 17:20:46.412568 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/100201@10.95.2.2 PCMU/8000 10 ms 80 samples 64000 bits 1 channels 2017-10-17 17:20:46.412568 [DEBUG] switch_core_codec.c:123 sofia/internal/100201@10.95.2.2 Original read codec replaced with PCMU:0 2017-10-17 17:20:46.412568 [ALERT] switch_core_media.c:2952 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC] 2017-10-17 17:20:46.412568 [ALERT] switch_core_media.c:2971 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC] 2017-10-17 17:20:46.412568 [ALERT] switch_core_media.c:3017 sofia/internal/100201@10.95.2.2 receive message [AUDIO_SYNC] 2017-10-17 17:20:46.432785 [ALERT] switch_core_io.c:1152 sofia/internal/100201@10.95.2.2 receive message [TRANSCODING_NECESSARY] 2017-10-17 17:20:46.432785 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 160 bytes to accommodate 320->160 2017-10-17 17:20:46.432785 [ALERT] switch_rtp.c:6827 sofia/internal/100201@10.95.2.2 syncing 1 audio packet(s) 2017-10-17 17:20:46.432785 [ALERT] switch_core_io.c:1152 sofia/internal/1001@10.95.2.81:50461 receive message [TRANSCODING_NECESSARY] 2017-10-17 17:20:46.432785 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 320 bytes to accommodate 160->320 nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:46.474198: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 1000 ms 2017-10-17 17:20:46.532568 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 0.00 0/1 flaws: 1 mos: 1.00 v: 0.00 0.00/0.00 2017-10-17 17:20:46.532568 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 10.000000 2017-10-17 17:20:46.554525 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 3.500000 2017-10-17 17:20:46.554525 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 1.005263 2017-10-17 17:20:46.554525 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 2.100000 2017-10-17 17:20:46.554525 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 1.400000 2017-10-17 17:20:46.592597 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 1.428571 2017-10-17 17:20:46.612567 [ALERT] switch_rtp.c:1755 Calculated Instantaneous Packet Delay Variation: audio packet 1.111111 nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:47.474915: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 2000 ms nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:49.475385: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 4001 ms 2017-10-17 17:20:51.552576 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 502/503 flaws: 1 mos: 4.49 v: 127.75 105.55/266.43 nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:53.477339: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 4001 ms 2017-10-17 17:20:56.572599 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 1004/1005 flaws: 1 mos: 4.49 v: 123.71 105.55/266.43 nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:20:57.478830: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 4000 ms 2017-10-17 17:21:00.452655 [ALERT] sofia_reg.c:939 Updating ping expires for profile internal 2017-10-17 17:21:00.452655 [ALERT] sofia_reg.c:875 Generated random 16, max is 30 2017-10-17 17:21:01.452603 [NOTICE] sofia_reg.c:448 Registering ale nua.c:622 nua_register() nua: nua_register: entering nua_stack.c:569 nua_stack_signal() nua(0x7f0d9c030d40): recv signal r_register nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f0da000f2b0, ...) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f0d9c030d40): adding register usage nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da0018140) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = udp/192.168.1.11:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.1.11:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name udp/192.168.1.11:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 536 bytes of 536 to udp/192.168.1.11:5060 tport.c:3492 tport_send_msg() tport_vsend returned 536 send 536 bytes to udp/[192.168.1.11]:5060 at 17:21:01.458539: ------------------------------------------------------------------------ REGISTER sip:192.168.1.11;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKBFHKDp8FyK5Sj Max-Forwards: 70 From: ;tag=7v3HXmaU70B4r To: Call-ID: 3bf2563f-444c-4541-9dc9-9b73f46b2ea2 CSeq: 113792566 REGISTER Contact: Expires: 3600 User-Agent: ECSCore Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent REGISTER (113792566) to udp/192.168.1.11:5060 tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da001a580 for udp/10.3.2.4:5060 (already 0) nua_stack.c:529 nua_signal() nua(0x7f0d9c030d40): sent signal r_register nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:01.478804: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 980 ms 2017-10-17 17:21:01.592574 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 1506/1507 flaws: 1 mos: 4.49 v: 118.89 105.55/266.43 nta.c:8893 _nta_outgoing_timer() nta: timer E fired, retransmit REGISTER (113792566) tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da001a580 by 0x7f0da00165c0 with (nil) tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = udp/192.168.1.11:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 192.168.1.11:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name udp/192.168.1.11:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 536 bytes of 536 to udp/192.168.1.11:5060 tport.c:3492 tport_send_msg() tport_vsend returned 536 send 536 bytes to udp/[192.168.1.11]:5060 at 17:21:02.460134: ------------------------------------------------------------------------ REGISTER sip:192.168.1.11;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKBFHKDp8FyK5Sj Max-Forwards: 70 From: ;tag=7v3HXmaU70B4r To: Call-ID: 3bf2563f-444c-4541-9dc9-9b73f46b2ea2 CSeq: 113792566 REGISTER Contact: Expires: 3600 User-Agent: ECSCore Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: resent REGISTER (113792566) to udp/192.168.1.11:5060 tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da001a580 for udp/10.3.2.4:5060 (already 0) nta.c:8929 _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 2000 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events ERR tport_type_udp.c:519 tport_udp_error() tport_udp_error: No route to host (113) [icmp type=3 code=1] tport_type_udp.c:524 tport_udp_error() reported by [10.3.2.4]:0 tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da001a580 by 0x7f0da00165c0 with (nil) nta.c:8496 outgoing_print_tport_error() nta: REGISTER (113792566): No route to host (113) with udp/[192.168.1.11]:5060 nua_stack.c:271 nua_stack_event() nua(0x7f0d9c030d40): event r_register 503 Service Unavailable nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f0d9c030d40): removing register usage nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da0018140) tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events ERR tport_type_udp.c:519 tport_udp_error() tport_udp_error: No route to host (113) [icmp type=3 code=1] tport_type_udp.c:524 tport_udp_error() reported by [10.3.2.4]:0 nta.c:2719 agent_tp_error() nta_agent: tport: 192.168.1.11:5060: No route to host nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2017-10-17 17:21:04.452578 [ERR] sofia_reg.c:2447 ale Failed Registration with status Service Unavailable [503]. failure #34 nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nta.c:1296 agent_timer() nta: timer set next to 1019 ms 2017-10-17 17:21:04.452578 [WARNING] sofia_reg.c:505 ale Failed Registration [503], setting retry to 30 seconds. nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:05.480390: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 3975 ms 2017-10-17 17:21:06.612763 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 2008/2009 flaws: 1 mos: 4.49 v: 116.82 105.55/266.43 nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate REGISTER (113792566) nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f0daedefd40) nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free nta.c:1296 agent_timer() nta: timer set next to 24 ms nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:09.480948: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 3302 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0012d00 from (udp/10.3.2.4:5060) has 284 bytes, veclen = 1 recv 284 bytes from udp/[10.95.2.2]:5060 at 17:21:11.633254: ------------------------------------------------------------------------ OPTIONS sip:10.3.2.4 SIP/2.0 Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1034276 Max-Forwards: 70 From: ;tag=123448 To: Contact: Call-ID: 10.95.2.2:5060 CSeq: 34 OPTIONS User-Agent: TATTILE PBX v.3.4 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0012d00 (284 bytes) from udp/10.95.2.2:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received OPTIONS sip:10.3.2.4 SIP/2.0 (CSeq 34) nta.c:3248 agent_aliases() nta: canonizing sip:10.3.2.4 with contact nta.c:3085 agent_recv_request() nta: OPTIONS (34) 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:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0da0017360) called soa.c:403 soa_set_params() soa_set_params(static::0x7f0da001e880, ...) called nua_stack.c:271 nua_stack_event() nua(0x7f0da0017360): event i_options 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(0x7f0da0017360): recv signal r_respond 200 OK nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f0da001e880, ...) called soa.c:845 soa_get_capability_sdp() soa_get_capability_sdp(static::0x7f0da001e880, [(nil)], [0x7f0daedefc68], [0x7f0daedefc64]) called tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 594 bytes of 594 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 594 send 594 bytes to udp/[10.95.2.2]:5060 at 17:21:11.633676: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1034276 From: ;tag=123448 To: ;tag=9ep30ac21jr9F Call-ID: 10.95.2.2:5060 CSeq: 34 OPTIONS Contact: User-Agent: ECSCore 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 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 200 OK for OPTIONS (34) nua_stack.c:529 nua_signal() nua(0x7f0da0017360): sent signal r_respond 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(0x7f0da0017360): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) soa.c:356 soa_destroy() soa_destroy(static::0x7f0da001e880) called nua_stack.c:529 nua_signal() nua(0x7f0da0017360): sent signal r_destroy 2017-10-17 17:21:11.632625 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 2510/2511 flaws: 1 mos: 4.49 v: 117.11 105.55/266.43 nta.c:7159 _nta_incoming_timer() nta: timer J fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f0daedefc60) nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/1 resent, 0/1 tout, 1/2 term, 1/3 free nta.c:1296 agent_timer() nta: timer set next to 697 ms nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:13.481759: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/1 term, 0/2 free nta.c:1296 agent_timer() nta: timer set next to 4000 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0012740 from (udp/10.3.2.4:5060) has 4 bytes, veclen = 1 tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): bad msg 0x7f0da0012740 (4 bytes) from udp/10.95.2.81:5060/sip next=(nil) tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0012740 from (udp/10.3.2.4:5060) has 602 bytes, veclen = 1 recv 602 bytes from udp/[10.95.2.81]:50461 at 17:21:15.250541: ------------------------------------------------------------------------ SUBSCRIBE sip:1001@10.3.2.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.95.2.81:50461;branch=z9hG4bK-524287-1---10949e77dc307966;rport Max-Forwards: 70 Contact: To: ;tag=7KqPYZsM5cVl From: ;tag=3776e149 Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI CSeq: 17 SUBSCRIBE Expires: 300 Accept: application/simple-message-summary Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, MESSAGE User-Agent: Bria 4 release 4.8.2 stamp 85656 Event: message-summary Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0012740 (602 bytes) from udp/10.95.2.81:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received SUBSCRIBE sip:1001@10.3.2.4:5060 SIP/2.0 (CSeq 17) nta.c:3248 agent_aliases() nta: canonizing sip:1001@10.3.2.4:5060 with contact nta.c:3085 agent_recv_request() nta: SUBSCRIBE (17) 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:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0da0004b00) called soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0003240, ...) called nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da0018290) nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f0da0004b00): adding notify usage with event message-summary nua_stack.c:271 nua_stack_event() nua(0x7f0da0004b00): event i_subscribe 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_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh notify after 300 seconds (in [300..300]) nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7f0da0004b00): recv signal r_respond 202 Accepted nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0003240, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.81:50461 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.81:50461 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 719 bytes of 719 to udp/10.95.2.81:50461 tport.c:3492 tport_send_msg() tport_vsend returned 719 send 719 bytes to udp/[10.95.2.81]:50461 at 17:21:15.251936: ------------------------------------------------------------------------ SIP/2.0 202 Accepted Via: SIP/2.0/UDP 10.95.2.81:50461;branch=z9hG4bK-524287-1---10949e77dc307966;rport=50461 From: ;tag=3776e149 To: ;tag=7KqPYZsM5cVl Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI CSeq: 17 SUBSCRIBE Contact: Expires: 300 User-Agent: ECSCore 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 Subscription-State: active;expires=300 Content-Length: 0 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 202 Accepted for SUBSCRIBE (17) nua_stack.c:529 nua_signal() nua(0x7f0da0004b00): sent signal r_respond nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering nua_stack.c:569 nua_stack_signal() nua(0x7f0da0004b00): recv signal r_destroy nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f0da0004b00): removing notify usage with event message-summary nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da0018290) soa.c:356 soa_destroy() soa_destroy(static::0x7f0da0003240) called nua_stack.c:529 nua_signal() nua(0x7f0da0004b00): sent signal r_destroy 2017-10-17 17:21:15.312570 [ALERT] switch_rtp.c:1658 sofia/internal/100201@10.95.2.2 Got: audio seq 28865 but expected: 28864 lost: 1 2017-10-17 17:21:15.312570 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 2877/2879 flaws: 2 mos: 4.49 v: 118.40 105.55/266.43 nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua.c:716 nua_notify() nua: nua_notify: entering nua_stack.c:569 nua_stack_signal() nua(0x7f0d98034360): recv signal r_notify nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:280 soa_clone() soa_clone(static::0x7f0da00064a0, 0x7f0da00010a0, 0x7f0d98034360) called soa.c:403 soa_set_params() soa_set_params(static::0x7f0da002fed0, ...) called soa.c:403 soa_set_params() soa_set_params(static::0x7f0da002fed0, ...) called nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f0da0018290) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.81:50461 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.81:50461 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 881 bytes of 881 to udp/10.95.2.81:50461 tport.c:3492 tport_send_msg() tport_vsend returned 881 send 881 bytes to udp/[10.95.2.81]:50461 at 17:21:15.340076: ------------------------------------------------------------------------ NOTIFY sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7 SIP/2.0 Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKcracFHSKUvUce Max-Forwards: 70 From: ;tag=7KqPYZsM5cVl To: ;tag=3776e149 Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI CSeq: 1251603751 NOTIFY Contact: User-Agent: ECSCore Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: message-summary Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: active;expires=300 Content-Type: application/simple-message-summary Content-Length: 60 Messages-Waiting: no Message-Account: sip:1001@10.3.2.4 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent NOTIFY (1251603751) to */10.95.2.81:50461 tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da0003160 for udp/10.3.2.4:5060 (already 0) nta.c:1348 set_timeout() nta: timer shortened to 1000 ms nua_stack.c:529 nua_signal() nua(0x7f0d98034360): sent signal r_notify tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da002a010 from (udp/10.3.2.4:5060) has 380 bytes, veclen = 1 recv 380 bytes from udp/[10.95.2.81]:50461 at 17:21:15.341065: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bKcracFHSKUvUce Contact: To: ;tag=3776e149 From: ;tag=7KqPYZsM5cVl Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI CSeq: 1251603751 NOTIFY User-Agent: Bria 4 release 4.8.2 stamp 85656 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da002a010 (380 bytes) from udp/10.95.2.81:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for NOTIFY (1251603751) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 1.17 ms tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0003160 by 0x7f0da001d620 with 0x7f0da002a010 nua_stack.c:271 nua_stack_event() nua(0x7f0d98034360): event r_notify 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 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(0x7f0d98034360): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da0018290) soa.c:356 soa_destroy() soa_destroy(static::0x7f0da002fed0) called nua_stack.c:529 nua_signal() nua(0x7f0d98034360): sent signal r_destroy nta.c:1296 agent_timer() nta: timer set next to 1141 ms 2017-10-17 17:21:16.652595 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 3011/3013 flaws: 2 mos: 4.49 v: 117.21 105.55/266.43 nta.c:6996 _nta_incoming_timer() nta: timer G fired, retransmitting 200 reply tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = UDP/10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name UDP/10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 891 bytes of 891 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 891 send 891 bytes to udp/[10.95.2.2]:5060 at 17:21:17.482783: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.95.2.2:5060;branch=z9hG4bK-1003924 From: "100201" ;tag=123447 To: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 13 INVITE Contact: User-Agent: ECSCore 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: 206 v=0 o=ECSCore 1508239083 1508239084 IN IP4 10.3.2.4 s=ECSCore c=IN IP4 10.3.2.4 t=0 0 m=audio 18162 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 1/1 resent, 0/1 tout, 0/2 term, 0/3 free nta.c:1296 agent_timer() nta: timer set next to 472 ms nta.c:9101 outgoing_timer_dk() nta: timer D fired, terminate INVITE (113792556) nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f0daedefd40) nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free nta.c:1296 agent_timer() nta: timer set next to 1 ms nta.c:8982 outgoing_timer_bf() nta: timer F fired, terminating ACK (113792556) nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f0daedefd40) nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/1 term, 1/2 free nta.c:1296 agent_timer() nta: timer set next to 18 ms nta.c:7105 _nta_incoming_timer() nta: timer H fired, timeout and terminate 200 response nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_error 408 ACK Timeout nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:1784 soa_terminate() soa_terminate(static::0x7f0da0017b10) called soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f0da0017b10) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.2:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.2:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.2:5060 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 543 bytes of 543 to udp/10.95.2.2:5060 tport.c:3492 tport_send_msg() tport_vsend returned 543 send 543 bytes to udp/[10.95.2.2]:5060 at 17:21:17.974808: ------------------------------------------------------------------------ BYE sip:100201@10.95.2.2:5060 SIP/2.0 Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKD134gcaQr5HZS Max-Forwards: 70 From: ;tag=5aH0Sy8KDFZyH To: "100201" ;tag=123447 Call-ID: 100201@10.95.2.2:5060 CSeq: 113792574 BYE Contact: User-Agent: ECSCore Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Reason: SIP;cause=408;text="ACK Timeout" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent BYE (113792574) to */10.95.2.2:5060 tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da0010400 for udp/10.3.2.4:5060 (already 0) nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: completed -> terminating nua_stack.c:269 nua_stack_event() nua(0x7f0da00130b0): event i_state ACK Timeout nta.c:5744 incoming_free() nta: incoming_free(0x7f0da00112a0) nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/1 resent, 1/1 tout, 0/2 term, 0/3 free nta.c:1296 agent_timer() nta: timer set next to 1001 ms 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(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0018400 from (udp/10.3.2.4:5060) has 276 bytes, veclen = 1 recv 276 bytes from udp/[10.95.2.2]:5060 at 17:21:17.977778: ------------------------------------------------------------------------ SIP/2.0 200 OK To: "100201" ;tag=123447 From: ;tag=5aH0Sy8KDFZyH Call-ID: 100201@10.95.2.2:5060 CSeq: 113792574 BYE Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKD134gcaQr5HZS User-Agent: TATTILE PBX v.3.4 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0018400 (276 bytes) from udp/10.95.2.2:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (113792574) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 3.156 ms tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da0010400 by 0x7f0da0029e40 with 0x7f0da0018400 nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event r_bye 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7f0da00130b0): call state changed: terminating -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_state 200 to BYE nua_stack.c:271 nua_stack_event() nua(0x7f0da00130b0): event i_terminated 200 to BYE nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f0da00130b0): removing session usage soa.c:356 soa_destroy() soa_destroy(static::0x7f0da0017b10) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da0022e90) nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f0da00130b0 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-10-17 17:21:17.953318 [DEBUG] sofia.c:7048 Channel sofia/internal/100201@10.95.2.2 entering state [terminating][0] 2017-10-17 17:21:17.953318 [NOTICE] sofia.c:8237 Hangup sofia/internal/100201@10.95.2.2 [CS_EXECUTE] [NORMAL_UNSPECIFIED] 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(0x7f0da00130b0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) nua_stack.c:529 nua_signal() nua(0x7f0da00130b0): sent signal r_destroy 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 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-10-17 17:21:17.953318 [DEBUG] switch_ivr_bridge.c:712 sofia/internal/100201@10.95.2.2 ending bridge by request from read function 2017-10-17 17:21:17.953318 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/100201@10.95.2.2] 2017-10-17 17:21:17.992576 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/100201@10.95.2.2 ending bridge by request from write function 2017-10-17 17:21:17.992576 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/1001@10.95.2.81:50461] 2017-10-17 17:21:17.992576 [NOTICE] switch_ivr_bridge.c:891 Hangup sofia/internal/1001@10.95.2.81:50461 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1001@10.95.2.81:50461) State EXCHANGE_MEDIA going to sleep 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_HANGUP (Cur 2 Tot 26) 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1001@10.95.2.81:50461) Callstate Change ACTIVE -> HANGUP 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@10.95.2.81:50461) State HANGUP 2017-10-17 17:21:17.992576 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1001@10.95.2.81:50461 hanging up, cause: NORMAL_CLEARING 2017-10-17 17:21:17.992576 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/1001@10.95.2.81:50461 nua.c:645 nua_bye() nua: nua_bye: entering nua_stack.c:569 nua_stack_signal() nua(0x7f0d98031830): recv signal r_bye nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7f0da0017760, ...) called soa.c:1784 soa_terminate() soa_terminate(static::0x7f0da0017760) called soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f0da0017760) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7f0da00086c0) tpn = */10.95.2.81:50461 tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.95.2.81:50461 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f0da00086c0): not found by name */10.95.2.81:50461 tport.c:3594 tport_vsend() tport_vsend(0x7f0da00086c0): 575 bytes of 575 to udp/10.95.2.81:50461 tport.c:3492 tport_send_msg() tport_vsend returned 575 send 575 bytes to udp/[10.95.2.81]:50461 at 17:21:18.000064: ------------------------------------------------------------------------ BYE sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7 SIP/2.0 Via: SIP/2.0/UDP 10.3.2.4;rport;branch=z9hG4bKeaXXj7ttNe8HN Max-Forwards: 70 From: "100201" ;tag=6KaSUSSQarNHD To: ;tag=48e7bf7e Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c CSeq: 113792557 BYE User-Agent: ECSCore Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent BYE (113792557) to */10.95.2.81:50461 tport.c:4160 tport_pend() tport_pend(0x7f0da00086c0): pending 0x7f0da001bb30 for udp/10.3.2.4:5060 (already 0) nua_stack.c:529 nua_signal() nua(0x7f0d98031830): sent signal r_bye 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@10.95.2.81:50461 Standard HANGUP, cause: NORMAL_CLEARING 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@10.95.2.81:50461) State HANGUP going to sleep 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1001@10.95.2.81:50461) State Change CS_HANGUP -> CS_REPORTING 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_REPORTING (Cur 2 Tot 26) 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@10.95.2.81:50461) State REPORTING 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1001@10.95.2.81:50461 Standard REPORTING, cause: NORMAL_CLEARING 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@10.95.2.81:50461) State REPORTING going to sleep 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1001@10.95.2.81:50461) State Change CS_REPORTING -> CS_DESTROY 2017-10-17 17:21:17.992576 [DEBUG] switch_core_session.c:1664 Session 26 (sofia/internal/1001@10.95.2.81:50461) Locked, Waiting on external entities 2017-10-17 17:21:17.992576 [ALERT] switch_ivr_bridge.c:1702 sofia/internal/100201@10.95.2.2 receive message [UNBRIDGE] 2017-10-17 17:21:17.992576 [DEBUG] switch_ivr_bridge.c:1702 sofia/internal/100201@10.95.2.2 skip receive message [UNBRIDGE] (channel is hungup already) 2017-10-17 17:21:17.992576 [ALERT] switch_core_session.c:2814 sofia/internal/100201@10.95.2.2 receive message [APPLICATION_EXEC_COMPLETE] 2017-10-17 17:21:17.992576 [DEBUG] switch_core_session.c:2814 sofia/internal/100201@10.95.2.2 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/100201@10.95.2.2) State EXECUTE going to sleep 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_HANGUP (Cur 2 Tot 26) 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100201@10.95.2.2) Callstate Change ACTIVE -> HANGUP 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100201@10.95.2.2) State HANGUP 2017-10-17 17:21:17.992576 [DEBUG] mod_sofia.c:438 Channel sofia/internal/100201@10.95.2.2 hanging up, cause: NORMAL_UNSPECIFIED 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100201@10.95.2.2 Standard HANGUP, cause: NORMAL_UNSPECIFIED 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/100201@10.95.2.2) State HANGUP going to sleep 2017-10-17 17:21:17.992576 [ALERT] switch_rtp.c:1581 sofia/internal/100201@10.95.2.2 audio stat 99.00 3142/3144 flaws: 2 mos: 4.49 v: 117.58 105.55/266.43 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/100201@10.95.2.2) State Change CS_HANGUP -> CS_REPORTING 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/100201@10.95.2.2) Running State Change CS_REPORTING (Cur 2 Tot 26) 2017-10-17 17:21:17.992576 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100201@10.95.2.2) State REPORTING 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100201@10.95.2.2 Standard REPORTING, cause: NORMAL_UNSPECIFIED 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/100201@10.95.2.2) State REPORTING going to sleep 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/100201@10.95.2.2) State Change CS_REPORTING -> CS_DESTROY 2017-10-17 17:21:18.012579 [DEBUG] switch_core_session.c:1664 Session 25 (sofia/internal/100201@10.95.2.2) Locked, Waiting on external entities 2017-10-17 17:21:18.012579 [NOTICE] switch_core_session.c:1682 Session 25 (sofia/internal/100201@10.95.2.2) Ended 2017-10-17 17:21:18.012579 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/100201@10.95.2.2 [CS_DESTROY] 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/100201@10.95.2.2) Running State Change CS_DESTROY (Cur 1 Tot 26) 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100201@10.95.2.2) State DESTROY 2017-10-17 17:21:18.012579 [DEBUG] mod_sofia.c:343 sofia/internal/100201@10.95.2.2 SOFIA DESTROY 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100201@10.95.2.2 Standard DESTROY 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/100201@10.95.2.2) State DESTROY going to sleep 2017-10-17 17:21:18.012579 [NOTICE] switch_core_session.c:1682 Session 26 (sofia/internal/1001@10.95.2.81:50461) Ended 2017-10-17 17:21:18.012579 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1001@10.95.2.81:50461 [CS_DESTROY] 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@10.95.2.81:50461) Running State Change CS_DESTROY (Cur 0 Tot 26) 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@10.95.2.81:50461) State DESTROY 2017-10-17 17:21:18.012579 [DEBUG] mod_sofia.c:343 sofia/internal/1001@10.95.2.81:50461 SOFIA DESTROY 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1001@10.95.2.81:50461 Standard DESTROY 2017-10-17 17:21:18.012579 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@10.95.2.81:50461) State DESTROY going to sleep tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f0da00086c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7f0da00086c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f0da00086c0) msg 0x7f0da0021ad0 from (udp/10.3.2.4:5060) has 411 bytes, veclen = 1 recv 411 bytes from udp/[10.95.2.81]:50461 at 17:21:18.151413: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.2.4;rport=5060;branch=z9hG4bKeaXXj7ttNe8HN Contact: To: ;tag=48e7bf7e From: "100201" ;tag=6KaSUSSQarNHD Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c CSeq: 113792557 BYE User-Agent: Bria 4 release 4.8.2 stamp 85656 Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7f0da00086c0): msg 0x7f0da0021ad0 (411 bytes) from udp/10.95.2.81:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for BYE (113792557) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 154.556 ms tport.c:4222 tport_release() tport_release(0x7f0da00086c0): 0x7f0da001bb30 by 0x7f0da00054c0 with 0x7f0da0021ad0 nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event r_bye 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7f0d98031830): call state changed: terminating -> terminated nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_state 200 to BYE nua_stack.c:271 nua_stack_event() nua(0x7f0d98031830): event i_terminated 200 to BYE nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f0d98031830): removing session usage soa.c:356 soa_destroy() soa_destroy(static::0x7f0da0017760) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f0da001c9f0) nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f0d98031830 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(0x7f0d98031830): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) nua_stack.c:529 nua_signal() nua(0x7f0d98031830): sent signal r_destroy nta.c:1296 agent_timer() nta: timer set next to 1366 ms