2020-07-09 21:16:47.771541 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/718291782@43.225.1.1 [bf481e37-12bd-4a87-a12c-cbcf7ffb5212]
2020-07-09 21:16:47.771541 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/718291782@43.225.1.1) Running State Change CS_NEW (Cur 1 Tot 1)
2020-07-09 21:16:47.771541 [DEBUG] sofia.c:10279 sofia/internal/718291782@43.225.1.1 receiving invite from 43.225.1.1:5060 version: 1.10.4-dev git 00113c4 2020-06-29 18:46:18Z 64bit
2020-07-09 21:16:47.771541 [DEBUG] sofia.c:10373 verifying acl "domains" for ip/port 43.225.1.1:0.
2020-07-09 21:16:47.771541 [DEBUG] sofia.c:10402 IP 43.225.1.1 Approved by acl "domains[]". Access Granted.
2020-07-09 21:16:47.791476 [DEBUG] sofia.c:7325 Channel sofia/internal/718291782@43.225.1.1 entering state [received][100]
2020-07-09 21:16:47.791476 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=- 77028 77028 IN IP4 192.1.1.1
s=-
c=IN IP4 43.225.1.1
t=0 0
m=audio 48346 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=ptime:40
m=image 46286 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxUdpEC:t38UDPRedundancy
a=T38FaxRateManagement:transferredTCF
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=direction:active

2020-07-09 21:16:47.791476 [DEBUG] sofia.c:7738 (sofia/internal/718291782@43.225.1.1) State Change CS_NEW -> CS_INIT
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/718291782@43.225.1.1) State NEW
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/718291782@43.225.1.1) Running State Change CS_INIT (Cur 1 Tot 1)
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/718291782@43.225.1.1) State INIT
2020-07-09 21:16:47.791476 [DEBUG] mod_sofia.c:93 sofia/internal/718291782@43.225.1.1 SOFIA INIT
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:40 sofia/internal/718291782@43.225.1.1 Standard INIT
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/718291782@43.225.1.1) State Change CS_INIT -> CS_ROUTING
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/718291782@43.225.1.1) State INIT going to sleep
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/718291782@43.225.1.1) Running State Change CS_ROUTING (Cur 1 Tot 1)
2020-07-09 21:16:47.791476 [DEBUG] switch_channel.c:2332 (sofia/internal/718291782@43.225.1.1) Callstate Change DOWN -> RINGING
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/718291782@43.225.1.1) State ROUTING
2020-07-09 21:16:47.791476 [DEBUG] mod_sofia.c:154 sofia/internal/718291782@43.225.1.1 SOFIA ROUTING
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:236 sofia/internal/718291782@43.225.1.1 Standard ROUTING
2020-07-09 21:16:47.791476 [INFO] mod_dialplan_xml.c:637 Processing 718291782 <718291782>->73715050001110 in context public
Dialplan: sofia/internal/718291782@43.225.1.1 parsing [public->unloop] continue=false
Dialplan: sofia/internal/718291782@43.225.1.1 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/718291782@43.225.1.1 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/718291782@43.225.1.1 parsing [public->outside_call] continue=true
Dialplan: sofia/internal/718291782@43.225.1.1 Absolute Condition [outside_call]
Dialplan: sofia/internal/718291782@43.225.1.1 Action set(outside_call=true)
Dialplan: sofia/internal/718291782@43.225.1.1 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/718291782@43.225.1.1 parsing [public->call_debug] continue=true
Dialplan: sofia/internal/718291782@43.225.1.1 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/718291782@43.225.1.1 parsing [public->public_extensions] continue=false
Dialplan: sofia/internal/718291782@43.225.1.1 Regex (FAIL) [public_extensions] destination_number(73715050001110) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/718291782@43.225.1.1 parsing [public->public_conference_extensions] continue=false
Dialplan: sofia/internal/718291782@43.225.1.1 Regex (FAIL) [public_conference_extensions] destination_number(73715050001110) =~ /^(3[5-8][01][0-9])$/ break=on-false
Dialplan: sofia/internal/718291782@43.225.1.1 parsing [public->local-delay-echo] continue=false
Dialplan: sofia/internal/718291782@43.225.1.1 Regex (PASS) [local-delay-echo] destination_number(73715050001110) =~ /^73715050001110$/ break=on-false
Dialplan: sofia/internal/718291782@43.225.1.1 Action answer()
Dialplan: sofia/internal/718291782@43.225.1.1 Action delay_echo(5000)
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/718291782@43.225.1.1) State Change CS_ROUTING -> CS_EXECUTE
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/718291782@43.225.1.1) State ROUTING going to sleep
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/718291782@43.225.1.1) Running State Change CS_EXECUTE (Cur 1 Tot 1)
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/718291782@43.225.1.1) State EXECUTE
2020-07-09 21:16:47.791476 [DEBUG] mod_sofia.c:209 sofia/internal/718291782@43.225.1.1 SOFIA EXECUTE
2020-07-09 21:16:47.791476 [DEBUG] switch_core_state_machine.c:329 sofia/internal/718291782@43.225.1.1 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/718291782@43.225.1.1 set(outside_call=true)
2020-07-09 21:16:47.791476 [CONSOLE] sofia_presence.c:1619 Event Thread Started
2020-07-09 21:16:47.791476 [DEBUG] mod_dptools.c:1672 SET sofia/internal/718291782@43.225.1.1 [outside_call]=[true]
EXECUTE [depth=0] sofia/internal/718291782@43.225.1.1 export(RFC2822_DATE=Thu, 09 Jul 2020 21:16:47 +0500)
2020-07-09 21:16:47.791476 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 09 Jul 2020 21:16:47 +0500]
EXECUTE [depth=0] sofia/internal/718291782@43.225.1.1 answer()
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[G722:9:8000:20:64000:1]
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[PCMU:0:8000:20:64000:1]
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:5630 Audio Codec Compare [PCMU:0:8000:20:64000:1] is saved as a near-match
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[PCMA:8:8000:20:64000:1]
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:5701 Substituting codec PCMU@40i@8000h@1c
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/718291782@43.225.1.1 PCMU/8000 40 ms 320 samples 64000 bits 1 channels
2020-07-09 21:16:47.791476 [DEBUG] switch_core_codec.c:111 sofia/internal/718291782@43.225.1.1 Original read codec set to PCMU:0
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:5882 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:5911 sofia/internal/718291782@43.225.1.1 Set 2833 dtmf send payload to 101 recv payload to 101
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:5172 sofia/internal/718291782@43.225.1.1 T38 REFUSE on request
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/internal/718291782@43.225.1.1] 43.225.1.2 port 25500 -> 43.225.1.1 port 48346 codec: 0 ms: 40
2020-07-09 21:16:47.791476 [DEBUG] switch_rtp.c:4431 Starting timer [soft] 320 bytes per 40ms
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:8977 sofia/internal/718291782@43.225.1.1 Set 2833 dtmf send payload to 101
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:8984 sofia/internal/718291782@43.225.1.1 Set 2833 dtmf receive payload to 101
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:9007 sofia/internal/718291782@43.225.1.1 Set rtp dtmf delay to 40
2020-07-09 21:16:47.791476 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/718291782@43.225.1.1!
2020-07-09 21:16:47.791476 [DEBUG] switch_channel.c:3565 (sofia/internal/718291782@43.225.1.1) Callstate Change RINGING -> EARLY
2020-07-09 21:16:47.791476 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/internal/718291782@43.225.1.1.
2020-07-09 21:16:47.791476 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/718291782@43.225.1.1:
v=0
o=FreeSWITCH 1594285907 1594285908 IN IP4 43.225.1.2
s=FreeSWITCH
c=IN IP4 43.225.1.2
t=0 0
m=audio 25500 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
a=sendrecv
m=image 0 UDPTL T38

