2017-04-28 08:58:05.101113 [NOTICE] mod_cdr_csv.c:123 Rotated CDR logfile /var/log/freeswitch/cdr-csv/1002.csv 2017-04-28 08:58:05.101113 [NOTICE] mod_logfile.c:192 New log started. recv 419 bytes from udp/[192.168.1.104]:5060 at 08:59:41.830596: ------------------------------------------------------------------------ INVITE sip:1002@172.17.0.3:5080 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-0;nosdp=true;out-of-dialog=true From: sipp ;tag=1 To: Call-ID: 1-1988@192.168.1.104 CSeq: 1 INVITE Contact: Max-Forwards: 70 Subject: Performance Test Session-Expires: 1800 Min-SE: 900 Content-Length: 0 ------------------------------------------------------------------------ send 317 bytes to udp/[192.168.1.104]:5060 at 08:59:41.830888: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-0;nosdp=true;out-of-dialog=true From: sipp ;tag=1 To: Call-ID: 1-1988@192.168.1.104 CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Content-Length: 0 ------------------------------------------------------------------------ c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [NOTICE] switch_channel.c:1104 New Channel sofia/external/sipp@192.168.1.104:5060 [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_NEW (Cur 1 Tot 9) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] sofia.c:9834 sofia/external/sipp@192.168.1.104:5060 receiving invite from 192.168.1.104:5060 version: 1.6.17 -34-0fc0946 64bit c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [received][100] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] sofia.c:7568 (sofia/external/sipp@192.168.1.104:5060) State Change CS_NEW -> CS_INIT c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:603 (sofia/external/sipp@192.168.1.104:5060) State NEW c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_INIT (Cur 1 Tot 9) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:627 (sofia/external/sipp@192.168.1.104:5060) State INIT c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_sofia.c:90 sofia/external/sipp@192.168.1.104:5060 SOFIA INIT c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:40 sofia/external/sipp@192.168.1.104:5060 Standard INIT c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:48 (sofia/external/sipp@192.168.1.104:5060) State Change CS_INIT -> CS_ROUTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:627 (sofia/external/sipp@192.168.1.104:5060) State INIT going to sleep c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_ROUTING (Cur 1 Tot 9) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_channel.c:2249 (sofia/external/sipp@192.168.1.104:5060) Callstate Change DOWN -> RINGING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:643 (sofia/external/sipp@192.168.1.104:5060) State ROUTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_sofia.c:143 sofia/external/sipp@192.168.1.104:5060 SOFIA ROUTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:236 sofia/external/sipp@192.168.1.104:5060 Standard ROUTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [INFO] mod_dialplan_xml.c:637 Processing sipp ->1002 in context public c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [public->unloop] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [public->outside_call] continue=true c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Absolute Condition [outside_call] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(outside_call=true) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [public->call_debug] continue=true c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [call_debug] ${call_debug}(true) =~ /^true$/ break=never c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action info() c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [public->public_extensions] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [public_extensions] destination_number(1002) =~ /^(10[01][0-9])$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action transfer(1002 XML default) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:286 (sofia/external/sipp@192.168.1.104:5060) State Change CS_ROUTING -> CS_EXECUTE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:643 (sofia/external/sipp@192.168.1.104:5060) State ROUTING going to sleep c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_EXECUTE (Cur 1 Tot 9) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:650 (sofia/external/sipp@192.168.1.104:5060) State EXECUTE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_sofia.c:198 sofia/external/sipp@192.168.1.104:5060 SOFIA EXECUTE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:328 sofia/external/sipp@192.168.1.104:5060 Standard EXECUTE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 set(outside_call=true) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [outside_call]=[true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 export(RFC2822_DATE=Fri, 28 Apr 2017 08:59:41 +0000) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 28 Apr 2017 08:59:41 +0000] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 info() c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [INFO] mod_dptools.c:1743 CHANNEL_DATA: c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-State: [CS_EXECUTE] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-Call-State: [RINGING] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-State-Number: [4] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-Name: [sofia/external/sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Unique-ID: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Call-Direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Presence-Call-Direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-HIT-Dialplan: [true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-Call-UUID: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Answer-State: [ringing] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Logical-Direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Username: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Dialplan: [XML] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Caller-ID-Name: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Caller-ID-Number: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Orig-Caller-ID-Name: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Orig-Caller-ID-Number: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Network-Addr: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-ANI: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Destination-Number: [1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Unique-ID: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Source: [mod_sofia] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Context: [public] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Name: [sofia/external/sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Profile-Index: [1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Profile-Created-Time: [1493369981831115] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Created-Time: [1493369981831115] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Answered-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Progress-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Progress-Media-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Hangup-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Transfer-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Resurrect-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Bridged-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Last-Hold: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Hold-Accum: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Screen-Bit: [true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Privacy-Hide-Name: [false] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Privacy-Hide-Number: [false] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_uuid: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_session_id: [9] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_user: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_uri: [sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_host: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_video_media_flow: [sendrecv] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_audio_media_flow: [sendrecv] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_channel_name: [sofia/external/sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_call_id: [1-1988@192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_local_network_addr: [172.17.0.3] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_network_ip: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_network_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_received_ip: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_received_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_via_protocol: [udp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_user_stripped: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_tag: [1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sofia_profile_name: [external] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_recovery_profile_name: [external] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_full_via: [SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-0;nosdp=true;out-of-dialog=true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_display: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_full_from: [sipp ;tag=1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_full_to: [] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_req_user: [1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_req_port: [5080] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_req_uri: [1002@172.17.0.3:5080] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_req_host: [172.17.0.3] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_to_user: [1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_to_port: [5080] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_to_uri: [1002@172.17.0.3:5080] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_to_host: [172.17.0.3] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_params: [transport=udp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_user: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_uri: [sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_host: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_rtp_use_codec_string: [OPUS,G722,PCMU,PCMA,VP8] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_subject: [Performance Test] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_via_host: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_via_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_max_forwards: [70] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_endpoint_disposition: [RECEIVED_NOSDP] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_DP_MATCH: [ARRAY::1002|:1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_call_uuid: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_outside_call: [true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_RFC2822_DATE: [Fri, 28 Apr 2017 08:59:41 +0000] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_export_vars: [RFC2822_DATE] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_current_application: [info] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 transfer(1002 XML default) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_ivr.c:2165 (sofia/external/sipp@192.168.1.104:5060) State Change CS_EXECUTE -> CS_ROUTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/sipp@192.168.1.104:5060 to XML[1002@default] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:650 (sofia/external/sipp@192.168.1.104:5060) State EXECUTE going to sleep c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_ROUTING (Cur 1 Tot 9) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:643 (sofia/external/sipp@192.168.1.104:5060) State ROUTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_sofia.c:143 sofia/external/sipp@192.168.1.104:5060 SOFIA ROUTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:236 sofia/external/sipp@192.168.1.104:5060 Standard ROUTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [INFO] mod_dialplan_xml.c:637 Processing sipp ->1002 in context default c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->unloop] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->tod_example] continue=true c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Date/TimeMatch (FAIL) [tod_example] break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->holiday_example] continue=true c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Date/TimeMatch (FAIL) [holiday_example] break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->global-intercept] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [global-intercept] destination_number(1002) =~ /^886$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->group-intercept] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [group-intercept] destination_number(1002) =~ /^\*8$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->intercept-ext] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [intercept-ext] destination_number(1002) =~ /^\*\*(\d+)$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->redial] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [redial] destination_number(1002) =~ /^(redial|870)$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->global] continue=true c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [global] ${call_debug}(true) =~ /^true$/ break=never c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action info() c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [global] ${default_password}(12345) =~ /^1234$/ break=never c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 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 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [global] ${endpoint_disposition}(RECEIVED_NOSDP) =~ /^(DELAYED NEGOTIATION)/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->snom-demo-2] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [snom-demo-2] destination_number(1002) =~ /^9001$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->snom-demo-1] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [snom-demo-1] destination_number(1002) =~ /^9000$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->eavesdrop] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->eavesdrop] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^779$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->call_return] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [call_return] destination_number(1002) =~ /^\*69$|^869$|^lcr$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->del-group] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [del-group] destination_number(1002) =~ /^80(\d{2})$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->add-group] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [add-group] destination_number(1002) =~ /^81(\d{2})$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->call-group-simo] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [call-group-simo] destination_number(1002) =~ /^82(\d{2})$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->call-group-order] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [call-group-order] destination_number(1002) =~ /^83(\d{2})$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->extension-intercom] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [extension-intercom] destination_number(1002) =~ /^8(10[01][0-9])$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->Local_Extension] continue=false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [Local_Extension] destination_number(1002) =~ /^(10[01][0-9])$/ break=on-false c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action export(dialed_extension=1002) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bind_meta_app(1 b s execute_extension::dx XML features) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bind_meta_app(3 b s execute_extension::cf XML features) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(call_timeout=30) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(hangup_after_bridge=true) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(continue_on_fail=true) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(3pcc_always_gen_sdp=true) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bridge(user/${dialed_extension}@${domain_name}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action answer() c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action sleep(1000) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:286 (sofia/external/sipp@192.168.1.104:5060) State Change CS_ROUTING -> CS_EXECUTE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:643 (sofia/external/sipp@192.168.1.104:5060) State ROUTING going to sleep c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_EXECUTE (Cur 1 Tot 9) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:650 (sofia/external/sipp@192.168.1.104:5060) State EXECUTE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_sofia.c:198 sofia/external/sipp@192.168.1.104:5060 SOFIA EXECUTE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_core_state_machine.c:328 sofia/external/sipp@192.168.1.104:5060 Standard EXECUTE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 info() c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [INFO] mod_dptools.c:1743 CHANNEL_DATA: c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-State: [CS_EXECUTE] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-Call-State: [RINGING] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-State-Number: [4] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-Name: [sofia/external/sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Unique-ID: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Call-Direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Presence-Call-Direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-HIT-Dialplan: [true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Channel-Call-UUID: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Answer-State: [ringing] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Logical-Direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Username: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Dialplan: [XML] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Caller-ID-Name: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Caller-ID-Number: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Orig-Caller-ID-Name: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Orig-Caller-ID-Number: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Network-Addr: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-ANI: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Destination-Number: [1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Unique-ID: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Source: [mod_sofia] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Transfer-Source: [1493369981:858cf5c7-117b-4df9-972a-f4afdfecf711:bl_xfer:1002/default/XML] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Context: [default] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-RDNIS: [1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Name: [sofia/external/sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Profile-Index: [2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Profile-Created-Time: [1493369981831115] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Created-Time: [1493369981831115] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Answered-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Progress-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Progress-Media-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Hangup-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Transfer-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Resurrect-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Bridged-Time: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Last-Hold: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Channel-Hold-Accum: [0] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Screen-Bit: [true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Privacy-Hide-Name: [false] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 Caller-Privacy-Hide-Number: [false] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_direction: [inbound] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_uuid: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_session_id: [9] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_user: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_uri: [sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_host: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_video_media_flow: [sendrecv] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_audio_media_flow: [sendrecv] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_channel_name: [sofia/external/sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_call_id: [1-1988@192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_local_network_addr: [172.17.0.3] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_network_ip: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_network_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_received_ip: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_received_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_via_protocol: [udp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_user_stripped: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_tag: [1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sofia_profile_name: [external] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_recovery_profile_name: [external] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_full_via: [SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-0;nosdp=true;out-of-dialog=true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_from_display: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_full_from: [sipp ;tag=1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_full_to: [] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_req_user: [1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_req_port: [5080] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_req_uri: [1002@172.17.0.3:5080] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_req_host: [172.17.0.3] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_to_user: [1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_to_port: [5080] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_to_uri: [1002@172.17.0.3:5080] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_to_host: [172.17.0.3] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_params: [transport=udp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_user: [sipp] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_uri: [sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_contact_host: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_rtp_use_codec_string: [OPUS,G722,PCMU,PCMA,VP8] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_subject: [Performance Test] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_via_host: [192.168.1.104] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_sip_via_port: [5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_endpoint_disposition: [RECEIVED_NOSDP] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_outside_call: [true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_RFC2822_DATE: [Fri, 28 Apr 2017 08:59:41 +0000] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_export_vars: [RFC2822_DATE] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_max_forwards: [69] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_transfer_history: [1493369981:858cf5c7-117b-4df9-972a-f4afdfecf711:bl_xfer:1002/default/XML] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_transfer_source: [1493369981:858cf5c7-117b-4df9-972a-f4afdfecf711:bl_xfer:1002/default/XML] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_DP_MATCH: [ARRAY::1002|:1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_call_uuid: [c514aafe-c9de-45b1-897d-0ddd5fa3f4b2] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 variable_current_application: [info] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 export(dialed_extension=1002) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1002] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 bind_meta_app(1 b s execute_extension::dx XML features) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *1 execute_extension::dx XML features c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/sipp.2017-04-28-08-59-41.wav) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *2 record_session::/var/lib/freeswitch/recordings/sipp.2017-04-28-08-59-41.wav c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 bind_meta_app(3 b s execute_extension::cf XML features) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *3 execute_extension::cf XML features c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 bind_meta_app(4 b s execute_extension::att_xfer XML features) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *4 execute_extension::att_xfer XML features c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 set(call_timeout=30) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [call_timeout]=[30] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 set(hangup_after_bridge=true) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [hangup_after_bridge]=[true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 set(continue_on_fail=true) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.831115 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [continue_on_fail]=[true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-call_return/1002/sipp) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial_ext/1002/c514aafe-c9de-45b1-897d-0ddd5fa3f4b2) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 set(called_party_callgroup=techsupport) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [called_party_callgroup]=[techsupport] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial_ext/techsupport/c514aafe-c9de-45b1-897d-0ddd5fa3f4b2) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial_ext/global/c514aafe-c9de-45b1-897d-0ddd5fa3f4b2) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial/techsupport/c514aafe-c9de-45b1-897d-0ddd5fa3f4b2) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 set(3pcc_always_gen_sdp=true) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [3pcc_always_gen_sdp]=[true] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 EXECUTE sofia/external/sipp@192.168.1.104:5060 bridge(user/1002@172.17.0.3) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 28 Apr 2017 08:59:41 +0000] to event c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [dialed_extension]=[1002] to event c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 28 Apr 2017 08:59:41 +0000] to event c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [dialed_extension]=[1002] to event c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1002@172.17.0.1:15060 [a39555b8-b95f-479f-b480-4601fd615f24] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] mod_sofia.c:4818 (sofia/internal/1002@172.17.0.1:15060) State Change CS_NEW -> CS_INIT a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_INIT (Cur 2 Tot 10) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:41.841115 [NOTICE] switch_ivr_originate.c:2845 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@172.17.0.1:15060) State INIT a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] mod_sofia.c:90 sofia/internal/1002@172.17.0.1:15060 SOFIA INIT a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] sofia_glue.c:1295 sofia/internal/1002@172.17.0.1:15060 sending invite version: 1.6.17 -34-0fc0946 64bit a39555b8-b95f-479f-b480-4601fd615f24 Local SDP: a39555b8-b95f-479f-b480-4601fd615f24 v=0 a39555b8-b95f-479f-b480-4601fd615f24 o=FreeSWITCH 1493337485 1493337486 IN IP4 172.17.0.3 a39555b8-b95f-479f-b480-4601fd615f24 s=FreeSWITCH a39555b8-b95f-479f-b480-4601fd615f24 c=IN IP4 172.17.0.3 a39555b8-b95f-479f-b480-4601fd615f24 t=0 0 a39555b8-b95f-479f-b480-4601fd615f24 m=audio 32496 RTP/AVP 102 9 0 8 104 101 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:102 opus/48000/2 a39555b8-b95f-479f-b480-4601fd615f24 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:9 G722/8000 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:0 PCMU/8000 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:8 PCMA/8000 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:104 telephone-event/48000 a39555b8-b95f-479f-b480-4601fd615f24 a=fmtp:104 0-16 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:101 telephone-event/8000 a39555b8-b95f-479f-b480-4601fd615f24 a=fmtp:101 0-16 a39555b8-b95f-479f-b480-4601fd615f24 a=ptime:20 a39555b8-b95f-479f-b480-4601fd615f24 a=sendrecv a39555b8-b95f-479f-b480-4601fd615f24 m=video 18064 RTP/AVP 103 a39555b8-b95f-479f-b480-4601fd615f24 b=AS:1024 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:103 VP8/90000 a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:103 ccm fir a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:103 ccm tmmbr a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:103 nack a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:103 nack pli a39555b8-b95f-479f-b480-4601fd615f24 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1002@172.17.0.1:15060 Standard INIT a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1002@172.17.0.1:15060) State Change CS_INIT -> CS_ROUTING a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@172.17.0.1:15060) State INIT going to sleep a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_ROUTING (Cur 2 Tot 10) a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@172.17.0.1:15060) State ROUTING a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] mod_sofia.c:143 sofia/internal/1002@172.17.0.1:15060 SOFIA ROUTING a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1002@172.17.0.1:15060) State Change CS_ROUTING -> CS_CONSUME_MEDIA a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@172.17.0.1:15060) State ROUTING going to sleep send 1549 bytes to udp/[172.17.0.1]:15060 at 08:59:41.845256: ------------------------------------------------------------------------ INVITE sip:1002@172.17.0.1:15060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKKtB7Dgr6DtZaN Max-Forwards: 68 From: "sipp" ;tag=Q2gmU46vre09H To: Call-ID: dbbbf1c8-a693-1235-0e9b-0242ac110003 CSeq: 106348926 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: sessiona39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 10) Content-Length: 617 X-FS-Support: update_display,send_info Remote-Party-ID: "sipp" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1493337485 1493337486 IN IP4 172.17.0.3 s=FreeSWITCH c=IN IP4 172.17.0.3 t=0 0 m=audio 32496 RTP/AVP 102 9 0 8 104 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:104 telephone-event/48000 a=fmtp:104 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 18064 RTP/AVP 103 b=AS:1024 a=rtpmap:103 VP8/90000 a=rtcp-fb:103 ccm fir a=rtcp-fb:103 ccm tmmbr a=rtcp-fb:103 nack a=rtcp-fb:103 nack pli ------------------------------------------------------------------------ a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@172.17.0.1:15060 entering state [calling][0] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1002@172.17.0.1:15060) State CONSUME_MEDIA a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.841115 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1002@172.17.0.1:15060) State CONSUME_MEDIA going to sleep recv 257 bytes from udp/[172.17.0.1]:15060 at 08:59:41.866749: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKKtB7Dgr6DtZaN From: "sipp" ;tag=Q2gmU46vre09H To: Call-ID: dbbbf1c8-a693-1235-0e9b-0242ac110003 CSeq: 106348926 INVITE ------------------------------------------------------------------------ recv 348 bytes from udp/[172.17.0.1]:15060 at 08:59:41.883124: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKKtB7Dgr6DtZaN From: "sipp" ;tag=Q2gmU46vre09H To: ;tag=p4j0hb7 Call-ID: dbbbf1c8-a693-1235-0e9b-0242ac110003 CSeq: 106348926 INVITE User-Agent: Linphone/3.11.1 (belle-sip/1.6.1) Supported: replaces, outbound ------------------------------------------------------------------------ a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:41.881123 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@172.17.0.1:15060 entering state [proceeding][180] recv 905 bytes from udp/[172.17.0.1]:15060 at 08:59:50.246067: ------------------------------------------------------------------------ SIP/2.0 200 Ok Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKKtB7Dgr6DtZaN From: "sipp" ;tag=Q2gmU46vre09H To: ;tag=p4j0hb7 Call-ID: dbbbf1c8-a693-1235-0e9b-0242ac110003 CSeq: 106348926 INVITE User-Agent: Linphone/3.11.1 (belle-sip/1.6.1) Supported: replaces, outbound Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE Contact: ;+sip.instance="" Content-Type: application/sdp Content-Length: 303 v=0 o=1002 701 51 IN IP4 172.17.0.1 s=Talk c=IN IP4 172.17.0.1 t=0 0 m=audio 7078 RTP/AVP 0 8 101 a=rtpmap:101 telephone-event/8000 m=video 9076 RTP/AVP 103 a=rtpmap:103 VP8/90000 a=rtcp-fb:* trr-int 5000 a=rtcp-fb:* nack a=rtcp-fb:* ccm tmmbr a=rtcp-fb:103 nack pli a=rtcp-fb:103 ccm fir ------------------------------------------------------------------------ a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.241114 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@172.17.0.1:15060 entering state [completing][200] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.241114 [DEBUG] sofia.c:7058 Remote SDP: a39555b8-b95f-479f-b480-4601fd615f24 v=0 a39555b8-b95f-479f-b480-4601fd615f24 o=1002 701 51 IN IP4 172.17.0.1 a39555b8-b95f-479f-b480-4601fd615f24 s=Talk a39555b8-b95f-479f-b480-4601fd615f24 c=IN IP4 172.17.0.1 a39555b8-b95f-479f-b480-4601fd615f24 t=0 0 a39555b8-b95f-479f-b480-4601fd615f24 m=audio 7078 RTP/AVP 0 8 101 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:101 telephone-event/8000 a39555b8-b95f-479f-b480-4601fd615f24 m=video 9076 RTP/AVP 103 a39555b8-b95f-479f-b480-4601fd615f24 a=rtpmap:103 VP8/90000 a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:* trr-int 5000 a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:* nack a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:* ccm tmmbr a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:103 nack pli a39555b8-b95f-479f-b480-4601fd615f24 a=rtcp-fb:103 ccm fir a39555b8-b95f-479f-b480-4601fd615f24 send 378 bytes to udp/[172.17.0.1]:15060 at 08:59:50.249818: ------------------------------------------------------------------------ ACK sip:1002@172.17.0.1:15060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKm34ZFB99a3NXg Max-Forwards: 70 From: "sipp" ;tag=Q2gmU46vre09H To: ;tag=p4j0hb7 Call-ID: dbbbf1c8-a693-1235-0e9b-0242ac110003 CSeq: 106348926 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@172.17.0.1:15060 entering state [ready][200] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/1002@172.17.0.1:15060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_codec.c:111 sofia/internal/1002@172.17.0.1:15060 Original read codec set to PCMU:0 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4754 sofia/internal/1002@172.17.0.1:15060 Set 2833 dtmf send payload to 101 recv payload to 101 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4937 Video Codec Compare [VP8:103]/[VP8:99] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:4969 Video Codec Compare [VP8:103] +++ is saved as a match 2017-04-28 08:59:50.251119 [DEBUG] switch_vpx.c:627 VPX VER:v1.6.0 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:7 2017-04-28 08:59:50.251119 [DEBUG] switch_vpx.c:627 VPX VER:v1.6.0 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:7 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:2866 Set VIDEO Codec sofia/internal/1002@172.17.0.1:15060 VP8/90000 0 ms a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/1002@172.17.0.1:15060] 172.17.0.3 port 32496 -> 172.17.0.1 port 7078 codec: 0 ms: 20 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:7166 sofia/internal/1002@172.17.0.1:15060 Set 2833 dtmf send payload to 101 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:7173 sofia/internal/1002@172.17.0.1:15060 Set 2833 dtmf receive payload to 101 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:7196 sofia/internal/1002@172.17.0.1:15060 Set rtp dtmf delay to 40 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_rtp.c:4107 Starting video timer. a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:7385 VIDEO RTP [sofia/internal/1002@172.17.0.1:15060] 172.17.0.3:18064->172.17.0.1:9076 codec: 103 ms: 0 [SUCCESS] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:5990 sofia/internal/1002@172.17.0.1:15060 Starting Video thread 2017-04-28 08:59:50.251119 [DEBUG] switch_core_media.c:5856 sofia/internal/1002@172.17.0.1:15060 Video thread started. Echo is off a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [INFO] switch_core_media.c:7465 Activating VIDEO RTCP PORT 9077 interval 1000 mux -1 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_rtp.c:4488 RTCP send rate is: 1000 and packet rate is: 90000 Remote Port: 9077 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_rtp.c:2560 Setting RTCP remote addr to 172.17.0.1:9077 2 a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [NOTICE] sofia.c:8182 Channel [sofia/internal/1002@172.17.0.1:15060] has been answered a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.251119 [DEBUG] switch_channel.c:3772 (sofia/internal/1002@172.17.0.1:15060) Callstate Change DOWN -> ACTIVE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.263332 [DEBUG] mod_sofia.c:790 3PCC-PROXY, Sent a 200 OK, waiting for ACK send 1284 bytes to udp/[192.168.1.104]:5060 at 08:59:50.269280: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-0;nosdp=true;out-of-dialog=true From: sipp ;tag=1 To: ;tag=ND882pjeBXeQH Call-ID: 1-1988@192.168.1.104 CSeq: 1 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Session-Expires: 1800;refresher=uas Content-Type: application/sdp Content-Disposition: session Content-Length: 617 v=0 o=FreeSWITCH 1493349136 1493349137 IN IP4 172.17.0.3 s=FreeSWITCH c=IN IP4 172.17.0.3 t=0 0 m=audio 20854 RTP/AVP 102 9 0 8 103 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 19190 RTP/AVP 103 b=AS:1024 a=rtpmap:103 VP8/90000 a=rtcp-fb:103 ccm fir a=rtcp-fb:103 ccm tmmbr a=rtcp-fb:103 nack a=rtcp-fb:103 nack pli ------------------------------------------------------------------------ c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.263332 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [completed][200] recv 572 bytes from udp/[192.168.1.104]:5060 at 08:59:50.274616: ------------------------------------------------------------------------ ACK sip:mod_sofia@172.17.0.3:5080 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-4 From: sipp ;tag=1 To: ;tag=ND882pjeBXeQH Call-ID: 1-1988@192.168.1.104 CSeq: 1 ACK Contact: Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 171 v=0 o=ipjib 1492600869292 1492600869292 IN IP4 192.168.1.104 s=wms c=IN IP4 192.168.1.104 t=0 0 m=audio 6000 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv ------------------------------------------------------------------------ c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [ready][200] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] sofia.c:7058 Remote SDP: c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 v=0 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 o=ipjib 1492600869292 1492600869292 IN IP4 192.168.1.104 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 s=wms c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 c=IN IP4 192.168.1.104 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 t=0 0 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 m=audio 6000 RTP/AVP 0 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 a=rtpmap:0 PCMU/8000 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 a=ptime:20 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:3056 Set Codec sofia/external/sipp@192.168.1.104:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_codec.c:111 sofia/external/sipp@192.168.1.104:5060 Original read codec set to PCMU:0 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:4725 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:4754 sofia/external/sipp@192.168.1.104:5060 Set 2833 dtmf send payload to 101 recv payload to 101 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/external/sipp@192.168.1.104:5060] 172.17.0.3 port 20854 -> 192.168.1.104 port 6000 codec: 0 ms: 20 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:7166 sofia/external/sipp@192.168.1.104:5060 Set 2833 dtmf send payload to 101 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:7173 sofia/external/sipp@192.168.1.104:5060 Set 2833 dtmf receive payload to 101 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_core_media.c:7196 sofia/external/sipp@192.168.1.104:5060 Set rtp dtmf delay to 40 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [NOTICE] sofia.c:8182 Channel [sofia/external/sipp@192.168.1.104:5060] has been answered c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_channel.c:3772 (sofia/external/sipp@192.168.1.104:5060) Callstate Change RINGING -> ACTIVE c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] sofia.c:8191 3PCC-PROXY, Got my ACK c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] mod_sofia.c:808 3PCC-PROXY, Done waiting for ACK c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1002@172.17.0.1:15060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.271103 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1002@172.17.0.1:15060] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.281108 [DEBUG] switch_ivr_bridge.c:1601 (sofia/internal/1002@172.17.0.1:15060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.281108 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 10) a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.281108 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1002@172.17.0.1:15060) State EXCHANGE_MEDIA a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.281108 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.331105 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.361105 [DEBUG] switch_rtp.c:6679 Correct video RTCP ip/port confirmed. a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:50.371107 [NOTICE] switch_vpx.c:402 VPX reset encoder picture from 320x240 to 352x288 1024 BW recv 627 bytes from udp/[192.168.1.104]:5060 at 08:59:50.776894: ------------------------------------------------------------------------ INVITE sip:mod_sofia@172.17.0.3:5080 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-6 From: sipp ;tag=1 To: ;tag=ND882pjeBXeQH Call-ID: 1-1988@192.168.1.104 CSeq: 2 INVITE Contact: Max-Forwards: 70 Subject: Performance Test Session-Expires: 1800 Min-SE: 900 Content-Length: 215 v=0 o=ipjib 1492600869292 1492600869294 IN IP4 192.168.1.104 s=Basic Session c=IN IP4 192.168.1.104 t=0 0 m=audio 6000 RTP/AVP 0 8 18 99 a=rtpmap:99 telephone-event/8000 a=fmtp:99 0-15 a=fmtp:18 annexb=yes ------------------------------------------------------------------------ send 911 bytes to udp/[192.168.1.104]:5060 at 08:59:50.777648: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-6 From: sipp ;tag=1 To: ;tag=ND882pjeBXeQH Call-ID: 1-1988@192.168.1.104 CSeq: 2 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Session-Expires: 1800;refresher=uas Content-Type: application/sdp Content-Disposition: session Content-Length: 319 v=0 o=FreeSWITCH 1493349136 1493349138 IN IP4 172.17.0.3 s=FreeSWITCH c=IN IP4 172.17.0.3 t=0 0 m=audio 20854 RTP/AVP 0 8 103 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:103 telephone-event/48000 a=fmtp:103 0-16 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 0 RTP/AVP 19 ------------------------------------------------------------------------ recv 406 bytes from udp/[192.168.1.104]:5060 at 08:59:50.778254: ------------------------------------------------------------------------ ACK sip:mod_sofia@172.17.0.3:5080 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-1988-1-10 From: sipp ;tag=1 To: sut ;tag=ND882pjeBXeQH Call-ID: 1-1988@192.168.1.104 CSeq: 2 ACK Contact: Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 0 ------------------------------------------------------------------------ c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [completed][200] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] sofia.c:7058 Remote SDP: c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 v=0 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 o=ipjib 1492600869292 1492600869294 IN IP4 192.168.1.104 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 s=Basic Session c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 c=IN IP4 192.168.1.104 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 t=0 0 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 m=audio 6000 RTP/AVP 0 8 18 99 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 a=fmtp:18 annexb=yes c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 a=rtpmap:99 telephone-event/8000 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 a=fmtp:99 0-15 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 99@8000 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 99@8000 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:4754 sofia/external/sipp@192.168.1.104:5060 Set 2833 dtmf send payload to 99 recv payload to 99 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/external/sipp@192.168.1.104:5060. c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] sofia.c:7963 Processing updated SDP c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:50.791167 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [ready][200] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:51.031123 [DEBUG] switch_rtp.c:1885 rtcp_stats_init: video ssrc[985159765] base_seq[0] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:51.081126 [DEBUG] switch_rtp.c:7229 Correct video ip/port confirmed. recv 331 bytes from udp/[172.17.0.1]:15060 at 08:59:56.693337: ------------------------------------------------------------------------ BYE sip:mod_sofia@172.17.0.3:5060 SIP/2.0 Via: SIP/2.0/UDP 172.17.0.1:15060;branch=z9hG4bK.VTfhChwLa;rport From: ;tag=p4j0hb7 To: "sipp" ;tag=Q2gmU46vre09H CSeq: 111 BYE Call-ID: dbbbf1c8-a693-1235-0e9b-0242ac110003 Max-Forwards: 70 User-Agent: Linphone/3.11.1 (belle-sip/1.6.1) ------------------------------------------------------------------------ a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [NOTICE] sofia.c:1012 Hangup sofia/internal/1002@172.17.0.1:15060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] send 466 bytes to udp/[172.17.0.1]:15060 at 08:59:56.713853: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.17.0.1:15060;branch=z9hG4bK.VTfhChwLa;rport=15060 From: ;tag=p4j0hb7 To: "sipp" ;tag=Q2gmU46vre09H Call-ID: dbbbf1c8-a693-1235-0e9b-0242ac110003 CSeq: 111 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/1002@172.17.0.1:15060] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_media.c:11605 sofia/internal/1002@172.17.0.1:15060 skip receive message [VIDEO_REFRESH_REQ] (channel is hungup already) a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1002@172.17.0.1:15060) State EXCHANGE_MEDIA going to sleep a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_HANGUP (Cur 2 Tot 10) a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1002@172.17.0.1:15060) Callstate Change ACTIVE -> HANGUP a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@172.17.0.1:15060) State HANGUP a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1002@172.17.0.1:15060 hanging up, cause: NORMAL_CLEARING a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@172.17.0.1:15060 Standard HANGUP, cause: NORMAL_CLEARING a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@172.17.0.1:15060) State HANGUP going to sleep a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1002@172.17.0.1:15060) State Change CS_HANGUP -> CS_REPORTING a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_REPORTING (Cur 2 Tot 10) a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@172.17.0.1:15060) State REPORTING a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1002@172.17.0.1:15060 Standard REPORTING, cause: NORMAL_CLEARING a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@172.17.0.1:15060) State REPORTING going to sleep a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1002@172.17.0.1:15060) State Change CS_REPORTING -> CS_DESTROY a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_session.c:1664 Session 10 (sofia/internal/1002@172.17.0.1:15060) Locked, Waiting on external entities c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/external/sipp@192.168.1.104:5060] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [NOTICE] switch_ivr_bridge.c:1751 Hangup sofia/external/sipp@192.168.1.104:5060 [CS_EXECUTE] [NORMAL_CLEARING] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_session.c:2814 sofia/external/sipp@192.168.1.104:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:650 (sofia/external/sipp@192.168.1.104:5060) State EXECUTE going to sleep c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_HANGUP (Cur 2 Tot 10) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:850 (sofia/external/sipp@192.168.1.104:5060) Callstate Change ACTIVE -> HANGUP c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:852 (sofia/external/sipp@192.168.1.104:5060) State HANGUP c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] mod_sofia.c:432 sofia/external/sipp@192.168.1.104:5060 Overriding SIP cause 480 with 200 from the other leg c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] mod_sofia.c:438 Channel sofia/external/sipp@192.168.1.104:5060 hanging up, cause: NORMAL_CLEARING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/external/sipp@192.168.1.104:5060 c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:60 sofia/external/sipp@192.168.1.104:5060 Standard HANGUP, cause: NORMAL_CLEARING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:852 (sofia/external/sipp@192.168.1.104:5060) State HANGUP going to sleep c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:619 (sofia/external/sipp@192.168.1.104:5060) State Change CS_HANGUP -> CS_REPORTING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_REPORTING (Cur 2 Tot 10) send 541 bytes to udp/[192.168.1.104]:5060 at 08:59:56.718214: ------------------------------------------------------------------------ BYE sip:sipp@192.168.1.104:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.17.0.3:5080;rport;branch=z9hG4bKN5XtmKjQrrS3p Max-Forwards: 70 From: ;tag=ND882pjeBXeQH To: sipp ;tag=1 Call-ID: 1-1988@192.168.1.104 CSeq: 106348934 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFYc514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:938 (sofia/external/sipp@192.168.1.104:5060) State REPORTING Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:174 sofia/external/sipp@192.168.1.104:5060 Standard REPORTING, cause: NORMAL_CLEARING c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:938 (sofia/external/sipp@192.168.1.104:5060) State REPORTING going to sleep recv 255 bytes from udp/[192.168.1.104]:5060 at 08:59:56.718368: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.17.0.3:5080;rport;branch=z9hG4bKN5XtmKjQrrS3p From: ;tag=ND882pjeBXeQH To: sipp ;tag=1 Call-ID: 1-1988@192.168.1.104 CSeq: 106348934 BYE Content-Length: 0 ------------------------------------------------------------------------ c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:610 (sofia/external/sipp@192.168.1.104:5060) State Change CS_REPORTING -> CS_DESTROY c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_session.c:1664 Session 9 (sofia/external/sipp@192.168.1.104:5060) Locked, Waiting on external entities c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [NOTICE] switch_core_session.c:1682 Session 9 (sofia/external/sipp@192.168.1.104:5060) Ended c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [NOTICE] switch_core_session.c:1686 Close Channel sofia/external/sipp@192.168.1.104:5060 [CS_DESTROY] c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:741 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_DESTROY (Cur 1 Tot 10) c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:751 (sofia/external/sipp@192.168.1.104:5060) State DESTROY c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] mod_sofia.c:343 sofia/external/sipp@192.168.1.104:5060 SOFIA DESTROY c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:181 sofia/external/sipp@192.168.1.104:5060 Standard DESTROY c514aafe-c9de-45b1-897d-0ddd5fa3f4b2 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:751 (sofia/external/sipp@192.168.1.104:5060) State DESTROY going to sleep 2017-04-28 08:59:56.711226 [DEBUG] switch_core_media.c:5957 sofia/internal/1002@172.17.0.1:15060 Video thread ended a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [NOTICE] switch_core_session.c:1682 Session 10 (sofia/internal/1002@172.17.0.1:15060) Ended a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1002@172.17.0.1:15060 [CS_DESTROY] a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_DESTROY (Cur 0 Tot 10) a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@172.17.0.1:15060) State DESTROY a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] mod_sofia.c:343 sofia/internal/1002@172.17.0.1:15060 SOFIA DESTROY a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1002@172.17.0.1:15060 Standard DESTROY a39555b8-b95f-479f-b480-4601fd615f24 2017-04-28 08:59:56.711226 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@172.17.0.1:15060) State DESTROY going to sleep 2017-04-28 09:00:04.351110 [NOTICE] mod_cdr_csv.c:123 Rotated CDR logfile /var/log/freeswitch/cdr-csv/Master.csv