freeswitch@fs1> 
2017-06-02 12:18:15.532836 [WARNING] switch_core_state_machine.c:687 1e81da34-4a69-482b-984e-bb96291ad115 sofia/internal/1@68.157.150.128 Abandoned
2017-06-02 12:18:15.532836 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/internal/1@68.157.150.128 [CS_NEW] [WRONG_CALL_STATE]
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1@68.157.150.128) Running State Change CS_HANGUP (Cur 1 Tot 231)
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1@68.157.150.128) Callstate Change DOWN -> HANGUP
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1@68.157.150.128) State HANGUP
2017-06-02 12:18:15.532836 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1@68.157.150.128 hanging up, cause: WRONG_CALL_STATE
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1@68.157.150.128 Standard HANGUP, cause: WRONG_CALL_STATE
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1@68.157.150.128) State HANGUP going to sleep
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1@68.157.150.128) State Change CS_HANGUP -> CS_REPORTING
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1@68.157.150.128) Running State Change CS_REPORTING (Cur 1 Tot 231)
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1@68.157.150.128) State REPORTING
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1@68.157.150.128 Standard REPORTING, cause: WRONG_CALL_STATE
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1@68.157.150.128) State REPORTING going to sleep
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1@68.157.150.128) State Change CS_REPORTING -> CS_DESTROY
2017-06-02 12:18:15.532836 [DEBUG] switch_core_session.c:1712 Session 231 (sofia/internal/1@68.157.150.128) Locked, Waiting on external entities
2017-06-02 12:18:15.532836 [NOTICE] switch_core_session.c:1730 Session 231 (sofia/internal/1@68.157.150.128) Ended
2017-06-02 12:18:15.532836 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1@68.157.150.128 [CS_DESTROY]
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1@68.157.150.128) Running State Change CS_DESTROY (Cur 0 Tot 231)
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1@68.157.150.128) State DESTROY
2017-06-02 12:18:15.532836 [DEBUG] mod_sofia.c:354 sofia/internal/1@68.157.150.128 SOFIA DESTROY
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1@68.157.150.128 Standard DESTROY
2017-06-02 12:18:15.532836 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1@68.157.150.128) State DESTROY going to sleep
2017-06-02 12:18:16.812835 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@192.168.150.124 [5be54fde-a661-4390-9624-f603eed99e42]
2017-06-02 12:18:16.812835 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.150.124) Running State Change CS_NEW (Cur 1 Tot 232)
2017-06-02 12:18:16.812835 [DEBUG] sofia.c:10031 sofia/internal/1001@192.168.150.124 receiving invite from 192.168.150.102:5060 version: 1.9.0 git 6b3cef9 2017-06-01 23:40:50Z 64bit
2017-06-02 12:18:16.812835 [DEBUG] sofia.c:10202 IP 192.168.150.102 Rejected by acl "domains". Falling back to Digest auth.
2017-06-02 12:18:16.812835 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1001@192.168.150.124) State NEW
2017-06-02 12:18:16.812835 [DEBUG] sofia.c:2405 detaching session 5be54fde-a661-4390-9624-f603eed99e42
2017-06-02 12:18:16.822811 [DEBUG] sofia.c:2514 Re-attaching to session 5be54fde-a661-4390-9624-f603eed99e42
2017-06-02 12:18:16.832835 [DEBUG] sofia.c:10031 sofia/internal/1001@192.168.150.124 receiving invite from 192.168.150.102:5060 version: 1.9.0 git 6b3cef9 2017-06-01 23:40:50Z 64bit
2017-06-02 12:18:16.832835 [DEBUG] sofia.c:10202 IP 192.168.150.102 Rejected by acl "domains". Falling back to Digest auth.
2017-06-02 12:18:16.832835 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.150.124 entering state [received][100]
2017-06-02 12:18:16.832835 [DEBUG] sofia.c:7257 Remote SDP:
v=0
o=1001 8000 8001 IN IP4 192.168.150.102
s=SIP Call
c=IN IP4 192.168.150.102
t=0 0
m=audio 5004 RTP/AVP 0 8 4 18 3 2 101
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=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
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,aM4Ecn==
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-06-02 12:18:16.832835 [DEBUG] sofia.c:7649 (sofia/internal/1001@192.168.150.124) State Change CS_NEW -> CS_INIT
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.150.124) Running State Change CS_INIT (Cur 1 Tot 232)
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.150.124) State INIT
2017-06-02 12:18:16.832835 [DEBUG] mod_sofia.c:93 sofia/internal/1001@192.168.150.124 SOFIA INIT
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@192.168.150.124 Standard INIT
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@192.168.150.124) State Change CS_INIT -> CS_ROUTING
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.150.124) State INIT going to sleep
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.150.124) Running State Change CS_ROUTING (Cur 1 Tot 232)
2017-06-02 12:18:16.832835 [DEBUG] switch_channel.c:2249 (sofia/internal/1001@192.168.150.124) Callstate Change DOWN -> RINGING
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.150.124) State ROUTING
2017-06-02 12:18:16.832835 [DEBUG] mod_sofia.c:154 sofia/internal/1001@192.168.150.124 SOFIA ROUTING
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1001@192.168.150.124 Standard ROUTING
2017-06-02 12:18:16.832835 [INFO] mod_dialplan_xml.c:637 Processing 1001 <1001>->1010 in context default
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1001@192.168.150.124 Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 Action set(open=true) 
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1001@192.168.150.124 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [global-intercept] destination_number(1010) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [group-intercept] destination_number(1010) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [intercept-ext] destination_number(1010) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->redial] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [redial] destination_number(1010) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->global] continue=true
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [global] ${default_password}(j0sh3b0sh) =~ /^1234$/ break=never
Dialplan: sofia/internal/1001@192.168.150.124 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/1001@192.168.150.124 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=1001 8000 8001 IN IP4 192.168.150.102
s=SIP Call
c=IN IP4 192.168.150.102
t=0 0
m=audio 5004 RTP/AVP 0 8 4 18 3 2 101
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=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
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,aM4Ecn==
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/1001@192.168.150.124 Absolute Condition [global]
Dialplan: sofia/internal/1001@192.168.150.124 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [snom-demo-2] destination_number(1010) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [snom-demo-1] destination_number(1010) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [eavesdrop] destination_number(1010) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [eavesdrop] destination_number(1010) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [call_return] destination_number(1010) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [del-group] destination_number(1010) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [add-group] destination_number(1010) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [call-group-simo] destination_number(1010) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [call-group-order] destination_number(1010) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (FAIL) [extension-intercom] destination_number(1010) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1001@192.168.150.124 Regex (PASS) [Local_Extension] destination_number(1010) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@192.168.150.124 Action export(dialed_extension=1010) 
Dialplan: sofia/internal/1001@192.168.150.124 Action bind_meta_app(1 b s execute_extension::dx XML features) 
Dialplan: sofia/internal/1001@192.168.150.124 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) 
Dialplan: sofia/internal/1001@192.168.150.124 Action bind_meta_app(3 b s execute_extension::cf XML features) 
Dialplan: sofia/internal/1001@192.168.150.124 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) 
Dialplan: sofia/internal/1001@192.168.150.124 Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/1001@192.168.150.124 Action set(call_timeout=30) 
Dialplan: sofia/internal/1001@192.168.150.124 Action set(hangup_after_bridge=true) 
Dialplan: sofia/internal/1001@192.168.150.124 Action set(continue_on_fail=true) 
Dialplan: sofia/internal/1001@192.168.150.124 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action set(record_concat_video=true) 
Dialplan: sofia/internal/1001@192.168.150.124 Action record_session(/var/www/html/fs/${strftime(%Y-%m-%d_%H-%M-%S)}_${uuid}.mp4) 
Dialplan: sofia/internal/1001@192.168.150.124 Action bridge(user/${dialed_extension}@${domain_name}) 
Dialplan: sofia/internal/1001@192.168.150.124 Action answer() 
Dialplan: sofia/internal/1001@192.168.150.124 Action sleep(1000) 
Dialplan: sofia/internal/1001@192.168.150.124 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1001@192.168.150.124) State Change CS_ROUTING -> CS_EXECUTE
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.150.124) State ROUTING going to sleep
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.150.124) Running State Change CS_EXECUTE (Cur 1 Tot 232)
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.150.124) State EXECUTE
2017-06-02 12:18:16.832835 [DEBUG] mod_sofia.c:209 sofia/internal/1001@192.168.150.124 SOFIA EXECUTE
2017-06-02 12:18:16.832835 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1001@192.168.150.124 Standard EXECUTE
EXECUTE sofia/internal/1001@192.168.150.124 set(open=true)
2017-06-02 12:18:16.832835 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.150.124 [open]=[true]
EXECUTE sofia/internal/1001@192.168.150.124 hash(insert/192.168.150.124-spymap/1001/5be54fde-a661-4390-9624-f603eed99e42)
EXECUTE sofia/internal/1001@192.168.150.124 hash(insert/192.168.150.124-last_dial/1001/1010)
EXECUTE sofia/internal/1001@192.168.150.124 hash(insert/192.168.150.124-last_dial/global/5be54fde-a661-4390-9624-f603eed99e42)
EXECUTE sofia/internal/1001@192.168.150.124 export(RFC2822_DATE=Fri, 02 Jun 2017 12:18:16 -0400)
2017-06-02 12:18:16.842804 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 02 Jun 2017 12:18:16 -0400]
EXECUTE sofia/internal/1001@192.168.150.124 export(dialed_extension=1010)
2017-06-02 12:18:16.842804 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1010]
EXECUTE sofia/internal/1001@192.168.150.124 bind_meta_app(1 b s execute_extension::dx XML features)
2017-06-02 12:18:16.842804 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/1001@192.168.150.124 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1001.2017-06-02-12-18-16.wav)
2017-06-02 12:18:16.842804 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1001.2017-06-02-12-18-16.wav
EXECUTE sofia/internal/1001@192.168.150.124 bind_meta_app(3 b s execute_extension::cf XML features)
2017-06-02 12:18:16.842804 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/1001@192.168.150.124 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2017-06-02 12:18:16.842804 [INFO] switch_ivr_async.c:4260 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/1001@192.168.150.124 set(ringback=%(2000,4000,440,480))
2017-06-02 12:18:16.842804 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.150.124 [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1001@192.168.150.124 set(transfer_ringback=local_stream://moh)
2017-06-02 12:18:16.842804 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.150.124 [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1001@192.168.150.124 set(call_timeout=30)
2017-06-02 12:18:16.842804 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.150.124 [call_timeout]=[30]
EXECUTE sofia/internal/1001@192.168.150.124 set(hangup_after_bridge=true)
2017-06-02 12:18:16.842804 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.150.124 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1001@192.168.150.124 set(continue_on_fail=true)
2017-06-02 12:18:16.842804 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.150.124 [continue_on_fail]=[true]
EXECUTE sofia/internal/1001@192.168.150.124 hash(insert/192.168.150.124-call_return/1010/1001)
EXECUTE sofia/internal/1001@192.168.150.124 hash(insert/192.168.150.124-last_dial_ext/1010/5be54fde-a661-4390-9624-f603eed99e42)
EXECUTE sofia/internal/1001@192.168.150.124 set(called_party_callgroup=techsupport)
2017-06-02 12:18:16.842804 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.150.124 [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1001@192.168.150.124 hash(insert/192.168.150.124-last_dial_ext/techsupport/5be54fde-a661-4390-9624-f603eed99e42)
EXECUTE sofia/internal/1001@192.168.150.124 hash(insert/192.168.150.124-last_dial_ext/global/5be54fde-a661-4390-9624-f603eed99e42)
EXECUTE sofia/internal/1001@192.168.150.124 hash(insert/192.168.150.124-last_dial/techsupport/5be54fde-a661-4390-9624-f603eed99e42)
EXECUTE sofia/internal/1001@192.168.150.124 set(record_concat_video=true)
2017-06-02 12:18:16.842804 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.150.124 [record_concat_video]=[true]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_session.c:2707 Application record_session Requires media! pre_answering channel sofia/internal/1001@192.168.150.124
2017-06-02 12:18:16.842804 [INFO] switch_core_session.c:2709 Sending early media
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5166 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5166 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G723:4:8000:20:6300:1]/[opus:116:48000:20:0:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G726-32:2:8000:20:0:1]/[opus:116:48000:20:0:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G726-32:2:8000:20:0:1]/[G722:9:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5027 Set telephone-event payload to 101@8000
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:3426 Set Codec sofia/internal/1001@192.168.150.124 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-02 12:18:16.842804 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@192.168.150.124 Original read codec set to PCMU:0
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5370 Set telephone-event payload to 101@8000
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5428 sofia/internal/1001@192.168.150.124 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H264:99]/[VP8:99]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H264:99]/[H264:99]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5743 Video Codec Compare [H264:99] +++ is saved as a match
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H263:34]/[VP8:99]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H263:34]/[H264:99]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H263-1998:103]/[VP8:99]
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H263-1998:103]/[H264:99]
2017-06-02 12:18:16.842804 [NOTICE] avcodec.c:1019 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2017-06-02 12:18:16.842804 [NOTICE] avcodec.c:1019 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:3236 Set VIDEO Codec sofia/internal/1001@192.168.150.124 H264/90000 0 ms
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:8145 AUDIO RTP [sofia/internal/1001@192.168.150.124] 192.168.150.124 port 26284 -> 192.168.150.102 port 5004 codec: 0 ms: 20
2017-06-02 12:18:16.842804 [DEBUG] switch_rtp.c:4108 Starting timer [soft] 160 bytes per 20ms
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:8448 sofia/internal/1001@192.168.150.124 Set 2833 dtmf send payload to 101
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:8455 sofia/internal/1001@192.168.150.124 Set 2833 dtmf receive payload to 101
2017-06-02 12:18:16.842804 [DEBUG] switch_core_media.c:8478 sofia/internal/1001@192.168.150.124 Set rtp dtmf delay to 40
2017-06-02 12:18:16.842804 [DEBUG] switch_rtp.c:4123 Starting video timer.
2017-06-02 12:18:16.852805 [DEBUG] switch_core_media.c:8973 VIDEO RTP [sofia/internal/1001@192.168.150.124] 192.168.150.124:18850->192.168.150.102:5006 codec: 99 ms: 0 [SUCCESS]
2017-06-02 12:18:16.852805 [DEBUG] switch_core_media.c:7137 sofia/internal/1001@192.168.150.124 Starting Video thread
2017-06-02 12:18:16.852805 [DEBUG] switch_core_media.c:7003 sofia/internal/1001@192.168.150.124 Video thread started. Echo is off
2017-06-02 12:18:16.852805 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1001@192.168.150.124!
2017-06-02 12:18:16.852805 [DEBUG] switch_channel.c:3481 (sofia/internal/1001@192.168.150.124) Callstate Change RINGING -> EARLY
2017-06-02 12:18:16.852805 [DEBUG] switch_core_media.c:8128 Audio params are unchanged for sofia/internal/1001@192.168.150.124.
2017-06-02 12:18:16.852805 [DEBUG] switch_core_media.c:8831 Video params are unchanged for sofia/internal/1001@192.168.150.124.
2017-06-02 12:18:16.852805 [DEBUG] mod_sofia.c:2512 Ring SDP:
v=0
o=FreeSWITCH 1496394012 1496394013 IN IP4 192.168.150.124
s=FreeSWITCH
c=IN IP4 192.168.150.124
t=0 0
m=audio 26284 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 18850 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,aM4Ecn==
a=sendrecv

