1. 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]
2. 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)
3. 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
4. 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.
5. 2018-08-24 13:53:09.083869 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@192.168.234.131) State NEW
6. 2018-08-24 13:53:09.083869 [DEBUG] sofia.c:2413 detaching session 97d0ed93-627c-4e72-a36c-d5e3fadd74ba
7. 2018-08-24 13:53:09.143709 [DEBUG] sofia.c:2522 Re-attaching to session 97d0ed93-627c-4e72-a36c-d5e3fadd74ba
8. 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
9. 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.
10. 2018-08-24 13:53:09.163814 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@192.168.234.131 entering state [received][100]
11. 2018-08-24 13:53:09.163814 [DEBUG] sofia.c:7301 Remote SDP:
12. v=0
13. o=1000 2995 3750 IN IP4 192.168.234.1
14. s=Talk
15. c=IN IP4 192.168.234.1
16. t=0 0
17. a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
18. m=audio 7078 RTP/AVP 96 97 98 0 8 101 99 100
19. a=rtpmap:96 opus/48000/2
20. a=fmtp:96 useinbandfec=1
21. a=rtpmap:97 speex/16000
22. a=fmtp:97 vbr=on
23. a=rtpmap:98 speex/8000
24. a=fmtp:98 vbr=on
25. a=rtpmap:101 telephone-event/48000
26. a=rtpmap:99 telephone-event/16000
27. a=rtpmap:100 telephone-event/8000
28. a=rtcp-fb:* trr-int 5000
29. a=rtcp-fb:* ccm tmmbr
30.  
31. 2018-08-24 13:53:09.163814 [DEBUG] sofia.c:7693 (sofia/internal/1000@192.168.234.131) State Change CS_NEW -> CS_INIT
32. 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)
33. 2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@192.168.234.131) State INIT
34. 2018-08-24 13:53:09.163814 [DEBUG] mod_sofia.c:93 sofia/internal/1000@192.168.234.131 SOFIA INIT
35. 2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@192.168.234.131 Standard INIT
36. 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
37. 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
38. 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)
39. 2018-08-24 13:53:09.163814 [DEBUG] switch_channel.c:2249 (sofia/internal/1000@192.168.234.131) Callstate Change DOWN -> RINGING
40. 2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@192.168.234.131) State ROUTING
41. 2018-08-24 13:53:09.163814 [DEBUG] mod_sofia.c:154 sofia/internal/1000@192.168.234.131 SOFIA ROUTING
42. 2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1000@192.168.234.131 Standard ROUTING
43. 2018-08-24 13:53:09.163814 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->amd_test in context default
44. Dialplan: sofia/internal/1000@192.168.234.131 parsing [default->amd_test] continue=false
45. Dialplan: sofia/internal/1000@192.168.234.131 Regex (PASS) [amd_test] destination_number(amd_test) =~ /^(amd_test)$/ break=on-false
46. Dialplan: sofia/internal/1000@192.168.234.131 Action set(media_bug_answer_req=true)
47. Dialplan: sofia/internal/1000@192.168.234.131 Action set(amd_execute_on_machine=transfer machine_found XML default)
48. Dialplan: sofia/internal/1000@192.168.234.131 Action set(amd_execute_on_person=transfer person_found XML default)
49. Dialplan: sofia/internal/1000@192.168.234.131 Action set(amd_execute_on_unsure=transfer amd_unsure XML default)
50. Dialplan: sofia/internal/1000@192.168.234.131 Action voice_start()
51. Dialplan: sofia/internal/1000@192.168.234.131 Action set(api_on_answer=uuid_displace ${uuid} start ${sounds_dir}/Answering_Machine.wav 0 mr)
52. Dialplan: sofia/internal/1000@192.168.234.131 Action answer()
53. Dialplan: sofia/internal/1000@192.168.234.131 Action waitforresult(ivr/ivr-one_moment_please.wav)
54. Dialplan: sofia/internal/1000@192.168.234.131 Action sleep(200)
55. Dialplan: sofia/internal/1000@192.168.234.131 Action playback(tone_stream://%(200,100,500,400,300,50,25);loops=2)
56. Dialplan: sofia/internal/1000@192.168.234.131 Action sleep(200)
57. Dialplan: sofia/internal/1000@192.168.234.131 Action log(CRIT AMD Result is => ${amd_status} => ${amd_result})
58. Dialplan: sofia/internal/1000@192.168.234.131 Action hangup()
59. 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
60. 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
61. 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)
62. 2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1000@192.168.234.131) State EXECUTE
63. 2018-08-24 13:53:09.163814 [DEBUG] mod_sofia.c:209 sofia/internal/1000@192.168.234.131 SOFIA EXECUTE
64. 2018-08-24 13:53:09.163814 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1000@192.168.234.131 Standard EXECUTE
65. EXECUTE sofia/internal/1000@192.168.234.131 set(media_bug_answer_req=true)
66. 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]
67. EXECUTE sofia/internal/1000@192.168.234.131 set(amd_execute_on_machine=transfer machine_found XML default)
68. 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]
69. EXECUTE sofia/internal/1000@192.168.234.131 set(amd_execute_on_person=transfer person_found XML default)
70. 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]
71. EXECUTE sofia/internal/1000@192.168.234.131 set(amd_execute_on_unsure=transfer amd_unsure XML default)
72. 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]
73. 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
74. 2018-08-24 13:53:09.163814 [INFO] switch_core_session.c:2710 Sending early media
75. 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]
76. 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
77. 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]
78. 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]
79. 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]
80. 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]
81. 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]
82. 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]
83. 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]
84. 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]
85. 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]
86. 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]
87. 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]
88. 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]
89. 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]
90. 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]
91. 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
92. 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]
93. 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]
94. 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]
95. 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]
96. 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]
97. 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
98. 2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5045 Set telephone-event payload to 101@48000
99. 2018-08-24 13:53:09.163814 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps]
100. 2018-08-24 13:53:09.163814 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps]
101. 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
102. 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
103. 2018-08-24 13:53:09.163814 [DEBUG] switch_core_media.c:5388 Set telephone-event payload to 101@48000
104. 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
105. 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
106. 2018-08-24 13:53:09.163814 [DEBUG] switch_rtp.c:4189 Starting timer [soft] 960 bytes per 20ms
107. 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
108. 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
109. 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
110. 2018-08-24 13:53:09.184017 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1000@192.168.234.131!
111. 2018-08-24 13:53:09.184017 [DEBUG] switch_channel.c:3482 (sofia/internal/1000@192.168.234.131) Callstate Change RINGING -> EARLY
112. 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.
113. 2018-08-24 13:53:09.184017 [DEBUG] mod_sofia.c:2512 Ring SDP:
114. v=0
115. o=FreeSWITCH 1535121259 1535121260 IN IP4 192.168.234.131
116. s=FreeSWITCH
117. c=IN IP4 192.168.234.131
118. t=0 0
119. m=audio 22730 RTP/AVP 96 101
120. a=rtpmap:96 opus/48000/2
121. a=fmtp:96 useinbandfec=1
122. a=rtpmap:101 telephone-event/48000
123. a=fmtp:101 0-16
124. a=ptime:20
125. a=sendrecv
126.  
127. EXECUTE sofia/internal/1000@192.168.234.131 voice_start()
128. 2018-08-24 13:53:09.184017 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/internal/1000@192.168.234.131
129. 2018-08-24 13:53:09.184017 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@192.168.234.131 entering state [early][183]
130. 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)
131. 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]
132. EXECUTE sofia/internal/1000@192.168.234.131 answer()
133. 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.
134. 2018-08-24 13:53:09.184017 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/1000@192.168.234.131:
135. v=0
136. o=FreeSWITCH 1535121259 1535121261 IN IP4 192.168.234.131
137. s=FreeSWITCH
138. c=IN IP4 192.168.234.131
139. t=0 0
140. m=audio 22730 RTP/AVP 96 101
141. a=rtpmap:96 opus/48000/2
142. a=fmtp:96 useinbandfec=1
143. a=rtpmap:101 telephone-event/48000
144. a=fmtp:101 0-16
145. a=ptime:20
146. a=sendrecv
147.  
148. 2018-08-24 13:53:09.184017 [NOTICE] mod_dptools.c:1357 Channel [sofia/internal/1000@192.168.234.131] has been answered
149. 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)
150.  
151. 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
152. 2018-08-24 13:53:09.184017 [WARNING] switch_core_file.c:376 File has 2 channels, muxing to 1 channel will occur.
153. 2018-08-24 13:53:09.184017 [DEBUG] sofia.c:7291 Channel sofia/internal/1000@192.168.234.131 entering state [completed][200]
154. 2018-08-24 13:53:09.184017 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/internal/1000@192.168.234.131
155. 2018-08-24 13:53:09.184017 [DEBUG] switch_channel.c:3781 (sofia/internal/1000@192.168.234.131) Callstate Change EARLY -> ACTIVE
156. EXECUTE sofia/internal/1000@192.168.234.131 waitforresult(ivr/ivr-one_moment_please.wav)
157.