2017-04-28 09:02:12.761114 [NOTICE] mod_cdr_csv.c:123 Rotated CDR logfile /var/log/freeswitch/cdr-csv/1002.csv 2017-04-28 09:02:12.761114 [NOTICE] mod_logfile.c:192 New log started. recv 604 bytes from udp/[192.168.1.104]:5060 at 09:02:26.780895: ------------------------------------------------------------------------ INVITE sip:1002@172.17.0.3:5080 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-0 From: sipp ;tag=1 To: Call-ID: 1-5963@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 287 bytes to udp/[192.168.1.104]:5060 at 09:02:26.781391: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-0 From: sipp ;tag=1 To: Call-ID: 1-5963@192.168.1.104 CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Content-Length: 0 ------------------------------------------------------------------------ b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.771120 [NOTICE] switch_channel.c:1104 New Channel sofia/external/sipp@192.168.1.104:5060 [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_NEW (Cur 1 Tot 11) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [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 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [received][100] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] sofia.c:7058 Remote SDP: b67498b9-31db-433a-b901-5c12546ffc1a v=0 b67498b9-31db-433a-b901-5c12546ffc1a o=ipjib 1492600869292 1492600869294 IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a s=Basic Session b67498b9-31db-433a-b901-5c12546ffc1a c=IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a t=0 0 b67498b9-31db-433a-b901-5c12546ffc1a m=audio 6000 RTP/AVP 0 8 18 99 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:18 annexb=yes b67498b9-31db-433a-b901-5c12546ffc1a a=rtpmap:99 telephone-event/8000 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:99 0-15 b67498b9-31db-433a-b901-5c12546ffc1a b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] sofia.c:7450 (sofia/external/sipp@192.168.1.104:5060) State Change CS_NEW -> CS_INIT b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:603 (sofia/external/sipp@192.168.1.104:5060) State NEW b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_INIT (Cur 1 Tot 11) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:627 (sofia/external/sipp@192.168.1.104:5060) State INIT b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] mod_sofia.c:90 sofia/external/sipp@192.168.1.104:5060 SOFIA INIT b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:40 sofia/external/sipp@192.168.1.104:5060 Standard INIT b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:48 (sofia/external/sipp@192.168.1.104:5060) State Change CS_INIT -> CS_ROUTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:627 (sofia/external/sipp@192.168.1.104:5060) State INIT going to sleep b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_ROUTING (Cur 1 Tot 11) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_channel.c:2249 (sofia/external/sipp@192.168.1.104:5060) Callstate Change DOWN -> RINGING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:643 (sofia/external/sipp@192.168.1.104:5060) State ROUTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] mod_sofia.c:143 sofia/external/sipp@192.168.1.104:5060 SOFIA ROUTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:236 sofia/external/sipp@192.168.1.104:5060 Standard ROUTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [INFO] mod_dialplan_xml.c:637 Processing sipp ->1002 in context public b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [public->unloop] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [public->outside_call] continue=true b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Absolute Condition [outside_call] b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(outside_call=true) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [public->call_debug] continue=true b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [call_debug] ${call_debug}(true) =~ /^true$/ break=never b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action info() b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [public->public_extensions] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [public_extensions] destination_number(1002) =~ /^(10[01][0-9])$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action transfer(1002 XML default) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:286 (sofia/external/sipp@192.168.1.104:5060) State Change CS_ROUTING -> CS_EXECUTE b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:643 (sofia/external/sipp@192.168.1.104:5060) State ROUTING going to sleep b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_EXECUTE (Cur 1 Tot 11) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:650 (sofia/external/sipp@192.168.1.104:5060) State EXECUTE b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] mod_sofia.c:198 sofia/external/sipp@192.168.1.104:5060 SOFIA EXECUTE b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:328 sofia/external/sipp@192.168.1.104:5060 Standard EXECUTE b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 set(outside_call=true) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [outside_call]=[true] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 export(RFC2822_DATE=Fri, 28 Apr 2017 09:02:26 +0000) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 28 Apr 2017 09:02:26 +0000] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 info() b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [INFO] mod_dptools.c:1743 CHANNEL_DATA: b67498b9-31db-433a-b901-5c12546ffc1a Channel-State: [CS_EXECUTE] b67498b9-31db-433a-b901-5c12546ffc1a Channel-Call-State: [RINGING] b67498b9-31db-433a-b901-5c12546ffc1a Channel-State-Number: [4] b67498b9-31db-433a-b901-5c12546ffc1a Channel-Name: [sofia/external/sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a Unique-ID: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a Call-Direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a Presence-Call-Direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a Channel-HIT-Dialplan: [true] b67498b9-31db-433a-b901-5c12546ffc1a Channel-Call-UUID: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a Answer-State: [ringing] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Logical-Direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Username: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Dialplan: [XML] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Caller-ID-Name: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Caller-ID-Number: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Orig-Caller-ID-Name: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Orig-Caller-ID-Number: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Network-Addr: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a Caller-ANI: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Destination-Number: [1002] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Unique-ID: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Source: [mod_sofia] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Context: [public] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Name: [sofia/external/sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Profile-Index: [1] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Profile-Created-Time: [1493370146782570] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Created-Time: [1493370146782570] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Answered-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Progress-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Progress-Media-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Hangup-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Transfer-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Resurrect-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Bridged-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Last-Hold: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Hold-Accum: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Screen-Bit: [true] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Privacy-Hide-Name: [false] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Privacy-Hide-Number: [false] b67498b9-31db-433a-b901-5c12546ffc1a variable_direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a variable_uuid: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a variable_session_id: [11] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_user: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_uri: [sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_host: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_video_media_flow: [sendrecv] b67498b9-31db-433a-b901-5c12546ffc1a variable_audio_media_flow: [sendrecv] b67498b9-31db-433a-b901-5c12546ffc1a variable_channel_name: [sofia/external/sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_call_id: [1-5963@192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_ep_codec_string: [CORE_PCM_MODULE.PCMU@8000h@20i@64000b,CORE_PCM_MODULE.PCMA@8000h@20i@64000b] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_local_network_addr: [172.17.0.3] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_network_ip: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_network_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_received_ip: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_received_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_via_protocol: [udp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_user_stripped: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_tag: [1] b67498b9-31db-433a-b901-5c12546ffc1a variable_sofia_profile_name: [external] b67498b9-31db-433a-b901-5c12546ffc1a variable_recovery_profile_name: [external] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_full_via: [SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-0] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_display: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_full_from: [sipp ;tag=1] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_full_to: [] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_req_user: [1002] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_req_port: [5080] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_req_uri: [1002@172.17.0.3:5080] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_req_host: [172.17.0.3] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_to_user: [1002] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_to_port: [5080] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_to_uri: [1002@172.17.0.3:5080] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_to_host: [172.17.0.3] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_params: [transport=udp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_user: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_uri: [sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_host: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_rtp_use_codec_string: [OPUS,G722,PCMU,PCMA,VP8] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_subject: [Performance Test] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_via_host: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_via_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_max_forwards: [70] b67498b9-31db-433a-b901-5c12546ffc1a variable_switch_r_sdp: [v=0 b67498b9-31db-433a-b901-5c12546ffc1a o=ipjib 1492600869292 1492600869294 IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a s=Basic Session b67498b9-31db-433a-b901-5c12546ffc1a c=IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a t=0 0 b67498b9-31db-433a-b901-5c12546ffc1a m=audio 6000 RTP/AVP 0 8 18 99 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:18 annexb=yes b67498b9-31db-433a-b901-5c12546ffc1a a=rtpmap:99 telephone-event/8000 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:99 0-15 b67498b9-31db-433a-b901-5c12546ffc1a ] b67498b9-31db-433a-b901-5c12546ffc1a variable_endpoint_disposition: [DELAYED NEGOTIATION] b67498b9-31db-433a-b901-5c12546ffc1a variable_DP_MATCH: [ARRAY::1002|:1002] b67498b9-31db-433a-b901-5c12546ffc1a variable_call_uuid: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a variable_outside_call: [true] b67498b9-31db-433a-b901-5c12546ffc1a variable_RFC2822_DATE: [Fri, 28 Apr 2017 09:02:26 +0000] variable_export_vars: [RFC2822_DATE] variable_current_application: [info] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 transfer(1002 XML default) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_ivr.c:2165 (sofia/external/sipp@192.168.1.104:5060) State Change CS_EXECUTE -> CS_ROUTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/sipp@192.168.1.104:5060 to XML[1002@default] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:650 (sofia/external/sipp@192.168.1.104:5060) State EXECUTE going to sleep b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_ROUTING (Cur 1 Tot 11) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:643 (sofia/external/sipp@192.168.1.104:5060) State ROUTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] mod_sofia.c:143 sofia/external/sipp@192.168.1.104:5060 SOFIA ROUTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:236 sofia/external/sipp@192.168.1.104:5060 Standard ROUTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [INFO] mod_dialplan_xml.c:637 Processing sipp ->1002 in context default b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->unloop] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->tod_example] continue=true b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Date/Time Match (PASS) [tod_example] break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(open=true) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->holiday_example] continue=true b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Date/TimeMatch (FAIL) [holiday_example] break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->global-intercept] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [global-intercept] destination_number(1002) =~ /^886$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->group-intercept] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [group-intercept] destination_number(1002) =~ /^\*8$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->intercept-ext] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [intercept-ext] destination_number(1002) =~ /^\*\*(\d+)$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->redial] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [redial] destination_number(1002) =~ /^(redial|870)$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->global] continue=true b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [global] ${call_debug}(true) =~ /^true$/ break=never b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action info() b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [global] ${default_password}(12345) =~ /^1234$/ break=never b67498b9-31db-433a-b901-5c12546ffc1a 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 b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [global] ${switch_r_sdp}(v=0 b67498b9-31db-433a-b901-5c12546ffc1a o=ipjib 1492600869292 1492600869294 IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a s=Basic Session b67498b9-31db-433a-b901-5c12546ffc1a c=IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a t=0 0 b67498b9-31db-433a-b901-5c12546ffc1a m=audio 6000 RTP/AVP 0 8 18 99 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:18 annexb=yes b67498b9-31db-433a-b901-5c12546ffc1a a=rtpmap:99 telephone-event/8000 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:99 0-15 b67498b9-31db-433a-b901-5c12546ffc1a ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Absolute Condition [global] b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial/global/${uuid}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->snom-demo-2] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [snom-demo-2] destination_number(1002) =~ /^9001$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->snom-demo-1] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [snom-demo-1] destination_number(1002) =~ /^9000$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->eavesdrop] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->eavesdrop] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^779$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->call_return] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [call_return] destination_number(1002) =~ /^\*69$|^869$|^lcr$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->del-group] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [del-group] destination_number(1002) =~ /^80(\d{2})$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->add-group] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [add-group] destination_number(1002) =~ /^81(\d{2})$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->call-group-simo] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [call-group-simo] destination_number(1002) =~ /^82(\d{2})$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->call-group-order] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [call-group-order] destination_number(1002) =~ /^83(\d{2})$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->extension-intercom] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (FAIL) [extension-intercom] destination_number(1002) =~ /^8(10[01][0-9])$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 parsing [default->Local_Extension] continue=false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Regex (PASS) [Local_Extension] destination_number(1002) =~ /^(10[01][0-9])$/ break=on-false b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action export(dialed_extension=1002) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bind_meta_app(1 b s execute_extension::dx XML features) b67498b9-31db-433a-b901-5c12546ffc1a 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) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bind_meta_app(3 b s execute_extension::cf XML features) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(call_timeout=30) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(hangup_after_bridge=true) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(continue_on_fail=true) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action set(3pcc_always_gen_sdp=true) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bridge(user/${dialed_extension}@${domain_name}) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action answer() b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action sleep(1000) b67498b9-31db-433a-b901-5c12546ffc1a Dialplan: sofia/external/sipp@192.168.1.104:5060 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:286 (sofia/external/sipp@192.168.1.104:5060) State Change CS_ROUTING -> CS_EXECUTE b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:643 (sofia/external/sipp@192.168.1.104:5060) State ROUTING going to sleep b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_EXECUTE (Cur 1 Tot 11) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:650 (sofia/external/sipp@192.168.1.104:5060) State EXECUTE b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] mod_sofia.c:198 sofia/external/sipp@192.168.1.104:5060 SOFIA EXECUTE b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_core_state_machine.c:328 sofia/external/sipp@192.168.1.104:5060 Standard EXECUTE b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 set(open=true) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [open]=[true] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 info() b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [INFO] mod_dptools.c:1743 CHANNEL_DATA: b67498b9-31db-433a-b901-5c12546ffc1a Channel-State: [CS_EXECUTE] b67498b9-31db-433a-b901-5c12546ffc1a Channel-Call-State: [RINGING] b67498b9-31db-433a-b901-5c12546ffc1a Channel-State-Number: [4] b67498b9-31db-433a-b901-5c12546ffc1a Channel-Name: [sofia/external/sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a Unique-ID: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a Call-Direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a Presence-Call-Direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a Channel-HIT-Dialplan: [true] b67498b9-31db-433a-b901-5c12546ffc1a Channel-Call-UUID: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a Answer-State: [ringing] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Logical-Direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Username: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Dialplan: [XML] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Caller-ID-Name: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Caller-ID-Number: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Orig-Caller-ID-Name: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Orig-Caller-ID-Number: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Network-Addr: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a Caller-ANI: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Destination-Number: [1002] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Unique-ID: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Source: [mod_sofia] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Transfer-Source: [1493370146:2180249a-d415-4991-8c10-41e208af4467:bl_xfer:1002/default/XML] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Context: [default] b67498b9-31db-433a-b901-5c12546ffc1a Caller-RDNIS: [1002] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Name: [sofia/external/sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Profile-Index: [2] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Profile-Created-Time: [1493370146782570] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Created-Time: [1493370146782570] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Answered-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Progress-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Progress-Media-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Hangup-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Transfer-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Resurrect-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Bridged-Time: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Last-Hold: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Channel-Hold-Accum: [0] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Screen-Bit: [true] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Privacy-Hide-Name: [false] b67498b9-31db-433a-b901-5c12546ffc1a Caller-Privacy-Hide-Number: [false] b67498b9-31db-433a-b901-5c12546ffc1a variable_direction: [inbound] b67498b9-31db-433a-b901-5c12546ffc1a variable_uuid: [b67498b9-31db-433a-b901-5c12546ffc1a] b67498b9-31db-433a-b901-5c12546ffc1a variable_session_id: [11] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_user: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_uri: [sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_host: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_video_media_flow: [sendrecv] b67498b9-31db-433a-b901-5c12546ffc1a variable_audio_media_flow: [sendrecv] b67498b9-31db-433a-b901-5c12546ffc1a variable_channel_name: [sofia/external/sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_call_id: [1-5963@192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_ep_codec_string: [CORE_PCM_MODULE.PCMU@8000h@20i@64000b,CORE_PCM_MODULE.PCMA@8000h@20i@64000b] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_local_network_addr: [172.17.0.3] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_network_ip: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_network_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_received_ip: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_received_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_via_protocol: [udp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_user_stripped: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_tag: [1] b67498b9-31db-433a-b901-5c12546ffc1a variable_sofia_profile_name: [external] b67498b9-31db-433a-b901-5c12546ffc1a variable_recovery_profile_name: [external] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_full_via: [SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-0] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_from_display: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_full_from: [sipp ;tag=1] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_full_to: [] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_req_user: [1002] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_req_port: [5080] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_req_uri: [1002@172.17.0.3:5080] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_req_host: [172.17.0.3] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_to_user: [1002] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_to_port: [5080] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_to_uri: [1002@172.17.0.3:5080] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_to_host: [172.17.0.3] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_params: [transport=udp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_user: [sipp] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_uri: [sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_contact_host: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_rtp_use_codec_string: [OPUS,G722,PCMU,PCMA,VP8] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_subject: [Performance Test] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_via_host: [192.168.1.104] b67498b9-31db-433a-b901-5c12546ffc1a variable_sip_via_port: [5060] b67498b9-31db-433a-b901-5c12546ffc1a variable_switch_r_sdp: [v=0 b67498b9-31db-433a-b901-5c12546ffc1a o=ipjib 1492600869292 1492600869294 IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a s=Basic Session b67498b9-31db-433a-b901-5c12546ffc1a c=IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a t=0 0 b67498b9-31db-433a-b901-5c12546ffc1a m=audio 6000 RTP/AVP 0 8 18 99 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:18 annexb=yes b67498b9-31db-433a-b901-5c12546ffc1a a=rtpmap:99 telephone-event/8000 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:99 0-15 b67498b9-31db-433a-b901-5c12546ffc1a ] b67498b9-31db-433a-b901-5c12546ffc1a variable_endpoint_disposition: [DELAYED NEGOTIATION] b67498b9-31db-433a-b901-5c12546ffc1a variable_outside_call: [true] b67498b9-31db-433a-b901-5c12546ffc1a variable_RFC2822_DATE: [Fri, 28 Apr 2017 09:02:26 +0000] b67498b9-31db-433a-b901-5c12546ffc1a variable_export_vars: [RFC2822_DATE] variable_max_forwards: [69] variable_transfer_history: [1493370146:2180249a-d415-4991-8c10-41e208af4467:bl_xfer:1002/default/XML] variable_transfer_source: [1493370146:2180249a-d415-4991-8c10-41e208af4467:bl_xfer:1002/default/XML] variable_DP_MATCH: [ARRAY::1002|:1002] variable_call_uuid: [b67498b9-31db-433a-b901-5c12546ffc1a] variable_open: [true] variable_current_application: [info] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-spymap/sipp/b67498b9-31db-433a-b901-5c12546ffc1a) b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial/sipp/1002) b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial/global/b67498b9-31db-433a-b901-5c12546ffc1a) b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 export(RFC2822_DATE=Fri, 28 Apr 2017 09:02:26 +0000) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 28 Apr 2017 09:02:26 +0000] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 export(dialed_extension=1002) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.782570 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1002] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 bind_meta_app(1 b s execute_extension::dx XML features) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *1 execute_extension::dx XML features b67498b9-31db-433a-b901-5c12546ffc1a 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-09-02-26.wav) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *2 record_session::/var/lib/freeswitch/recordings/sipp.2017-04-28-09-02-26.wav b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 bind_meta_app(3 b s execute_extension::cf XML features) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *3 execute_extension::cf XML features b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 bind_meta_app(4 b s execute_extension::att_xfer XML features) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *4 execute_extension::att_xfer XML features b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 set(call_timeout=30) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [call_timeout]=[30] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 set(hangup_after_bridge=true) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [hangup_after_bridge]=[true] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 set(continue_on_fail=true) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [continue_on_fail]=[true] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-call_return/1002/sipp) b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial_ext/1002/b67498b9-31db-433a-b901-5c12546ffc1a) b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 set(called_party_callgroup=techsupport) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [called_party_callgroup]=[techsupport] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial_ext/techsupport/b67498b9-31db-433a-b901-5c12546ffc1a) b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial_ext/global/b67498b9-31db-433a-b901-5c12546ffc1a) b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 hash(insert/172.17.0.3-last_dial/techsupport/b67498b9-31db-433a-b901-5c12546ffc1a) b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 set(3pcc_always_gen_sdp=true) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] mod_dptools.c:1530 SET sofia/external/sipp@192.168.1.104:5060 [3pcc_always_gen_sdp]=[true] b67498b9-31db-433a-b901-5c12546ffc1a EXECUTE sofia/external/sipp@192.168.1.104:5060 bridge(user/1002@172.17.0.3) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 28 Apr 2017 09:02:26 +0000] to event b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 28 Apr 2017 09:02:26 +0000] to event b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [dialed_extension]=[1002] to event b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 28 Apr 2017 09:02:26 +0000] to event b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 28 Apr 2017 09:02:26 +0000] to event b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] switch_channel.c:1250 sofia/external/sipp@192.168.1.104:5060 EXPORTING[export_vars] [dialed_extension]=[1002] to event b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1002@172.17.0.1:15060 [597aefe7-3040-4d8a-9ddf-c0a0a02eb028] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] mod_sofia.c:4818 (sofia/internal/1002@172.17.0.1:15060) State Change CS_NEW -> CS_INIT 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_INIT (Cur 2 Tot 12) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.791102 [NOTICE] switch_ivr_originate.c:2845 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@172.17.0.1:15060) State INIT 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] mod_sofia.c:90 sofia/internal/1002@172.17.0.1:15060 SOFIA INIT 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] sofia_glue.c:1295 sofia/internal/1002@172.17.0.1:15060 sending invite version: 1.6.17 -34-0fc0946 64bit 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 Local SDP: 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 v=0 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 o=FreeSWITCH 1493346454 1493346455 IN IP4 172.17.0.3 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 s=FreeSWITCH 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 c=IN IP4 172.17.0.3 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 t=0 0 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 m=audio 23692 RTP/AVP 0 8 101 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 a=rtpmap:0 PCMU/8000 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 a=rtpmap:8 PCMA/8000 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 a=rtpmap:101 telephone-event/8000 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 a=fmtp:101 0-16 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 a=ptime:20 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 a=sendrecv 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1002@172.17.0.1:15060 Standard INIT 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1002@172.17.0.1:15060) State Change CS_INIT -> CS_ROUTING 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@172.17.0.1:15060) State INIT going to sleep 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_ROUTING (Cur 2 Tot 12) send 1172 bytes to udp/[172.17.0.1]:15060 at 09:02:26.796066: ------------------------------------------------------------------------ INVITE sip:1002@172.17.0.1:15060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKNcyrH6SD8Bcgc Max-Forwards: 68 From: "sipp" ;tag=rBaDXZQ0NQpvD To: Call-ID: 3e0d7216-a694-1235-0e9b-0242ac110003 CSeq: 106349009 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: session Content-Length: 240 X-FS-Support: update_display,send_info Remote-Party-ID: "sipp" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1493346454 1493346455 IN IP4 172.17.0.3 s=FreeSWITCH c=IN IP4 172.17.0.3 t=0 0 m=audio 23692 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@172.17.0.1:15060 entering state [calling][0] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@172.17.0.1:15060) State ROUTING 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] mod_sofia.c:143 sofia/internal/1002@172.17.0.1:15060 SOFIA ROUTING 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1002@172.17.0.1:15060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@172.17.0.1:15060) State ROUTING going to sleep 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 12) 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1002@172.17.0.1:15060) State CONSUME_MEDIA 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.791102 [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 09:02:26.823639: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKNcyrH6SD8Bcgc From: "sipp" ;tag=rBaDXZQ0NQpvD To: Call-ID: 3e0d7216-a694-1235-0e9b-0242ac110003 CSeq: 106349009 INVITE ------------------------------------------------------------------------ recv 348 bytes from udp/[172.17.0.1]:15060 at 09:02:26.842451: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKNcyrH6SD8Bcgc From: "sipp" ;tag=rBaDXZQ0NQpvD To: ;tag=dHv2qIq Call-ID: 3e0d7216-a694-1235-0e9b-0242ac110003 CSeq: 106349009 INVITE User-Agent: Linphone/3.11.1 (belle-sip/1.6.1) Supported: replaces, outbound ------------------------------------------------------------------------ 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.841111 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@172.17.0.1:15060 entering state [proceeding][180] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.841111 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/1002@172.17.0.1:15060! 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:26.841111 [DEBUG] switch_channel.c:3345 (sofia/internal/1002@172.17.0.1:15060) Callstate Change DOWN -> RINGING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.851101 [NOTICE] mod_sofia.c:2272 Ring-Ready sofia/external/sipp@192.168.1.104:5060! send 634 bytes to udp/[192.168.1.104]:5060 at 09:02:26.857032: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-0 From: sipp ;tag=1 To: ;tag=pp114H3H8549c Call-ID: 1-5963@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 Allow-Events: talk, hold, conference, refer Content-Length: 0 Remote-Party-ID: "1002" ;party=calling;privacy=off;screen=no ------------------------------------------------------------------------ b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.851101 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [early][180] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:26.851101 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/external/sipp@192.168.1.104:5060! recv 744 bytes from udp/[172.17.0.1]:15060 at 09:02:33.267901: ------------------------------------------------------------------------ SIP/2.0 200 Ok Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKNcyrH6SD8Bcgc From: "sipp" ;tag=rBaDXZQ0NQpvD To: ;tag=dHv2qIq Call-ID: 3e0d7216-a694-1235-0e9b-0242ac110003 CSeq: 106349009 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: 142 v=0 o=1002 2302 3120 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 ------------------------------------------------------------------------ 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@172.17.0.1:15060 entering state [completing][200] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] sofia.c:7058 Remote SDP: 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 v=0 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 o=1002 2302 3120 IN IP4 172.17.0.1 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 s=Talk 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 c=IN IP4 172.17.0.1 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 t=0 0 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 m=audio 7078 RTP/AVP 0 8 101 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 a=rtpmap:101 telephone-event/8000 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 send 378 bytes to udp/[172.17.0.1]:15060 at 09:02:33.269338: ------------------------------------------------------------------------ ACK sip:1002@172.17.0.1:15060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 172.17.0.3;rport;branch=z9hG4bKpNQHK1aH5m22Q Max-Forwards: 70 From: "sipp" ;tag=rBaDXZQ0NQpvD To: ;tag=dHv2qIq Call-ID: 3e0d7216-a694-1235-0e9b-0242ac110003 CSeq: 106349009 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] sofia.c:7048 Channel sofia/internal/1002@172.17.0.1:15060 entering state [ready][200] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 101@8000 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [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 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_codec.c:111 sofia/internal/1002@172.17.0.1:15060 Original read codec set to PCMU:0 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 101@8000 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [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 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/1002@172.17.0.1:15060] 172.17.0.3 port 23692 -> 172.17.0.1 port 7078 codec: 0 ms: 20 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.261129 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.271108 [DEBUG] switch_core_media.c:7166 sofia/internal/1002@172.17.0.1:15060 Set 2833 dtmf send payload to 101 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.271108 [DEBUG] switch_core_media.c:7173 sofia/internal/1002@172.17.0.1:15060 Set 2833 dtmf receive payload to 101 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.271108 [DEBUG] switch_core_media.c:7196 sofia/internal/1002@172.17.0.1:15060 Set rtp dtmf delay to 40 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.271108 [NOTICE] sofia.c:8182 Channel [sofia/internal/1002@172.17.0.1:15060] has been answered 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.271108 [DEBUG] switch_channel.c:3772 (sofia/internal/1002@172.17.0.1:15060) Callstate Change RINGING -> ACTIVE b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 99@8000 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [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 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_codec.c:111 sofia/external/sipp@192.168.1.104:5060 Original read codec set to PCMU:0 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 99@8000 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [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 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/external/sipp@192.168.1.104:5060] 172.17.0.3 port 21658 -> 192.168.1.104 port 6000 codec: 0 ms: 20 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.281116 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] switch_core_media.c:7166 sofia/external/sipp@192.168.1.104:5060 Set 2833 dtmf send payload to 99 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] switch_core_media.c:7173 sofia/external/sipp@192.168.1.104:5060 Set 2833 dtmf receive payload to 99 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] switch_core_media.c:7196 sofia/external/sipp@192.168.1.104:5060 Set rtp dtmf delay to 40 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/sipp@192.168.1.104:5060! b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] switch_channel.c:3473 (sofia/external/sipp@192.168.1.104:5060) Callstate Change RINGING -> EARLY b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/external/sipp@192.168.1.104:5060. b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] mod_sofia.c:850 Local SDP sofia/external/sipp@192.168.1.104:5060: b67498b9-31db-433a-b901-5c12546ffc1a v=0 b67498b9-31db-433a-b901-5c12546ffc1a o=FreeSWITCH 1493348495 1493348496 IN IP4 172.17.0.3 b67498b9-31db-433a-b901-5c12546ffc1a s=FreeSWITCH b67498b9-31db-433a-b901-5c12546ffc1a c=IN IP4 172.17.0.3 b67498b9-31db-433a-b901-5c12546ffc1a t=0 0 b67498b9-31db-433a-b901-5c12546ffc1a m=audio 21658 RTP/AVP 0 99 b67498b9-31db-433a-b901-5c12546ffc1a a=rtpmap:0 PCMU/8000 b67498b9-31db-433a-b901-5c12546ffc1a a=rtpmap:99 telephone-event/8000 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:99 0-16 b67498b9-31db-433a-b901-5c12546ffc1a a=ptime:20 b67498b9-31db-433a-b901-5c12546ffc1a a=sendrecv b67498b9-31db-433a-b901-5c12546ffc1a b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [NOTICE] switch_ivr_originate.c:3632 Channel [sofia/external/sipp@192.168.1.104:5060] has been answered send 926 bytes to udp/[192.168.1.104]:5060 at 09:02:33.292962: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-0 From: sipp ;tag=1 To: ;tag=pp114H3H8549c Call-ID: 1-5963@192.168.1.104 CSeq: 2 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 Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Session-Expires: 1800;refresher=uas Content-Type: application/sdp Content-Disposition: session Content-Length: 213 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1493348495 1493348496 IN IP4 172.17.0.3 s=FreeSWITCH c=IN IP4 172.17.0.3 t=0 0 m=audio 21658 RTP/AVP 0 99 a=rtpmap:0 PCMU/8000 a=rtpmap:99 telephone-event/8000 a=fmtp:99 0-16 a=ptime:20 ------------------------------------------------------------------------ recv 414 bytes from udp/[192.168.1.104]:5060 at 09:02:33.293255: ------------------------------------------------------------------------ ACK sip:1002@172.17.0.3:5080;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-5 From: sipp ;tag=1 To: sut ;tag=pp114H3H8549c Call-ID: 1-5963@192.168.1.104 CSeq: 2 ACK Contact: Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 0 ------------------------------------------------------------------------ b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] switch_channel.c:3772 (sofia/external/sipp@192.168.1.104:5060) Callstate Change EARLY -> ACTIVE b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [completed][200] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [ready][200] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1002@172.17.0.1:15060] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.291105 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1002@172.17.0.1:15060] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.291105 [DEBUG] switch_ivr_bridge.c:1601 (sofia/internal/1002@172.17.0.1:15060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.291105 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 12) 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.291105 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1002@172.17.0.1:15060) State EXCHANGE_MEDIA 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.291105 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:33.321105 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. recv 636 bytes from udp/[192.168.1.104]:5060 at 09:02:33.796706: ------------------------------------------------------------------------ INVITE sip:1002@172.17.0.3:5080;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-7 From: sipp ;tag=1 To: ;tag=pp114H3H8549c Call-ID: 1-5963@192.168.1.104 CSeq: 4 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 305 bytes to udp/[192.168.1.104]:5060 at 09:02:33.796975: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-7 From: sipp ;tag=1 To: ;tag=pp114H3H8549c Call-ID: 1-5963@192.168.1.104 CSeq: 4 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Content-Length: 0 ------------------------------------------------------------------------ b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [received][100] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] sofia.c:7055 Duplicate SDP b67498b9-31db-433a-b901-5c12546ffc1a v=0 b67498b9-31db-433a-b901-5c12546ffc1a o=ipjib 1492600869292 1492600869294 IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a s=Basic Session b67498b9-31db-433a-b901-5c12546ffc1a c=IN IP4 192.168.1.104 b67498b9-31db-433a-b901-5c12546ffc1a t=0 0 b67498b9-31db-433a-b901-5c12546ffc1a m=audio 6000 RTP/AVP 0 8 18 99 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:18 annexb=yes b67498b9-31db-433a-b901-5c12546ffc1a a=rtpmap:99 telephone-event/8000 b67498b9-31db-433a-b901-5c12546ffc1a a=fmtp:99 0-15 b67498b9-31db-433a-b901-5c12546ffc1a b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4352 Set telephone-event payload to 99@8000 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [DEBUG] switch_core_media.c:4695 Set telephone-event payload to 99@8000 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.801109 [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 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.811106 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/external/sipp@192.168.1.104:5060. b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.811106 [DEBUG] sofia.c:7963 Processing updated SDP send 814 bytes to udp/[192.168.1.104]:5060 at 09:02:33.811351: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-7 From: sipp ;tag=1 To: ;tag=pp114H3H8549c Call-ID: 1-5963@192.168.1.104 CSeq: 4 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: 213 v=0 o=FreeSWITCH 1493348495 1493348496 IN IP4 172.17.0.3 s=FreeSWITCH c=IN IP4 172.17.0.3 t=0 0 m=audio 21658 RTP/AVP 0 99 a=rtpmap:0 PCMU/8000 a=rtpmap:99 telephone-event/8000 a=fmtp:99 0-16 a=ptime:20 ------------------------------------------------------------------------ recv 415 bytes from udp/[192.168.1.104]:5060 at 09:02:33.811696: ------------------------------------------------------------------------ ACK sip:1002@172.17.0.3:5080;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.104:5060;branch=z9hG4bK-5963-1-11 From: sipp ;tag=1 To: sut ;tag=pp114H3H8549c Call-ID: 1-5963@192.168.1.104 CSeq: 4 ACK Contact: Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 0 ------------------------------------------------------------------------ b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.821101 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [completed][200] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:33.821101 [DEBUG] sofia.c:7048 Channel sofia/external/sipp@192.168.1.104:5060 entering state [ready][200] recv 331 bytes from udp/[172.17.0.1]:15060 at 09:02:41.915681: ------------------------------------------------------------------------ BYE sip:mod_sofia@172.17.0.3:5060 SIP/2.0 Via: SIP/2.0/UDP 172.17.0.1:15060;branch=z9hG4bK.Wz0dMShp9;rport From: ;tag=dHv2qIq To: "sipp" ;tag=rBaDXZQ0NQpvD CSeq: 111 BYE Call-ID: 3e0d7216-a694-1235-0e9b-0242ac110003 Max-Forwards: 70 User-Agent: Linphone/3.11.1 (belle-sip/1.6.1) ------------------------------------------------------------------------ 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.921103 [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 09:02:41.931136: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.17.0.1:15060;branch=z9hG4bK.Wz0dMShp9;rport=15060 From: ;tag=dHv2qIq To: "sipp" ;tag=rBaDXZQ0NQpvD Call-ID: 3e0d7216-a694-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 ------------------------------------------------------------------------ 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/1002@172.17.0.1:15060] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1002@172.17.0.1:15060) State EXCHANGE_MEDIA going to sleep 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_HANGUP (Cur 2 Tot 12) 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1002@172.17.0.1:15060) Callstate Change ACTIVE -> HANGUP 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@172.17.0.1:15060) State HANGUP 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1002@172.17.0.1:15060 hanging up, cause: NORMAL_CLEARING 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@172.17.0.1:15060 Standard HANGUP, cause: NORMAL_CLEARING 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@172.17.0.1:15060) State HANGUP going to sleep 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1002@172.17.0.1:15060) State Change CS_HANGUP -> CS_REPORTING 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_REPORTING (Cur 2 Tot 12) 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@172.17.0.1:15060) State REPORTING 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1002@172.17.0.1:15060 Standard REPORTING, cause: NORMAL_CLEARING 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@172.17.0.1:15060) State REPORTING going to sleep 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1002@172.17.0.1:15060) State Change CS_REPORTING -> CS_DESTROY 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.931100 [DEBUG] switch_core_session.c:1664 Session 12 (sofia/internal/1002@172.17.0.1:15060) Locked, Waiting on external entities b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.941125 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/external/sipp@192.168.1.104:5060] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.941125 [NOTICE] switch_ivr_bridge.c:1751 Hangup sofia/external/sipp@192.168.1.104:5060 [CS_EXECUTE] [NORMAL_CLEARING] 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.941125 [NOTICE] switch_core_session.c:1682 Session 12 (sofia/internal/1002@172.17.0.1:15060) Ended 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.941125 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1002@172.17.0.1:15060 [CS_DESTROY] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_session.c:2814 sofia/external/sipp@192.168.1.104:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:650 (sofia/external/sipp@192.168.1.104:5060) State EXECUTE going to sleep b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_HANGUP (Cur 1 Tot 12) 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1002@172.17.0.1:15060) Running State Change CS_DESTROY (Cur 1 Tot 12) 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@172.17.0.1:15060) State DESTROY 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.951145 [DEBUG] mod_sofia.c:343 sofia/internal/1002@172.17.0.1:15060 SOFIA DESTROY b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:850 (sofia/external/sipp@192.168.1.104:5060) Callstate Change ACTIVE -> HANGUP 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1002@172.17.0.1:15060 Standard DESTROY 597aefe7-3040-4d8a-9ddf-c0a0a02eb028 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@172.17.0.1:15060) State DESTROY going to sleep b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:852 (sofia/external/sipp@192.168.1.104:5060) State HANGUP b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] mod_sofia.c:432 sofia/external/sipp@192.168.1.104:5060 Overriding SIP cause 480 with 200 from the other leg b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] mod_sofia.c:438 Channel sofia/external/sipp@192.168.1.104:5060 hanging up, cause: NORMAL_CLEARING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/external/sipp@192.168.1.104:5060 b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:60 sofia/external/sipp@192.168.1.104:5060 Standard HANGUP, cause: NORMAL_CLEARING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:852 (sofia/external/sipp@192.168.1.104:5060) State HANGUP going to sleep b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:619 (sofia/external/sipp@192.168.1.104:5060) State Change CS_HANGUP -> CS_REPORTING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:584 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_REPORTING (Cur 1 Tot 12) send 541 bytes to udp/[192.168.1.104]:5060 at 09:02:41.951802: ------------------------------------------------------------------------ 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=z9hG4bKpeQKpe3tN1Fpj Max-Forwards: 70b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:938 (sofia/external/sipp@192.168.1.104:5060) State REPORTING From: ;tag=pp114H3H8549c To: sipp ;tag=1 Call-ID: 1-5963@192.168.1.104 CSeq: 106349016 BYE User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:174 sofia/external/sipp@192.168.1.104:5060 Standard REPORTING, cause: NORMAL_CLEARING b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [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 09:02:41.951994: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.17.0.3:5080;rport;branch=z9hG4bKpeQKpe3tN1Fpj From: ;tag=pp114H3H8549c To: sipp ;tag=1 Call-ID: 1-5963@192.168.1.104 CSeq: 106349016 BYE Content-Length: 0 ------------------------------------------------------------------------ b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:610 (sofia/external/sipp@192.168.1.104:5060) State Change CS_REPORTING -> CS_DESTROY b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_session.c:1664 Session 11 (sofia/external/sipp@192.168.1.104:5060) Locked, Waiting on external entities b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [NOTICE] switch_core_session.c:1682 Session 11 (sofia/external/sipp@192.168.1.104:5060) Ended b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [NOTICE] switch_core_session.c:1686 Close Channel sofia/external/sipp@192.168.1.104:5060 [CS_DESTROY] b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:741 (sofia/external/sipp@192.168.1.104:5060) Running State Change CS_DESTROY (Cur 0 Tot 12) b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:751 (sofia/external/sipp@192.168.1.104:5060) State DESTROY b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] mod_sofia.c:343 sofia/external/sipp@192.168.1.104:5060 SOFIA DESTROY b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:181 sofia/external/sipp@192.168.1.104:5060 Standard DESTROY b67498b9-31db-433a-b901-5c12546ffc1a 2017-04-28 09:02:41.951145 [DEBUG] switch_core_state_machine.c:751 (sofia/external/sipp@192.168.1.104:5060) State DESTROY going to sleep 2017-04-28 09:02:51.461114 [NOTICE] mod_cdr_csv.c:123 Rotated CDR logfile /var/log/freeswitch/cdr-csv/Master.csv