EXECUTE sofia/internal/1001@192.168.150.124 record_session(/var/www/html/fs/2017-06-02_12-18-16_5be54fde-a661-4390-9624-f603eed99e42.mp4)
2017-06-02 12:18:16.852805 [DEBUG] avformat.c:1851 sample rate: 8000, channels: 2
2017-06-02 12:18:16.852805 [DEBUG] avformat.c:1956 use video codec: [28] h264 (H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10)
2017-06-02 12:18:16.852805 [NOTICE] avformat.c:640 sample_rate: 8000 nb_samples: 1024
2017-06-02 12:18:16.852805 [INFO] avformat.c:1980 Opening File [/var/www/html/fs/2017-06-02_12-18-16_5be54fde-a661-4390-9624-f603eed99e42.mp4] 8000hz  with VIDEO
2017-06-02 12:18:16.852805 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.150.124 entering state [early][183]
2017-06-02 12:18:16.862804 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/internal/1001@192.168.150.124
EXECUTE sofia/internal/1001@192.168.150.124 bridge(user/1010@192.168.150.124)
2017-06-02 12:18:16.862804 [DEBUG] switch_channel.c:1250 sofia/internal/1001@192.168.150.124 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 02 Jun 2017 12:18:16 -0400] to event
2017-06-02 12:18:16.862804 [DEBUG] switch_channel.c:1250 sofia/internal/1001@192.168.150.124 EXPORTING[export_vars] [dialed_extension]=[1010] to event
2017-06-02 12:18:16.862804 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables
2017-06-02 12:18:16.862804 [DEBUG] switch_channel.c:1250 sofia/internal/1001@192.168.150.124 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 02 Jun 2017 12:18:16 -0400] to event
2017-06-02 12:18:16.862804 [DEBUG] switch_channel.c:1250 sofia/internal/1001@192.168.150.124 EXPORTING[export_vars] [dialed_extension]=[1010] to event
2017-06-02 12:18:16.862804 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables
2017-06-02 12:18:16.862804 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1010@192.168.150.103:5060 [daee73d2-3b9d-4241-9dcb-6bb71b0bcb0e]
2017-06-02 12:18:16.862804 [DEBUG] mod_sofia.c:5026 (sofia/internal/1010@192.168.150.103:5060) State Change CS_NEW -> CS_INIT
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.150.103:5060) Running State Change CS_INIT (Cur 2 Tot 233)
2017-06-02 12:18:16.862804 [NOTICE] switch_ivr_originate.c:2856 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1010@192.168.150.103:5060) State INIT
2017-06-02 12:18:16.862804 [DEBUG] mod_sofia.c:93 sofia/internal/1010@192.168.150.103:5060 SOFIA INIT
2017-06-02 12:18:16.862804 [DEBUG] sofia_glue.c:1298 sofia/internal/1010@192.168.150.103:5060 sending invite version: 1.9.0 git 6b3cef9 2017-06-01 23:40:50Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1496402746 1496402747 IN IP4 192.168.150.124
s=FreeSWITCH
c=IN IP4 192.168.150.124
t=0 0
m=audio 17550 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 28398 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,aM4Ecn==
a=sendrecv
a=rtcp-fb:102 ccm fir
a=rtcp-fb:102 ccm tmmbr
a=rtcp-fb:102 nack
a=rtcp-fb:102 nack pli

