2018-08-16 15:18:49.953089 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/7002128858@10.10.10.20 [640d9131-f2fa-4bee-82d1-d7435082f38d]
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7002128858@10.10.10.20) Running State Change CS_NEW (Cur 1 Tot 47)
2018-08-16 15:18:49.953089 [DEBUG] sofia.c:9873 sofia/internal/7002128858@10.10.10.20 receiving invite from 10.10.10.34:5060 version: 1.6.20 -37-987c9b9 64bit
2018-08-16 15:18:49.953089 [DEBUG] sofia.c:9989 IP 10.10.10.34 Approved by acl "caztel[]". Access Granted.
2018-08-16 15:18:49.953089 [DEBUG] sofia.c:7084 Channel sofia/internal/7002128858@10.10.10.20 entering state [received][100]
2018-08-16 15:18:49.953089 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=CiscoSystemsSIP-GW-UserAgent 3034 1151 IN IP4 10.10.10.20
s=SIP Call
c=IN IP4 10.10.10.20
t=0 0
m=audio 19048 RTP/AVP 0
c=IN IP4 10.10.10.20
a=rtpmap:0 PCMU/8000
a=ptime:20

2018-08-16 15:18:49.953089 [DEBUG] sofia.c:7486 (sofia/internal/7002128858@10.10.10.20) State Change CS_NEW -> CS_INIT
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/7002128858@10.10.10.20) State NEW
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7002128858@10.10.10.20) Running State Change CS_INIT (Cur 1 Tot 47)
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/7002128858@10.10.10.20) State INIT
2018-08-16 15:18:49.953089 [DEBUG] mod_sofia.c:90 sofia/internal/7002128858@10.10.10.20 SOFIA INIT
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:40 sofia/internal/7002128858@10.10.10.20 Standard INIT
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/7002128858@10.10.10.20) State Change CS_INIT -> CS_ROUTING
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/7002128858@10.10.10.20) State INIT going to sleep
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7002128858@10.10.10.20) Running State Change CS_ROUTING (Cur 1 Tot 47)
2018-08-16 15:18:49.953089 [DEBUG] switch_channel.c:2249 (sofia/internal/7002128858@10.10.10.20) Callstate Change DOWN -> RINGING
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/7002128858@10.10.10.20) State ROUTING
2018-08-16 15:18:49.953089 [DEBUG] mod_sofia.c:143 sofia/internal/7002128858@10.10.10.20 SOFIA ROUTING
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:236 sofia/internal/7002128858@10.10.10.20 Standard ROUTING
2018-08-16 15:18:49.953089 [INFO] mod_dialplan_xml.c:637 Processing 7002128858 <7002128858>->7002320710 in context public
Dialplan: sofia/internal/7002128858@10.10.10.20 parsing [public->unloop] continue=false
Dialplan: sofia/internal/7002128858@10.10.10.20 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/7002128858@10.10.10.20 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/7002128858@10.10.10.20 parsing [public->outside_call] continue=true
Dialplan: sofia/internal/7002128858@10.10.10.20 Absolute Condition [outside_call]
Dialplan: sofia/internal/7002128858@10.10.10.20 Action set(outside_call=true)
Dialplan: sofia/internal/7002128858@10.10.10.20 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/7002128858@10.10.10.20 parsing [public->call_debug] continue=true
Dialplan: sofia/internal/7002128858@10.10.10.20 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/7002128858@10.10.10.20 parsing [public->ivr_710] continue=false
Dialplan: sofia/internal/7002128858@10.10.10.20 Regex (PASS) [ivr_710] destination_number(7002320710) =~ /^(7002320710)$/ break=on-false
Dialplan: sofia/internal/7002128858@10.10.10.20 Action lua(ivr_710.lua)
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/7002128858@10.10.10.20) State Change CS_ROUTING -> CS_EXECUTE
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/7002128858@10.10.10.20) State ROUTING going to sleep
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7002128858@10.10.10.20) Running State Change CS_EXECUTE (Cur 1 Tot 47)
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/7002128858@10.10.10.20) State EXECUTE
2018-08-16 15:18:49.953089 [DEBUG] mod_sofia.c:198 sofia/internal/7002128858@10.10.10.20 SOFIA EXECUTE
2018-08-16 15:18:49.953089 [DEBUG] switch_core_state_machine.c:328 sofia/internal/7002128858@10.10.10.20 Standard EXECUTE
EXECUTE sofia/internal/7002128858@10.10.10.20 set(outside_call=true)
2018-08-16 15:18:49.953089 [DEBUG] mod_dptools.c:1548 SET sofia/internal/7002128858@10.10.10.20 [outside_call]=[true]
EXECUTE sofia/internal/7002128858@10.10.10.20 export(RFC2822_DATE=Thu, 16 Aug 2018 15:18:49 -0400)
2018-08-16 15:18:49.953089 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 16 Aug 2018 15:18:49 -0400]
EXECUTE sofia/internal/7002128858@10.10.10.20 lua(ivr_710.lua)
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:3916 Activate Buggy RFC2833 Mode!
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/7002128858@10.10.10.20 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2018-08-16 15:18:49.953089 [DEBUG] switch_core_codec.c:111 sofia/internal/7002128858@10.10.10.20 Original read codec set to PCMU:0
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:4738 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:4767 sofia/internal/7002128858@10.10.10.20 Set 2833 dtmf send payload to 101 recv payload to 101
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/7002128858@10.10.10.20] 192.168.4.107 port 32538 -> 10.10.10.20 port 19048 codec: 0 ms: 20
2018-08-16 15:18:49.953089 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:7180 sofia/internal/7002128858@10.10.10.20 Set 2833 dtmf send payload to 101
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:7187 sofia/internal/7002128858@10.10.10.20 Set 2833 dtmf receive payload to 101
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:7210 sofia/internal/7002128858@10.10.10.20 Set rtp dtmf delay to 40
2018-08-16 15:18:49.953089 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/7002128858@10.10.10.20!
2018-08-16 15:18:49.953089 [DEBUG] switch_channel.c:3474 (sofia/internal/7002128858@10.10.10.20) Callstate Change RINGING -> EARLY
2018-08-16 15:18:49.953089 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/internal/7002128858@10.10.10.20.
2018-08-16 15:18:49.953089 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/7002128858@10.10.10.20:
v=0
o=FreeSWITCH 1534414591 1534414592 IN IP4 192.168.4.107
s=FreeSWITCH
c=IN IP4 192.168.4.107
t=0 0
m=audio 32538 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