2020-07-09 21:16:47.791476 [NOTICE] mod_dptools.c:1406 Channel [sofia/internal/718291782@43.225.1.1] has been answered
2020-07-09 21:16:47.791476 [DEBUG] switch_channel.c:3865 (sofia/internal/718291782@43.225.1.1) Callstate Change EARLY -> ACTIVE
2020-07-09 21:16:47.791476 [DEBUG] sofia.c:7325 Channel sofia/internal/718291782@43.225.1.1 entering state [completed][200]
EXECUTE [depth=0] sofia/internal/718291782@43.225.1.1 delay_echo(5000)
2020-07-09 21:16:47.791476 [DEBUG] switch_ivr.c:3552 Setting delay to 5000ms (125 frames)
2020-07-09 21:16:47.851575 [DEBUG] sofia.c:7325 Channel sofia/internal/718291782@43.225.1.1 entering state [ready][200]
freeswitch@ylinx-redtone-LIBOX>
2020-07-09 21:17:41.511554 [NOTICE] sofia.c:1089 Hangup sofia/internal/718291782@43.225.1.1 [CS_EXECUTE] [NORMAL_CLEARING]
2020-07-09 21:17:41.511554 [DEBUG] switch_core_session.c:2905 sofia/internal/718291782@43.225.1.1 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/718291782@43.225.1.1) State EXECUTE going to sleep
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/718291782@43.225.1.1) Running State Change CS_HANGUP (Cur 1 Tot 1)
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/718291782@43.225.1.1) Callstate Change ACTIVE -> HANGUP
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/718291782@43.225.1.1) State HANGUP
2020-07-09 21:17:41.511554 [DEBUG] mod_sofia.c:453 Channel sofia/internal/718291782@43.225.1.1 hanging up, cause: NORMAL_CLEARING
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:60 sofia/internal/718291782@43.225.1.1 Standard HANGUP, cause: NORMAL_CLEARING
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/718291782@43.225.1.1) State HANGUP going to sleep
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/718291782@43.225.1.1) State Change CS_HANGUP -> CS_REPORTING
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/718291782@43.225.1.1) Running State Change CS_REPORTING (Cur 1 Tot 1)
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/718291782@43.225.1.1) State REPORTING
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:174 sofia/internal/718291782@43.225.1.1 Standard REPORTING, cause: NORMAL_CLEARING
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/718291782@43.225.1.1) State REPORTING going to sleep
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/718291782@43.225.1.1) State Change CS_REPORTING -> CS_DESTROY
2020-07-09 21:17:41.511554 [DEBUG] switch_core_session.c:1726 Session 1 (sofia/internal/718291782@43.225.1.1) Locked, Waiting on external entities
2020-07-09 21:17:41.511554 [NOTICE] switch_core_session.c:1744 Session 1 (sofia/internal/718291782@43.225.1.1) Ended
2020-07-09 21:17:41.511554 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/718291782@43.225.1.1 [CS_DESTROY]
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/718291782@43.225.1.1) Running State Change CS_DESTROY (Cur 0 Tot 1)
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/718291782@43.225.1.1) State DESTROY
2020-07-09 21:17:41.511554 [DEBUG] mod_sofia.c:364 sofia/internal/718291782@43.225.1.1 SOFIA DESTROY
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:181 sofia/internal/718291782@43.225.1.1 Standard DESTROY
2020-07-09 21:17:41.511554 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/718291782@43.225.1.1) State DESTROY going to sleep