2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1010@192.168.150.103:5060 Standard INIT
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1010@192.168.150.103:5060) State Change CS_INIT -> CS_ROUTING
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1010@192.168.150.103:5060) State INIT going to sleep
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.150.103:5060) Running State Change CS_ROUTING (Cur 2 Tot 233)
2017-06-02 12:18:16.862804 [DEBUG] sofia.c:7247 Channel sofia/internal/1010@192.168.150.103:5060 entering state [calling][0]
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1010@192.168.150.103:5060) State ROUTING
2017-06-02 12:18:16.862804 [DEBUG] mod_sofia.c:154 sofia/internal/1010@192.168.150.103:5060 SOFIA ROUTING
2017-06-02 12:18:16.862804 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1010@192.168.150.103:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1010@192.168.150.103:5060) State ROUTING going to sleep
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.150.103:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 233)
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1010@192.168.150.103:5060) State CONSUME_MEDIA
2017-06-02 12:18:16.862804 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1010@192.168.150.103:5060) State CONSUME_MEDIA going to sleep
2017-06-02 12:18:16.862804 [DEBUG] switch_ivr_async.c:1508 No silence detection configured; assuming start of speech
2017-06-02 12:18:16.872806 [INFO] avcodec.c:1077 initializing encoder 352x288
2017-06-02 12:18:16.872806 [DEBUG] avcodec.c:831 NVENC HW CODEC NOT PRESENT
2017-06-02 12:18:16.872806 [DEBUG] sofia.c:7247 Channel sofia/internal/1010@192.168.150.103:5060 entering state [proceeding][180]
2017-06-02 12:18:16.872806 [NOTICE] sofia.c:7355 Ring-Ready sofia/internal/1010@192.168.150.103:5060!
2017-06-02 12:18:16.872806 [DEBUG] switch_channel.c:3353 (sofia/internal/1010@192.168.150.103:5060) Callstate Change DOWN -> RINGING
2017-06-02 12:18:16.882809 [DEBUG] switch_rtp.c:7267 Correct audio ip/port confirmed.
2017-06-02 12:18:16.882809 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2017-06-02 12:18:16.902835 [DEBUG] switch_ivr_originate.c:1278 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2017-06-02 12:18:16.902835 [DEBUG] switch_core_codec.c:223 sofia/internal/1001@192.168.150.124 Push codec L16:100
2017-06-02 12:18:16.902835 [DEBUG] switch_ivr_originate.c:1347 Play Ringback Tone [%(2000,4000,440,480)]
2017-06-02 12:18:16.942808 [INFO] avformat.c:2610 use video codec implementation Video: libx264, yuv420p, 1280x720, q=10-31
2017-06-02 12:18:16.942808 [NOTICE] avformat.c:722 video thread start
2017-06-02 12:18:17.452835 [ERR] avformat.c:2131 Error while writing audio frame: Invalid argument
2017-06-02 12:18:17.462812 [DEBUG] switch_rtp.c:7267 Correct video ip/port confirmed.
2017-06-02 12:18:18.902835 [DEBUG] sofia.c:7247 Channel sofia/internal/1010@192.168.150.103:5060 entering state [completing][200]
2017-06-02 12:18:18.902835 [DEBUG] sofia.c:7257 Remote SDP:
v=0
o=1010 8000 8000 IN IP4 192.168.150.103
s=SIP Call
c=IN IP4 192.168.150.103
t=0 0
m=audio 5004 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
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,aM4Ecs==
a=framerate:15