2018-08-16 15:18:49.953089 [NOTICE] switch_cpp.cpp:685 Channel [sofia/internal/7002128858@10.10.10.20] has been answered
2018-08-16 15:18:49.953089 [DEBUG] switch_channel.c:3773 (sofia/internal/7002128858@10.10.10.20) Callstate Change EARLY -> ACTIVE
2018-08-16 15:18:49.953089 [DEBUG] sofia.c:7084 Channel sofia/internal/7002128858@10.10.10.20 entering state [completed][200]
2018-08-16 15:18:50.232967 [DEBUG] switch_ivr_play_say.c:3025 OPEN TTS watson_ws
2018-08-16 15:18:50.232967 [DEBUG] switch_ivr_play_say.c:3035 Raw Codec Activated
2018-08-16 15:18:50.232967 [INFO] watson_tts_ws.c:259 feed tts welcome to caztel 10 10 710. This is jenny speaking. How many I help you?
2018-08-16 15:18:50.932967 [DEBUG] watson_tts_ws.c:281 read: {
   "binary_streams": [
      {
         "content_type": "audio/l16;channels=1;rate=8000"
      }
   ]
}
2018-08-16 15:18:50.932967 [DEBUG] switch_ivr_play_say.c:2729 Speaking text: welcome to caztel 10 10 710. This is jenny speaking. How many I help you?
2018-08-16 15:18:51.692967 [NOTICE] watson_tts_ws.c:130 watson tts read thread start
2018-08-16 15:18:51.692967 [DEBUG] sofia.c:7084 Channel sofia/internal/7002128858@10.10.10.20 entering state [ready][200]
2018-08-16 15:18:51.692967 [NOTICE] watson_tts_ws.c:165 watson read thread done
2018-08-16 15:18:51.712967 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2018-08-16 15:18:58.012967 [DEBUG] switch_ivr_play_say.c:2907 done speaking text
EXECUTE sofia/internal/7002128858@10.10.10.20 detect_speech(watson default default default)
2018-08-16 15:18:58.272967 [INFO] watson_asr_ws.c:274 codec = L16, rate = 8000, dest = default
2018-08-16 15:18:58.272967 [DEBUG] switch_core_media_bug.c:945 Attaching BUG to sofia/internal/7002128858@10.10.10.20
2018-08-16 15:18:58.272967 [DEBUG] watson_asr_ws.c:322 Connecting to url wss://stream.watsonplatform.net/speech-to-text/api/v1/recognize?watson-token=NDOYeMzORpta%2BN6MCcDn1JnpFeEQz%2B5NlxorLnim24Yqu2yFffg5KgYB0uZ4Gs316GeM7cXUttb1f6ZtCOJtSmmCnLSNF1%2BF7XuH%2BWyrtG%2F1cjHmtFLXTUKFMC%2B45tQ0SOPBsG37fiILzL1mz4OAFxfPp9CvxZP5DBIa79Rz9BptsJ4D0Ya90M4QvVqIOtzyHzXywAP51sIbWp54Bedq0UBSQKZp1lJLi3%2Bylvk99nLcY9b6PBM6M66W9hb%2F5NuBqpM%2BRropr0fJrcZpTo7AQ1FfIT6Ks7z%2FNR1DQLKDd%2Ff4LjB8vOW08kiTm5a%2B5Rxx7AkxVp%2FXwOM2Ei%2FqI2QyOQAcbyoeOGPtIt2pwa1ecMDi1RrI%2Fgr7JyP5ZRiPPxycnLCGiIoPT3aL%2FtdZTuQajieI4czuUanZbFK%2FEwIyE9lTEFm4Yge2OGjVy5b9402ZmgPaxxslbkKltMxEu5eM3MLIOuWPuxQy8dE5mo5HD8We3CgAwmpwJcN6ptzRoSVTH6EBV5UGjXcEWy4ivxAiNEDBrkFErMh92R%2BiBaCSU%2F%2FOzNTrDtdgnQuCZOdm%2FMm8JgDOTgHWHh%2FySawq8Rp9y16fwJTxk7KliCDYhEt9REE0Mwvt%2FLfMiEONNGi5AJgUZ9BpJ0s01BoRVEH4F27y1XVQd%2BM4PSvpRhvnVdORjQcv61KFuThD7gCTdQXUvi%2F%2Fhkq1ii9nGa7A8cgVjzJhk7Rl9OOW1mIlWd713hUiEFMG7cIwB9LNQmJqZqB5IxHiXmxKd1F%2Fm1y6kkcpS98iNZz3OIlk4NHHqHi4CHOvGKVIX%2FD1cN0MIs5SVa5zkz8%2BJQXjS6Cg6tBP7emRr47Cx52bBl9lvynDZGT16nd0VCJobJc83%2Fl7NVt%2FRpb8INp9ia%2FAQ8UfXiTLPshT9F2OoqBBjodpoMwgYACWRDkp%2Bf8GQ8yOpMpbTSYLKy8orMO362XLlf8R2kxMk5VBJHwcROUdQdK%2FWNUjDwgr5BjtjPo%3D&model=en-US_NarrowbandModel
2018-08-16 15:18:58.593036 [INFO] watson_asr_ws.c:355 read: 27 {
   "state": "listening"
}
2018-08-16 15:18:58.593036 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2018-08-16 15:18:58.593036 [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2018-08-16 15:19:02.452967 [INFO] watson_asr_ws.c:462 Silence detected, sending stop.
2018-08-16 15:19:03.052968 [DEBUG] watson_asr_ws.c:175 read {
   "results": [],
   "result_index": 0
}
2018-08-16 15:19:03.052968 [DEBUG] watson_asr_ws.c:569 Recognized: {
   "results": [],
   "result_index": 0
}, Confidence: 0.000000, Confidence-Threshold: 0
EXECUTE sofia/internal/7002128858@10.10.10.20 detect_speech(resume)
2018-08-16 15:19:03.072967 [DEBUG] watson_asr_ws.c:538 Manually Resuming
2018-08-16 15:19:09.572967 [INFO] watson_asr_ws.c:462 Silence detected, sending stop.
2018-08-16 15:19:09.572967 [DEBUG] watson_asr_ws.c:175 read {
   "state": "listening"
}
2018-08-16 15:19:10.152967 [DEBUG] watson_asr_ws.c:175 read {
   "results": [],
   "result_index": 0
}
2018-08-16 15:19:10.152967 [DEBUG] watson_asr_ws.c:569 Recognized: {
   "results": [],
   "result_index": 0
}, Confidence: 0.000000, Confidence-Threshold: 0
EXECUTE sofia/internal/7002128858@10.10.10.20 detect_speech(resume)
2018-08-16 15:19:10.152967 [DEBUG] watson_asr_ws.c:538 Manually Resuming
2018-08-16 15:19:15.972968 [NOTICE] sofia.c:1012 Hangup sofia/internal/7002128858@10.10.10.20 [CS_EXECUTE] [NORMAL_CLEARING]
2018-08-16 15:19:15.972968 [DEBUG] switch_ivr_play_say.c:1942 done playing file silence_stream://90000000
2018-08-16 15:19:15.972968 [DEBUG] switch_cpp.cpp:1112 sofia/internal/7002128858@10.10.10.20 destroy/unlink session from object
2018-08-16 15:19:15.972968 [DEBUG] switch_core_session.c:2815 sofia/internal/7002128858@10.10.10.20 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/7002128858@10.10.10.20) State EXECUTE going to sleep
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7002128858@10.10.10.20) Running State Change CS_HANGUP (Cur 1 Tot 47)
2018-08-16 15:19:15.972968 [DEBUG] switch_core_media_bug.c:1298 Removing BUG from sofia/internal/7002128858@10.10.10.20
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/7002128858@10.10.10.20) Callstate Change ACTIVE -> HANGUP
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/7002128858@10.10.10.20) State HANGUP
2018-08-16 15:19:15.972968 [DEBUG] mod_sofia.c:438 Channel sofia/internal/7002128858@10.10.10.20 hanging up, cause: NORMAL_CLEARING
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:60 sofia/internal/7002128858@10.10.10.20 Standard HANGUP, cause: NORMAL_CLEARING
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/7002128858@10.10.10.20) State HANGUP going to sleep
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/7002128858@10.10.10.20) State Change CS_HANGUP -> CS_REPORTING
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/7002128858@10.10.10.20) Running State Change CS_REPORTING (Cur 1 Tot 47)
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/7002128858@10.10.10.20) State REPORTING
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:174 sofia/internal/7002128858@10.10.10.20 Standard REPORTING, cause: NORMAL_CLEARING
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/7002128858@10.10.10.20) State REPORTING going to sleep
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/7002128858@10.10.10.20) State Change CS_REPORTING -> CS_DESTROY
2018-08-16 15:19:15.972968 [DEBUG] switch_core_session.c:1665 Session 47 (sofia/internal/7002128858@10.10.10.20) Locked, Waiting on external entities
2018-08-16 15:19:15.972968 [NOTICE] switch_core_session.c:1683 Session 47 (sofia/internal/7002128858@10.10.10.20) Ended
2018-08-16 15:19:15.972968 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/7002128858@10.10.10.20 [CS_DESTROY]
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/7002128858@10.10.10.20) Running State Change CS_DESTROY (Cur 0 Tot 47)
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/7002128858@10.10.10.20) State DESTROY
2018-08-16 15:19:15.972968 [DEBUG] mod_sofia.c:343 sofia/internal/7002128858@10.10.10.20 SOFIA DESTROY
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:181 sofia/internal/7002128858@10.10.10.20 Standard DESTROY
2018-08-16 15:19:15.972968 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/7002128858@10.10.10.20) State DESTROY going to sleep
freeswitch@froakie>