span style="color: cornflowerblue; font-weight: bold;"> freeswitch@internal> 2018-07-04 20:43:46.391945 [NOTICE] switch_channel.c:1075 New Channel sofia/default/7120041412@103.226.53.10 [20dd777c-7f77-11e8-894d-555946780031]
2018-07-04 20:43:46.391945 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:46.391945 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:46.391945 [DEBUG] switch_core_state_machine.c:472 (sofia/default/7120041412@103.226.53.10) Running State Change CS_NEW
2018-07-04 20:43:46.391945 [DEBUG] sofia.c:8919 sofia/default/7120041412@103.226.53.10 receiving invite from 103.239.77.180:1126 version: 1.4.21 64bit
2018-07-04 20:43:46.391945 [DEBUG] sofia.c:9086 IP 103.239.77.180 Rejected by acl "default". Falling back to Digest auth.
2018-07-04 20:43:46.391945 [WARNING] sofia_reg.c:1742 SIP auth challenge (INVITE) on sofia profile 'default' for [1300368909@103.226.53.10] from ip 103.239.77.180
2018-07-04 20:43:46.391945 [DEBUG] switch_core_state_machine.c:491 (sofia/default/7120041412@103.226.53.10) State NEW
2018-07-04 20:43:46.391945 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:46.391945 [DEBUG] sofia.c:2065 detaching session 20dd777c-7f77-11e8-894d-555946780031
2018-07-04 20:43:46.411947 [DEBUG] sofia.c:2173 Re-attaching to session 20dd777c-7f77-11e8-894d-555946780031
2018-07-04 20:43:46.411947 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:46.411947 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:46.432029 [DEBUG] sofia.c:8919 sofia/default/7120041412@103.226.53.10 receiving invite from 103.239.77.180:1126 version: 1.4.21 64bit
2018-07-04 20:43:46.432029 [DEBUG] sofia.c:9086 IP 103.239.77.180 Rejected by acl "default". Falling back to Digest auth.
2018-07-04 20:43:46.551938 [DEBUG] sofia.c:10184 Setting NAT mode based on via received
2018-07-04 20:43:46.551938 [DEBUG] sofia.c:6634 Channel sofia/default/7120041412@103.226.53.10 entering state [received][100]
2018-07-04 20:43:46.551938 [DEBUG] sofia.c:6644 Remote SDP:
v=0
o=7120041412 8000 8000 IN IP4 192.168.10.192
s=SIP Call
c=IN IP4 192.168.10.192
t=0 0
m=audio 5004 RTP/AVP 0 8 4 18 2 97 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:2 G726-32/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16,32-36,54
a=ptime:20
2018-07-04 20:43:46.551938 [DEBUG] sofia.c:6910 (sofia/default/7120041412@103.226.53.10) State Change CS_NEW -> CS_INIT
2018-07-04 20:43:46.551938 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:46.551938 [DEBUG] switch_core_state_machine.c:472 (sofia/default/7120041412@103.226.53.10) Running State Change CS_INIT
2018-07-04 20:43:46.551938 [DEBUG] switch_core_state_machine.c:512 (sofia/default/7120041412@103.226.53.10) State INIT
2018-07-04 20:43:46.551938 [DEBUG] mod_sofia.c:87 sofia/default/7120041412@103.226.53.10 SOFIA INIT
2018-07-04 20:43:46.551938 [DEBUG] switch_core_state_machine.c:40 sofia/default/7120041412@103.226.53.10 Standard INIT
2018-07-04 20:43:46.551938 [DEBUG] switch_core_state_machine.c:48 (sofia/default/7120041412@103.226.53.10) State Change CS_INIT -> CS_ROUTING
2018-07-04 20:43:46.551938 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:46.551938 [DEBUG] switch_core_state_machine.c:512 (sofia/default/7120041412@103.226.53.10) State INIT going to sleep
2018-07-04 20:43:46.551938 [DEBUG] switch_core_state_machine.c:472 (sofia/default/7120041412@103.226.53.10) Running State Change CS_ROUTING
2018-07-04 20:43:46.551938 [DEBUG] switch_channel.c:2204 (sofia/default/7120041412@103.226.53.10) Callstate Change DOWN -> RINGING
2018-07-04 20:43:46.551938 [DEBUG] switch_core_state_machine.c:528 (sofia/default/7120041412@103.226.53.10) State ROUTING
2018-07-04 20:43:46.551938 [DEBUG] mod_sofia.c:123 sofia/default/7120041412@103.226.53.10 SOFIA ROUTING
2018-07-04 20:43:46.551938 [DEBUG] switch_core_state_machine.c:166 sofia/default/7120041412@103.226.53.10 Standard ROUTING
2018-07-04 20:43:46.551938 [INFO] mod_dialplan_xml.c:635 Processing 7120041412 <7120041412>->1300368909 in context default
Dialplan: sofia/default/7120041412@103.226.53.10 parsing [default->] continue=false
Dialplan: sofia/default/7120041412@103.226.53.10 Regex (PASS) [] destination_number(1300368909) =~ // break=on-false
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(callstart=2018-07-04 10:43:46)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(call_processed=internal)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(originated_destination_number=1300368909)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(hangup_after_bridge=true)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(continue_on_fail=true)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(fax_enable_t38_request=true)
Dialplan: sofia/default/7120041412@103.226.53.10 Action export(t38_passthru=true)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(accountid=28)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(account_type=0)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(resellerid=0)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(accountcode=98055562)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(call_direction=outbound)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(calltype=STANDARD)
Dialplan: sofia/default/7120041412@103.226.53.10 Action sched_hangup(+6000 allotted_timeout)
Dialplan: sofia/default/7120041412@103.226.53.10 Action log(INFO [Customer info] : [Account code: 98055562, Rategroup Id: 1, Called number: 1300368909])
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(origination_rates=ID:7|CODE:^13.*|DESTINATION:Australia|CONNECTIONCOST:0.35000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|RATEGROUP:1|MARKUP:0|ACCID:28)
Dialplan: sofia/default/7120041412@103.226.53.10 Action limit(db 98055562 db_98055562 11)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(effective_destination_number=1300368909)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(termination_rates=ID:7|CODE:^13.*|DESTINATION:Australia|CONNECTIONCOST:0.35000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|TRUNK:2|PROVIDER:2)
Dialplan: sofia/default/7120041412@103.226.53.10 Action export(rtp_append_audio_sdp=a=fmtp:18 annexb=no)
Dialplan: sofia/default/7120041412@103.226.53.10 Action bridge(sofia/gateway/ivox/1300368909)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(effective_destination_number=1300368909)
Dialplan: sofia/default/7120041412@103.226.53.10 Action set(termination_rates=ID:4698|CODE:^13.*|DESTINATION:13 numbers|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|TRUNK:2|PROVIDER:2)
Dialplan: sofia/default/7120041412@103.226.53.10 Action export(rtp_append_audio_sdp=a=fmtp:18 annexb=no)
Dialplan: sofia/default/7120041412@103.226.53.10 Action bridge(sofia/gateway/ivox/1300368909)
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:216 (sofia/default/7120041412@103.226.53.10) State Change CS_ROUTING -> CS_EXECUTE
2018-07-04 20:43:46.672000 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:528 (sofia/default/7120041412@103.226.53.10) State ROUTING going to sleep
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:472 (sofia/default/7120041412@103.226.53.10) Running State Change CS_EXECUTE
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:535 (sofia/default/7120041412@103.226.53.10) State EXECUTE
2018-07-04 20:43:46.672000 [DEBUG] mod_sofia.c:178 sofia/default/7120041412@103.226.53.10 SOFIA EXECUTE
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:258 sofia/default/7120041412@103.226.53.10 Standard EXECUTE
EXECUTE sofia/default/7120041412@103.226.53.10 set(callstart=2018-07-04 10:43:46)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [callstart]=[2018-07-04 10:43:46]
EXECUTE sofia/default/7120041412@103.226.53.10 set(call_processed=internal)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [call_processed]=[internal]
EXECUTE sofia/default/7120041412@103.226.53.10 set(originated_destination_number=1300368909)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [originated_destination_number]=[1300368909]
EXECUTE sofia/default/7120041412@103.226.53.10 set(hangup_after_bridge=true)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [hangup_after_bridge]=[true]
EXECUTE sofia/default/7120041412@103.226.53.10 set(continue_on_fail=true)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [continue_on_fail]=[true]
EXECUTE sofia/default/7120041412@103.226.53.10 set(fax_enable_t38_request=true)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [fax_enable_t38_request]=[true]
EXECUTE sofia/default/7120041412@103.226.53.10 export(t38_passthru=true)
2018-07-04 20:43:46.672000 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [t38_passthru]=[true]
EXECUTE sofia/default/7120041412@103.226.53.10 set(accountid=28)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [accountid]=[28]
EXECUTE sofia/default/7120041412@103.226.53.10 set(account_type=0)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [account_type]=[0]
EXECUTE sofia/default/7120041412@103.226.53.10 set(resellerid=0)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [resellerid]=[0]
EXECUTE sofia/default/7120041412@103.226.53.10 set(accountcode=98055562)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [accountcode]=[98055562]
EXECUTE sofia/default/7120041412@103.226.53.10 set(call_direction=outbound)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [call_direction]=[outbound]
EXECUTE sofia/default/7120041412@103.226.53.10 set(calltype=STANDARD)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [calltype]=[STANDARD]
EXECUTE sofia/default/7120041412@103.226.53.10 sched_hangup(+6000 allotted_timeout)
2018-07-04 20:43:46.672000 [DEBUG] switch_scheduler.c:249 Added task 7 switch_ivr_schedule_hangup (20dd777c-7f77-11e8-894d-555946780031) to run at 1530707026
EXECUTE sofia/default/7120041412@103.226.53.10 log(INFO [Customer info] : [Account code: 98055562, Rategroup Id: 1, Called number: 1300368909])
2018-07-04 20:43:46.672000 [INFO] mod_dptools.c:1670 [Customer info] : [Account code: 98055562, Rategroup Id: 1, Called number: 1300368909]
EXECUTE sofia/default/7120041412@103.226.53.10 set(origination_rates=ID:7|CODE:^13.*|DESTINATION:Australia|CONNECTIONCOST:0.35000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|RATEGROUP:1|MARKUP:0|ACCID:28)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [origination_rates]=[ID:7|CODE:^13.*|DESTINATION:Australia|CONNECTIONCOST:0.35000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|RATEGROUP:1|MARKUP:0|ACCID:28]
EXECUTE sofia/default/7120041412@103.226.53.10 limit(db 98055562 db_98055562 11)
2018-07-04 20:43:46.672000 [DEBUG] switch_limit.c:126 incr called: 98055562_db_98055562 max:11, interval:0
2018-07-04 20:43:46.672000 [DEBUG] mod_db.c:194 Usage for 98055562_db_98055562 is now 1/11
EXECUTE sofia/default/7120041412@103.226.53.10 set(effective_destination_number=1300368909)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [effective_destination_number]=[1300368909]
EXECUTE sofia/default/7120041412@103.226.53.10 set(termination_rates=ID:7|CODE:^13.*|DESTINATION:Australia|CONNECTIONCOST:0.35000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|TRUNK:2|PROVIDER:2)
2018-07-04 20:43:46.672000 [DEBUG] mod_dptools.c:1477 sofia/default/7120041412@103.226.53.10 SET [termination_rates]=[ID:7|CODE:^13.*|DESTINATION:Australia|CONNECTIONCOST:0.35000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|TRUNK:2|PROVIDER:2]
EXECUTE sofia/default/7120041412@103.226.53.10 export(rtp_append_audio_sdp=a=fmtp:18 annexb=no)
2018-07-04 20:43:46.672000 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [rtp_append_audio_sdp]=[a=fmtp:18 annexb=no]
EXECUTE sofia/default/7120041412@103.226.53.10 bridge(sofia/gateway/ivox/1300368909)
2018-07-04 20:43:46.672000 [DEBUG] switch_channel.c:1221 sofia/default/7120041412@103.226.53.10 EXPORTING[export_vars] [t38_passthru]=[true] to event
2018-07-04 20:43:46.672000 [DEBUG] switch_channel.c:1221 sofia/default/7120041412@103.226.53.10 EXPORTING[export_vars] [rtp_append_audio_sdp]=[a=fmtp:18 annexb=no] to event
2018-07-04 20:43:46.672000 [DEBUG] switch_ivr_originate.c:2101 Parsing global variables
2018-07-04 20:43:46.672000 [NOTICE] switch_channel.c:1075 New Channel sofia/default/1300368909 [210bd1a8-7f77-11e8-896a-555946780031]
2018-07-04 20:43:46.672000 [DEBUG] mod_sofia.c:4701 (sofia/default/1300368909) State Change CS_NEW -> CS_INIT
2018-07-04 20:43:46.672000 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:472 (sofia/default/1300368909) Running State Change CS_INIT
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:512 (sofia/default/1300368909) State INIT
2018-07-04 20:43:46.672000 [DEBUG] mod_sofia.c:87 sofia/default/1300368909 SOFIA INIT
2018-07-04 20:43:46.672000 [DEBUG] sofia_glue.c:1241 sofia/default/1300368909 sending invite version: 1.4.21 64bit
Local SDP:
v=0
o=FreeSWITCH 1530672266 1530672267 IN IP4 103.226.53.10
s=FreeSWITCH
c=IN IP4 103.226.53.10
t=0 0
m=audio 28760 RTP/AVP 0 8 18 9 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=fmtp:18 annexb=no
a=ptime:20
a=sendrecv
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:40 sofia/default/1300368909 Standard INIT
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:48 (sofia/default/1300368909) State Change CS_INIT -> CS_ROUTING
2018-07-04 20:43:46.672000 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:512 (sofia/default/1300368909) State INIT going to sleep
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:472 (sofia/default/1300368909) Running State Change CS_ROUTING
2018-07-04 20:43:46.672000 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:46.672000 [DEBUG] sofia.c:6634 Channel sofia/default/1300368909 entering state [calling][0]
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:528 (sofia/default/1300368909) State ROUTING
2018-07-04 20:43:46.672000 [DEBUG] mod_sofia.c:123 sofia/default/1300368909 SOFIA ROUTING
2018-07-04 20:43:46.672000 [DEBUG] switch_ivr_originate.c:67 (sofia/default/1300368909) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-07-04 20:43:46.672000 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:528 (sofia/default/1300368909) State ROUTING going to sleep
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:472 (sofia/default/1300368909) Running State Change CS_CONSUME_MEDIA
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:547 (sofia/default/1300368909) State CONSUME_MEDIA
2018-07-04 20:43:46.672000 [DEBUG] switch_core_state_machine.c:547 (sofia/default/1300368909) State CONSUME_MEDIA going to sleep
2018-07-04 20:43:49.432027 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:49.432027 [DEBUG] sofia.c:6634 Channel sofia/default/1300368909 entering state [proceeding][183]
2018-07-04 20:43:49.432027 [DEBUG] sofia.c:6644 Remote SDP:
v=0
o=- 1160355361 1160355361 IN IP4 202.83.183.33
s=ENSResip
c=IN IP4 27.34.224.16
t=0 0
m=audio 14194 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=silenceSupp:off - - - -
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3735 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3596 Set telephone-event payload to 101
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:2507 Set Codec sofia/default/1300368909 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2018-07-04 20:43:49.432027 [DEBUG] switch_core_codec.c:111 sofia/default/1300368909 Original read codec set to PCMU:0
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3934 Set 2833 dtmf send payload to 101
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:5179 AUDIO RTP [sofia/default/1300368909] 103.226.53.10 port 28760 -> 27.34.224.16 port 14194 codec: 0 ms: 20
2018-07-04 20:43:49.432027 [DEBUG] switch_rtp.c:3579 Starting timer [soft] 160 bytes per 20ms
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:5477 Set 2833 dtmf send payload to 101
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:5483 Set 2833 dtmf receive payload to 101
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:5505 sofia/default/1300368909 Set rtp dtmf delay to 40
2018-07-04 20:43:49.432027 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/1300368909!
2018-07-04 20:43:49.432027 [DEBUG] switch_channel.c:3415 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:49.432027 [DEBUG] switch_channel.c:3419 (sofia/default/1300368909) Callstate Change DOWN -> EARLY
2018-07-04 20:43:49.432027 [INFO] switch_ivr_originate.c:3530 Sending early media
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3735 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3735 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G723:4:8000:20:6300:1]/[G729:18:8000:20:8000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3735 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G726-32:2:8000:20:0:1]/[G729:18:8000:20:8000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [G726-32:2:8000:20:0:1]/[G722:9:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [iLBC:97:8000:20:0:1]/[G729:18:8000:20:8000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3680 Audio Codec Compare [iLBC:97:8000:20:0:1]/[G722:9:8000:20:64000:1]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3596 Set telephone-event payload to 101
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:2507 Set Codec sofia/default/7120041412@103.226.53.10 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2018-07-04 20:43:49.432027 [DEBUG] switch_core_codec.c:111 sofia/default/7120041412@103.226.53.10 Original read codec set to PCMU:0
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:3943 Set 2833 dtmf send/recv payload to 101
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:5179 AUDIO RTP [sofia/default/7120041412@103.226.53.10] 103.226.53.10 port 20662 -> 192.168.10.192 port 5004 codec: 0 ms: 20
2018-07-04 20:43:49.432027 [DEBUG] switch_rtp.c:3579 Starting timer [soft] 160 bytes per 20ms
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:5477 Set 2833 dtmf send payload to 101
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:5483 Set 2833 dtmf receive payload to 101
2018-07-04 20:43:49.432027 [DEBUG] switch_core_media.c:5505 sofia/default/7120041412@103.226.53.10 Set rtp dtmf delay to 40
2018-07-04 20:43:49.432027 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/7120041412@103.226.53.10!
2018-07-04 20:43:49.432027 [DEBUG] switch_channel.c:3419 (sofia/default/7120041412@103.226.53.10) Callstate Change RINGING -> EARLY
2018-07-04 20:43:49.432027 [DEBUG] mod_sofia.c:2268 Ring SDP:
v=0
o=FreeSWITCH 1530680367 1530680368 IN IP4 103.226.53.10
s=FreeSWITCH
c=IN IP4 103.226.53.10
t=0 0
m=audio 20662 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=fmtp:18 annexb=no
a=ptime:20
a=sendrecv
2018-07-04 20:43:49.432027 [DEBUG] switch_core_session.c:912 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:49.432027 [DEBUG] switch_ivr_originate.c:3581 Originate Resulted in Success: [sofia/default/1300368909]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:49.432027 [DEBUG] sofia.c:6634 Channel sofia/default/7120041412@103.226.53.10 entering state [early][183]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_session.c:912 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_session.c:912 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:49.432027 [DEBUG] switch_ivr_bridge.c:1468 (sofia/default/1300368909) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2018-07-04 20:43:49.432027 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:49.432027 [DEBUG] switch_core_state_machine.c:472 (sofia/default/1300368909) Running State Change CS_EXCHANGE_MEDIA
2018-07-04 20:43:49.432027 [DEBUG] switch_core_state_machine.c:538 (sofia/default/1300368909) State EXCHANGE_MEDIA
2018-07-04 20:43:49.432027 [DEBUG] mod_sofia.c:594 SOFIA EXCHANGE_MEDIA
2018-07-04 20:43:49.511938 [DEBUG] switch_rtp.c:5894 Correct ip/port confirmed.
2018-07-04 20:43:49.752015 [INFO] switch_rtp.c:5867 Auto Changing port from 192.168.10.192:5004 to 103.239.77.180:5004
2018-07-04 20:43:50.671945 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:50.671945 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:50.691944 [DEBUG] sofia.c:6634 Channel sofia/default/1300368909 entering state [completing][200]
2018-07-04 20:43:50.691944 [DEBUG] sofia.c:6641 Duplicate SDP
v=0
o=- 1160355361 1160355361 IN IP4 202.83.183.33
s=ENSResip
c=IN IP4 27.34.224.16
t=0 0
m=audio 14194 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=silenceSupp:off - - - -
2018-07-04 20:43:50.691944 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:50.691944 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:50.711944 [DEBUG] sofia.c:6634 Channel sofia/default/1300368909 entering state [ready][200]
2018-07-04 20:43:50.711944 [DEBUG] switch_channel.c:3657 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:50.711944 [NOTICE] sofia.c:7436 Channel [sofia/default/1300368909] has been answered
2018-07-04 20:43:50.711944 [DEBUG] switch_channel.c:3711 (sofia/default/1300368909) Callstate Change EARLY -> ACTIVE
2018-07-04 20:43:50.731943 [DEBUG] mod_sofia.c:780 Local SDP sofia/default/7120041412@103.226.53.10:
v=0
o=FreeSWITCH 1530680367 1530680369 IN IP4 103.226.53.10
s=FreeSWITCH
c=IN IP4 103.226.53.10
t=0 0
m=audio 20662 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=fmtp:18 annexb=no
a=ptime:20
a=sendrecv
2018-07-04 20:43:50.731943 [DEBUG] switch_core_session.c:912 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:50.731943 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:50.731943 [NOTICE] switch_ivr_bridge.c:496 Channel [sofia/default/7120041412@103.226.53.10] has been answered
2018-07-04 20:43:50.731943 [DEBUG] switch_channel.c:3711 (sofia/default/7120041412@103.226.53.10) Callstate Change EARLY -> ACTIVE
2018-07-04 20:43:50.731943 [DEBUG] sofia.c:6634 Channel sofia/default/7120041412@103.226.53.10 entering state [completed][200]
2018-07-04 20:43:50.731943 [DEBUG] switch_rtp.c:5894 Correct ip/port confirmed.
2018-07-04 20:43:50.851942 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:50.851942 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:50.851942 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:50.851942 [DEBUG] sofia.c:6634 Channel sofia/default/7120041412@103.226.53.10 entering state [ready][200]
2018-07-04 20:43:50.851942 [DEBUG] switch_core_session.c:978 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:50.851942 [DEBUG] switch_core_session.c:978 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:50.951938 [DEBUG] switch_rtp.c:5894 Correct ip/port confirmed.
2018-07-04 20:43:57.411945 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:57.411945 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:57.411945 [DEBUG] sofia.c:6634 Channel sofia/default/1300368909 entering state [received][100]
2018-07-04 20:43:57.411945 [DEBUG] sofia.c:6644 Remote SDP:
v=0
o=- 1160355361 1160355362 IN IP4 202.83.183.33
s=ENSResip
c=IN IP4 27.34.224.16
t=0 0
m=image 14502 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:72
a=T38FaxRateManagement:transferredTCF
a=T38FaxUdpEC:t38UDPRedundancy
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
2018-07-04 20:43:57.411945 [DEBUG] switch_core_media.c:3374 Audio params changed for sofia/default/1300368909 from 27.34.224.16:14194 to 27.34.224.16:14502
2018-07-04 20:43:57.411945 [DEBUG] switch_core_media.c:3401 Passing T38 req to other leg.
v=0
o=- 1160355361 1160355362 IN IP4 202.83.183.33
s=ENSResip
c=IN IP4 27.34.224.16
t=0 0
m=image 14502 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:72
a=T38FaxRateManagement:transferredTCF
a=T38FaxUdpEC:t38UDPRedundancy
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
2018-07-04 20:43:57.411945 [DEBUG] switch_core_session.c:978 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:57.432028 [DEBUG] switch_core_media.c:7413 sofia/default/7120041412@103.226.53.10 image media sdp:
v=0
o=FreeSWITCH 1530680367 1530680370 IN IP4 103.226.53.10
s=FreeSWITCH
c=IN IP4 103.226.53.10
t=0 0
m=image 20662 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:72
a=T38FaxUdpEC:t38UDPRedundancy
2018-07-04 20:43:57.432028 [DEBUG] sofia_glue.c:1241 sofia/default/7120041412@103.226.53.10 sending invite version: 1.4.21 64bit
Local SDP:
v=0
o=FreeSWITCH 1530680367 1530680370 IN IP4 103.226.53.10
s=FreeSWITCH
c=IN IP4 103.226.53.10
t=0 0
m=image 20662 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:72
a=T38FaxUdpEC:t38UDPRedundancy
2018-07-04 20:43:57.432028 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:57.432028 [DEBUG] sofia.c:6634 Channel sofia/default/7120041412@103.226.53.10 entering state [calling][0]
2018-07-04 20:43:57.491941 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:57.491941 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:57.491941 [DEBUG] switch_core_media.c:4615 Remote address:port [192.168.10.192:5004] has not changed.
2018-07-04 20:43:57.491941 [DEBUG] sofia.c:6219 Passing 200 OK to other leg
2018-07-04 20:43:57.491941 [DEBUG] switch_core_media.c:524 Audio params are unchanged for sofia/default/7120041412@103.226.53.10.
2018-07-04 20:43:57.491941 [INFO] sofia.c:6268 Activating T38 Passthru
2018-07-04 20:43:57.491941 [DEBUG] switch_core_session.c:978 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:57.491941 [DEBUG] sofia.c:6634 Channel sofia/default/7120041412@103.226.53.10 entering state [completing][200]
2018-07-04 20:43:57.491941 [DEBUG] sofia.c:6641 Duplicate SDP
v=0
o=7120041412 8000 8001 IN IP4 192.168.10.192
s=SIP Call
c=IN IP4 192.168.10.192
t=0 0
m=image 5004 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:72
a=T38FaxUdpEC:t38UDPRedundancy
2018-07-04 20:43:57.491941 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:57.491941 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:43:57.491941 [DEBUG] mod_sofia.c:1983 Responding with 200 [OK]
2018-07-04 20:43:57.491941 [DEBUG] switch_core_media.c:7413 sofia/default/1300368909 image media sdp:
v=0
o=FreeSWITCH 1530672266 1530672268 IN IP4 103.226.53.10
s=FreeSWITCH
c=IN IP4 103.226.53.10
t=0 0
m=image 28760 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:9600
a=T38FaxFillBitRemoval:0
a=T38FaxTranscodingMMR:0
a=T38FaxTranscodingJBIG:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:200
a=T38FaxMaxDatagram:72
a=T38FaxUdpEC:t38UDPRedundancy
2018-07-04 20:43:57.491941 [DEBUG] switch_core_session.c:912 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:57.491941 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:57.491941 [DEBUG] sofia.c:6634 Channel sofia/default/1300368909 entering state [completed][200]
2018-07-04 20:43:57.511949 [DEBUG] sofia.c:6634 Channel sofia/default/7120041412@103.226.53.10 entering state [ready][200]
2018-07-04 20:43:57.611939 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:57.611939 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:57.611939 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:43:57.611939 [DEBUG] sofia.c:6634 Channel sofia/default/1300368909 entering state [ready][200]
2018-07-04 20:44:29.551942 [DEBUG] switch_core_session.c:1061 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:44:29.551942 [NOTICE] sofia.c:952 Hangup sofia/default/7120041412@103.226.53.10 [CS_EXECUTE] [NORMAL_CLEARING]
2018-07-04 20:44:29.551942 [DEBUG] switch_channel.c:3242 Send signal sofia/default/7120041412@103.226.53.10 [KILL]
2018-07-04 20:44:29.551942 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:44:29.551942 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/default/7120041412@103.226.53.10]
2018-07-04 20:44:29.551942 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:44:29.551942 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/default/1300368909]
2018-07-04 20:44:29.551942 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:44:29.551942 [NOTICE] switch_ivr_bridge.c:758 Hangup sofia/default/1300368909 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2018-07-04 20:44:29.551942 [DEBUG] switch_channel.c:3242 Send signal sofia/default/1300368909 [KILL]
2018-07-04 20:44:29.551942 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:538 (sofia/default/1300368909) State EXCHANGE_MEDIA going to sleep
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:472 (sofia/default/1300368909) Running State Change CS_HANGUP
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:735 (sofia/default/1300368909) Callstate Change ACTIVE -> HANGUP
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:737 (sofia/default/1300368909) State HANGUP
2018-07-04 20:44:29.551942 [DEBUG] mod_sofia.c:407 sofia/default/1300368909 Overriding SIP cause 480 with 200 from the other leg
2018-07-04 20:44:29.551942 [DEBUG] mod_sofia.c:413 Channel sofia/default/1300368909 hanging up, cause: NORMAL_CLEARING
2018-07-04 20:44:29.551942 [DEBUG] switch_ivr_bridge.c:1566 sofia/default/1300368909 skip receive message [UNBRIDGE] (channel is hungup already)
2018-07-04 20:44:29.551942 [DEBUG] switch_ivr_bridge.c:1569 sofia/default/7120041412@103.226.53.10 skip receive message [UNBRIDGE] (channel is hungup already)
2018-07-04 20:44:29.551942 [DEBUG] switch_core_session.c:2902 sofia/default/7120041412@103.226.53.10 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2018-07-04 20:44:29.551942 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/default/1300368909
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:535 (sofia/default/7120041412@103.226.53.10) State EXECUTE going to sleep
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:472 (sofia/default/7120041412@103.226.53.10) Running State Change CS_HANGUP
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:735 (sofia/default/7120041412@103.226.53.10) Callstate Change ACTIVE -> HANGUP
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:60 sofia/default/1300368909 Standard HANGUP, cause: NORMAL_CLEARING
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:737 (sofia/default/1300368909) State HANGUP going to sleep
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:504 (sofia/default/1300368909) State Change CS_HANGUP -> CS_REPORTING
2018-07-04 20:44:29.551942 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:472 (sofia/default/1300368909) Running State Change CS_REPORTING
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:737 (sofia/default/7120041412@103.226.53.10) State HANGUP
2018-07-04 20:44:29.551942 [DEBUG] mod_sofia.c:413 Channel sofia/default/7120041412@103.226.53.10 hanging up, cause: NORMAL_CLEARING
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:823 (sofia/default/1300368909) State REPORTING
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:60 sofia/default/7120041412@103.226.53.10 Standard HANGUP, cause: NORMAL_CLEARING
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:737 (sofia/default/7120041412@103.226.53.10) State HANGUP going to sleep
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:504 (sofia/default/7120041412@103.226.53.10) State Change CS_HANGUP -> CS_REPORTING
2018-07-04 20:44:29.551942 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:472 (sofia/default/7120041412@103.226.53.10) Running State Change CS_REPORTING
2018-07-04 20:44:29.551942 [DEBUG] switch_core_state_machine.c:823 (sofia/default/7120041412@103.226.53.10) State REPORTING
2018-07-04 20:44:29.891946 [DEBUG] switch_core_state_machine.c:104 sofia/default/1300368909 Standard REPORTING, cause: NORMAL_CLEARING
2018-07-04 20:44:29.891946 [DEBUG] switch_core_state_machine.c:823 (sofia/default/1300368909) State REPORTING going to sleep
2018-07-04 20:44:29.891946 [DEBUG] switch_core_state_machine.c:498 (sofia/default/1300368909) State Change CS_REPORTING -> CS_DESTROY
2018-07-04 20:44:29.891946 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/1300368909 [BREAK]
2018-07-04 20:44:29.891946 [DEBUG] switch_core_session.c:1623 Session 11 (sofia/default/1300368909) Locked, Waiting on external entities
2018-07-04 20:44:29.891946 [NOTICE] switch_core_session.c:1641 Session 11 (sofia/default/1300368909) Ended
2018-07-04 20:44:29.891946 [NOTICE] switch_core_session.c:1645 Close Channel sofia/default/1300368909 [CS_DESTROY]
2018-07-04 20:44:29.891946 [DEBUG] switch_core_state_machine.c:626 (sofia/default/1300368909) Running State Change CS_DESTROY
2018-07-04 20:44:29.891946 [DEBUG] switch_core_state_machine.c:636 (sofia/default/1300368909) State DESTROY
2018-07-04 20:44:29.891946 [DEBUG] mod_sofia.c:323 sofia/default/1300368909 SOFIA DESTROY
2018-07-04 20:44:29.891946 [DEBUG] switch_core_state_machine.c:111 sofia/default/1300368909 Standard DESTROY
2018-07-04 20:44:29.891946 [DEBUG] switch_core_state_machine.c:636 (sofia/default/1300368909) State DESTROY going to sleep
2018-07-04 20:44:30.111934 [DEBUG] switch_core_state_machine.c:104 sofia/default/7120041412@103.226.53.10 Standard REPORTING, cause: NORMAL_CLEARING
2018-07-04 20:44:30.111934 [DEBUG] switch_core_state_machine.c:823 (sofia/default/7120041412@103.226.53.10) State REPORTING going to sleep
2018-07-04 20:44:30.111934 [DEBUG] switch_core_state_machine.c:498 (sofia/default/7120041412@103.226.53.10) State Change CS_REPORTING -> CS_DESTROY
2018-07-04 20:44:30.111934 [DEBUG] switch_core_session.c:1396 Send signal sofia/default/7120041412@103.226.53.10 [BREAK]
2018-07-04 20:44:30.111934 [DEBUG] switch_core_session.c:1623 Session 10 (sofia/default/7120041412@103.226.53.10) Locked, Waiting on external entities
2018-07-04 20:44:30.111934 [NOTICE] switch_core_session.c:1641 Session 10 (sofia/default/7120041412@103.226.53.10) Ended
2018-07-04 20:44:30.111934 [NOTICE] switch_core_session.c:1645 Close Channel sofia/default/7120041412@103.226.53.10 [CS_DESTROY]
2018-07-04 20:44:30.111934 [DEBUG] switch_core_state_machine.c:626 (sofia/default/7120041412@103.226.53.10) Running State Change CS_DESTROY
2018-07-04 20:44:30.111934 [DEBUG] switch_core_state_machine.c:636 (sofia/default/7120041412@103.226.53.10) State DESTROY
2018-07-04 20:44:30.111934 [DEBUG] mod_sofia.c:323 sofia/default/7120041412@103.226.53.10 SOFIA DESTROY
2018-07-04 20:44:30.111934 [DEBUG] switch_core_state_machine.c:111 sofia/default/7120041412@103.226.53.10 Standard DESTROY
2018-07-04 20:44:30.111934 [DEBUG] switch_core_state_machine.c:636 (sofia/default/7120041412@103.226.53.10) State DESTROY going to sleep
2018-07-04 20:44:30.211936 [DEBUG] switch_scheduler.c:144 Deleting task 7 switch_ivr_schedule_hangup (20dd777c-7f77-11e8-894d-555946780031)