2017-06-02 12:18:18.902835 [DEBUG] sofia.c:7247 Channel sofia/internal/1010@192.168.150.103:5060 entering state [ready][200]
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5111 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5166 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5027 Set telephone-event payload to 101@8000
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:3426 Set Codec sofia/internal/1010@192.168.150.103:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-02 12:18:18.902835 [DEBUG] switch_core_codec.c:111 sofia/internal/1010@192.168.150.103:5060 Original read codec set to PCMU:0
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5370 Set telephone-event payload to 101@8000
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5428 sofia/internal/1010@192.168.150.103:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H264:102]/[H264:99]
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5754 No matches with FTMP, fallback to ignoring FMTP
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H264:102]/[H264:99]
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5762 No matches with inherit_codec, fallback to ignoring PT
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5711 Video Codec Compare [H264:102]/[H264:99]
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:5743 Video Codec Compare [H264:102] +++ is saved as a match
2017-06-02 12:18:18.902835 [NOTICE] avcodec.c:1019 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2017-06-02 12:18:18.902835 [NOTICE] avcodec.c:1019 codec: id=28 H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:3236 Set VIDEO Codec sofia/internal/1010@192.168.150.103:5060 H264/90000 0 ms
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:8145 AUDIO RTP [sofia/internal/1010@192.168.150.103:5060] 192.168.150.124 port 17550 -> 192.168.150.103 port 5004 codec: 0 ms: 20
2017-06-02 12:18:18.902835 [DEBUG] switch_rtp.c:4108 Starting timer [soft] 160 bytes per 20ms
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:8448 sofia/internal/1010@192.168.150.103:5060 Set 2833 dtmf send payload to 101
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:8455 sofia/internal/1010@192.168.150.103:5060 Set 2833 dtmf receive payload to 101
2017-06-02 12:18:18.902835 [DEBUG] switch_core_media.c:8478 sofia/internal/1010@192.168.150.103:5060 Set rtp dtmf delay to 40
2017-06-02 12:18:18.902835 [DEBUG] switch_rtp.c:4123 Starting video timer.
2017-06-02 12:18:18.912807 [DEBUG] switch_core_media.c:8973 VIDEO RTP [sofia/internal/1010@192.168.150.103:5060] 192.168.150.124:28398->192.168.150.103:5006 codec: 102 ms: 0 [SUCCESS]
2017-06-02 12:18:18.912807 [DEBUG] switch_core_media.c:7137 sofia/internal/1010@192.168.150.103:5060 Starting Video thread
2017-06-02 12:18:18.912807 [DEBUG] switch_core_media.c:7003 sofia/internal/1010@192.168.150.103:5060 Video thread started. Echo is off
2017-06-02 12:18:18.912807 [NOTICE] sofia.c:8383 Channel [sofia/internal/1010@192.168.150.103:5060] has been answered
2017-06-02 12:18:18.912807 [DEBUG] switch_channel.c:3780 (sofia/internal/1010@192.168.150.103:5060) Callstate Change RINGING -> ACTIVE
2017-06-02 12:18:18.922810 [DEBUG] switch_core_codec.c:248 sofia/internal/1001@192.168.150.124 Restore previous codec PCMU:0.
2017-06-02 12:18:18.922810 [DEBUG] switch_core_media.c:8128 Audio params are unchanged for sofia/internal/1001@192.168.150.124.
2017-06-02 12:18:18.922810 [DEBUG] switch_core_media.c:8831 Video params are unchanged for sofia/internal/1001@192.168.150.124.
2017-06-02 12:18:18.922810 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/1001@192.168.150.124:
v=0
o=FreeSWITCH 1496394012 1496394014 IN IP4 192.168.150.124
s=FreeSWITCH
c=IN IP4 192.168.150.124
t=0 0
m=audio 26284 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 18850 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,aM4Ecn==
a=sendrecv

