2018-08-24 13:53:09.083869 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@192.168.234.131 [97d0ed93-627c-4e72-a36c-d5e3fadd74ba]
2018-08-24 13:53:09.083869 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.234.131) Running State Change CS_NEW (Cur 1 Tot 1)
2018-08-24 13:53:09.083869 [DEBUG] sofia.c:10078 sofia/internal/1000@192.168.234.131 receiving invite from 192.168.234.1:5060 version: 1.9.0 git e1bff03 2018-04-13 16:41:04Z 64bit
2018-08-24 13:53:09.083869 [DEBUG] sofia.c:10249 IP 192.168.234.1 Rejected by acl "domains". Falling back to Digest auth.
2018-08-24 13:53:09.083869 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@192.168.234.131) State NEW
2018-08-24 13:53:09.083869 [DEBUG] sofia.c:2413 detaching session 97d0ed93-627c-4e72-a36c-d5e3fadd74ba
2018-08-24 13:53:09.143709 [DEBUG] sofia.c:2522 Re-attaching to session 97d0ed93-627c-4e72-a36c-d5e3fadd74ba
2018-08-24 13:53:09.163814 [DEBUG] sofia.c:10078 sofia/internal/1000@192.168.234.131 receiving invite from 192.168.234.1:5060 version: 1.9.0 git e1bff03 2018-04-13 16:41:04Z 64bit
2018-08-24 13:53:09.163814 [DEBUG] sofia.c:10249 IP 192.168.234.1 Rejected by acl "domains". Falling back to Digest auth.
2018-08-24 13:53:09.163814 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@192.168.234.131 entering state [received][100]
2018-08-24 13:53:09.163814 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=1000 2995 3750 IN IP4 192.168.234.1
s=Talk
c=IN IP4 192.168.234.1
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7078 RTP/AVP 96 97 98 0 8 101 99 100
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:97 speex/16000
a=fmtp:97 vbr=on
a=rtpmap:98 speex/8000
a=fmtp:98 vbr=on
a=rtpmap:101 telephone-event/48000
a=rtpmap:99 telephone-event/16000
a=rtpmap:100 telephone-event/8000
a=rtcp-fb:* trr-int 5000
a=rtcp-fb:* ccm tmmbr

