freeswitch@freeswitch> recv 1170 bytes from udp/[192.168.1.213]:5060 at 18:47:12.095185: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.8;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bK20c45d64e8611c93 From: ;tag=e6075687f1077b96 To: Contact: Supported: replaces, timer, path Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12674 INVITE User-Agent: Grandstream GXV3000 1.2.3.7 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Type: application/sdp Content-Length: 577 v=0 o=1010 8000 8000 IN IP4 192.168.1.213 s=SIP Call c=IN IP4 192.168.1.213 t=0 0 m=audio 5004 RTP/AVP 0 8 4 18 3 2 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=rtpmap:3 GSM/8000 a=rtpmap:2 G726-32/8000 a=ptime:20 m=video 5006 RTP/AVP 99 34 103 a=sendrecv a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== a=rtpmap:34 H263/90000 a=fmtp:34 CIF=2 MaxBR=1280 a=rtpmap:103 H263-1998/90000 a=fmtp:103 CIF=2 MaxBR=1280 a=framerate:15 ------------------------------------------------------------------------ send 345 bytes to udp/[192.168.1.213]:5060 at 18:47:12.095733: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bK20c45d64e8611c93 From: ;tag=e6075687f1077b96 To: Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12674 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:12.088131 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1010@192.168.1.8 [870e01be-202b-4efb-971a-3a5c695b3fbc] 2017-05-08 18:47:12.088131 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_NEW (Cur 1 Tot 17) 2017-05-08 18:47:12.088131 [DEBUG] sofia.c:9834 sofia/internal/1010@192.168.1.8 receiving invite from 192.168.1.213:5060 version: 1.6.17 -34-0fc0946 64bit 2017-05-08 18:47:12.088131 [DEBUG] sofia.c:10005 IP 192.168.1.213 Rejected by acl "domains". Falling back to Digest auth. send 847 bytes to udp/[192.168.1.213]:5060 at 18:47:12.097608: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bK20c45d64e8611c93 From: ;tag=e6075687f1077b96 To: ;tag=DpgKjQ6SN56tD Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12674 INVITE 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, 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 Proxy-Authenticate: Digest realm="192.168.1.8", nonce="17336329-8f64-49ab-a570-29b61951bb71", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:12.088131 [DEBUG] sofia.c:2334 detaching session 870e01be-202b-4efb-971a-3a5c695b3fbc 2017-05-08 18:47:12.098181 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1010@192.168.1.8) State NEW recv 538 bytes from udp/[192.168.1.213]:5060 at 18:47:12.100254: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.8;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bK20c45d64e8611c93 From: ;tag=e6075687f1077b96 To: ;tag=DpgKjQ6SN56tD Contact: Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12674 ACK User-Agent: Grandstream GXV3000 1.2.3.7 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Length: 0 ------------------------------------------------------------------------ recv 1431 bytes from udp/[192.168.1.213]:5060 at 18:47:12.102192: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.8;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bKc7a637844fe10960 From: ;tag=e6075687f1077b96 To: Contact: Supported: replaces, timer, path Proxy-Authorization: Digest username="1010", realm="192.168.1.8", algorithm=MD5, uri="sip:1001@192.168.1.8;user=phone", qop=auth, nc=00000001, cnonce="6482f0d5e6f12940", nonce="17336329-8f64-49ab-a570-29b61951bb71", response="c024ac1f5e0ccc59d82c73d3397a30ad" Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12675 INVITE User-Agent: Grandstream GXV3000 1.2.3.7 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Type: application/sdp Content-Length: 577 v=0 o=1010 8000 8001 IN IP4 192.168.1.213 s=SIP Call c=IN IP4 192.168.1.213 t=0 0 m=audio 5004 RTP/AVP 0 8 4 18 3 2 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=rtpmap:3 GSM/8000 a=rtpmap:2 G726-32/8000 a=ptime:20 m=video 5006 RTP/AVP 99 34 103 a=sendrecv a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== a=rtpmap:34 H263/90000 a=fmtp:34 CIF=2 MaxBR=1280 a=rtpmap:103 H263-1998/90000 a=fmtp:103 CIF=2 MaxBR=1280 a=framerate:15 ------------------------------------------------------------------------ send 345 bytes to udp/[192.168.1.213]:5060 at 18:47:12.102693: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bKc7a637844fe10960 From: ;tag=e6075687f1077b96 To: Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12675 INVITE User-Agent: FreeSWITCH-mod_sofia/1.6.17-34-0fc0946~64bit Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:12.098181 [DEBUG] sofia.c:2442 Re-attaching to session 870e01be-202b-4efb-971a-3a5c695b3fbc 2017-05-08 18:47:12.118205 [DEBUG] sofia.c:9834 sofia/internal/1010@192.168.1.8 receiving invite from 192.168.1.213:5060 version: 1.6.17 -34-0fc0946 64bit 2017-05-08 18:47:12.118205 [DEBUG] sofia.c:10005 IP 192.168.1.213 Rejected by acl "domains". Falling back to Digest auth. 2017-05-08 18:47:12.118205 [DEBUG] sofia.c:7048 Channel sofia/internal/1010@192.168.1.8 entering state [received][100] 2017-05-08 18:47:12.118205 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=1010 8000 8001 IN IP4 192.168.1.213 s=SIP Call c=IN IP4 192.168.1.213 t=0 0 m=audio 5004 RTP/AVP 0 8 4 18 3 2 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=rtpmap:3 GSM/8000 a=rtpmap:2 G726-32/8000 a=ptime:20 m=video 5006 RTP/AVP 99 34 103 a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== a=rtpmap:34 H263/90000 a=fmtp:34 CIF=2 MaxBR=1280 a=rtpmap:103 H263-1998/90000 a=fmtp:103 CIF=2 MaxBR=1280 a=framerate:15 2017-05-08 18:47:12.118205 [DEBUG] sofia.c:7450 (sofia/internal/1010@192.168.1.8) State Change CS_NEW -> CS_INIT 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_INIT (Cur 1 Tot 17) 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1010@192.168.1.8) State INIT 2017-05-08 18:47:12.118205 [DEBUG] mod_sofia.c:90 sofia/internal/1010@192.168.1.8 SOFIA INIT 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1010@192.168.1.8 Standard INIT 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1010@192.168.1.8) State Change CS_INIT -> CS_ROUTING 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1010@192.168.1.8) State INIT going to sleep 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_ROUTING (Cur 1 Tot 17) 2017-05-08 18:47:12.118205 [DEBUG] switch_channel.c:2249 (sofia/internal/1010@192.168.1.8) Callstate Change DOWN -> RINGING 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1010@192.168.1.8) State ROUTING 2017-05-08 18:47:12.118205 [DEBUG] mod_sofia.c:143 sofia/internal/1010@192.168.1.8 SOFIA ROUTING 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1010@192.168.1.8 Standard ROUTING 2017-05-08 18:47:12.118205 [INFO] mod_dialplan_xml.c:637 Processing 1010 <1010>->1001 in context default Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->unloop] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1010@192.168.1.8 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1010@192.168.1.8 Action set(open=true) Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1010@192.168.1.8 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->redial] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->global] continue=true Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global] ${default_password}() =~ /^1234$/ break=never Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never Dialplan: sofia/internal/1010@192.168.1.8 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [global] ${switch_r_sdp}(v=0 o=1010 8000 8001 IN IP4 192.168.1.213 s=SIP Call c=IN IP4 192.168.1.213 t=0 0 m=audio 5004 RTP/AVP 0 8 4 18 3 2 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=rtpmap:3 GSM/8000 a=rtpmap:2 G726-32/8000 a=ptime:20 m=video 5006 RTP/AVP 99 34 103 a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== a=rtpmap:34 H263/90000 a=fmtp:34 CIF=2 MaxBR=1280 a=rtpmap:103 H263-1998/90000 a=fmtp:103 CIF=2 MaxBR=1280 a=framerate:15 ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never Dialplan: sofia/internal/1010@192.168.1.8 Absolute Condition [global] Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1010@192.168.1.8 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->call_return] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->del-group] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->add-group] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1010@192.168.1.8 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1010@192.168.1.8 Action export(dialed_extension=1001) Dialplan: sofia/internal/1010@192.168.1.8 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1010@192.168.1.8 Action bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.mp4) Dialplan: sofia/internal/1010@192.168.1.8 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1010@192.168.1.8 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/internal/1010@192.168.1.8 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1010@192.168.1.8 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1010@192.168.1.8 Action set(call_timeout=30) Dialplan: sofia/internal/1010@192.168.1.8 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1010@192.168.1.8 Action set(continue_on_fail=true) Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1010@192.168.1.8 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/internal/1010@192.168.1.8 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1010@192.168.1.8 Action set(record_file_name=/var/lib/freeswitch/recordings/${strftime(%Y-%m-%d-%H-%M-%S)}_${uuid}.mp4) INLINE EXECUTE sofia/internal/1010@192.168.1.8 set(record_file_name=/var/lib/freeswitch/recordings/2017-05-08-18-47-12_870e01be-202b-4efb-971a-3a5c695b3fbc.mp4) 2017-05-08 18:47:12.118205 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [record_file_name]=[/var/lib/freeswitch/recordings/2017-05-08-18-47-12_870e01be-202b-4efb-971a-3a5c695b3fbc.mp4] Dialplan: sofia/internal/1010@192.168.1.8 Action record_session(${record_file_name}) Dialplan: sofia/internal/1010@192.168.1.8 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1010@192.168.1.8 Action answer() Dialplan: sofia/internal/1010@192.168.1.8 Action sleep(1000) Dialplan: sofia/internal/1010@192.168.1.8 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1010@192.168.1.8) State Change CS_ROUTING -> CS_EXECUTE 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1010@192.168.1.8) State ROUTING going to sleep 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_EXECUTE (Cur 1 Tot 17) 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1010@192.168.1.8) State EXECUTE 2017-05-08 18:47:12.118205 [DEBUG] mod_sofia.c:198 sofia/internal/1010@192.168.1.8 SOFIA EXECUTE 2017-05-08 18:47:12.118205 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1010@192.168.1.8 Standard EXECUTE EXECUTE sofia/internal/1010@192.168.1.8 set(open=true) 2017-05-08 18:47:12.118205 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [open]=[true] EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-spymap/1010/870e01be-202b-4efb-971a-3a5c695b3fbc) EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial/1010/1001) EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial/global/870e01be-202b-4efb-971a-3a5c695b3fbc) EXECUTE sofia/internal/1010@192.168.1.8 export(RFC2822_DATE=Mon, 08 May 2017 18:47:12 -0400) 2017-05-08 18:47:12.118205 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 08 May 2017 18:47:12 -0400] EXECUTE sofia/internal/1010@192.168.1.8 export(dialed_extension=1001) 2017-05-08 18:47:12.118205 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1001] EXECUTE sofia/internal/1010@192.168.1.8 bind_meta_app(1 b s execute_extension::dx XML features) 2017-05-08 18:47:12.118205 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/internal/1010@192.168.1.8 bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/1010.2017-05-08-18-47-12.mp4) 2017-05-08 18:47:12.118205 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *2 record_session::/var/lib/freeswitch/recordings/1010.2017-05-08-18-47-12.mp4 EXECUTE sofia/internal/1010@192.168.1.8 bind_meta_app(3 b s execute_extension::cf XML features) 2017-05-08 18:47:12.118205 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/internal/1010@192.168.1.8 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2017-05-08 18:47:12.118205 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/internal/1010@192.168.1.8 set(ringback=%(2000,4000,440,480)) 2017-05-08 18:47:12.118205 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/internal/1010@192.168.1.8 set(transfer_ringback=local_stream://moh) 2017-05-08 18:47:12.118205 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1010@192.168.1.8 set(call_timeout=30) 2017-05-08 18:47:12.118205 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [call_timeout]=[30] EXECUTE sofia/internal/1010@192.168.1.8 set(hangup_after_bridge=true) 2017-05-08 18:47:12.118205 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [hangup_after_bridge]=[true] EXECUTE sofia/internal/1010@192.168.1.8 set(continue_on_fail=true) 2017-05-08 18:47:12.118205 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [continue_on_fail]=[true] EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-call_return/1001/1010) EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial_ext/1001/870e01be-202b-4efb-971a-3a5c695b3fbc) EXECUTE sofia/internal/1010@192.168.1.8 set(called_party_callgroup=techsupport) 2017-05-08 18:47:12.118205 [DEBUG] mod_dptools.c:1530 SET sofia/internal/1010@192.168.1.8 [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial_ext/techsupport/870e01be-202b-4efb-971a-3a5c695b3fbc) EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial_ext/global/870e01be-202b-4efb-971a-3a5c695b3fbc) EXECUTE sofia/internal/1010@192.168.1.8 hash(insert/192.168.1.8-last_dial/techsupport/870e01be-202b-4efb-971a-3a5c695b3fbc) 2017-05-08 18:47:12.118205 [DEBUG] switch_core_session.c:2646 Application record_session Requires media! pre_answering channel sofia/internal/1010@192.168.1.8 2017-05-08 18:47:12.118205 [INFO] switch_core_session.c:2648 Sending early media 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G723:4:8000:20:6300:1]/[opus:116:48000:20:0:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-32:2:8000:20:0:1]/[opus:116:48000:20:0:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-32:2:8000:20:0:1]/[G722:9:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/1010@192.168.1.8 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-05-08 18:47:12.118205 [DEBUG] switch_core_codec.c:111 sofia/internal/1010@192.168.1.8 Original read codec set to PCMU:0 2017-05-08 18:47:12.118205 [DEBUG] switch_core_media.c:4725 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4754 sofia/internal/1010@192.168.1.8 Set 2833 dtmf send payload to 101 recv payload to 101 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:99]/[VP8:99] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:99]/[H264:99] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4969 Video Codec Compare [H264:99] +++ is saved as a match 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:99]/[H263:34] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H263:34]/[VP8:99] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H263:34]/[H264:99] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H263:34]/[H263:34] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4969 Video Codec Compare [H263:34] +++ is saved as a match 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H263-1998:103]/[VP8:99] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H263-1998:103]/[H264:99] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H263-1998:103]/[H263:34] 2017-05-08 18:47:12.128215 [NOTICE] avcodec.c:1011 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 2017-05-08 18:47:12.128215 [NOTICE] avcodec.c:1011 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:2866 Set VIDEO Codec sofia/internal/1010@192.168.1.8 H264/90000 0 ms 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/1010@192.168.1.8] 192.168.1.8 port 17500 -> 192.168.1.213 port 5004 codec: 0 ms: 20 2017-05-08 18:47:12.128215 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:7166 sofia/internal/1010@192.168.1.8 Set 2833 dtmf send payload to 101 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:7173 sofia/internal/1010@192.168.1.8 Set 2833 dtmf receive payload to 101 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:7196 sofia/internal/1010@192.168.1.8 Set rtp dtmf delay to 40 2017-05-08 18:47:12.128215 [DEBUG] switch_rtp.c:4107 Starting video timer. 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:7385 VIDEO RTP [sofia/internal/1010@192.168.1.8] 192.168.1.8:18138->192.168.1.213:5006 codec: 99 ms: 0 [SUCCESS] 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:5990 sofia/internal/1010@192.168.1.8 Starting Video thread 2017-05-08 18:47:12.128215 [DEBUG] switch_core_media.c:5856 sofia/internal/1010@192.168.1.8 Video thread started. Echo is off 2017-05-08 18:47:12.128215 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1010@192.168.1.8! 2017-05-08 18:47:12.128215 [DEBUG] switch_channel.c:3473 (sofia/internal/1010@192.168.1.8) Callstate Change RINGING -> EARLY 2017-05-08 18:47:12.138439 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/1010@192.168.1.8. 2017-05-08 18:47:12.138439 [DEBUG] switch_core_media.c:7243 Video params are unchanged for sofia/internal/1010@192.168.1.8. 2017-05-08 18:47:12.138439 [DEBUG] mod_sofia.c:2363 Ring SDP: v=0 o=FreeSWITCH 1494266132 1494266133 IN IP4 192.168.1.8 s=FreeSWITCH c=IN IP4 192.168.1.8 t=0 0 m=audio 17500 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 18138 RTP/AVP 99 b=AS:1024 a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== send 1292 bytes to udp/[192.168.1.213]:5060 at 18:47:12.139040: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bKc7a637844fe10960 From: ;tag=e6075687f1077b96 To: ;tag=eZ9BmjQXjeXDS Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12675 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, 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: 380 Remote-Party-ID: "1001" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1494266132 1494266133 IN IP4 192.168.1.8 s=FreeSWITCH c=IN IP4 192.168.1.8 t=0 0 m=audio 17500 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 18138 RTP/AVP 99 b=AS:1024 a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== ------------------------------------------------------------------------ 2017-05-08 18:47:12.138439 [DEBUG] sofia.c:7048 Channel sofia/internal/1010@192.168.1.8 entering state [early][183] EXECUTE sofia/internal/1010@192.168.1.8 record_session(/var/lib/freeswitch/recordings/2017-05-08-18-47-12_870e01be-202b-4efb-971a-3a5c695b3fbc.mp4) 2017-05-08 18:47:12.138439 [DEBUG] avformat.c:1735 sample rate: 8000, channels: 2 2017-05-08 18:47:12.138439 [DEBUG] avformat.c:1840 use video codec: [28] h264 (H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10) 2017-05-08 18:47:12.138439 [WARNING] avformat.c:513 Codec [aac] is experimental feature in libavcodec, never mind 2017-05-08 18:47:12.138439 [ERR] avformat.c:521 Could not open audio codec [aac], error: Invalid argument 2017-05-08 18:47:12.138439 [ERR] switch_ivr_async.c:2550 Error opening /var/lib/freeswitch/recordings/2017-05-08-18-47-12_870e01be-202b-4efb-971a-3a5c695b3fbc.mp4 EXECUTE sofia/internal/1010@192.168.1.8 bridge(user/1001@192.168.1.8) 2017-05-08 18:47:12.138439 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 08 May 2017 18:47:12 -0400] to event 2017-05-08 18:47:12.138439 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2017-05-08 18:47:12.138439 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2017-05-08 18:47:12.138439 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 08 May 2017 18:47:12 -0400] to event 2017-05-08 18:47:12.138439 [DEBUG] switch_channel.c:1250 sofia/internal/1010@192.168.1.8 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2017-05-08 18:47:12.138439 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2017-05-08 18:47:12.138439 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@192.168.1.161:5060 [4bee329f-42cf-4d54-b658-8c90a6ced178] 2017-05-08 18:47:12.138439 [DEBUG] mod_sofia.c:4818 (sofia/internal/1001@192.168.1.161:5060) State Change CS_NEW -> CS_INIT 2017-05-08 18:47:12.138439 [NOTICE] switch_ivr_originate.c:2845 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.161:5060) Running State Change CS_INIT (Cur 2 Tot 18) 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.1.161:5060) State INIT 2017-05-08 18:47:12.138439 [DEBUG] mod_sofia.c:90 sofia/internal/1001@192.168.1.161:5060 SOFIA INIT 2017-05-08 18:47:12.138439 [DEBUG] sofia_glue.c:1295 sofia/internal/1001@192.168.1.161:5060 sending invite version: 1.6.17 -34-0fc0946 64bit Local SDP: v=0 o=FreeSWITCH 1494262960 1494262961 IN IP4 192.168.1.8 s=FreeSWITCH c=IN IP4 192.168.1.8 t=0 0 m=audio 20672 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 24210 RTP/AVP 102 b=AS:1024 a=rtpmap:102 H264/90000 a=fmtp:102 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== a=rtcp-fb:102 ccm fir a=rtcp-fb:102 ccm tmmbr a=rtcp-fb:102 nack a=rtcp-fb:102 nack pli send 1457 bytes to udp/[192.168.1.161]:5060 at 18:47:12.144377: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.161:5060;transport=udp;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.8;rport;branch=z9hG4bKrpytB1FaHgeta Max-Forwards: 69 From: "Extension 1010" ;tag=F824ND80FQK0m To: Call-ID: 1dbfdc70-aee3-1235-77b2-080027de30fb CSeq: 106805752 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: 475 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1010" ;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1494262960 1494262961 IN IP4 192.168.1.8 s=FreeSWITCH c=IN IP4 192.168.1.8 t=0 0 m=audio 20672 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 24210 RTP/AVP 102 b=AS:1024 a=rtpmap:102 H264/90000 a=fmtp:102 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== a=rtcp-fb:102 ccm fir a=rtcp-fb:102 ccm tmmbr a=rtcp-fb:102 nack a=rtcp-fb:102 nack pli ------------------------------------------------------------------------ 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@192.168.1.161:5060 Standard INIT 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@192.168.1.161:5060) State Change CS_INIT -> CS_ROUTING 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.1.161:5060) State INIT going to sleep 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.161:5060) Running State Change CS_ROUTING (Cur 2 Tot 18) 2017-05-08 18:47:12.138439 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@192.168.1.161:5060 entering state [calling][0] 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.161:5060) State ROUTING 2017-05-08 18:47:12.138439 [DEBUG] mod_sofia.c:143 sofia/internal/1001@192.168.1.161:5060 SOFIA ROUTING 2017-05-08 18:47:12.138439 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@192.168.1.161:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.161:5060) State ROUTING going to sleep 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.161:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 18) 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@192.168.1.161:5060) State CONSUME_MEDIA 2017-05-08 18:47:12.138439 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@192.168.1.161:5060) State CONSUME_MEDIA going to sleep recv 342 bytes from udp/[192.168.1.161]:5060 at 18:47:12.148794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.8;rport;branch=z9hG4bKrpytB1FaHgeta From: "Extension 1010" ;tag=F824ND80FQK0m To: Call-ID: 1dbfdc70-aee3-1235-77b2-080027de30fb CSeq: 106805752 INVITE User-Agent: Grandstream GXV3000 1.2.3.7 Content-Length: 0 ------------------------------------------------------------------------ recv 516 bytes from udp/[192.168.1.161]:5060 at 18:47:12.148851: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.8;rport;branch=z9hG4bKrpytB1FaHgeta From: "Extension 1010" ;tag=F824ND80FQK0m To: ;tag=89d037d35ba61306 Call-ID: 1dbfdc70-aee3-1235-77b2-080027de30fb CSeq: 106805752 INVITE User-Agent: Grandstream GXV3000 1.2.3.7 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:12.148168 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@192.168.1.161:5060 entering state [proceeding][180] 2017-05-08 18:47:12.148168 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/1001@192.168.1.161:5060! 2017-05-08 18:47:12.148168 [DEBUG] switch_channel.c:3345 (sofia/internal/1001@192.168.1.161:5060) Callstate Change DOWN -> RINGING 2017-05-08 18:47:12.148168 [INFO] avcodec.c:1069 initializing encoder 352x288 2017-05-08 18:47:12.148168 [DEBUG] avcodec.c:831 NVENC HW CODEC NOT PRESENT 2017-05-08 18:47:12.168487 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. 2017-05-08 18:47:12.168487 [DEBUG] switch_ivr_originate.c:1273 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2017-05-08 18:47:12.168487 [DEBUG] switch_core_codec.c:223 sofia/internal/1010@192.168.1.8 Push codec L16:100 2017-05-08 18:47:12.168487 [DEBUG] switch_ivr_originate.c:1342 Play Ringback Tone [%(2000,4000,440,480)] 2017-05-08 18:47:12.728143 [DEBUG] switch_rtp.c:7229 Correct video ip/port confirmed. recv 924 bytes from udp/[192.168.1.161]:5060 at 18:47:15.520142: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.8;rport;branch=z9hG4bKrpytB1FaHgeta From: "Extension 1010" ;tag=F824ND80FQK0m To: ;tag=89d037d35ba61306 Call-ID: 1dbfdc70-aee3-1235-77b2-080027de30fb CSeq: 106805752 INVITE User-Agent: Grandstream GXV3000 1.2.3.7 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Type: application/sdp Supported: replaces, timer, 100rel, path Content-Length: 338 v=0 o=1001 8000 8000 IN IP4 192.168.1.161 s=SIP Call c=IN IP4 192.168.1.161 t=0 0 m=audio 5004 RTP/AVP 0 a=sendrecv a=rtpmap:0 PCMU/8000 a=ptime:20 m=video 5006 RTP/AVP 102 a=sendrecv a=rtpmap:102 H264/90000 a=fmtp:102 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Eco== a=framerate:15 ------------------------------------------------------------------------ 2017-05-08 18:47:15.518405 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@192.168.1.161:5060 entering state [completing][200] 2017-05-08 18:47:15.518405 [DEBUG] sofia.c:7058 Remote SDP: v=0 o=1001 8000 8000 IN IP4 192.168.1.161 s=SIP Call c=IN IP4 192.168.1.161 t=0 0 m=audio 5004 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 m=video 5006 RTP/AVP 102 a=rtpmap:102 H264/90000 a=fmtp:102 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Eco== a=framerate:15 send 426 bytes to udp/[192.168.1.161]:5060 at 18:47:15.521583: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.161:5060;transport=udp;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.8;rport;branch=z9hG4bKSZQKDv0DeS4cp Max-Forwards: 70 From: "Extension 1010" ;tag=F824ND80FQK0m To: ;tag=89d037d35ba61306 Call-ID: 1dbfdc70-aee3-1235-77b2-080027de30fb CSeq: 106805752 ACK Contact: Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:15.518405 [DEBUG] sofia.c:7048 Channel sofia/internal/1001@192.168.1.161:5060 entering state [ready][200] 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4491 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:3056 Set Codec sofia/internal/1001@192.168.1.161:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2017-05-08 18:47:15.518405 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@192.168.1.161:5060 Original read codec set to PCMU:0 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4725 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4754 sofia/internal/1001@192.168.1.161:5060 Set 2833 dtmf send payload to 101 recv payload to 101 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:102]/[H264:99] 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4980 No matches with FTMP, fallback to ignoring FMTP 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:102]/[H264:99] 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4988 No matches with inherit_codec, fallback to ignoring PT 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4937 Video Codec Compare [H264:102]/[H264:99] 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:4969 Video Codec Compare [H264:102] +++ is saved as a match 2017-05-08 18:47:15.518405 [NOTICE] avcodec.c:1011 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 2017-05-08 18:47:15.518405 [NOTICE] avcodec.c:1011 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:2866 Set VIDEO Codec sofia/internal/1001@192.168.1.161:5060 H264/90000 0 ms 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:6865 AUDIO RTP [sofia/internal/1001@192.168.1.161:5060] 192.168.1.8 port 20672 -> 192.168.1.161 port 5004 codec: 0 ms: 20 2017-05-08 18:47:15.518405 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:7166 sofia/internal/1001@192.168.1.161:5060 Set 2833 dtmf send payload to 101 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:7173 sofia/internal/1001@192.168.1.161:5060 Set 2833 dtmf receive payload to 101 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:7196 sofia/internal/1001@192.168.1.161:5060 Set rtp dtmf delay to 40 2017-05-08 18:47:15.518405 [DEBUG] switch_rtp.c:4107 Starting video timer. 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:7385 VIDEO RTP [sofia/internal/1001@192.168.1.161:5060] 192.168.1.8:24210->192.168.1.161:5006 codec: 102 ms: 0 [SUCCESS] 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:5990 sofia/internal/1001@192.168.1.161:5060 Starting Video thread 2017-05-08 18:47:15.518405 [DEBUG] switch_core_media.c:5856 sofia/internal/1001@192.168.1.161:5060 Video thread started. Echo is off 2017-05-08 18:47:15.528399 [NOTICE] sofia.c:8182 Channel [sofia/internal/1001@192.168.1.161:5060] has been answered 2017-05-08 18:47:15.528399 [DEBUG] switch_channel.c:3772 (sofia/internal/1001@192.168.1.161:5060) Callstate Change RINGING -> ACTIVE 2017-05-08 18:47:15.528399 [DEBUG] switch_core_codec.c:248 sofia/internal/1010@192.168.1.8 Restore previous codec PCMU:0. 2017-05-08 18:47:15.528399 [DEBUG] switch_core_media.c:6848 Audio params are unchanged for sofia/internal/1010@192.168.1.8. 2017-05-08 18:47:15.528399 [DEBUG] switch_core_media.c:7243 Video params are unchanged for sofia/internal/1010@192.168.1.8. 2017-05-08 18:47:15.528399 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/1010@192.168.1.8: v=0 o=FreeSWITCH 1494266132 1494266134 IN IP4 192.168.1.8 s=FreeSWITCH c=IN IP4 192.168.1.8 t=0 0 m=audio 17500 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 18138 RTP/AVP 99 b=AS:1024 a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== send 1262 bytes to udp/[192.168.1.213]:5060 at 18:47:15.534586: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bKc7a637844fe10960 From: ;tag=e6075687f1077b96 To: ;tag=eZ9BmjQXjeXDS Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12675 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: 380 Remote-Party-ID: "Outbound Call" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1494266132 1494266133 IN IP4 192.168.1.8 s=FreeSWITCH c=IN IP4 192.168.1.8 t=0 0 m=audio 17500 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 m=video 18138 RTP/AVP 99 b=AS:1024 a=rtpmap:99 H264/90000 a=fmtp:99 profile-level-id=428014; packetization-mode=0; sprop-parameter-sets=Z0KADJWgUH5A,aM4Ecs== ------------------------------------------------------------------------ 2017-05-08 18:47:15.528399 [DEBUG] sofia.c:7048 Channel sofia/internal/1010@192.168.1.8 entering state [completed][200] 2017-05-08 18:47:15.528399 [NOTICE] switch_ivr_originate.c:3632 Channel [sofia/internal/1010@192.168.1.8] has been answered 2017-05-08 18:47:15.528399 [DEBUG] switch_channel.c:3772 (sofia/internal/1010@192.168.1.8) Callstate Change EARLY -> ACTIVE 2017-05-08 18:47:15.528399 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1001@192.168.1.161:5060] 2017-05-08 18:47:15.538525 [DEBUG] switch_ivr_originate.c:3690 Originate Resulted in Success: [sofia/internal/1001@192.168.1.161:5060] 2017-05-08 18:47:15.538525 [DEBUG] switch_ivr_bridge.c:1601 (sofia/internal/1001@192.168.1.161:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2017-05-08 18:47:15.538525 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.161:5060) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 18) 2017-05-08 18:47:15.538525 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1001@192.168.1.161:5060) State EXCHANGE_MEDIA 2017-05-08 18:47:15.538525 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA recv 807 bytes from udp/[192.168.1.213]:5060 at 18:47:15.541516: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.8:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bK64e49523bb65cc10 From: ;tag=e6075687f1077b96 To: ;tag=eZ9BmjQXjeXDS Contact: Proxy-Authorization: Digest username="1010", realm="192.168.1.8", algorithm=MD5, uri="sip:1001@192.168.1.8;user=phone", qop=auth, nc=00000001, cnonce="6482f0d5e6f12940", nonce="17336329-8f64-49ab-a570-29b61951bb71", response="c024ac1f5e0ccc59d82c73d3397a30ad" Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12675 ACK User-Agent: Grandstream GXV3000 1.2.3.7 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:15.538525 [DEBUG] sofia.c:7048 Channel sofia/internal/1010@192.168.1.8 entering state [ready][200] 2017-05-08 18:47:15.548212 [INFO] avcodec.c:1069 initializing encoder 352x288 2017-05-08 18:47:15.548212 [DEBUG] avcodec.c:831 NVENC HW CODEC NOT PRESENT 2017-05-08 18:47:15.558464 [DEBUG] switch_rtp.c:7229 Correct video ip/port confirmed. 2017-05-08 18:47:15.578168 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. 2017-05-08 18:47:15.588136 [DEBUG] switch_rtp.c:7229 Correct audio ip/port confirmed. 2017-05-08 18:47:15.608132 [DEBUG] switch_rtp.c:7229 Correct video ip/port confirmed. recv 770 bytes from udp/[192.168.1.213]:5060 at 18:47:20.369674: ------------------------------------------------------------------------ BYE sip:1001@192.168.1.8:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bK669382f230c735f6 From: ;tag=e6075687f1077b96 To: ;tag=eZ9BmjQXjeXDS Proxy-Authorization: Digest username="1010", realm="192.168.1.8", algorithm=MD5, uri="sip:1001@192.168.1.8:5060", qop=auth, nc=00000002, cnonce="b9967c47e7b7ae61", nonce="17336329-8f64-49ab-a570-29b61951bb71", response="432ef820aa76ac4f9e5402e61785d654" Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12676 BYE User-Agent: Grandstream GXV3000 1.2.3.7 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Reason: SIP ;text="Onhook event" Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:20.368279 [NOTICE] sofia.c:1012 Hangup sofia/internal/1010@192.168.1.8 [CS_EXECUTE] [NORMAL_CLEARING] send 500 bytes to udp/[192.168.1.213]:5060 at 18:47:20.373269: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.213:5060;branch=z9hG4bK669382f230c735f6 From: ;tag=e6075687f1077b96 To: ;tag=eZ9BmjQXjeXDS Call-ID: b4d0de557e560071b0932e454933e794@192.168.1.213 CSeq: 12676 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 ------------------------------------------------------------------------ 2017-05-08 18:47:20.368279 [DEBUG] switch_ivr_bridge.c:726 Ending video thread. 2017-05-08 18:47:20.368279 [DEBUG] switch_ivr_bridge.c:776 Ending video thread. 2017-05-08 18:47:20.368279 [DEBUG] switch_ivr_bridge.c:155 sofia/internal/1010@192.168.1.8 video thread ended. 2017-05-08 18:47:20.368279 [DEBUG] switch_core_media.c:11605 sofia/internal/1010@192.168.1.8 skip receive message [VIDEO_REFRESH_REQ] (channel is hungup already) 2017-05-08 18:47:20.368279 [DEBUG] switch_core_media.c:5957 sofia/internal/1010@192.168.1.8 Video thread ended 2017-05-08 18:47:20.378523 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/1010@192.168.1.8] 2017-05-08 18:47:20.378523 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/1010@192.168.1.8 ending bridge by request from write function 2017-05-08 18:47:20.378523 [DEBUG] switch_ivr_bridge.c:726 Ending video thread. 2017-05-08 18:47:20.378523 [DEBUG] switch_ivr_bridge.c:776 Ending video thread. 2017-05-08 18:47:20.418129 [DEBUG] switch_ivr_bridge.c:155 sofia/internal/1001@192.168.1.161:5060 video thread ended. 2017-05-08 18:47:20.418129 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/internal/1001@192.168.1.161:5060] 2017-05-08 18:47:20.418129 [NOTICE] switch_ivr_bridge.c:891 Hangup sofia/internal/1001@192.168.1.161:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2017-05-08 18:47:20.418129 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1001@192.168.1.161:5060) State EXCHANGE_MEDIA going to sleep 2017-05-08 18:47:20.418129 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.161:5060) Running State Change CS_HANGUP (Cur 2 Tot 18) 2017-05-08 18:47:20.418129 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1001@192.168.1.161:5060) Callstate Change ACTIVE -> HANGUP 2017-05-08 18:47:20.418129 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@192.168.1.161:5060) State HANGUP 2017-05-08 18:47:20.418129 [DEBUG] mod_sofia.c:432 sofia/internal/1001@192.168.1.161:5060 Overriding SIP cause 480 with 200 from the other leg 2017-05-08 18:47:20.418129 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1001@192.168.1.161:5060 hanging up, cause: NORMAL_CLEARING 2017-05-08 18:47:20.418129 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/1001@192.168.1.161:5060 send 618 bytes to udp/[192.168.1.161]:5060 at 18:47:20.427103: ------------------------------------------------------------------------ BYE sip:1001@192.168.1.161:5060;transport=udp;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.8;rport;branch=z9hG4bKt8gcFQHHB2tZH Max-Forwards: 70 From: "Extension 1010" ;tag=F824ND80FQK0m To: ;tag=89d037d35ba61306 Call-ID: 1dbfdc70-aee3-1235-77b2-080027de30fb CSeq: 106805753 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 Reason: SIP;text="Onhook event" Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:20.418129 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@192.168.1.161:5060 Standard HANGUP, cause: NORMAL_CLEARING 2017-05-08 18:47:20.418129 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@192.168.1.161:5060) State HANGUP going to sleep 2017-05-08 18:47:20.418129 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1001@192.168.1.161:5060) State Change CS_HANGUP -> CS_REPORTING 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.161:5060) Running State Change CS_REPORTING (Cur 2 Tot 18) 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@192.168.1.161:5060) State REPORTING 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1001@192.168.1.161:5060 Standard REPORTING, cause: NORMAL_CLEARING 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@192.168.1.161:5060) State REPORTING going to sleep 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1001@192.168.1.161:5060) State Change CS_REPORTING -> CS_DESTROY 2017-05-08 18:47:20.428558 [DEBUG] switch_core_session.c:1664 Session 18 (sofia/internal/1001@192.168.1.161:5060) Locked, Waiting on external entities recv 550 bytes from udp/[192.168.1.161]:5060 at 18:47:20.429720: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.8;rport;branch=z9hG4bKt8gcFQHHB2tZH From: "Extension 1010" ;tag=F824ND80FQK0m To: ;tag=89d037d35ba61306 Call-ID: 1dbfdc70-aee3-1235-77b2-080027de30fb CSeq: 106805753 BYE User-Agent: Grandstream GXV3000 1.2.3.7 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Supported: replaces, timer, 100rel, path Content-Length: 0 ------------------------------------------------------------------------ 2017-05-08 18:47:20.428558 [DEBUG] switch_ivr_bridge.c:1702 sofia/internal/1010@192.168.1.8 skip receive message [UNBRIDGE] (channel is hungup already) 2017-05-08 18:47:20.428558 [DEBUG] switch_core_session.c:2814 sofia/internal/1010@192.168.1.8 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1010@192.168.1.8) State EXECUTE going to sleep 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_HANGUP (Cur 2 Tot 18) 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1010@192.168.1.8) Callstate Change ACTIVE -> HANGUP 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1010@192.168.1.8) State HANGUP 2017-05-08 18:47:20.428558 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1010@192.168.1.8 hanging up, cause: NORMAL_CLEARING 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1010@192.168.1.8 Standard HANGUP, cause: NORMAL_CLEARING 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1010@192.168.1.8) State HANGUP going to sleep 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1010@192.168.1.8) State Change CS_HANGUP -> CS_REPORTING 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.1.8) Running State Change CS_REPORTING (Cur 2 Tot 18) 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1010@192.168.1.8) State REPORTING 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1010@192.168.1.8 Standard REPORTING, cause: NORMAL_CLEARING 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1010@192.168.1.8) State REPORTING going to sleep 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1010@192.168.1.8) State Change CS_REPORTING -> CS_DESTROY 2017-05-08 18:47:20.428558 [DEBUG] switch_core_session.c:1664 Session 17 (sofia/internal/1010@192.168.1.8) Locked, Waiting on external entities 2017-05-08 18:47:20.428558 [NOTICE] switch_core_session.c:1682 Session 17 (sofia/internal/1010@192.168.1.8) Ended 2017-05-08 18:47:20.428558 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1010@192.168.1.8 [CS_DESTROY] 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1010@192.168.1.8) Running State Change CS_DESTROY (Cur 1 Tot 18) 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1010@192.168.1.8) State DESTROY 2017-05-08 18:47:20.428558 [DEBUG] mod_sofia.c:343 sofia/internal/1010@192.168.1.8 SOFIA DESTROY 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1010@192.168.1.8 Standard DESTROY 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1010@192.168.1.8) State DESTROY going to sleep 2017-05-08 18:47:20.428558 [DEBUG] switch_core_media.c:5957 sofia/internal/1001@192.168.1.161:5060 Video thread ended 2017-05-08 18:47:20.428558 [NOTICE] switch_core_session.c:1682 Session 18 (sofia/internal/1001@192.168.1.161:5060) Ended 2017-05-08 18:47:20.428558 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1001@192.168.1.161:5060 [CS_DESTROY] 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@192.168.1.161:5060) Running State Change CS_DESTROY (Cur 0 Tot 18) 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@192.168.1.161:5060) State DESTROY 2017-05-08 18:47:20.428558 [DEBUG] mod_sofia.c:343 sofia/internal/1001@192.168.1.161:5060 SOFIA DESTROY 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1001@192.168.1.161:5060 Standard DESTROY 2017-05-08 18:47:20.428558 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@192.168.1.161:5060) State DESTROY going to sleep recv 766 bytes from udp/[192.168.1.47]:62774 at 18:47:38.010823: ------------------------------------------------------------------------ REGISTER sip:192.168.1.8:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.47:62774;branch=z9hG4bK-524287-1---ddbd420316564882;rport Max-Forwards: 70 Contact: To: From: ;tag=15c4215a Call-ID: ZjdLSPb86MPCiU4PQSdWkg.. CSeq: 39 REGISTER Expires: 60 User-Agent: Zoiper rv2.8.30 Authorization: Digest username="1008",realm="192.168.1.8",nonce="fcb0f64a-833c-4244-ac93-44e02e26b3c5",uri="sip:192.168.1.8:5060;transport=UDP",response="cd6d197c53f27f9116a6c12c6d5ea168",cnonce="f5780d160aa7584404dd6bf0ee8e0714",nc=00000026,qop=auth,algorithm=MD5 Allow-Events: presence, kpml, talk Content-Length: 0 ------------------------------------------------------------------------ send 641 bytes to udp/[192.168.1.47]:62774 at 18:47:38.012546: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.47:62774;branch=z9hG4bK-524287-1---ddbd420316564882;rport=62774 From: ;tag=15c4215a To: ;tag=gHvXQ8r4c09jg Call-ID: ZjdLSPb86MPCiU4PQSdWkg.. CSeq: 39 REGISTER Contact: ;expires=60 Date: Mon, 08 May 2017 22:47:38 GMT 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 ------------------------------------------------------------------------ freeswitch@freeswitch>