2017-06-02 12:18:18.922810 [NOTICE] switch_ivr_originate.c:3652 Channel [sofia/internal/1001@192.168.150.124] has been answered
2017-06-02 12:18:18.932807 [DEBUG] switch_channel.c:3780 (sofia/internal/1001@192.168.150.124) Callstate Change EARLY -> ACTIVE
2017-06-02 12:18:18.932807 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.150.124 entering state [completed][200]
2017-06-02 12:18:18.932807 [DEBUG] switch_ivr_originate.c:3710 Originate Resulted in Success: [sofia/internal/1010@192.168.150.103:5060]
2017-06-02 12:18:18.932807 [DEBUG] switch_ivr_originate.c:3710 Originate Resulted in Success: [sofia/internal/1010@192.168.150.103:5060]
2017-06-02 12:18:18.932807 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.150.124 entering state [ready][200]
2017-06-02 12:18:18.932807 [DEBUG] switch_ivr_bridge.c:1744 (sofia/internal/1010@192.168.150.103:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2017-06-02 12:18:18.932807 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.150.103:5060) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 233)
2017-06-02 12:18:18.932807 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1010@192.168.150.103:5060) State EXCHANGE_MEDIA
2017-06-02 12:18:18.932807 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA
2017-06-02 12:18:18.942835 [INFO] avcodec.c:1077 initializing encoder 352x288
2017-06-02 12:18:18.942835 [DEBUG] avcodec.c:831 NVENC HW CODEC NOT PRESENT
2017-06-02 12:18:18.942835 [DEBUG] switch_rtp.c:7267 Correct video ip/port confirmed.
2017-06-02 12:18:18.962812 [DEBUG] switch_rtp.c:7267 Correct audio ip/port confirmed.
2017-06-02 12:18:18.982810 [DEBUG] switch_rtp.c:7267 Correct audio ip/port confirmed.
2017-06-02 12:18:19.002834 [DEBUG] switch_rtp.c:7267 Correct video ip/port confirmed.
2017-06-02 12:18:19.012805 [DEBUG] avcodec.c:1085 picture size changed from 352x288 to 320x240, reinitializing encoder
2017-06-02 12:18:19.122809 [DEBUG] switch_ivr.c:624 sofia/internal/1010@192.168.150.103:5060 Command Execute lua(record_details.lua)
EXECUTE sofia/internal/1010@192.168.150.103:5060 lua(record_details.lua)
2017-06-02 12:18:19.122809 [ERR] mod_lua.cpp:203 /usr/local/freeswitch/scripts/record_details.lua:18: attempt to concatenate a nil value
stack traceback:
        /usr/local/freeswitch/scripts/record_details.lua:18: in main chunk