2018-08-24 13:53:09.163814 [DEBUG] sofia.c:7693 (sofia/internal/1000@192.168.234.131) State Change CS_NEW -> CS_INIT
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.234.131) Running State Change CS_INIT (Cur 1 Tot 1)
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@192.168.234.131) State INIT
2018-08-24 13:53:09.163814 [DEBUG] mod_sofia.c:93 sofia/internal/1000@192.168.234.131 SOFIA INIT
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@192.168.234.131 Standard INIT
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@192.168.234.131) State Change CS_INIT -> CS_ROUTING
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@192.168.234.131) State INIT going to sleep
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.234.131) Running State Change CS_ROUTING (Cur 1 Tot 1)
2018-08-24 13:53:09.163814 [DEBUG] switch_channel.c:2249 (sofia/internal/1000@192.168.234.131) Callstate Change DOWN -> RINGING
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@192.168.234.131) State ROUTING
2018-08-24 13:53:09.163814 [DEBUG] mod_sofia.c:154 sofia/internal/1000@192.168.234.131 SOFIA ROUTING
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1000@192.168.234.131 Standard ROUTING
2018-08-24 13:53:09.163814 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->amd_test in context default
Dialplan: sofia/internal/1000@192.168.234.131 parsing [default->amd_test] continue=false
Dialplan: sofia/internal/1000@192.168.234.131 Regex (PASS) [amd_test] destination_number(amd_test) =~ /^(amd_test)$/ break=on-false
Dialplan: sofia/internal/1000@192.168.234.131 Action set(media_bug_answer_req=true)
Dialplan: sofia/internal/1000@192.168.234.131 Action set(amd_execute_on_machine=transfer machine_found XML default)
Dialplan: sofia/internal/1000@192.168.234.131 Action set(amd_execute_on_person=transfer person_found XML default)
Dialplan: sofia/internal/1000@192.168.234.131 Action set(amd_execute_on_unsure=transfer amd_unsure XML default)
Dialplan: sofia/internal/1000@192.168.234.131 Action voice_start()
Dialplan: sofia/internal/1000@192.168.234.131 Action set(api_on_answer=uuid_displace ${uuid} start ${sounds_dir}/Answering_Machine.wav 0 mr)
Dialplan: sofia/internal/1000@192.168.234.131 Action answer()
Dialplan: sofia/internal/1000@192.168.234.131 Action waitforresult(ivr/ivr-one_moment_please.wav)
Dialplan: sofia/internal/1000@192.168.234.131 Action sleep(200)
Dialplan: sofia/internal/1000@192.168.234.131 Action playback(tone_stream://%(200,100,500,400,300,50,25);loops=2)
Dialplan: sofia/internal/1000@192.168.234.131 Action sleep(200)
Dialplan: sofia/internal/1000@192.168.234.131 Action log(CRIT AMD Result is => ${amd_status} => ${amd_result})
Dialplan: sofia/internal/1000@192.168.234.131 Action hangup()
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1000@192.168.234.131) State Change CS_ROUTING -> CS_EXECUTE
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@192.168.234.131) State ROUTING going to sleep
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@192.168.234.131) Running State Change CS_EXECUTE (Cur 1 Tot 1)
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1000@192.168.234.131) State EXECUTE
2018-08-24 13:53:09.163814 [DEBUG] mod_sofia.c:209 sofia/internal/1000@192.168.234.131 SOFIA EXECUTE
2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1000@192.168.234.131 Standard EXECUTE
EXECUTE sofia/internal/1000@192.168.234.131 set(media_bug_answer_req=true)
2018-08-24 13:53:09.163814 [DEBUG] mod_dptools.c:1593 SET sofia/internal/1000@192.168.234.131 [media_bug_answer_req]=[true]
EXECUTE sofia/internal/1000@192.168.234.131 set(amd_execute_on_machine=transfer machine_found XML default)
2018-08-24 13:53:09.163814 [DEBUG] mod_dptools.c:1593 SET sofia/internal/1000@192.168.234.131 [amd_execute_on_machine]=[transfer machine_found XML default]
EXECUTE sofia/internal/1000@192.168.234.131 set(amd_execute_on_person=transfer person_found XML default)
2018-08-24 13:53:09.163814 [DEBUG] mod_dptools.c:1593 SET sofia/internal/1000@192.168.234.131 [amd_execute_on_person]=[transfer person_found XML default]
EXECUTE sofia/internal/1000@192.168.234.131 set(amd_execute_on_unsure=transfer amd_unsure XML default)
2018-08-24 13:53:09.163814 [DEBUG] mod_dptools.c:1593 SET sofia/internal/1000@192.168.234.131 [amd_execute_on_unsure]=[transfer amd_unsure XML default]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_session.c:2708 Application voice_start Requires media! pre_answering channel sofia/internal/1000@192.168.234.131
2018-08-24 13:53:09.163814 [INFO] switch_core_session.c:2710 Sending early media
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [opus:96:48000:20:0:1]/[opus:116:48000:20:0:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5184 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [opus:96:48000:20:0:1]/[G722:9:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [opus:96:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [opus:96:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [speex:97:16000:20:0:1]/[opus:116:48000:20:0:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [speex:97:16000:20:0:1]/[G722:9:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [speex:97:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [speex:97:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [speex:98:8000:20:0:1]/[opus:116:48000:20:0:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [speex:98:8000:20:0:1]/[G722:9:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [speex:98:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [speex:98:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5184 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5129 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5184 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5045 Set telephone-event payload to 101@48000
2018-08-24 13:53:09.163814 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps]
2018-08-24 13:53:09.163814 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps]
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:3444 Set Codec sofia/internal/1000@192.168.234.131 opus/48000 20 ms 960 samples 0 bits 1 channels
2018-08-24 13:53:09.163814 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@192.168.234.131 Original read codec set to opus:116
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5388 Set telephone-event payload to 101@48000
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5446 sofia/internal/1000@192.168.234.131 Set 2833 dtmf send payload to 101 recv payload to 101
2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:8163 AUDIO RTP [sofia/internal/1000@192.168.234.131] 192.168.234.131 port 22730 -> 192.168.234.1 port 7078 codec: 96 ms: 20
2018-08-24 13:53:09.163814 [DEBUG] switch_rtp.c:4189 Starting timer [soft] 960 bytes per 20ms
2018-08-24 13:53:09.184017 [DEBUG] switch_core_media.c:8467 sofia/internal/1000@192.168.234.131 Set 2833 dtmf send payload to 101
2018-08-24 13:53:09.184017 [DEBUG] switch_core_media.c:8474 sofia/internal/1000@192.168.234.131 Set 2833 dtmf receive payload to 101
2018-08-24 13:53:09.184017 [DEBUG] switch_core_media.c:8497 sofia/internal/1000@192.168.234.131 Set rtp dtmf delay to 40
2018-08-24 13:53:09.184017 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@192.168.234.131!
2018-08-24 13:53:09.184017 [DEBUG] switch_channel.c:3482 (sofia/internal/1000@192.168.234.131) Callstate Change RINGING -> EARLY
2018-08-24 13:53:09.184017 [DEBUG] switch_core_media.c:8146 Audio params are unchanged for sofia/internal/1000@192.168.234.131.
2018-08-24 13:53:09.184017 [DEBUG] mod_sofia.c:2512 Ring SDP:
v=0
o=FreeSWITCH 1535121259 1535121260 IN IP4 192.168.234.131
s=FreeSWITCH
c=IN IP4 192.168.234.131
t=0 0
m=audio 22730 RTP/AVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/48000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

EXECUTE sofia/internal/1000@192.168.234.131 voice_start()
2018-08-24 13:53:09.184017 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/internal/1000@192.168.234.131
2018-08-24 13:53:09.184017 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@192.168.234.131 entering state [early][183]
EXECUTE sofia/internal/1000@192.168.234.131 set(api_on_answer=uuid_displace 97d0ed93-627c-4e72-a36c-d5e3fadd74ba start /usr/local/freeswitch/sounds/Answering_Machine.wav 0 mr)
2018-08-24 13:53:09.184017 [DEBUG] mod_dptools.c:1593 SET sofia/internal/1000@192.168.234.131 [api_on_answer]=[uuid_displace 97d0ed93-627c-4e72-a36c-d5e3fadd74ba start /usr/local/freeswitch/sounds/Answering_Machine.wav 0 mr]
EXECUTE sofia/internal/1000@192.168.234.131 answer()
2018-08-24 13:53:09.184017 [DEBUG] switch_core_media.c:8146 Audio params are unchanged for sofia/internal/1000@192.168.234.131.
2018-08-24 13:53:09.184017 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/1000@192.168.234.131:
v=0
o=FreeSWITCH 1535121259 1535121261 IN IP4 192.168.234.131
s=FreeSWITCH
c=IN IP4 192.168.234.131
t=0 0
m=audio 22730 RTP/AVP 96 101
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:101 telephone-event/48000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2018-08-24 13:53:09.184017 [NOTICE] mod_dptools.c:1357 Channel [sofia/internal/1000@192.168.234.131] has been answered
2018-08-24 13:53:09.184017 [DEBUG] switch_channel.c:3579 sofia/internal/1000@192.168.234.131 process uuid_displace 97d0ed93-627c-4e72-a36c-d5e3fadd74ba start /usr/local/freeswitch/sounds/Answering_Machine.wav 0 mr: uuid_displace(97d0ed93-627c-4e72-a36c-d5e3fadd74ba start /usr/local/freeswitch/sounds/Answering_Machine.wav 0 mr)

2018-08-24 13:53:09.184017 [DEBUG] switch_core_file.c:358 File /usr/local/freeswitch/sounds/Answering_Machine.wav sample rate 96000 doesn't match requested rate 48000
2018-08-24 13:53:09.184017 [WARNING] switch_core_file.c:376 File has 2 channels, muxing to 1 channel will occur.
2018-08-24 13:53:09.184017 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@192.168.234.131 entering state [completed][200]
2018-08-24 13:53:09.184017 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/internal/1000@192.168.234.131
2018-08-24 13:53:09.184017 [DEBUG] switch_channel.c:3781 (sofia/internal/1000@192.168.234.131) Callstate Change EARLY -> ACTIVE
EXECUTE sofia/internal/1000@192.168.234.131 waitforresult(ivr/ivr-one_moment_please.wav)