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)