2017-06-02 12:18:19.122809 [DEBUG] switch_cpp.cpp:1122 sofia/internal/1010@192.168.150.103:5060 destroy/unlink session from object
2017-06-02 12:18:19.132811 [DEBUG] avcodec.c:1085 picture size changed from 352x288 to 320x240, reinitializing encoder
2017-06-02 12:18:19.162809 [DEBUG] switch_ivr.c:624 sofia/internal/1001@192.168.150.124 Command Execute lua(record_details.lua)
EXECUTE sofia/internal/1001@192.168.150.124 lua(record_details.lua)
2017-06-02 12:18:19.162809 [INFO] switch_cpp.cpp:1303 









uuid,5be54fde-a661-4390-9624-f603eed99e42
direction,inbound
channel_name,sofia/internal/1001@192.168.150.124
caller_id_number,1001
read_codec,PCMU
read_rate,8000
write_codec,PCMU
write_rate,8000
video_read_codec,H264
video_read_rate,90000
video_write_codec,H264
video_write_rate,90000
video_width,320
video_height,240
video_fps,10
record_stereo,true
dialed_extension,1010










2017-06-02 12:18:19.162809 [DEBUG] switch_cpp.cpp:1122 sofia/internal/1001@192.168.150.124 destroy/unlink session from object
2017-06-02 12:18:19.702834 [ERR] avformat.c:2131 Error while writing audio frame: Invalid argument
2017-06-02 12:18:19.722811 [ERR] avformat.c:2131 Error while writing audio frame: Invalid argument
2017-06-02 12:18:20.942833 [DEBUG] switch_ivr_bridge.c:825 sofia/internal/1010@192.168.150.103:5060 ending bridge by request from write function
2017-06-02 12:18:20.942833 [DEBUG] switch_ivr_bridge.c:848 Ending video thread.
2017-06-02 12:18:20.942833 [DEBUG] switch_ivr_bridge.c:906 Ending video thread.
2017-06-02 12:18:20.942833 [NOTICE] sofia.c:1079 Hangup sofia/internal/1010@192.168.150.103:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2017-06-02 12:18:20.942833 [DEBUG] switch_ivr_bridge.c:848 Ending video thread.
2017-06-02 12:18:20.942833 [DEBUG] switch_ivr_bridge.c:255 sofia/internal/1010@192.168.150.103:5060 video thread ended.
2017-06-02 12:18:20.942833 [DEBUG] switch_core_media.c:13744 sofia/internal/1010@192.168.150.103:5060 skip receive message [DISPLAY] (channel is hungup already)
2017-06-02 12:18:20.952807 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/1010@192.168.150.103:5060]
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/1010@192.168.150.103:5060) State EXCHANGE_MEDIA going to sleep
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.150.103:5060) Running State Change CS_HANGUP (Cur 2 Tot 233)
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1010@192.168.150.103:5060) Callstate Change ACTIVE -> HANGUP
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1010@192.168.150.103:5060) State HANGUP
2017-06-02 12:18:20.952807 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1010@192.168.150.103:5060 hanging up, cause: NORMAL_CLEARING
2017-06-02 12:18:20.952807 [DEBUG] switch_core_media.c:7104 sofia/internal/1010@192.168.150.103:5060 Video thread ended
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1010@192.168.150.103:5060 Standard HANGUP, cause: NORMAL_CLEARING
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1010@192.168.150.103:5060) State HANGUP going to sleep
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1010@192.168.150.103:5060) State Change CS_HANGUP -> CS_REPORTING
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1010@192.168.150.103:5060) Running State Change CS_REPORTING (Cur 2 Tot 233)
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1010@192.168.150.103:5060) State REPORTING
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1010@192.168.150.103:5060 Standard REPORTING, cause: NORMAL_CLEARING
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1010@192.168.150.103:5060) State REPORTING going to sleep
2017-06-02 12:18:20.952807 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1010@192.168.150.103:5060) State Change CS_REPORTING -> CS_DESTROY
2017-06-02 12:18:20.952807 [DEBUG] switch_core_session.c:1712 Session 233 (sofia/internal/1010@192.168.150.103:5060) Locked, Waiting on external entities
2017-06-02 12:18:20.972809 [DEBUG] switch_ivr_bridge.c:255 sofia/internal/1001@192.168.150.124 video thread ended.
2017-06-02 12:18:20.972809 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/1001@192.168.150.124]
2017-06-02 12:18:20.972809 [NOTICE] switch_ivr_bridge.c:1895 Hangup sofia/internal/1001@192.168.150.124 [CS_EXECUTE] [NORMAL_CLEARING]
2017-06-02 12:18:20.972809 [NOTICE] switch_core_session.c:1730 Session 233 (sofia/internal/1010@192.168.150.103:5060) Ended
2017-06-02 12:18:20.972809 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1010@192.168.150.103:5060 [CS_DESTROY]
2017-06-02 12:18:20.972809 [DEBUG] switch_core_session.c:2884 sofia/internal/1001@192.168.150.124 skip receive message [PHONE_EVENT] (channel is hungup already)
2017-06-02 12:18:20.972809 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.150.124) State EXECUTE going to sleep
2017-06-02 12:18:20.972809 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.150.124) Running State Change CS_HANGUP (Cur 1 Tot 233)
2017-06-02 12:18:20.972809 [DEBUG] switch_ivr_async.c:1324 Stop recording file /var/www/html/fs/2017-06-02_12-18-16_5be54fde-a661-4390-9624-f603eed99e42.mp4
2017-06-02 12:18:20.972809 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1010@192.168.150.103:5060) Running State Change CS_DESTROY (Cur 1 Tot 233)
2017-06-02 12:18:20.982807 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1010@192.168.150.103:5060) State DESTROY
2017-06-02 12:18:20.982807 [DEBUG] mod_sofia.c:354 sofia/internal/1010@192.168.150.103:5060 SOFIA DESTROY
2017-06-02 12:18:20.982807 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1010@192.168.150.103:5060 Standard DESTROY
2017-06-02 12:18:20.982807 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1010@192.168.150.103:5060) State DESTROY going to sleep
2017-06-02 12:18:21.022806 [DEBUG] switch_core_media.c:7104 sofia/internal/1001@192.168.150.124 Video thread ended
2017-06-02 12:18:21.062806 [NOTICE] avformat.c:894 video thread done
2017-06-02 12:18:21.072804 [DEBUG] switch_ivr_async.c:1388 Channel is hung up
2017-06-02 12:18:21.072804 [DEBUG] switch_core_media_bug.c:1313 Removing BUG from sofia/internal/1001@192.168.150.124
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1001@192.168.150.124) Callstate Change ACTIVE -> HANGUP
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@192.168.150.124) State HANGUP
2017-06-02 12:18:21.072804 [DEBUG] mod_sofia.c:443 sofia/internal/1001@192.168.150.124 Overriding SIP cause 480 with 200 from the other leg
2017-06-02 12:18:21.072804 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1001@192.168.150.124 hanging up, cause: NORMAL_CLEARING
2017-06-02 12:18:21.072804 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/1001@192.168.150.124
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@192.168.150.124 Standard HANGUP, cause: NORMAL_CLEARING
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@192.168.150.124) State HANGUP going to sleep
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1001@192.168.150.124) State Change CS_HANGUP -> CS_REPORTING
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.150.124) Running State Change CS_REPORTING (Cur 1 Tot 233)
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@192.168.150.124) State REPORTING
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1001@192.168.150.124 Standard REPORTING, cause: NORMAL_CLEARING
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@192.168.150.124) State REPORTING going to sleep
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1001@192.168.150.124) State Change CS_REPORTING -> CS_DESTROY
2017-06-02 12:18:21.072804 [DEBUG] switch_core_session.c:1712 Session 232 (sofia/internal/1001@192.168.150.124) Locked, Waiting on external entities
2017-06-02 12:18:21.072804 [NOTICE] switch_core_session.c:1730 Session 232 (sofia/internal/1001@192.168.150.124) Ended
2017-06-02 12:18:21.072804 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1001@192.168.150.124 [CS_DESTROY]
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@192.168.150.124) Running State Change CS_DESTROY (Cur 0 Tot 233)
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@192.168.150.124) State DESTROY
2017-06-02 12:18:21.072804 [DEBUG] mod_sofia.c:354 sofia/internal/1001@192.168.150.124 SOFIA DESTROY
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1001@192.168.150.124 Standard DESTROY
2017-06-02 12:18:21.072804 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@192.168.150.124) State DESTROY going to sleep
freeswitch@fs1>