- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>
- Contact: <sip:100201@10.95.2.2:5060>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>
- 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" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
- To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
- Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
- CSeq: 113792556 INVITE
- Contact: <sip:mod_sofia@10.3.2.4:5060>
- 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" <sip:100201@10.3.2.4>;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: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
- From: "100201" <sip:100201@10.3.2.4>;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: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
- To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
- From: "100201" <sip:100201@10.3.2.4>;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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
- To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
- From: "100201" <sip:100201@10.3.2.4>;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" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
- To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
- Call-ID: f5d71be1-2df9-1236-eb9b-080027ef0a4c
- CSeq: 113792556 ACK
- Contact: <sip:mod_sofia@10.3.2.4:5060>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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: <sip:100201@10.95.2.2:5060>
- User-Agent: TATTILE PBX v.3.4
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- From: "100201" <sip:100201@10.95.2.2>;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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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: <sip:ale@192.168.1.11>;tag=7v3HXmaU70B4r
- To: <sip:ale@192.168.1.11>
- Call-ID: 3bf2563f-444c-4541-9dc9-9b73f46b2ea2
- CSeq: 113792566 REGISTER
- Contact: <sip:gw+ale@10.3.2.4:5060;transport=udp;gw=ale>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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: <sip:ale@192.168.1.11>;tag=7v3HXmaU70B4r
- To: <sip:ale@192.168.1.11>
- Call-ID: 3bf2563f-444c-4541-9dc9-9b73f46b2ea2
- CSeq: 113792566 REGISTER
- Contact: <sip:gw+ale@10.3.2.4:5060;transport=udp;gw=ale>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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: <sip:10.95.2.2>;tag=123448
- To: <sip:10.3.2.4>
- Contact: <sip:10.95.2.2:5060>
- 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: <sip:10.95.2.2>;tag=123448
- To: <sip:10.3.2.4>;tag=9ep30ac21jr9F
- Call-ID: 10.95.2.2:5060
- CSeq: 34 OPTIONS
- Contact: <sip:10.3.2.4>
- 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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
- To: <sip:1001@10.3.2.4>;tag=7KqPYZsM5cVl
- From: <sip:1001@10.3.2.4>;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: <sip:1001@10.3.2.4>;tag=3776e149
- To: <sip:1001@10.3.2.4>;tag=7KqPYZsM5cVl
- Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI
- CSeq: 17 SUBSCRIBE
- Contact: <sip:1001@10.3.2.4:5060>
- 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: <sip:1001@10.3.2.4>;tag=7KqPYZsM5cVl
- To: <sip:1001@10.3.2.4>;tag=3776e149
- Call-ID: 85656OWUxYWY3ZTcyMDUxYmU5NDg4NjNhYmQ1NzFlYzVjNzI
- CSeq: 1251603751 NOTIFY
- Contact: <sip:1001@10.3.2.4:5060>
- 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: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
- To: <sip:1001@10.3.2.4>;tag=3776e149
- From: <sip:1001@10.3.2.4>;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" <sip:100201@10.95.2.2>;tag=123447
- To: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 13 INVITE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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: <sip:30161@10.3.2.4>;tag=5aH0Sy8KDFZyH
- To: "100201" <sip:100201@10.95.2.2>;tag=123447
- Call-ID: 100201@10.95.2.2:5060
- CSeq: 113792574 BYE
- Contact: <sip:30161@10.3.2.4:5060;transport=udp>
- 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" <sip:100201@10.95.2.2>;tag=123447
- From: <sip:30161@10.3.2.4>;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" <sip:100201@10.3.2.4>;tag=6KaSUSSQarNHD
- To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;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: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>
- To: <sip:1001@10.95.2.81:50461;rinstance=050bd88dd0d2c7e7>;tag=48e7bf7e
- From: "100201" <sip:100201@10.3.2.4>;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