tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc00026cb0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc00026cb0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc00026cb0) msg 0x7efc0002f820 from (udp/172.xx.xx.60:5060) has 1137 bytes, veclen = 1 recv 1137 bytes from udp/[172.xx.xx.3]:65516 at 09:04:45.697394: ------------------------------------------------------------------------ INVITE sip:4099@172.xx.xx.60:5060 SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.3:5060;branch=z9hG4bK109A3C1F9B From: ;tag=2E5A0858-1E87 To: Date: Fri, 04 Nov 2016 06:56:40 GMT Call-ID: ABCA635E-A19211E6-BC85C7B1-C40D3FF0@172.xx.xx.3 Supported: 100rel,timer,resource-priority,replaces,sdp-anat Min-SE: 1800 Cisco-Guid: 4277484416-0000065536-0000007232-1678944448 User-Agent: Cisco-SIPGateway/IOS-12.x Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER CSeq: 101 INVITE Timestamp: 1478242600 Contact: Expires: 180 Allow-Events: telephone-event Max-Forwards: 68 Session-Expires: 1800 Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 323 v=0 o=CiscoSystemsSIP-GW-UserAgent 920 9284 IN IP4 172.xx.xx.3 s=SIP Call c=IN IP4 172.xx.xx.3 t=0 0 m=audio 19472 RTP/AVP 18 101 121 c=IN IP4 172.xx.xx.3 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:121 frf-dialed-digit/8000 a=fmtp:121 0-15 a=ptime:20 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc00026cb0): msg 0x7efc0002f820 (1137 bytes) from udp/172.xx.xx.3:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INVITE sip:4099@172.xx.xx.60:5060 SIP/2.0 (CSeq 101) nta.c:3248 agent_aliases() nta: canonizing sip:4099@172.xx.xx.60:5060 with contact nta.c:3085 agent_recv_request() nta: INVITE (101) going to a default leg nta.c:1350 set_timeout() nta: timer set 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::0x7efc00024ec0, 0x7efc000141f0, 0x7efc0002f050) called soa.c:403 soa_set_params() soa_set_params(static::0x7efc00033ad0, ...) called nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7efc0002f3a0) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7efc00033ad0) called soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7efc00033ad0, (nil), 0x7efc0002d3ce, 323) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7efc0002f050): adding session usage tport.c:3257 tport_tsend() tport_tsend(0x7efc00026cb0) tpn = UDP/172.xx.xx.3:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.3:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc00026cb0): not found by name UDP/172.xx.xx.3:5060 tport.c:3594 tport_vsend() tport_vsend(0x7efc00026cb0): 364 bytes of 364 to udp/172.xx.xx.3:5060 tport.c:3492 tport_send_msg() tport_vsend returned 364 send 364 bytes to udp/[172.xx.xx.3]:5060 at 09:04:45.714668: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.xx.xx.3:5060;branch=z9hG4bK109A3C1F9B From: ;tag=2E5A0858-1E87 To: Call-ID: ABCA635E-A19211E6-BC85C7B1-C40D3FF0@172.xx.xx.3 CSeq: 101 INVITE Timestamp: 1478242600 0.000214 User-Agent: FreeSWITCH-mod_sofia/1.6.7+git~20160401T134007Z~f0c3870be3~64bit Content-Length: 0 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (101) nua_stack.c:271 nua_stack_event() nua(0x7efc0002f050): event i_invite 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_session.c:4139 signal_call_state_change() nua(0x7efc0002f050): call state changed: init -> received, received offer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7efc00033ad0, [0x7efc377458c8], [0x7efc377458d0], [(nil)]) called nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering nua_stack.c:271 nua_stack_event() nua(0x7efc0002f050): event i_state 100 Trying 2016-11-04 09:04:45.697691 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/8003@172.xx.xx.3 [544b6c82-4804-4791-bf86-f44a9e72b983] nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_NEW nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:04:45.697691 [DEBUG] sofia.c:9374 sofia/internal/8003@172.xx.xx.3 receiving invite from 172.xx.xx.3:65516 version: 1.6.7 git f0c3870 2016-04-01 13:40:07Z 64bit 2016-11-04 09:04:45.697691 [DEBUG] sofia.c:9486 IP 172.xx.xx.3 Approved by acl "domains[]". Access Granted. 2016-11-04 09:04:45.697691 [DEBUG] sofia.c:10676 Setting NAT mode based on via port nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:04:45.697691 [DEBUG] sofia.c:6858 Channel sofia/internal/8003@172.xx.xx.3 entering state [received][100] 2016-11-04 09:04:45.697691 [DEBUG] sofia.c:6868 Remote SDP: v=0 o=CiscoSystemsSIP-GW-UserAgent 920 9284 IN IP4 172.xx.xx.3 s=SIP Call c=IN IP4 172.xx.xx.3 t=0 0 m=audio 19472 RTP/AVP 18 101 121 c=IN IP4 172.xx.xx.3 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:121 frf-dialed-digit/8000 a=fmtp:121 0-15 a=ptime:20 2016-11-04 09:04:45.697691 [DEBUG] sofia.c:7227 (sofia/internal/8003@172.xx.xx.3) State Change CS_NEW -> CS_INIT nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:562 (sofia/internal/8003@172.xx.xx.3) State NEW 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_INIT 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/8003@172.xx.xx.3) State INIT 2016-11-04 09:04:45.697691 [DEBUG] mod_sofia.c:89 sofia/internal/8003@172.xx.xx.3 SOFIA INIT 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:40 sofia/internal/8003@172.xx.xx.3 Standard INIT 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/8003@172.xx.xx.3) State Change CS_INIT -> CS_ROUTING 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:586 (sofia/internal/8003@172.xx.xx.3) State INIT going to sleep 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_ROUTING 2016-11-04 09:04:45.697691 [DEBUG] switch_channel.c:2249 (sofia/internal/8003@172.xx.xx.3) Callstate Change DOWN -> RINGING 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/8003@172.xx.xx.3) State ROUTING 2016-11-04 09:04:45.697691 [DEBUG] mod_sofia.c:142 sofia/internal/8003@172.xx.xx.3 SOFIA ROUTING 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:236 sofia/internal/8003@172.xx.xx.3 Standard ROUTING 2016-11-04 09:04:45.697691 [INFO] mod_dialplan_xml.c:637 Processing 8003 <8003>->4099 in context public Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->unloop] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->group_dial_huntgroup] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [group_dial_huntgroup] destination_number(4099) =~ /^0870980891$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->group_dial_did_to_local] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [group_dial_did_to_local] destination_number(4099) =~ /^0870980892$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->outside_call] continue=true Dialplan: sofia/internal/8003@172.xx.xx.3 Absolute Condition [outside_call] Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(outside_call=true) Dialplan: sofia/internal/8003@172.xx.xx.3 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->call_debug] continue=true Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->public_extensions] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [public_extensions] destination_number(4099) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->public_did] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [public_did] destination_number(4099) =~ /^(5551212)$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->public_did] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [public_did] destination_number(4099) =~ /^(0870980892)$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->nb_conferences] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [nb_conferences] destination_number(4099) =~ /^0870980890$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->nb_conferences] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [nb_conferences] destination_number(4099) =~ /^0870980893$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->conf11001] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [conf11001] destination_number(4099) =~ /^11001$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->UNKNOWN] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (PASS) [UNKNOWN] destination_number(4099) =~ /^(4099)$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(transfer_after_bridge=4099) Dialplan: sofia/internal/8003@172.xx.xx.3 Action sleep(300) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(res=${callcenter_config(agent set uuid ${caller_id_number} '${uuid}')}) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(res=${callcenter_config(agent set type ${caller_id_number} 'uuid-standby')}) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(res=${callcenter_config(agent set status ${caller_id_number} 'Available')}) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(res=${callcenter_config(agent set state ${caller_id_number} 'idle')}) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(cc_warning_tone=tone_stream://%(200,0,500,600,700);loops=3) Dialplan: sofia/internal/8003@172.xx.xx.3 Action answer() Dialplan: sofia/internal/8003@172.xx.xx.3 Action playback(local_stream://moh) 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/8003@172.xx.xx.3) State Change CS_ROUTING -> CS_EXECUTE 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/8003@172.xx.xx.3) State ROUTING going to sleep 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_EXECUTE 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/8003@172.xx.xx.3) State EXECUTE 2016-11-04 09:04:45.697691 [DEBUG] mod_sofia.c:197 sofia/internal/8003@172.xx.xx.3 SOFIA EXECUTE 2016-11-04 09:04:45.697691 [DEBUG] switch_core_state_machine.c:328 sofia/internal/8003@172.xx.xx.3 Standard EXECUTE EXECUTE sofia/internal/8003@172.xx.xx.3 set(outside_call=true) 2016-11-04 09:04:45.697691 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [outside_call]=[true] EXECUTE sofia/internal/8003@172.xx.xx.3 export(RFC2822_DATE=Fri, 04 Nov 2016 09:04:45 +0200) 2016-11-04 09:04:45.697691 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 04 Nov 2016 09:04:45 +0200] EXECUTE sofia/internal/8003@172.xx.xx.3 set(transfer_after_bridge=4099) 2016-11-04 09:04:45.717455 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [transfer_after_bridge]=[4099] EXECUTE sofia/internal/8003@172.xx.xx.3 sleep(300) nta.c:1289 agent_timer() nta: timer not set 2016-11-04 09:04:46.017461 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set uuid = 544b6c82-4804-4791-bf86-f44a9e72b983 EXECUTE sofia/internal/8003@172.xx.xx.3 set(res=+OK ) 2016-11-04 09:04:46.017461 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [res]=[+OK ] 2016-11-04 09:04:46.017461 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set type = uuid-standby EXECUTE sofia/internal/8003@172.xx.xx.3 set(res=+OK ) 2016-11-04 09:04:46.017461 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [res]=[+OK ] 2016-11-04 09:04:46.017461 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set status = Available EXECUTE sofia/internal/8003@172.xx.xx.3 set(res=+OK ) 2016-11-04 09:04:46.017461 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [res]=[+OK ] 2016-11-04 09:04:46.017461 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set state = idle EXECUTE sofia/internal/8003@172.xx.xx.3 set(res=+OK ) 2016-11-04 09:04:46.017461 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [res]=[+OK ] EXECUTE sofia/internal/8003@172.xx.xx.3 set(cc_warning_tone=tone_stream://%(200,0,500,600,700);loops=3) 2016-11-04 09:04:46.017461 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [cc_warning_tone]=[tone_stream://%(200,0,500,600,700);loops=3] EXECUTE sofia/internal/8003@172.xx.xx.3 answer() 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:3720 Activate Buggy RFC2833 Mode! 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:4211 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:4266 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:4127 Set telephone-event payload to 101@8000 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:4211 Audio Codec Compare [frf-dialed-digit:121:8000:20:0:1]/[G729:18:8000:20:8000:1] 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:2946 Set Codec sofia/internal/8003@172.xx.xx.3 G729/8000 20 ms 160 samples 8000 bits 1 channels 2016-11-04 09:04:46.017461 [DEBUG] switch_core_codec.c:111 sofia/internal/8003@172.xx.xx.3 Original read codec set to G729:18 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:4479 Set telephone-event payload to 101@8000 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:4537 sofia/internal/8003@172.xx.xx.3 Set 2833 dtmf send payload to 101 recv payload to 101 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:6320 AUDIO RTP [sofia/internal/8003@172.xx.xx.3] 172.xx.xx.60 port 19744 -> 172.xx.xx.3 port 19472 codec: 18 ms: 20 2016-11-04 09:04:46.017461 [DEBUG] switch_rtp.c:3812 Starting timer [soft] 160 bytes per 20ms 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:6619 sofia/internal/8003@172.xx.xx.3 Set 2833 dtmf send payload to 101 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:6626 sofia/internal/8003@172.xx.xx.3 Set 2833 dtmf receive payload to 101 2016-11-04 09:04:46.017461 [DEBUG] switch_core_media.c:6649 sofia/internal/8003@172.xx.xx.3 Set rtp dtmf delay to 40 2016-11-04 09:04:46.017461 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/8003@172.xx.xx.3! 2016-11-04 09:04:46.017461 [DEBUG] switch_channel.c:3471 (sofia/internal/8003@172.xx.xx.3) Callstate Change RINGING -> EARLY 2016-11-04 09:04:46.017461 [DEBUG] mod_sofia.c:814 Local SDP sofia/internal/8003@172.xx.xx.3: v=0 o=FreeSWITCH 1478223342 1478223343 IN IP4 172.xx.xx.60 s=FreeSWITCH c=IN IP4 172.xx.xx.60 t=0 0 m=audio 19744 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no 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:529 nua_signal() nua(0x7efc0002f050): sent signal r_respond nua_stack.c:573 nua_stack_signal() nua(0x7efc0002f050): 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::0x7efc00033ad0, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7efc00033ad0, (nil), 0x7efc18066b44, -1) called soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7efc00033ad0, (nil), 0x7efc18066b44, -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::0x7efc00033ad0) called 2016-11-04 09:04:46.017461 [NOTICE] mod_dptools.c:1309 Channel [sofia/internal/8003@172.xx.xx.3] has been answered soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(0x7efc00033ad0, soa_generate_answer): called soa_static.c:1187 offer_answer_step() soa_static(0x7efc00033ad0, soa_generate_answer): generating local description soa_static.c:1228 offer_answer_step() soa_static(0x7efc00033ad0, soa_generate_answer): upgrade with remote description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7efc37743b00, 0x7efc00034900, ""): called soa_static.c:1444 offer_answer_step() soa_static(0x7efc00033ad0, soa_generate_answer): storing local description soa.c:1730 soa_activate() soa_activate(static::0x7efc00033ad0, (nil)) called soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7efc00033ad0, [(nil)], [0x7efc37745c38], [0x7efc37745c34]) called tport.c:3257 tport_tsend() tport_tsend(0x7efc00026cb0) tpn = UDP/172.xx.xx.3:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.3:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc00026cb0): not found by name UDP/172.xx.xx.3:5060 tport.c:3594 tport_vsend() tport_vsend(0x7efc00026cb0): 1183 bytes of 1183 to udp/172.xx.xx.3:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1183 send 1183 bytes to udp/[172.xx.xx.3]:5060 at 09:04:46.023692: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.xx.xx.3:5060;branch=z9hG4bK109A3C1F9B From: ;tag=2E5A0858-1E87 To: ;tag=99yX2garZcp4g Call-ID: ABCA635E-A19211E6-BC85C7B1-C40D3FF0@172.xx.xx.3 CSeq: 101 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.7+git~20160401T134007Z~f0c3870be3~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Require: timer Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Session-Expires: 1800;refresher=uac Content-Type: application/sdp Content-Disposition: session Content-Length: 243 Remote-Party-ID: "4099" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1478223342 1478223343 IN IP4 172.xx.xx.60 s=FreeSWITCH c=IN IP4 172.xx.xx.60 t=0 0 m=audio 19744 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no 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 (101) nta.c:1350 set_timeout() nta: timer set to 500 ms nua_session.c:4139 signal_call_state_change() nua(0x7efc0002f050): call state changed: received -> completed, sent answer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7efc00033ad0, [0x7efc37745ce8], [0x7efc37745cf0], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7efc00033ad0, ...) called nua_stack.c:271 nua_stack_event() nua(0x7efc0002f050): event i_state 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2016-11-04 09:04:46.017461 [DEBUG] switch_channel.c:3770 (sofia/internal/8003@172.xx.xx.3) Callstate Change EARLY -> ACTIVE nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:04:46.017461 [DEBUG] sofia.c:6858 Channel sofia/internal/8003@172.xx.xx.3 entering state [completed][200] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering EXECUTE sofia/internal/8003@172.xx.xx.3 playback(local_stream://moh) 2016-11-04 09:04:46.017461 [DEBUG] mod_local_stream.c:843 Opening Stream [moh/8000] 8000hz 2016-11-04 09:04:46.017461 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc00026cb0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc00026cb0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc00026cb0) msg 0x7efc00032e90 from (udp/172.xx.xx.60:5060) has 388 bytes, veclen = 1 recv 388 bytes from udp/[172.xx.xx.3]:65516 at 09:04:46.033007: ------------------------------------------------------------------------ ACK sip:4099@172.xx.xx.60:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.3:5060;branch=z9hG4bK109A3D6FF From: ;tag=2E5A0858-1E87 To: ;tag=99yX2garZcp4g Date: Fri, 04 Nov 2016 06:56:40 GMT Call-ID: ABCA635E-A19211E6-BC85C7B1-C40D3FF0@172.xx.xx.3 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: telephone-event Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc00026cb0): msg 0x7efc00032e90 (388 bytes) from udp/172.xx.xx.3:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received ACK sip:4099@172.xx.xx.60:5060;transport=udp SIP/2.0 (CSeq 101) nta.c:3019 agent_recv_request() nta: ACK (101) is going to INVITE (101) nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7efc00033ad0) called nua_stack.c:271 nua_stack_event() nua(0x7efc0002f050): event i_ack 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7efc0002f050): call state changed: completed -> ready nua_stack.c:271 nua_stack_event() nua(0x7efc0002f050): event i_state 200 OK nua_stack.c:271 nua_stack_event() nua(0x7efc0002f050): event i_active 200 Call active nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1768 seconds (in [1768..1768]) 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 2016-11-04 09:04:46.037462 [DEBUG] sofia.c:6858 Channel sofia/internal/8003@172.xx.xx.3 entering state [ready][200] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:04:46.037462 [INFO] mod_com_g729.c:126 ENCODER LICENSE ALLOCATED--->0x7efc1805dca8 0x7efc1805dca8 2016-11-04 09:04:46.037462 [INFO] mod_com_g729.c:133 ENCODER CREATED------------->0x7efc1805dca8 0x7efc1805dca8 2016-11-04 09:04:46.237530 [DEBUG] switch_rtp.c:6670 Correct audio ip/port confirmed. nta.c:1296 agent_timer() nta: timer set next to 4509 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc00026cb0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc00026cb0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc00026cb0) msg 0x7efc00032e90 from (udp/172.xx.xx.60:5060) has 4 bytes, veclen = 1 tport.c:3023 tport_deliver() tport_deliver(0x7efc00026cb0): bad msg 0x7efc00032e90 (4 bytes) from udp/10.99.107.25:5060/sip next=(nil) nta.c:7134 _nta_incoming_timer() nta: timer I fired, terminate 200 response nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7efc37745c60) nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta.c:1289 agent_timer() nta: timer not set 2016-11-04 09:04:57.577500 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set state = waiting 2016-11-04 09:05:00.897481 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2016-11-04 09:05:00.917472 [NOTICE] switch_channel.c:1104 New Channel sofia/external/0833573222 [908b0bfc-4bec-4fc6-bd3d-dfa7aea869bb] 2016-11-04 09:05:00.917472 [DEBUG] mod_sofia.c:4799 (sofia/external/0833573222) State Change CS_NEW -> CS_INIT 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_INIT 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:586 (sofia/external/0833573222) State INIT 2016-11-04 09:05:00.917472 [DEBUG] mod_sofia.c:89 sofia/external/0833573222 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 2016-11-04 09:05:00.917472 [DEBUG] sofia_glue.c:1257 sofia/external/0833573222 sending invite version: 1.6.7 git f0c3870 2016-04-01 13:40:07Z 64bit Local SDP: v=0 o=FreeSWITCH 1478221656 1478221657 IN IP4 172.xx.xx.85 s=FreeSWITCH c=IN IP4 172.xx.xx.85 t=0 0 m=audio 21444 RTP/AVP 18 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv nua.c:633 nua_invite() nua: nua_invite: entering nua_stack.c:529 nua_signal() nua(0x7efc0002eaf0): sent signal r_invite 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:40 sofia/external/0833573222 Standard INIT 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:48 (sofia/external/0833573222) State Change CS_INIT -> CS_ROUTING 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:586 (sofia/external/0833573222) State INIT going to sleep nua_stack.c:569 nua_stack_signal() nua(0x7efc0002eaf0): 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::0x7efc0c0035e0, 0x7efc0c005970, 0x7efc0002eaf0) called soa.c:403 soa_set_params() soa_set_params(static::0x7efc0c03a7a0, ...) called soa.c:403 soa_set_params() soa_set_params(static::0x7efc0c03a7a0, ...) called soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7efc0c03a7a0, (nil), 0x7efc00035187, -1) called soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7efc0c03a7a0, (nil), 0x7efc00035187, -1) called nua_dialog.c:338 nua_dialog_usage_add() nua(0x7efc0002eaf0): adding session usage nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7efc0c02eae0) soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7efc0c03a7a0) called soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7efc0c03a7a0, 0) called soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(0x7efc0c03a7a0, soa_generate_offer): called soa_static.c:1187 offer_answer_step() soa_static(0x7efc0c03a7a0, soa_generate_offer): generating local description soa_static.c:1215 offer_answer_step() soa_static(0x7efc0c03a7a0, soa_generate_offer): upgrade with local description soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7efc3768fac0, (nil), ""): called soa_static.c:1444 offer_answer_step() soa_static(0x7efc0c03a7a0, soa_generate_offer): storing local description soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7efc0c03a7a0, [(nil)], [0x7efc37691bf8], [0x7efc37691bf4]) called nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7efc0c0008c0) tpn = */172.xx.xx.61:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.61:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc0c0008c0): not found by name */172.xx.xx.61:5060 tport.c:3594 tport_vsend() tport_vsend(0x7efc0c0008c0): 997 bytes of 997 to udp/172.xx.xx.61:5060 tport.c:3492 tport_send_msg() tport_vsend returned 997 send 997 bytes to udp/[172.xx.xx.61]:5060 at 09:05:00.919046: ------------------------------------------------------------------------ INVITE sip:0833573222@172.xx.xx.61 SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.85;rport;branch=z9hG4bKrvSaD1g1gacUH Max-Forwards: 70 From: "" ;tag=HXvB6137Kycrc To: Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785486 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.7+git~20160401T134007Z~f0c3870be3~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 187 X-FS-Support: update_display,send_info Remote-Party-ID: ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1478221656 1478221657 IN IP4 172.xx.xx.85 s=FreeSWITCH c=IN IP4 172.xx.xx.85 t=0 0 m=audio 21444 RTP/AVP 18 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent INVITE (98785486) to */172.xx.xx.61:5060 tport.c:4160 tport_pend() tport_pend(0x7efc0c0008c0): pending 0x7efc0c0055b0 for udp/172.xx.xx.85:5060 (already 0) nta.c:1350 set_timeout() nta: timer set to 32000 ms nta.c:1348 set_timeout() nta: timer shortened to 1000 ms nua_session.c:4139 signal_call_state_change() nua(0x7efc0002eaf0): call state changed: init -> calling, sent offer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7efc0c03a7a0, [0x7efc37691bd8], [0x7efc37691be0], [(nil)]) called nua_stack.c:269 nua_stack_event() nua(0x7efc0002eaf0): event i_state INVITE sent nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_ROUTING nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:00.917472 [DEBUG] sofia.c:6858 Channel sofia/external/0833573222 entering state [calling][0] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:602 (sofia/external/0833573222) State ROUTING 2016-11-04 09:05:00.917472 [DEBUG] mod_sofia.c:142 sofia/external/0833573222 SOFIA ROUTING 2016-11-04 09:05:00.917472 [DEBUG] switch_ivr_originate.c:67 (sofia/external/0833573222) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:602 (sofia/external/0833573222) State ROUTING going to sleep 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_CONSUME_MEDIA 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:621 (sofia/external/0833573222) State CONSUME_MEDIA 2016-11-04 09:05:00.917472 [DEBUG] switch_core_state_machine.c:621 (sofia/external/0833573222) State CONSUME_MEDIA going to sleep tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc0c0008c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc0c0008c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc0c0008c0) msg 0x7efc0c041e00 from (udp/172.xx.xx.85:5060) has 291 bytes, veclen = 1 recv 291 bytes from udp/[172.xx.xx.61]:5060 at 09:05:00.919777: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.xx.xx.85;rport=5060;branch=z9hG4bKrvSaD1g1gacUH From: "" ;tag=HXvB6137Kycrc To: Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785486 INVITE User-Agent: FS Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc0c0008c0): msg 0x7efc0c041e00 (291 bytes) from udp/172.xx.xx.61:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (98785486) nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 0.844 ms tport.c:4222 tport_release() tport_release(0x7efc0c0008c0): 0x7efc0c0055b0 by 0x7efc0c044b60 with 0x7efc0c041e00 (preliminary) tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc0c0008c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc0c0008c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc0c0008c0) msg 0x7efc0c048450 from (udp/172.xx.xx.85:5060) has 780 bytes, veclen = 1 recv 780 bytes from udp/[172.xx.xx.61]:5060 at 09:05:00.921302: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 172.xx.xx.85;rport=5060;branch=z9hG4bKrvSaD1g1gacUH From: "" ;tag=HXvB6137Kycrc To: ;tag=052X1XjKaXpUS Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785486 INVITE User-Agent: FS Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="172.xx.xx.61", nonce="64a7a2e8-8f79-432e-bb5d-a89650b98760", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc0c0008c0): msg 0x7efc0c048450 (780 bytes) from udp/172.xx.xx.61:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 407 Proxy Authentication Required for INVITE (98785486) nta.c:3366 agent_recv_response() nta: 407 Proxy Authentication Required is going to a transaction tport.c:4222 tport_release() tport_release(0x7efc0c0008c0): 0x7efc0c0055b0 by 0x7efc0c044b60 with 0x7efc0c048450 tport.c:3257 tport_tsend() tport_tsend(0x7efc0c0008c0) tpn = UDP/172.xx.xx.61:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.61:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc0c0008c0): not found by name UDP/172.xx.xx.61:5060 tport.c:3594 tport_vsend() tport_vsend(0x7efc0c0008c0): 321 bytes of 321 to udp/172.xx.xx.61:5060 tport.c:3492 tport_send_msg() tport_vsend returned 321 send 321 bytes to udp/[172.xx.xx.61]:5060 at 09:05:00.921464: ------------------------------------------------------------------------ ACK sip:0833573222@172.xx.xx.61 SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.85;rport;branch=z9hG4bKrvSaD1g1gacUH Max-Forwards: 70 From: "" ;tag=HXvB6137Kycrc To: ;tag=052X1XjKaXpUS Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785486 ACK Content-Length: 0 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent ACK (98785486) to UDP/172.xx.xx.61:5060 nta.c:8722 outgoing_free() nta: outgoing_free(0x7efc0c002570) auth_digest.c:105 auth_digest_challenge_get() auth_digest_challenge_get(): got 6 nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event r_invite 407 Proxy Authentication Required 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:834 nua_authenticate() nua: nua_authenticate: entering nua_stack.c:569 nua_stack_signal() nua(0x7efc0002eaf0): recv signal r_authenticate nua_stack.c:529 nua_signal() nua(0x7efc0002eaf0): sent signal r_authenticate nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7efc0c03a7a0) called soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7efc0c03a7a0, 0) called soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(0x7efc0c03a7a0, soa_generate_offer): called soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7efc0c02f6b0, (nil), ""): called soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7efc0c03a7a0, [(nil)], [0x7efc37691c38], [0x7efc37691c34]) called auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(Enav8Pre:172.xx.xx.61:En@v8Pre!!@4543) = 0539d9f4459c6f955a5b6c5bce9c40b1 auth_digest.c:318 auth_digest_response() A2 = MD5(INVITE:sip:0833573222@172.xx.xx.61) auth_digest.c:348 auth_digest_response() auth_response: 119008ac15c252754a4c7e73c5d4527b = MD5(0539d9f4459c6f955a5b6c5bce9c40b1:64a7a2e8-8f79-432e-bb5d-a89650b98760:00000001:2BgUXBz/EjWAOwBQVosP+A:auth:693cbb1a365f86856545c8a064b538e6) (qop=auth) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7efc0c0008c0) tpn = */172.xx.xx.61:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.61:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc0c0008c0): not found by name */172.xx.xx.61:5060 tport.c:3594 tport_vsend() tport_vsend(0x7efc0c0008c0): 1265 bytes of 1265 to udp/172.xx.xx.61:5060 tport.c:3492 tport_send_msg() tport_vsend returned 1265 send 1265 bytes to udp/[172.xx.xx.61]:5060 at 09:05:00.922051: ------------------------------------------------------------------------ INVITE sip:0833573222@172.xx.xx.61 SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.85;rport;branch=z9hG4bKS5j3ev14DK2DD Max-Forwards: 70 From: "" ;tag=HXvB6137Kycrc To: Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785487 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.7+git~20160401T134007Z~f0c3870be3~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Proxy-Authorization: Digest username="Enav8Pre", realm="172.xx.xx.61", nonce="64a7a2e8-8f79-432e-bb5d-a89650b98760", cnonce="2BgUXBz/EjWAOwBQVosP+A", algorithm=MD5, uri="sip:0833573222@172.xx.xx.61", response="119008ac15c252754a4c7e73c5d4527b", qop=auth, nc=00000001 Content-Type: application/sdp Content-Disposition: session Content-Length: 187 X-FS-Support: update_display,send_info Remote-Party-ID: ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1478221656 1478221657 IN IP4 172.xx.xx.85 s=FreeSWITCH c=IN IP4 172.xx.xx.85 t=0 0 m=audio 21444 RTP/AVP 18 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent INVITE (98785487) to */172.xx.xx.61:5060 tport.c:4160 tport_pend() tport_pend(0x7efc0c0008c0): pending 0x7efc0c041820 for udp/172.xx.xx.85:5060 (already 0) nua_session.c:4139 signal_call_state_change() nua(0x7efc0002eaf0): call state changed: calling -> calling, sent offer soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7efc0c03a7a0, [0x7efc37691c18], [0x7efc37691c20], [(nil)]) called nua_stack.c:269 nua_stack_event() nua(0x7efc0002eaf0): event i_state INVITE sent nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:00.917472 [DEBUG] sofia.c:6858 Channel sofia/external/0833573222 entering state [calling][0] nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc0c0008c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc0c0008c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc0c0008c0) msg 0x7efc0c041d90 from (udp/172.xx.xx.85:5060) has 291 bytes, veclen = 1 recv 291 bytes from udp/[172.xx.xx.61]:5060 at 09:05:00.922619: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.xx.xx.85;rport=5060;branch=z9hG4bKS5j3ev14DK2DD From: "" ;tag=HXvB6137Kycrc To: Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785487 INVITE User-Agent: FS Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc0c0008c0): msg 0x7efc0c041d90 (291 bytes) from udp/172.xx.xx.61:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (98785487) nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 0.71 ms tport.c:4222 tport_release() tport_release(0x7efc0c0008c0): 0x7efc0c041820 by 0x7efc0c048250 with 0x7efc0c041d90 (preliminary) nta.c:1296 agent_timer() nta: timer set next to 31003 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc0c0008c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc0c0008c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc0c0008c0) msg 0x7efc0c041d90 from (udp/172.xx.xx.85:5060) has 1186 bytes, veclen = 1 recv 1186 bytes from udp/[172.xx.xx.61]:5060 at 09:05:02.188615: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 172.xx.xx.85;rport=5060;branch=z9hG4bKS5j3ev14DK2DD From: "" ;tag=HXvB6137Kycrc To: ;tag=1evp3r3p75ceN Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785487 INVITE Contact: User-Agent: FS Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE Supported: 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: 187 X-FS-Display-Name: Outbound Call X-FS-Display-Number: sip:D0820833573222@172.xx.xx.61 X-FS-Support: update_display,send_info Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1478216006 1478216007 IN IP4 172.xx.xx.61 s=FreeSWITCH c=IN IP4 172.xx.xx.61 t=0 0 m=audio 27110 RTP/AVP 18 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc0c0008c0): msg 0x7efc0c041d90 (1186 bytes) from udp/172.xx.xx.61:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 183 Session Progress for INVITE (98785487) nta.c:3366 agent_recv_response() nta: 183 Session Progress is going to a transaction tport.c:4222 tport_release() tport_release(0x7efc0c0008c0): 0x7efc0c041820 by 0x7efc0c048250 with 0x7efc0c041d90 (preliminary) soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7efc0c03a7a0, (nil), 0x7efc0c002717, 187) called soa.c:1595 soa_process_answer() soa_process_answer(static::0x7efc0c03a7a0) called soa_static.c:1146 offer_answer_step() soa_static_offer_answer_action(0x7efc0c03a7a0, soa_process_answer): called soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7efc0c02f6b0, 0x7efc0c02ef70, ""): called soa_static.c:1302 offer_answer_step() soa_static(0x7efc0c03a7a0, soa_process_answer): upgrade codecs with remote description soa.c:1730 soa_activate() soa_activate(static::0x7efc0c03a7a0, (nil)) called nua_session.c:988 nua_session_client_response() nua(0x7efc0002eaf0): INVITE: processed SDP answer in 183 Session Progress nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event r_invite 183 Session Progress nua_session.c:4139 signal_call_state_change() nua(0x7efc0002eaf0): call state changed: calling -> proceeding, received answer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7efc0c03a7a0, [0x7efc37691648], [0x7efc37691650], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7efc0c03a7a0, ...) called nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event i_state 183 Session Progress 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 2016-11-04 09:05:02.177486 [INFO] sofia.c:1255 sofia/external/0833573222 Update Callee ID to "Outbound Call" nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:02.177486 [DEBUG] sofia.c:6858 Channel sofia/external/0833573222 entering state [proceeding][183] 2016-11-04 09:05:02.177486 [DEBUG] sofia.c:6868 Remote SDP: v=0 o=FreeSWITCH 1478216006 1478216007 IN IP4 172.xx.xx.61 s=FreeSWITCH c=IN IP4 172.xx.xx.61 t=0 0 m=audio 27110 RTP/AVP 18 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:4211 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:4266 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:2946 Set Codec sofia/external/0833573222 G729/8000 20 ms 160 samples 8000 bits 1 channels 2016-11-04 09:05:02.177486 [DEBUG] switch_core_codec.c:111 sofia/external/0833573222 Original read codec set to G729:18 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:4509 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:4537 sofia/external/0833573222 Set 2833 dtmf send payload to 101 recv payload to 101 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:6320 AUDIO RTP [sofia/external/0833573222] 172.xx.xx.85 port 21444 -> 172.xx.xx.61 port 27110 codec: 18 ms: 20 2016-11-04 09:05:02.177486 [DEBUG] switch_rtp.c:3812 Starting timer [soft] 160 bytes per 20ms 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:6619 sofia/external/0833573222 Set 2833 dtmf send payload to 101 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:6626 sofia/external/0833573222 Set 2833 dtmf receive payload to 101 2016-11-04 09:05:02.177486 [DEBUG] switch_core_media.c:6649 sofia/external/0833573222 Set rtp dtmf delay to 40 2016-11-04 09:05:02.177486 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/0833573222! 2016-11-04 09:05:02.177486 [DEBUG] switch_channel.c:3471 (sofia/external/0833573222) Callstate Change DOWN -> EARLY nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:02.197460 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/external/0833573222] 2016-11-04 09:05:02.197460 [DEBUG] switch_ivr.c:2160 (sofia/external/0833573222) State Change CS_CONSUME_MEDIA -> CS_ROUTING 2016-11-04 09:05:02.197460 [NOTICE] switch_ivr.c:2167 Transfer sofia/external/0833573222 to XML[0870980890@default] 2016-11-04 09:05:02.197460 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_ROUTING 2016-11-04 09:05:02.197460 [DEBUG] switch_core_state_machine.c:602 (sofia/external/0833573222) State ROUTING 2016-11-04 09:05:02.197460 [DEBUG] mod_sofia.c:142 sofia/external/0833573222 SOFIA ROUTING 2016-11-04 09:05:02.197460 [DEBUG] switch_core_state_machine.c:236 sofia/external/0833573222 Standard ROUTING 2016-11-04 09:05:02.197460 [INFO] mod_dialplan_xml.c:637 Processing <0870980000>->0870980890 in context default Dialplan: sofia/external/0833573222 parsing [default->unloop] continue=false Dialplan: sofia/external/0833573222 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/0833573222 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->tod_example] continue=true Dialplan: sofia/external/0833573222 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/external/0833573222 Action set(open=true) Dialplan: sofia/external/0833573222 parsing [default->holiday_example] continue=true Dialplan: sofia/external/0833573222 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/external/0833573222 parsing [default->global-intercept] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [global-intercept] destination_number(0870980890) =~ /^886$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group-intercept] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group-intercept] destination_number(0870980890) =~ /^\*8$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->intercept-ext] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [intercept-ext] destination_number(0870980890) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->redial] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [redial] destination_number(0870980890) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->global] continue=true Dialplan: sofia/external/0833573222 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/0833573222 Regex (FAIL) [global] ${default_password}(4321) =~ /^1234$/ break=never Dialplan: sofia/external/0833573222 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never Dialplan: sofia/external/0833573222 Regex (FAIL) [global] ${endpoint_disposition}(EARLY MEDIA) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->snom-demo-2] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [snom-demo-2] destination_number(0870980890) =~ /^9001$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->snom-demo-1] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [snom-demo-1] destination_number(0870980890) =~ /^9000$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [eavesdrop] destination_number(0870980890) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [eavesdrop] destination_number(0870980890) =~ /^779$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->call_return] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [call_return] destination_number(0870980890) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->del-group] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [del-group] destination_number(0870980890) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->add-group] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [add-group] destination_number(0870980890) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->call-group-simo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [call-group-simo] destination_number(0870980890) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->call-group-order] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [call-group-order] destination_number(0870980890) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->extension-intercom] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [extension-intercom] destination_number(0870980890) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Local_Ext] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Local_Ext] destination_number(0870980890) =~ /^(30[01][0-9])$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Local_Extension] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Local_Extension] destination_number(0870980890) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Local_Extension_Skinny] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Local_Extension_Skinny] destination_number(0870980890) =~ /^(11[01][0-9])$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_sales] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_sales] destination_number(0870980890) =~ /^2000$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_support] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_support] destination_number(0870980890) =~ /^2001$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_billing] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_billing] destination_number(0870980890) =~ /^2002$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_huntgroup] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_huntgroup] destination_number(0870980890) =~ /^0870980891$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_did_to_local] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_did_to_local] destination_number(0870980890) =~ /^0870980892$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->operator] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [operator] destination_number(0870980890) =~ /^(operator|0)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->vmain] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [vmain] destination_number(0870980890) =~ /^vmain$|^4000$|^\*98$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->sip_uri] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [sip_uri] destination_number(0870980890) =~ /^sip:(.*)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->nb_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [nb_conferences] destination_number(0870980890) =~ /^(30\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->wb_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [wb_conferences] destination_number(0870980890) =~ /^(31\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->uwb_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [uwb_conferences] destination_number(0870980890) =~ /^(32\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [cdquality_conferences] destination_number(0870980890) =~ /^(33\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [cdquality_conferences] destination_number(0870980890) =~ /^(35\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->freeswitch_public_conf_via_sip] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(0870980890) =~ /^9(888|8888|1616|3232)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->mad_boss_intercom] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [mad_boss_intercom] destination_number(0870980890) =~ /^0911$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->mad_boss_intercom] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [mad_boss_intercom] destination_number(0870980890) =~ /^0912$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->mad_boss] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [mad_boss] destination_number(0870980890) =~ /^0913$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ivr_demo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ivr_demo] destination_number(0870980890) =~ /^5000$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->dynamic_conference] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [dynamic_conference] destination_number(0870980890) =~ /^5001$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->rtp_multicast_page] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [rtp_multicast_page] destination_number(0870980890) =~ /^pagegroup$|^7243$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [park] destination_number(0870980890) =~ /^5900$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->unpark] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [unpark] destination_number(0870980890) =~ /^5901$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->valet_park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [valet_park] destination_number(0870980890) =~ /^(6000)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->valet_park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [valet_park] destination_number(0870980890) =~ /^((?!6000)60\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [park] source(src/switch_ivr_originate.c) =~ /mod_sofia/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->unpark] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [unpark] source(src/switch_ivr_originate.c) =~ /mod_sofia/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [park] source(src/switch_ivr_originate.c) =~ /mod_sofia/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->unpark] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [unpark] source(src/switch_ivr_originate.c) =~ /mod_sofia/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->wait] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [wait] destination_number(0870980890) =~ /^wait$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->fax_receive] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [fax_receive] destination_number(0870980890) =~ /^9178$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->fax_transmit] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [fax_transmit] destination_number(0870980890) =~ /^9179$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_180] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_180] destination_number(0870980890) =~ /^9180$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_183_uk_ring] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_183_uk_ring] destination_number(0870980890) =~ /^9181$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_183_music_ring] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_183_music_ring] destination_number(0870980890) =~ /^9182$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_post_answer_uk_ring] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_post_answer_uk_ring] destination_number(0870980890) =~ /^9183$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_post_answer_music] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_post_answer_music] destination_number(0870980890) =~ /^9184$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ClueCon] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ClueCon] destination_number(0870980890) =~ /^9191$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->show_info] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [show_info] destination_number(0870980890) =~ /^9192$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->video_record] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [video_record] destination_number(0870980890) =~ /^9193$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->video_playback] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [video_playback] destination_number(0870980890) =~ /^9194$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->delay_echo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [delay_echo] destination_number(0870980890) =~ /^9195$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->echo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [echo] destination_number(0870980890) =~ /^9196$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->milliwatt] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [milliwatt] destination_number(0870980890) =~ /^9197$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->tone_stream] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [tone_stream] destination_number(0870980890) =~ /^9198$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->zrtp_enrollement] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [zrtp_enrollement] destination_number(0870980890) =~ /^9787$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->hold_music] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [hold_music] destination_number(0870980890) =~ /^9664$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->laugh break] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [laugh break] destination_number(0870980890) =~ /^9386$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->101] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [101] destination_number(0870980890) =~ /^101$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->pizza_demo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [pizza_demo] destination_number(0870980890) =~ /^(pizza|74992)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Talking Clock Time] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Talking Clock Time] destination_number(0870980890) =~ /^9170$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Talking Clock Date] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Talking Clock Date] destination_number(0870980890) =~ /^9171$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Talking Clock Date and Time] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Talking Clock Date and Time] destination_number(0870980890) =~ /^9172$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->exe_on_ans] continue=false Dialplan: sofia/external/0833573222 Regex (PASS) [exe_on_ans] destination_number(0870980890) =~ /^0870980890$/ break=on-false Dialplan: sofia/external/0833573222 Action set(execute_on_answer=transfer ANSWEREDCALL XML default) Dialplan: sofia/external/0833573222 Action log(INFO Waiting 30 seconds for $1 to answer...) Dialplan: sofia/external/0833573222 Action sleep(30000) Dialplan: sofia/external/0833573222 Action log(INFO Call to $1 was not answered, taking alternative action...) Dialplan: sofia/external/0833573222 Action transfer(UNANSWEREDCALL XML default) 2016-11-04 09:05:02.197460 [INFO] switch_channel.c:3127 sofia/external/0833573222 Flipping CID from "" <0870980000> to "Outbound Call" 2016-11-04 09:05:02.197460 [DEBUG] switch_core_state_machine.c:286 (sofia/external/0833573222) State Change CS_ROUTING -> CS_EXECUTE 2016-11-04 09:05:02.197460 [DEBUG] switch_core_state_machine.c:602 (sofia/external/0833573222) State ROUTING going to sleep 2016-11-04 09:05:02.197460 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_EXECUTE 2016-11-04 09:05:02.197460 [DEBUG] switch_core_state_machine.c:609 (sofia/external/0833573222) State EXECUTE 2016-11-04 09:05:02.197460 [DEBUG] mod_sofia.c:197 sofia/external/0833573222 SOFIA EXECUTE 2016-11-04 09:05:02.197460 [DEBUG] switch_core_state_machine.c:328 sofia/external/0833573222 Standard EXECUTE EXECUTE sofia/external/0833573222 set(open=true) 2016-11-04 09:05:02.197460 [DEBUG] mod_dptools.c:1519 SET sofia/external/0833573222 [open]=[true] EXECUTE sofia/external/0833573222 set(execute_on_answer=transfer ANSWEREDCALL XML default) 2016-11-04 09:05:02.197460 [DEBUG] mod_dptools.c:1519 SET sofia/external/0833573222 [execute_on_answer]=[transfer ANSWEREDCALL XML default] EXECUTE sofia/external/0833573222 log(INFO Waiting 30 seconds for $1 to answer...) 2016-11-04 09:05:02.197460 [INFO] mod_dptools.c:1713 Waiting 30 seconds for $1 to answer... EXECUTE sofia/external/0833573222 sleep(30000) 2016-11-04 09:05:02.217472 [DEBUG] switch_rtp.c:6670 Correct audio ip/port confirmed. 2016-11-04 09:05:02.877480 [DEBUG] switch_core_media.c:2386 Correcting calculated ptime value from 300 to 150 to compensate for 1 lost packet(s) 2016-11-04 09:05:02.997457 [WARNING] switch_core_media.c:2418 Asynchronous PTIME not supported, changing our end from 20 to 60 2016-11-04 09:05:03.017520 [DEBUG] switch_core_media.c:2844 Changing Codec from G729@20ms@8000hz to G729@60ms@8000hz 2016-11-04 09:05:03.057541 [DEBUG] switch_rtp.c:3690 RE-Starting timer [soft] 480 bytes per 60ms 2016-11-04 09:05:03.057541 [DEBUG] switch_core_media.c:2946 Set Codec sofia/external/0833573222 G729/8000 60 ms 480 samples 8000 bits 1 channels 2016-11-04 09:05:03.057541 [DEBUG] switch_core_codec.c:123 sofia/external/0833573222 Original read codec replaced with G729:18 tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc0c0008c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc0c0008c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc0c0008c0) msg 0x7efc0c002ae0 from (udp/172.xx.xx.85:5060) has 1147 bytes, veclen = 1 recv 1147 bytes from udp/[172.xx.xx.61]:5060 at 09:05:06.545536: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.xx.xx.85;rport=5060;branch=z9hG4bKS5j3ev14DK2DD From: "" ;tag=HXvB6137Kycrc To: ;tag=1evp3r3p75ceN Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785487 INVITE Contact: User-Agent: FS Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE Supported: 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: 187 X-FS-Display-Name: Outbound Call X-FS-Display-Number: sip:D0820833573222@172.xx.xx.61 X-FS-Support: update_display,send_info Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1478216006 1478216007 IN IP4 172.xx.xx.61 s=FreeSWITCH c=IN IP4 172.xx.xx.61 t=0 0 m=audio 27110 RTP/AVP 18 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc0c0008c0): msg 0x7efc0c002ae0 (1147 bytes) from udp/172.xx.xx.61:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (98785487) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction tport.c:4222 tport_release() tport_release(0x7efc0c0008c0): 0x7efc0c041820 by 0x7efc0c048250 with 0x7efc0c002ae0 soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7efc0c03a7a0, (nil), 0x7efc0c006f20, 187) called soa.c:1595 soa_process_answer() soa_process_answer(static::0x7efc0c03a7a0) called nua_session.c:978 nua_session_client_response() nua(0x7efc0002eaf0): INVITE: error processing SDP answer in 200 OK nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event r_invite 200 OK nua_session.c:4139 signal_call_state_change() nua(0x7efc0002eaf0): call state changed: proceeding -> completing, received answer soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7efc0c03a7a0, [0x7efc376917d8], [0x7efc376917e0], [(nil)]) called soa.c:616 soa_get_params() soa_get_params(static::0x7efc0c03a7a0, ...) called nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event i_state 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:06.537480 [INFO] sofia.c:1244 sofia/external/0833573222 Update Caller ID to "Outbound Call" nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:06.537480 [DEBUG] sofia.c:6858 Channel sofia/external/0833573222 entering state [completing][200] 2016-11-04 09:05:06.537480 [DEBUG] sofia.c:6865 Duplicate SDP v=0 o=FreeSWITCH 1478216006 1478216007 IN IP4 172.xx.xx.61 s=FreeSWITCH c=IN IP4 172.xx.xx.61 t=0 0 m=audio 27110 RTP/AVP 18 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=ptime:20 nua.c:639 nua_ack() nua: nua_ack: entering nua_stack.c:569 nua_stack_signal() nua(0x7efc0002eaf0): 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::0x7efc0c03a7a0, ...) called soa.c:1730 soa_activate() soa_activate(static::0x7efc0c03a7a0, (nil)) called nua_stack.c:529 nua_signal() nua(0x7efc0002eaf0): sent signal r_ack nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7efc0c0008c0) tpn = udp/172.xx.xx.61:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.61:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc0c0008c0): not found by name udp/172.xx.xx.61:5060 tport.c:3594 tport_vsend() tport_vsend(0x7efc0c0008c0): 674 bytes of 674 to udp/172.xx.xx.61:5060 tport.c:3492 tport_send_msg() tport_vsend returned 674 send 674 bytes to udp/[172.xx.xx.61]:5060 at 09:05:06.551756: ------------------------------------------------------------------------ ACK sip:0833573222@172.xx.xx.61:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.85;rport;branch=z9hG4bKtecvgQj8avr0r Max-Forwards: 70 From: "" ;tag=HXvB6137Kycrc To: ;tag=1evp3r3p75ceN Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785487 ACK Contact: Proxy-Authorization: Digest username="Enav8Pre", realm="172.xx.xx.61", nonce="64a7a2e8-8f79-432e-bb5d-a89650b98760", cnonce="2BgUXBz/EjWAOwBQVosP+A", algorithm=MD5, uri="sip:0833573222@172.xx.xx.61", response="119008ac15c252754a4c7e73c5d4527b", qop=auth, nc=00000001 Content-Length: 0 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent ACK (98785487) to udp/172.xx.xx.61:5060 nua_session.c:4139 signal_call_state_change() nua(0x7efc0002eaf0): call state changed: completing -> ready nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event i_state 200 ACK sent nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): 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 tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc0c0008c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc0c0008c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc0c0008c0) msg 0x7efc0c043c00 from (udp/172.xx.xx.85:5060) has 666 bytes, veclen = 1 recv 666 bytes from udp/[172.xx.xx.61]:5060 at 09:05:06.584465: ------------------------------------------------------------------------ INFO sip:gw+Enav8@172.xx.xx.85:5060;transport=udp;gw=Enav8 SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.61;rport;branch=z9hG4bK0gFgrycDKvFNB Max-Forwards: 70 From: ;tag=1evp3r3p75ceN To: "" ;tag=HXvB6137Kycrc Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785496 INFO Contact: User-Agent: FS Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: Outbound Call X-FS-Display-Number: D0820833573222 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc0c0008c0): msg 0x7efc0c043c00 (666 bytes) from udp/172.xx.xx.61:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received INFO sip:gw+Enav8@172.xx.xx.85:5060;transport=udp;gw=Enav8 SIP/2.0 (CSeq 98785496) nta.c:3248 agent_aliases() nta: canonizing sip:gw+Enav8@172.xx.xx.85:5060 with contact nta.c:3060 agent_recv_request() nta: INFO (98785496) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event i_info 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:06.597460 [DEBUG] sofia.c:6858 Channel sofia/external/0833573222 entering state [ready][200] 2016-11-04 09:05:06.597460 [NOTICE] sofia.c:7765 Channel [sofia/external/0833573222] has been answered EXECUTE sofia/external/0833573222 transfer(ANSWEREDCALL XML default) 2016-11-04 09:05:06.597460 [DEBUG] switch_ivr.c:2160 (sofia/external/0833573222) State Change CS_EXECUTE -> CS_ROUTING 2016-11-04 09:05:06.597460 [NOTICE] switch_ivr.c:2167 Transfer sofia/external/0833573222 to XML[ANSWEREDCALL@default] 2016-11-04 09:05:06.597460 [DEBUG] switch_channel.c:3770 (sofia/external/0833573222) Callstate Change EARLY -> ACTIVE nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 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(0x7efc0002eaf0): 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::0x7efc0c03a7a0, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7efc0c0008c0) tpn = UDP/172.xx.xx.61:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.61:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc0c0008c0): not found by name UDP/172.xx.xx.61:5060 nua_stack.c:529 nua_signal() nua(0x7efc0002eaf0): sent signal r_respond nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:609 (sofia/external/0833573222) State EXECUTE going to sleep tport.c:3594 tport_vsend() tport_vsend(0x7efc0c0008c0): 486 bytes of 486 to udp/172.xx.xx.61:5060 tport.c:3492 tport_send_msg() tport_vsend returned 486 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_ROUTING send 486 bytes to udp/[172.xx.xx.61]:5060 at 09:05:06.613417: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.xx.xx.61;rport=5060;branch=z9hG4bK0gFgrycDKvFNB From: ;tag=1evp3r3p75ceN To: "" ;tag=HXvB6137Kycrc Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785496 INFO User-Agent: FreeSWITCH-mod_sofia/1.6.7+git~20160401T134007Z~f0c3870be3~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 200 OK for INFO (98785496) 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:602 (sofia/external/0833573222) State ROUTING 2016-11-04 09:05:06.597460 [DEBUG] mod_sofia.c:142 sofia/external/0833573222 SOFIA ROUTING 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:236 sofia/external/0833573222 Standard ROUTING 2016-11-04 09:05:06.597460 [INFO] mod_dialplan_xml.c:637 Processing Outbound Call ->ANSWEREDCALL in context default Dialplan: sofia/external/0833573222 parsing [default->unloop] continue=false Dialplan: sofia/external/0833573222 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/0833573222 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->tod_example] continue=true Dialplan: sofia/external/0833573222 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/external/0833573222 Action set(open=true) Dialplan: sofia/external/0833573222 parsing [default->holiday_example] continue=true Dialplan: sofia/external/0833573222 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/external/0833573222 parsing [default->global-intercept] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [global-intercept] destination_number(ANSWEREDCALL) =~ /^886$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group-intercept] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group-intercept] destination_number(ANSWEREDCALL) =~ /^\*8$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->intercept-ext] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [intercept-ext] destination_number(ANSWEREDCALL) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->redial] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [redial] destination_number(ANSWEREDCALL) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->global] continue=true Dialplan: sofia/external/0833573222 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/0833573222 Regex (FAIL) [global] ${default_password}(4321) =~ /^1234$/ break=never Dialplan: sofia/external/0833573222 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never Dialplan: sofia/external/0833573222 Regex (FAIL) [global] ${endpoint_disposition}(ANSWER) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->snom-demo-2] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [snom-demo-2] destination_number(ANSWEREDCALL) =~ /^9001$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->snom-demo-1] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [snom-demo-1] destination_number(ANSWEREDCALL) =~ /^9000$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [eavesdrop] destination_number(ANSWEREDCALL) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->eavesdrop] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [eavesdrop] destination_number(ANSWEREDCALL) =~ /^779$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->call_return] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [call_return] destination_number(ANSWEREDCALL) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->del-group] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [del-group] destination_number(ANSWEREDCALL) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->add-group] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [add-group] destination_number(ANSWEREDCALL) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->call-group-simo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [call-group-simo] destination_number(ANSWEREDCALL) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->call-group-order] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [call-group-order] destination_number(ANSWEREDCALL) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->extension-intercom] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [extension-intercom] destination_number(ANSWEREDCALL) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Local_Ext] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Local_Ext] destination_number(ANSWEREDCALL) =~ /^(30[01][0-9])$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Local_Extension] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Local_Extension] destination_number(ANSWEREDCALL) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Local_Extension_Skinny] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Local_Extension_Skinny] destination_number(ANSWEREDCALL) =~ /^(11[01][0-9])$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_sales] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_sales] destination_number(ANSWEREDCALL) =~ /^2000$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_support] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_support] destination_number(ANSWEREDCALL) =~ /^2001$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_billing] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_billing] destination_number(ANSWEREDCALL) =~ /^2002$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_huntgroup] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_huntgroup] destination_number(ANSWEREDCALL) =~ /^0870980891$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->group_dial_did_to_local] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [group_dial_did_to_local] destination_number(ANSWEREDCALL) =~ /^0870980892$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->operator] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [operator] destination_number(ANSWEREDCALL) =~ /^(operator|0)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->vmain] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [vmain] destination_number(ANSWEREDCALL) =~ /^vmain$|^4000$|^\*98$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->sip_uri] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [sip_uri] destination_number(ANSWEREDCALL) =~ /^sip:(.*)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->nb_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [nb_conferences] destination_number(ANSWEREDCALL) =~ /^(30\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->wb_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [wb_conferences] destination_number(ANSWEREDCALL) =~ /^(31\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->uwb_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [uwb_conferences] destination_number(ANSWEREDCALL) =~ /^(32\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [cdquality_conferences] destination_number(ANSWEREDCALL) =~ /^(33\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->cdquality_conferences] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [cdquality_conferences] destination_number(ANSWEREDCALL) =~ /^(35\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->freeswitch_public_conf_via_sip] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(ANSWEREDCALL) =~ /^9(888|8888|1616|3232)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->mad_boss_intercom] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [mad_boss_intercom] destination_number(ANSWEREDCALL) =~ /^0911$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->mad_boss_intercom] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [mad_boss_intercom] destination_number(ANSWEREDCALL) =~ /^0912$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->mad_boss] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [mad_boss] destination_number(ANSWEREDCALL) =~ /^0913$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ivr_demo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ivr_demo] destination_number(ANSWEREDCALL) =~ /^5000$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->dynamic_conference] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [dynamic_conference] destination_number(ANSWEREDCALL) =~ /^5001$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->rtp_multicast_page] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [rtp_multicast_page] destination_number(ANSWEREDCALL) =~ /^pagegroup$|^7243$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [park] destination_number(ANSWEREDCALL) =~ /^5900$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->unpark] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [unpark] destination_number(ANSWEREDCALL) =~ /^5901$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->valet_park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [valet_park] destination_number(ANSWEREDCALL) =~ /^(6000)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->valet_park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [valet_park] destination_number(ANSWEREDCALL) =~ /^((?!6000)60\d{2})$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [park] source(src/switch_ivr_originate.c) =~ /mod_sofia/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->unpark] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [unpark] source(src/switch_ivr_originate.c) =~ /mod_sofia/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->park] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [park] source(src/switch_ivr_originate.c) =~ /mod_sofia/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->unpark] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [unpark] source(src/switch_ivr_originate.c) =~ /mod_sofia/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->wait] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [wait] destination_number(ANSWEREDCALL) =~ /^wait$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->fax_receive] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [fax_receive] destination_number(ANSWEREDCALL) =~ /^9178$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->fax_transmit] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [fax_transmit] destination_number(ANSWEREDCALL) =~ /^9179$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_180] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_180] destination_number(ANSWEREDCALL) =~ /^9180$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_183_uk_ring] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_183_uk_ring] destination_number(ANSWEREDCALL) =~ /^9181$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_183_music_ring] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_183_music_ring] destination_number(ANSWEREDCALL) =~ /^9182$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_post_answer_uk_ring] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_post_answer_uk_ring] destination_number(ANSWEREDCALL) =~ /^9183$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ringback_post_answer_music] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ringback_post_answer_music] destination_number(ANSWEREDCALL) =~ /^9184$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->ClueCon] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [ClueCon] destination_number(ANSWEREDCALL) =~ /^9191$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->show_info] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [show_info] destination_number(ANSWEREDCALL) =~ /^9192$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->video_record] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [video_record] destination_number(ANSWEREDCALL) =~ /^9193$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->video_playback] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [video_playback] destination_number(ANSWEREDCALL) =~ /^9194$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->delay_echo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [delay_echo] destination_number(ANSWEREDCALL) =~ /^9195$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->echo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [echo] destination_number(ANSWEREDCALL) =~ /^9196$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->milliwatt] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [milliwatt] destination_number(ANSWEREDCALL) =~ /^9197$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->tone_stream] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [tone_stream] destination_number(ANSWEREDCALL) =~ /^9198$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->zrtp_enrollement] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [zrtp_enrollement] destination_number(ANSWEREDCALL) =~ /^9787$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->hold_music] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [hold_music] destination_number(ANSWEREDCALL) =~ /^9664$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->laugh break] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [laugh break] destination_number(ANSWEREDCALL) =~ /^9386$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->101] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [101] destination_number(ANSWEREDCALL) =~ /^101$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->pizza_demo] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [pizza_demo] destination_number(ANSWEREDCALL) =~ /^(pizza|74992)$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Talking Clock Time] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Talking Clock Time] destination_number(ANSWEREDCALL) =~ /^9170$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Talking Clock Date] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Talking Clock Date] destination_number(ANSWEREDCALL) =~ /^9171$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->Talking Clock Date and Time] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [Talking Clock Date and Time] destination_number(ANSWEREDCALL) =~ /^9172$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->exe_on_ans] continue=false Dialplan: sofia/external/0833573222 Regex (FAIL) [exe_on_ans] destination_number(ANSWEREDCALL) =~ /^0870980890$/ break=on-false Dialplan: sofia/external/0833573222 parsing [default->nb_conferences_answered] continue=false Dialplan: sofia/external/0833573222 Regex (PASS) [nb_conferences_answered] destination_number(ANSWEREDCALL) =~ /^ANSWEREDCALL$/ break=on-false Dialplan: sofia/external/0833573222 Action answer() Dialplan: sofia/external/0833573222 Action set(hangup_after_bridge=true) Dialplan: sofia/external/0833573222 Action set(continue_on_fail=true) Dialplan: sofia/external/0833573222 Action callcenter(agent8003@default) 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:286 (sofia/external/0833573222) State Change CS_ROUTING -> CS_EXECUTE 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:602 (sofia/external/0833573222) State ROUTING going to sleep 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_EXECUTE 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:609 (sofia/external/0833573222) State EXECUTE 2016-11-04 09:05:06.597460 [DEBUG] mod_sofia.c:197 sofia/external/0833573222 SOFIA EXECUTE 2016-11-04 09:05:06.597460 [DEBUG] switch_core_state_machine.c:328 sofia/external/0833573222 Standard EXECUTE EXECUTE sofia/external/0833573222 set(open=true) 2016-11-04 09:05:06.597460 [DEBUG] mod_dptools.c:1519 SET sofia/external/0833573222 [open]=[true] EXECUTE sofia/external/0833573222 answer() EXECUTE sofia/external/0833573222 set(hangup_after_bridge=true) 2016-11-04 09:05:06.597460 [DEBUG] mod_dptools.c:1519 SET sofia/external/0833573222 [hangup_after_bridge]=[true] EXECUTE sofia/external/0833573222 set(continue_on_fail=true) 2016-11-04 09:05:06.597460 [DEBUG] mod_dptools.c:1519 SET sofia/external/0833573222 [continue_on_fail]=[true] EXECUTE sofia/external/0833573222 callcenter(agent8003@default) 2016-11-04 09:05:06.617484 [DEBUG] mod_callcenter.c:2731 Member Outbound Call joining queue agent8003@default 2016-11-04 09:05:06.617484 [DEBUG] mod_local_stream.c:843 Opening Stream [moh/8000] 8000hz 2016-11-04 09:05:06.617484 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 60ms 2016-11-04 09:05:06.617484 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set state = Receiving 2016-11-04 09:05:06.637472 [DEBUG] mod_callcenter.c:1236 Updated tier: Agent 8003 in Queue agent8003@default set state = Active Inbound 2016-11-04 09:05:06.637472 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set state = In a queue call 2016-11-04 09:05:06.637472 [DEBUG] switch_ivr.c:623 sofia/internal/8003@172.xx.xx.3 Command Execute playback(tone_stream://%(200,0,500,600,700);loops=3) EXECUTE sofia/internal/8003@172.xx.xx.3 playback(tone_stream://%(200,0,500,600,700);loops=3) 2016-11-04 09:05:06.637472 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms 2016-11-04 09:05:06.637472 [DEBUG] switch_core_media_bug.c:828 Attaching BUG to sofia/external/0833573222 2016-11-04 09:05:06.637472 [DEBUG] mod_callcenter.c:1776 Agent 8003 answered "Outbound Call" from queue agent8003@default (Recorded) 2016-11-04 09:05:06.637472 [DEBUG] switch_ivr_bridge.c:2010 (sofia/external/0833573222) State Change CS_EXECUTE -> CS_HIBERNATE 2016-11-04 09:05:06.637472 [DEBUG] switch_ivr_bridge.c:2012 (sofia/internal/8003@172.xx.xx.3) State Change CS_EXECUTE -> CS_HIBERNATE 2016-11-04 09:05:06.657461 [DEBUG] switch_ivr_play_say.c:1910 done playing file tone_stream://%(200,0,500,600,700);loops=3 2016-11-04 09:05:06.657461 [DEBUG] switch_ivr_async.c:1496 No silence detection configured; assuming start of speech 2016-11-04 09:05:06.657461 [DEBUG] switch_ivr_play_say.c:1910 done playing file local_stream://moh 2016-11-04 09:05:06.657461 [DEBUG] mod_callcenter.c:2887 Member Outbound Call is answered by an agent in queue agent8003@default 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:609 (sofia/external/0833573222) State EXECUTE going to sleep 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_HIBERNATE 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:624 (sofia/external/0833573222) State HIBERNATE 2016-11-04 09:05:06.677541 [DEBUG] mod_sofia.c:179 sofia/external/0833573222 SOFIA HIBERNATE 2016-11-04 09:05:06.677541 [DEBUG] switch_ivr_bridge.c:964 (sofia/external/0833573222) State Change CS_HIBERNATE -> CS_RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:624 (sofia/external/0833573222) State HIBERNATE going to sleep 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:605 (sofia/external/0833573222) State RESET 2016-11-04 09:05:06.677541 [DEBUG] mod_sofia.c:160 sofia/external/0833573222 SOFIA RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_ivr_bridge.c:949 sofia/external/0833573222 CUSTOM RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_ivr_bridge.c:956 (sofia/external/0833573222) State Change CS_RESET -> CS_SOFT_EXECUTE 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:605 (sofia/external/0833573222) State RESET going to sleep 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_SOFT_EXECUTE 2016-11-04 09:05:06.677541 [DEBUG] switch_ivr_play_say.c:1910 done playing file local_stream://moh 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:615 (sofia/external/0833573222) State SOFT_EXECUTE 2016-11-04 09:05:06.677541 [DEBUG] mod_sofia.c:634 SOFIA SOFT_EXECUTE 2016-11-04 09:05:06.677541 [DEBUG] switch_ivr_bridge.c:974 sofia/external/0833573222 CUSTOM SOFT_EXECUTE 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/8003@172.xx.xx.3) State EXECUTE going to sleep 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_HIBERNATE 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/8003@172.xx.xx.3) State HIBERNATE 2016-11-04 09:05:06.677541 [DEBUG] mod_sofia.c:179 sofia/internal/8003@172.xx.xx.3 SOFIA HIBERNATE 2016-11-04 09:05:06.677541 [DEBUG] switch_ivr_bridge.c:964 (sofia/internal/8003@172.xx.xx.3) State Change CS_HIBERNATE -> CS_RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/8003@172.xx.xx.3) State HIBERNATE going to sleep 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:605 (sofia/internal/8003@172.xx.xx.3) State RESET 2016-11-04 09:05:06.677541 [DEBUG] mod_sofia.c:160 sofia/internal/8003@172.xx.xx.3 SOFIA RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_ivr_bridge.c:949 sofia/internal/8003@172.xx.xx.3 CUSTOM RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:188 sofia/internal/8003@172.xx.xx.3 Standard RESET 2016-11-04 09:05:06.677541 [DEBUG] switch_core_state_machine.c:605 (sofia/internal/8003@172.xx.xx.3) State RESET going to sleep 2016-11-04 09:05:06.697469 [DEBUG] switch_ivr_bridge.c:1006 (sofia/internal/8003@172.xx.xx.3) State Change CS_RESET -> CS_SOFT_EXECUTE 2016-11-04 09:05:06.697469 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_SOFT_EXECUTE 2016-11-04 09:05:06.697469 [DEBUG] switch_core_state_machine.c:615 (sofia/internal/8003@172.xx.xx.3) State SOFT_EXECUTE 2016-11-04 09:05:06.697469 [DEBUG] mod_sofia.c:634 SOFIA SOFT_EXECUTE 2016-11-04 09:05:06.697469 [DEBUG] switch_ivr_bridge.c:974 sofia/internal/8003@172.xx.xx.3 CUSTOM SOFT_EXECUTE 2016-11-04 09:05:06.697469 [DEBUG] switch_core_state_machine.c:400 sofia/internal/8003@172.xx.xx.3 Standard SOFT_EXECUTE 2016-11-04 09:05:06.697469 [DEBUG] switch_core_state_machine.c:615 (sofia/internal/8003@172.xx.xx.3) State SOFT_EXECUTE going to sleep 2016-11-04 09:05:06.717485 [DEBUG] switch_ivr_bridge.c:1489 (sofia/internal/8003@172.xx.xx.3) State Change CS_SOFT_EXECUTE -> CS_CONSUME_MEDIA 2016-11-04 09:05:06.717485 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_CONSUME_MEDIA 2016-11-04 09:05:06.717485 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/8003@172.xx.xx.3) State CONSUME_MEDIA 2016-11-04 09:05:06.717485 [DEBUG] switch_ivr_bridge.c:913 sofia/internal/8003@172.xx.xx.3 CUSTOM HOLD 2016-11-04 09:05:06.717485 [DEBUG] switch_core_state_machine.c:621 (sofia/internal/8003@172.xx.xx.3) State CONSUME_MEDIA going to sleep 2016-11-04 09:05:06.717485 [DEBUG] switch_ivr_bridge.c:1594 (sofia/internal/8003@172.xx.xx.3) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2016-11-04 09:05:06.717485 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_EXCHANGE_MEDIA 2016-11-04 09:05:06.717485 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/8003@172.xx.xx.3) State EXCHANGE_MEDIA 2016-11-04 09:05:06.717485 [DEBUG] mod_sofia.c:628 SOFIA EXCHANGE_MEDIA 2016-11-04 09:05:06.717485 [INFO] mod_com_g729.c:126 ENCODER LICENSE ALLOCATED--->0x7efc1805dc28 0x7efc1805dc28 2016-11-04 09:05:06.717485 [INFO] mod_com_g729.c:133 ENCODER CREATED------------->0x7efc1805dc28 0x7efc1805dc28 2016-11-04 09:05:06.717485 [INFO] mod_com_g729.c:164 DECODER LICENSE ALLOCATED--->0x7efc1805dc28 0x7efc1805dc30 2016-11-04 09:05:06.717485 [INFO] mod_com_g729.c:171 DECODER CREATED------------->0x7efc1805dc28 0x7efc1805dc30 2016-11-04 09:05:06.717485 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 960 bytes to accommodate 320->960 nua.c:798 nua_info() nua: nua_info: entering nua_stack.c:529 nua_signal() nua(0x7efc0002eaf0): sent signal r_info nua_stack.c:569 nua_stack_signal() nua(0x7efc0002eaf0): recv signal r_info nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering soa.c:403 soa_set_params() soa_set_params(static::0x7efc0c03a7a0, ...) called auth_digest.c:226 auth_digest_a1() auth_digest_a1() has A1 = MD5(Enav8Pre:172.xx.xx.61:En@v8Pre!!@4543) = 0539d9f4459c6f955a5b6c5bce9c40b1 auth_digest.c:318 auth_digest_response() A2 = MD5(INFO:sip:0833573222@172.xx.xx.61:5060;transport=udp) auth_digest.c:348 auth_digest_response() auth_response: 958346cb56b8c5b979ea29812d109909 = MD5(0539d9f4459c6f955a5b6c5bce9c40b1:64a7a2e8-8f79-432e-bb5d-a89650b98760:00000002:2BgUXBz/EjWAOwBQVosP+A:auth:4741e082bbc515e1cd4bc5c629e44c28) (qop=auth) nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip tport.c:3257 tport_tsend() tport_tsend(0x7efc0c0008c0) tpn = udp/172.xx.xx.61:5060 tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.61:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc0c0008c0): not found by name udp/172.xx.xx.61:5060 tport.c:3594 tport_vsend() tport_vsend(0x7efc0c0008c0): 987 bytes of 987 to udp/172.xx.xx.61:5060 tport.c:3492 tport_send_msg() tport_vsend returned 987 send 987 bytes to udp/[172.xx.xx.61]:5060 at 09:05:06.731883: ------------------------------------------------------------------------ INFO sip:0833573222@172.xx.xx.61:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.85;rport;branch=z9hG4bKUQ5mjj3B84eKm Max-Forwards: 70 From: "" ;tag=HXvB6137Kycrc To: ;tag=1evp3r3p75ceN Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785488 INFO Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.7+git~20160401T134007Z~f0c3870be3~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Proxy-Authorization: Digest username="Enav8Pre", realm="172.xx.xx.61", nonce="64a7a2e8-8f79-432e-bb5d-a89650b98760", cnonce="2BgUXBz/EjWAOwBQVosP+A", algorithm=MD5, uri="sip:0833573222@172.xx.xx.61:5060;transport=udp", response="958346cb56b8c5b979ea29812d109909", qop=auth, nc=00000002 Content-Type: message/update_display Content-Length: 0 X-FS-Display-Name: 8003 X-FS-Display-Number: 8003 ------------------------------------------------------------------------ nta.c:8304 outgoing_send() nta: sent INFO (98785488) to udp/172.xx.xx.61:5060 tport.c:4160 tport_pend() tport_pend(0x7efc0c0008c0): pending 0x7efc0c03d7e0 for udp/172.xx.xx.85:5060 (already 0) nta.c:1348 set_timeout() nta: timer shortened to 1000 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc0c0008c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc0c0008c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc0c0008c0) msg 0x7efc0c04a1e0 from (udp/172.xx.xx.85:5060) has 433 bytes, veclen = 1 recv 433 bytes from udp/[172.xx.xx.61]:5060 at 09:05:06.747736: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.xx.xx.85;rport=5060;branch=z9hG4bKUQ5mjj3B84eKm From: "" ;tag=HXvB6137Kycrc To: ;tag=1evp3r3p75ceN Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785488 INFO User-Agent: FS Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Content-Length: 0 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc0c0008c0): msg 0x7efc0c04a1e0 (433 bytes) from udp/172.xx.xx.61:5060/sip next=(nil) nta.c:3299 agent_recv_response() nta: received 200 OK for INFO (98785488) nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 16 ms tport.c:4222 tport_release() tport_release(0x7efc0c0008c0): 0x7efc0c03d7e0 by 0x7efc0c045cb0 with 0x7efc0c04a1e0 nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event r_info 200 OK nua_stack.c:359 nua_application_event() nua: nua_application_event: entering 2016-11-04 09:05:06.757472 [INFO] mod_com_g729.c:126 ENCODER LICENSE ALLOCATED--->0x7efc28027798 0x7efc28027798 2016-11-04 09:05:06.757472 [INFO] mod_com_g729.c:133 ENCODER CREATED------------->0x7efc28027798 0x7efc28027798 nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:06.837473 [DEBUG] switch_rtp.c:6670 Correct audio ip/port confirmed. 2016-11-04 09:05:06.837473 [DEBUG] switch_core_io.c:448 Setting BUG Codec G729:18 2016-11-04 09:05:06.837473 [INFO] mod_com_g729.c:164 DECODER LICENSE ALLOCATED--->0x7efc00065110 0x7efc00065118 2016-11-04 09:05:06.837473 [INFO] mod_com_g729.c:171 DECODER CREATED------------->0x7efc00065110 0x7efc00065118 2016-11-04 09:05:06.837473 [INFO] mod_com_g729.c:164 DECODER LICENSE ALLOCATED--->0x7efc280277b8 0x7efc280277c0 2016-11-04 09:05:06.837473 [INFO] mod_com_g729.c:171 DECODER CREATED------------->0x7efc280277b8 0x7efc280277c0 2016-11-04 09:05:06.837473 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 320 bytes to accommodate 960->320 nta.c:1296 agent_timer() nta: timer set next to 4016 ms nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate INFO (98785488) nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7efc37691d40) nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free nta.c:1296 agent_timer() nta: timer set next to 21174 ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc0c0008c0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc0c0008c0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc0c0008c0) msg 0x7efc0c04a1e0 from (udp/172.xx.xx.85:5060) has 584 bytes, veclen = 1 recv 584 bytes from udp/[172.xx.xx.61]:5060 at 09:05:14.529516: ------------------------------------------------------------------------ BYE sip:gw+Enav8@172.xx.xx.85:5060;transport=udp;gw=Enav8 SIP/2.0 Via: SIP/2.0/UDP 172.xx.xx.61;rport;branch=z9hG4bK2211UmemDevtj Max-Forwards: 70 From: ;tag=1evp3r3p75ceN To: "" ;tag=HXvB6137Kycrc Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785497 BYE User-Agent: FS Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Reason: Q.850;cause=16 Content-Length: 0 P-RTP-Stat: PS=204,OS=12240,PR=126,OR=7560,PL=0,JI=0,LA=0,DU=8 ------------------------------------------------------------------------ tport.c:3023 tport_deliver() tport_deliver(0x7efc0c0008c0): msg 0x7efc0c04a1e0 (584 bytes) from udp/172.xx.xx.61:5060/sip next=(nil) nta.c:2880 agent_recv_request() nta: received BYE sip:gw+Enav8@172.xx.xx.85:5060;transport=udp;gw=Enav8 SIP/2.0 (CSeq 98785497) nta.c:3248 agent_aliases() nta: canonizing sip:gw+Enav8@172.xx.xx.85:5060 with contact nta.c:3060 agent_recv_request() nta: BYE (98785497) going to existing leg nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event i_bye 100 Trying nua_stack.c:359 nua_application_event() nua: nua_application_event: entering nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering 2016-11-04 09:05:14.517547 [NOTICE] sofia.c:988 Hangup sofia/external/0833573222 [CS_SOFT_EXECUTE] [NORMAL_CLEARING] nua.c:879 nua_respond() nua: nua_respond: entering nua_stack.c:573 nua_stack_signal() nua(0x7efc0002eaf0): 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::0x7efc0c03a7a0, ...) called tport.c:3257 tport_tsend() tport_tsend(0x7efc0c0008c0) tpn = UDP/172.xx.xx.61:5060 nua_stack.c:529 nua_signal() nua(0x7efc0002eaf0): sent signal r_respond tport.c:4046 tport_resolve() tport_resolve addrinfo = 172.xx.xx.61:5060 tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7efc0c0008c0): not found by name UDP/172.xx.xx.61:5060 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:529 nua_signal() nua(0x7efc0002eaf0): sent signal r_destroy tport.c:3594 tport_vsend() tport_vsend(0x7efc0c0008c0): 485 bytes of 485 to udp/172.xx.xx.61:5060 tport.c:3492 tport_send_msg() tport_vsend returned 485 send 485 bytes to udp/[172.xx.xx.61]:5060 at 09:05:14.532177: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.xx.xx.61;rport=5060;branch=z9hG4bK2211UmemDevtj From: ;tag=1evp3r3p75ceN To: "" ;tag=HXvB6137Kycrc Call-ID: d817aae3-1cff-1235-3b80-0050568b0ff8 CSeq: 98785497 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.7+git~20160401T134007Z~f0c3870be3~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (98785497) nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7efc0002eaf0): removing session usage nua_session.c:4139 signal_call_state_change() nua(0x7efc0002eaf0): call state changed: ready -> terminated nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event i_state 200 Session Terminated nua_stack.c:271 nua_stack_event() nua(0x7efc0002eaf0): event i_terminated 200 Session Terminated soa.c:356 soa_destroy() soa_destroy(static::0x7efc0c03a7a0) called nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7efc0c02eae0) nua_stack.c:569 nua_stack_signal() nua(0x7efc0002eaf0): recv signal r_destroy nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil)) 2016-11-04 09:05:14.517547 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/external/0833573222] 2016-11-04 09:05:14.537459 [DEBUG] switch_ivr_bridge.c:701 sofia/external/0833573222 ending bridge by request from write function 2016-11-04 09:05:14.537459 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/internal/8003@172.xx.xx.3] 2016-11-04 09:05:14.537459 [DEBUG] switch_ivr.c:2160 (sofia/internal/8003@172.xx.xx.3) State Change CS_EXCHANGE_MEDIA -> CS_ROUTING 2016-11-04 09:05:14.537459 [NOTICE] switch_ivr.c:2167 Transfer sofia/internal/8003@172.xx.xx.3 to XML[4099@public] 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/8003@172.xx.xx.3) State EXCHANGE_MEDIA going to sleep 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_ROUTING 2016-11-04 09:05:14.537459 [DEBUG] switch_channel.c:2249 (sofia/internal/8003@172.xx.xx.3) Callstate Change ACTIVE -> RINGING 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/8003@172.xx.xx.3) State ROUTING 2016-11-04 09:05:14.537459 [DEBUG] mod_sofia.c:142 sofia/internal/8003@172.xx.xx.3 SOFIA ROUTING 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:236 sofia/internal/8003@172.xx.xx.3 Standard ROUTING 2016-11-04 09:05:14.537459 [INFO] mod_dialplan_xml.c:637 Processing Outbound Call ->4099 in context public Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->unloop] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->group_dial_huntgroup] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [group_dial_huntgroup] destination_number(4099) =~ /^0870980891$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->group_dial_did_to_local] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [group_dial_did_to_local] destination_number(4099) =~ /^0870980892$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->outside_call] continue=true Dialplan: sofia/internal/8003@172.xx.xx.3 Absolute Condition [outside_call] Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(outside_call=true) Dialplan: sofia/internal/8003@172.xx.xx.3 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->call_debug] continue=true Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->public_extensions] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [public_extensions] destination_number(4099) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->public_did] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [public_did] destination_number(4099) =~ /^(5551212)$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->public_did] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [public_did] destination_number(4099) =~ /^(0870980892)$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->nb_conferences] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [nb_conferences] destination_number(4099) =~ /^0870980890$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->nb_conferences] continue=false Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [nb_conferences] destination_number(4099) =~ /^0870980893$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->conf11001] continue=false 2016-11-04 09:05:14.537459 [DEBUG] switch_ivr_bridge.c:1695 sofia/external/0833573222 skip receive message [UNBRIDGE] (channel is hungup already) Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (FAIL) [conf11001] destination_number(4099) =~ /^11001$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 parsing [public->UNKNOWN] continue=false 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:615 (sofia/external/0833573222) State SOFT_EXECUTE going to sleep 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_HANGUP Dialplan: sofia/internal/8003@172.xx.xx.3 Regex (PASS) [UNKNOWN] destination_number(4099) =~ /^(4099)$/ break=on-false Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(transfer_after_bridge=4099) Dialplan: sofia/internal/8003@172.xx.xx.3 Action sleep(300) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(res=${callcenter_config(agent set uuid ${caller_id_number} '${uuid}')}) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(res=${callcenter_config(agent set type ${caller_id_number} 'uuid-standby')}) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(res=${callcenter_config(agent set status ${caller_id_number} 'Available')}) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(res=${callcenter_config(agent set state ${caller_id_number} 'idle')}) Dialplan: sofia/internal/8003@172.xx.xx.3 Action set(cc_warning_tone=tone_stream://%(200,0,500,600,700);loops=3) Dialplan: sofia/internal/8003@172.xx.xx.3 Action answer() Dialplan: sofia/internal/8003@172.xx.xx.3 Action playback(local_stream://moh) 2016-11-04 09:05:14.537459 [DEBUG] switch_ivr_async.c:1312 Stop recording file /usr/local/freeswitch/recordings/2016-11-04-09-05-06.ANSWEREDCALL.D0820833573222.908b0bfc-4bec-4fc6-bd3d-dfa7aea869bb.wav 2016-11-04 09:05:14.537459 [INFO] switch_channel.c:3127 sofia/internal/8003@172.xx.xx.3 Flipping CID from "Outbound Call" to "8003" <8003> 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/8003@172.xx.xx.3) State Change CS_ROUTING -> CS_EXECUTE 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/8003@172.xx.xx.3) State ROUTING going to sleep 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:543 (sofia/internal/8003@172.xx.xx.3) Running State Change CS_EXECUTE 2016-11-04 09:05:14.537459 [DEBUG] switch_channel.c:2251 (sofia/internal/8003@172.xx.xx.3) Callstate Change RINGING -> ACTIVE 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:609 (sofia/internal/8003@172.xx.xx.3) State EXECUTE 2016-11-04 09:05:14.537459 [DEBUG] mod_sofia.c:197 sofia/internal/8003@172.xx.xx.3 SOFIA EXECUTE 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:328 sofia/internal/8003@172.xx.xx.3 Standard EXECUTE EXECUTE sofia/internal/8003@172.xx.xx.3 set(outside_call=true) 2016-11-04 09:05:14.537459 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [outside_call]=[true] EXECUTE sofia/internal/8003@172.xx.xx.3 export(RFC2822_DATE=Fri, 04 Nov 2016 09:05:14 +0200) 2016-11-04 09:05:14.537459 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 04 Nov 2016 09:05:14 +0200] EXECUTE sofia/internal/8003@172.xx.xx.3 set(transfer_after_bridge=4099) 2016-11-04 09:05:14.537459 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [transfer_after_bridge]=[4099] EXECUTE sofia/internal/8003@172.xx.xx.3 sleep(300) 2016-11-04 09:05:14.537459 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set state = Waiting 2016-11-04 09:05:14.537459 [DEBUG] switch_ivr_async.c:1376 Channel is hung up 2016-11-04 09:05:14.537459 [DEBUG] switch_core_media_bug.c:1120 Removing BUG from sofia/external/0833573222 2016-11-04 09:05:14.537459 [INFO] mod_com_g729.c:95 DECODER DESTROYED----------->0x7efc00065110 0x7efc00065118 2016-11-04 09:05:14.537459 [INFO] mod_com_g729.c:98 DECODER LICENSE DEALLOCATED->0x7efc00065110 0x7efc00065118 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:809 (sofia/external/0833573222) Callstate Change ACTIVE -> HANGUP 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:811 (sofia/external/0833573222) State HANGUP 2016-11-04 09:05:14.537459 [DEBUG] mod_sofia.c:437 Channel sofia/external/0833573222 hanging up, cause: NORMAL_CLEARING 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:60 sofia/external/0833573222 Standard HANGUP, cause: NORMAL_CLEARING 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:811 (sofia/external/0833573222) State HANGUP going to sleep 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:578 (sofia/external/0833573222) State Change CS_HANGUP -> CS_REPORTING 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:543 (sofia/external/0833573222) Running State Change CS_REPORTING 2016-11-04 09:05:14.537459 [DEBUG] switch_core_state_machine.c:897 (sofia/external/0833573222) State REPORTING 2016-11-04 09:05:14.537459 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_both (start_stamp, CallId, TEST_id, end_stamp) VALUES ('2016-11-04 09:05:00', '908b0bfc-4bec-4fc6-bd3d-dfa7aea869bb', 'Enav8Pre@172.xx.xx.61', '2016-11-04 09:05:14') 2016-11-04 09:05:14.630112 [DEBUG] mod_odbc_cdr.c:309 sql INSERT INTO cdr_table_a_leg (start_stamp, TelNumberFull, CallId, sip_endpoint_disposition, orig_id, CallerID, CODEC, sip_current_application, IP, term_id, ClientId, end_stamp) VALUES ('2016-11-04 09:05:00', '0833573222', '908b0bfc-4bec-4fc6-bd3d-dfa7aea869bb', 'ANSWER', '908b0bfc-4bec-4fc6-bd3d-dfa7aea869bb', 'Enav8Pre', 'G729', 'callcenter', '172.xx.xx.61', 'd817aae3-1cff-1235-3b80-0050568b0ff8', '908b0bfc-4bec-4fc6-bd3d-dfa7aea869bb', '2016-11-04 09:05:14') 2016-11-04 09:05:14.630112 [DEBUG] switch_core_state_machine.c:174 sofia/external/0833573222 Standard REPORTING, cause: NORMAL_CLEARING 2016-11-04 09:05:14.630112 [DEBUG] switch_core_state_machine.c:897 (sofia/external/0833573222) State REPORTING going to sleep 2016-11-04 09:05:14.630112 [DEBUG] switch_core_state_machine.c:569 (sofia/external/0833573222) State Change CS_REPORTING -> CS_DESTROY 2016-11-04 09:05:14.630112 [DEBUG] switch_core_session.c:1646 Session 103 (sofia/external/0833573222) Locked, Waiting on external entities 2016-11-04 09:05:14.630112 [NOTICE] switch_core_session.c:1664 Session 103 (sofia/external/0833573222) Ended 2016-11-04 09:05:14.630112 [NOTICE] switch_core_session.c:1668 Close Channel sofia/external/0833573222 [CS_DESTROY] 2016-11-04 09:05:14.630112 [DEBUG] switch_core_state_machine.c:700 (sofia/external/0833573222) Running State Change CS_DESTROY 2016-11-04 09:05:14.630112 [DEBUG] switch_core_state_machine.c:710 (sofia/external/0833573222) State DESTROY 2016-11-04 09:05:14.630112 [DEBUG] mod_sofia.c:342 sofia/external/0833573222 SOFIA DESTROY 2016-11-04 09:05:14.630112 [INFO] mod_com_g729.c:95 DECODER DESTROYED----------->0x7efc280277b8 0x7efc280277c0 2016-11-04 09:05:14.630112 [INFO] mod_com_g729.c:98 DECODER LICENSE DEALLOCATED->0x7efc280277b8 0x7efc280277c0 2016-11-04 09:05:14.630112 [INFO] mod_com_g729.c:84 ENCODER DESTROYED----------->0x7efc28027798 0x7efc28027798 2016-11-04 09:05:14.630112 [INFO] mod_com_g729.c:87 ENCODER LICENSE DEALLOCATED->0x7efc28027798 0x7efc28027798 2016-11-04 09:05:14.630112 [DEBUG] switch_core_state_machine.c:181 sofia/external/0833573222 Standard DESTROY 2016-11-04 09:05:14.630112 [DEBUG] switch_core_state_machine.c:710 (sofia/external/0833573222) State DESTROY going to sleep 2016-11-04 09:05:14.837564 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set uuid = 544b6c82-4804-4791-bf86-f44a9e72b983 EXECUTE sofia/internal/8003@172.xx.xx.3 set(res=+OK ) 2016-11-04 09:05:14.837564 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [res]=[+OK ] 2016-11-04 09:05:14.837564 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set type = uuid-standby EXECUTE sofia/internal/8003@172.xx.xx.3 set(res=+OK ) 2016-11-04 09:05:14.837564 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [res]=[+OK ] 2016-11-04 09:05:14.837564 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set status = Available EXECUTE sofia/internal/8003@172.xx.xx.3 set(res=+OK ) 2016-11-04 09:05:14.837564 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [res]=[+OK ] 2016-11-04 09:05:14.837564 [DEBUG] mod_callcenter.c:1115 Updated Agent 8003 set state = idle EXECUTE sofia/internal/8003@172.xx.xx.3 set(res=+OK ) 2016-11-04 09:05:14.837564 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [res]=[+OK ] EXECUTE sofia/internal/8003@172.xx.xx.3 set(cc_warning_tone=tone_stream://%(200,0,500,600,700);loops=3) 2016-11-04 09:05:14.837564 [DEBUG] mod_dptools.c:1519 SET sofia/internal/8003@172.xx.xx.3 [cc_warning_tone]=[tone_stream://%(200,0,500,600,700);loops=3] EXECUTE sofia/internal/8003@172.xx.xx.3 answer() EXECUTE sofia/internal/8003@172.xx.xx.3 playback(local_stream://moh) 2016-11-04 09:05:14.837564 [DEBUG] mod_local_stream.c:843 Opening Stream [moh/8000] 8000hz 2016-11-04 09:05:14.837564 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7efc00026cb0): events IN tport.c:2864 tport_recv_event() tport_recv_event(0x7efc00026cb0) tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7efc00026cb0) msg 0x7efc0004df80 from (udp/172.xx.xx.60:5060) has 4 bytes, veclen = 1 tport.c:3023 tport_deliver() tport_deliver(0x7efc00026cb0): bad msg 0x7efc0004df80 (4 bytes) from udp/10.99.107.25:5060/sip next=(nil)