2024-06-25 07:46:13.292038 [INFO] mod_dialplan_xml.c:637 Processing 27876303987 <27876303987>->27448734188 in context default Dialplan: sofia/default/27876303987@102.220.232.19 parsing [default->] continue=false Dialplan: sofia/default/27876303987@102.220.232.19 Regex (PASS) [] destination_number(27448734188) =~ // break=on-false Dialplan: sofia/default/27876303987@102.220.232.19 Action set(callstart=2024-06-25 05:46:13) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(call_processed=internal) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(originated_destination_number=27448734188) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(hangup_after_bridge=true) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(continue_on_fail=true) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(fax_enable_t38=true) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(fax_enable_t38_request=true) Dialplan: sofia/default/27876303987@102.220.232.19 Action export(t38_passthru=true) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(accountid=2270) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(account_type=0) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(resellerid=0) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(accountcode=7439137964) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(call_direction=outbound) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(calltype=STANDARD) Dialplan: sofia/default/27876303987@102.220.232.19 Action sched_hangup(+5400 allotted_timeout) Dialplan: sofia/default/27876303987@102.220.232.19 Action log(INFO [Customer info] : [Account code: 7439137964, Rategroup Id: 189, Called number: 27448734188]) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(origination_rates=ID:349049768|CODE:^2744873.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.33000|INC:1|RATEGROUP:189|MARKUP:0|ACCID:2270) Dialplan: sofia/default/27876303987@102.220.232.19 Action limit(db 7439137964 db_7439137964 6/1) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(effective_destination_number=27448734188) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(termination_rates=ID:4278012|CODE:^2744873.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.09000|INC:1|TRUNK:3|PROVIDER:37) Dialplan: sofia/default/27876303987@102.220.232.19 Action export(rtp_append_audio_sdp=a=fmtp:18 annexb=no) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(absolute_codec_string=^^:G729:PCMA:PCMU) Dialplan: sofia/default/27876303987@102.220.232.19 Action limit_execute(db Transit_JHB_BRY_SBC gw_Transit_JHB_BRY_SBC 500 bridge {absolute_codec_string=^^:G729:PCMA:PCMU}sofia/gateway/Transit_JHB_BRY_SBC/27448734188) Dialplan: sofia/default/27876303987@102.220.232.19 Action bridge(sofia/gateway/Transit_JHB_PKL_SBC/27448734188) Dialplan: sofia/default/27876303987@102.220.232.19 Action bridge(sofia/gateway/Transit_CPT_BREE_SBC/27448734188) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(effective_destination_number=27448734188) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(termination_rates=ID:4296332|CODE:^274487.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.09000|INC:1|TRUNK:3|PROVIDER:37) Dialplan: sofia/default/27876303987@102.220.232.19 Action export(rtp_append_audio_sdp=a=fmtp:18 annexb=no) Dialplan: sofia/default/27876303987@102.220.232.19 Action set(absolute_codec_string=^^:G729:PCMA:PCMU) Dialplan: sofia/default/27876303987@102.220.232.19 Action limit_execute(db Transit_JHB_BRY_SBC gw_Transit_JHB_BRY_SBC 500 bridge {absolute_codec_string=^^:G729:PCMA:PCMU}sofia/gateway/Transit_JHB_BRY_SBC/27448734188) Dialplan: sofia/default/27876303987@102.220.232.19 Action bridge(sofia/gateway/Transit_JHB_PKL_SBC/27448734188) Dialplan: sofia/default/27876303987@102.220.232.19 Action bridge(sofia/gateway/Transit_CPT_BREE_SBC/27448734188) 2024-06-25 07:46:13.472092 [DEBUG] switch_core_state_machine.c:286 (sofia/default/27876303987@102.220.232.19) State Change CS_ROUTING -> CS_EXECUTE 2024-06-25 07:46:13.472092 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27876303987@102.220.232.19) State ROUTING going to sleep 2024-06-25 07:46:13.472092 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27876303987@102.220.232.19) Running State Change CS_EXECUTE 2024-06-25 07:46:13.472092 [DEBUG] switch_core_state_machine.c:609 (sofia/default/27876303987@102.220.232.19) State EXECUTE 2024-06-25 07:46:13.472092 [DEBUG] mod_sofia.c:197 sofia/default/27876303987@102.220.232.19 SOFIA EXECUTE 2024-06-25 07:46:13.472092 [DEBUG] switch_core_state_machine.c:328 sofia/default/27876303987@102.220.232.19 Standard EXECUTE EXECUTE sofia/default/27876303987@102.220.232.19 set(callstart=2024-06-25 05:46:13) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [callstart]=[2024-06-25 05:46:13] EXECUTE sofia/default/27876303987@102.220.232.19 set(call_processed=internal) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [call_processed]=[internal] EXECUTE sofia/default/27876303987@102.220.232.19 set(originated_destination_number=27448734188) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [originated_destination_number]=[27448734188] EXECUTE sofia/default/27876303987@102.220.232.19 set(hangup_after_bridge=true) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [hangup_after_bridge]=[true] EXECUTE sofia/default/27876303987@102.220.232.19 set(continue_on_fail=true) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [continue_on_fail]=[true] EXECUTE sofia/default/27876303987@102.220.232.19 set(fax_enable_t38=true) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [fax_enable_t38]=[true] EXECUTE sofia/default/27876303987@102.220.232.19 set(fax_enable_t38_request=true) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [fax_enable_t38_request]=[true] EXECUTE sofia/default/27876303987@102.220.232.19 export(t38_passthru=true) 2024-06-25 07:46:13.472092 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [t38_passthru]=[true] EXECUTE sofia/default/27876303987@102.220.232.19 set(accountid=2270) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [accountid]=[2270] EXECUTE sofia/default/27876303987@102.220.232.19 set(account_type=0) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [account_type]=[0] EXECUTE sofia/default/27876303987@102.220.232.19 set(resellerid=0) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [resellerid]=[0] EXECUTE sofia/default/27876303987@102.220.232.19 set(accountcode=7439137964) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [accountcode]=[7439137964] EXECUTE sofia/default/27876303987@102.220.232.19 set(call_direction=outbound) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [call_direction]=[outbound] EXECUTE sofia/default/27876303987@102.220.232.19 set(calltype=STANDARD) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [calltype]=[STANDARD] EXECUTE sofia/default/27876303987@102.220.232.19 sched_hangup(+5400 allotted_timeout) 2024-06-25 07:46:13.472092 [DEBUG] switch_scheduler.c:249 Added task 2738361 switch_ivr_schedule_hangup (a5d94864-7170-4506-84a1-e088245af79a) to run at 1719299773 EXECUTE sofia/default/27876303987@102.220.232.19 log(INFO [Customer info] : [Account code: 7439137964, Rategroup Id: 189, Called number: 27448734188]) 2024-06-25 07:46:13.472092 [INFO] mod_dptools.c:1713 [Customer info] : [Account code: 7439137964, Rategroup Id: 189, Called number: 27448734188] EXECUTE sofia/default/27876303987@102.220.232.19 set(origination_rates=ID:349049768|CODE:^2744873.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.33000|INC:1|RATEGROUP:189|MARKUP:0|ACCID:2270) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [origination_rates]=[ID:349049768|CODE:^2744873.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.33000|INC:1|RATEGROUP:189|MARKUP:0|ACCID:2270] EXECUTE sofia/default/27876303987@102.220.232.19 limit(db 7439137964 db_7439137964 6/1) 2024-06-25 07:46:13.472092 [DEBUG] switch_limit.c:126 incr called: 7439137964_db_7439137964 max:6, interval:1 2024-06-25 07:46:13.472092 [DEBUG] mod_db.c:194 Usage for 7439137964_db_7439137964 is now 1/6 EXECUTE sofia/default/27876303987@102.220.232.19 set(effective_destination_number=27448734188) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [effective_destination_number]=[27448734188] EXECUTE sofia/default/27876303987@102.220.232.19 set(termination_rates=ID:4278012|CODE:^2744873.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.09000|INC:1|TRUNK:3|PROVIDER:37) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [termination_rates]=[ID:4278012|CODE:^2744873.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.09000|INC:1|TRUNK:3|PROVIDER:37] EXECUTE sofia/default/27876303987@102.220.232.19 export(rtp_append_audio_sdp=a=fmtp:18 annexb=no) 2024-06-25 07:46:13.472092 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [rtp_append_audio_sdp]=[a=fmtp:18 annexb=no] EXECUTE sofia/default/27876303987@102.220.232.19 set(absolute_codec_string=^^:G729:PCMA:PCMU) 2024-06-25 07:46:13.472092 [DEBUG] mod_dptools.c:1519 SET sofia/default/27876303987@102.220.232.19 [absolute_codec_string]=[^^:G729:PCMA:PCMU] EXECUTE sofia/default/27876303987@102.220.232.19 limit_execute(db Transit_JHB_BRY_SBC gw_Transit_JHB_BRY_SBC 500 bridge {absolute_codec_string=^^:G729:PCMA:PCMU}sofia/gateway/Transit_JHB_BRY_SBC/27448734188) 2024-06-25 07:46:13.472092 [DEBUG] switch_limit.c:126 incr called: Transit_JHB_BRY_SBC_gw_Transit_JHB_BRY_SBC max:500, interval:0 2024-06-25 07:46:13.472092 [DEBUG] mod_db.c:194 Usage for Transit_JHB_BRY_SBC_gw_Transit_JHB_BRY_SBC is now 35/500 EXECUTE sofia/default/27876303987@102.220.232.19 bridge({absolute_codec_string=^^:G729:PCMA:PCMU}sofia/gateway/Transit_JHB_BRY_SBC/27448734188) 2024-06-25 07:46:13.492051 [DEBUG] switch_channel.c:1250 sofia/default/27876303987@102.220.232.19 EXPORTING[export_vars] [t38_passthru]=[true] to event 2024-06-25 07:46:13.492051 [DEBUG] switch_channel.c:1250 sofia/default/27876303987@102.220.232.19 EXPORTING[export_vars] [rtp_append_audio_sdp]=[a=fmtp:18 annexb=no] to event 2024-06-25 07:46:13.492051 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2024-06-25 07:46:13.492051 [NOTICE] switch_channel.c:1104 New Channel sofia/default/27448734188 [576446a8-c04a-4717-a207-9096dba23e22] 2024-06-25 07:46:13.492051 [DEBUG] mod_sofia.c:4813 (sofia/default/27448734188) State Change CS_NEW -> CS_INIT 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27448734188) Running State Change CS_INIT 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27448734188) State INIT 2024-06-25 07:46:13.492051 [DEBUG] mod_sofia.c:89 sofia/default/27448734188 SOFIA INIT 2024-06-25 07:46:13.492051 [DEBUG] sofia_glue.c:1228 sip:196.31.25.91 Setting proxy route to sofia/default/27448734188 2024-06-25 07:46:13.492051 [DEBUG] sofia_glue.c:1257 sofia/default/27448734188 sending invite version: 1.6.8 64bit Local SDP: v=0 o=FreeSWITCH 1719276935 1719276936 IN IP4 196.31.25.87 s=FreeSWITCH c=IN IP4 196.31.25.87 t=0 0 m=audio 17438 RTP/AVP 18 8 0 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 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 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:40 sofia/default/27448734188 Standard INIT 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:48 (sofia/default/27448734188) State Change CS_INIT -> CS_ROUTING 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27448734188) State INIT going to sleep 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27448734188) Running State Change CS_ROUTING 2024-06-25 07:46:13.492051 [DEBUG] sofia.c:6858 Channel sofia/default/27448734188 entering state [calling][0] 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27448734188) State ROUTING 2024-06-25 07:46:13.492051 [DEBUG] mod_sofia.c:142 sofia/default/27448734188 SOFIA ROUTING 2024-06-25 07:46:13.492051 [DEBUG] switch_ivr_originate.c:67 (sofia/default/27448734188) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27448734188) State ROUTING going to sleep 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27448734188) Running State Change CS_CONSUME_MEDIA 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:621 (sofia/default/27448734188) State CONSUME_MEDIA 2024-06-25 07:46:13.492051 [DEBUG] switch_core_state_machine.c:621 (sofia/default/27448734188) State CONSUME_MEDIA going to sleep 2024-06-25 07:46:13.792066 [WARNING] sofia_reg.c:2889 Can't find user [27106300711@196.31.25.87] from 196.31.25.91 You must define a domain called '196.31.25.87' in your directory and add a user with the id="27106300711" attribute and you must configure your device to use the proper domain in it's authentication credentials. 2024-06-25 07:46:13.812086 [WARNING] sofia_reg.c:2889 Can't find user [27106300712@196.31.25.87] from 196.31.25.91 You must define a domain called '196.31.25.87' in your directory and add a user with the id="27106300712" attribute and you must configure your device to use the proper domain in it's authentication credentials. 2024-06-25 07:46:14.272093 [WARNING] sofia_reg.c:2889 Can't find user [27106300717@196.31.25.87] from 196.31.25.91 You must define a domain called '196.31.25.87' in your directory and add a user with the id="27106300717" attribute and you must configure your device to use the proper domain in it's authentication credentials. 2024-06-25 07:46:15.912069 [DEBUG] sofia.c:6858 Channel sofia/default/27448734188 entering state [proceeding][180] 2024-06-25 07:46:15.912069 [DEBUG] sofia.c:6868 Remote SDP: v=0 o=PortaSIP 4084356539596529243 1 IN IP4 197.97.67.168 s=- t=0 0 m=audio 21386 RTP/AVP 18 101 c=IN IP4 197.97.67.168 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=ptime:20 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:3090 Set Codec sofia/default/27448734188 G729/8000 20 ms 160 samples 8000 bits 1 channels 2024-06-25 07:46:15.912069 [DEBUG] switch_core_codec.c:111 sofia/default/27448734188 Original read codec set to G729:18 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4681 sofia/default/27448734188 Set 2833 dtmf send payload to 101 recv payload to 101 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/default/27448734188] 196.31.25.87 port 17438 -> 197.97.67.168 port 21386 codec: 18 ms: 20 2024-06-25 07:46:15.912069 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:6763 sofia/default/27448734188 Set 2833 dtmf send payload to 101 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:6770 sofia/default/27448734188 Set 2833 dtmf receive payload to 101 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:6793 sofia/default/27448734188 Set rtp dtmf delay to 40 2024-06-25 07:46:15.912069 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/27448734188! 2024-06-25 07:46:15.912069 [DEBUG] switch_channel.c:3471 (sofia/default/27448734188) Callstate Change DOWN -> EARLY 2024-06-25 07:46:15.912069 [INFO] switch_ivr_originate.c:3556 Sending early media 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:3090 Set Codec sofia/default/27876303987@102.220.232.19 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2024-06-25 07:46:15.912069 [DEBUG] switch_core_codec.c:111 sofia/default/27876303987@102.220.232.19 Original read codec set to PCMA:8 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:4681 sofia/default/27876303987@102.220.232.19 Set 2833 dtmf send payload to 101 recv payload to 101 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/default/27876303987@102.220.232.19] 196.31.25.87 port 31202 -> 102.220.232.19 port 23228 codec: 8 ms: 20 2024-06-25 07:46:15.912069 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:6763 sofia/default/27876303987@102.220.232.19 Set 2833 dtmf send payload to 101 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:6770 sofia/default/27876303987@102.220.232.19 Set 2833 dtmf receive payload to 101 2024-06-25 07:46:15.912069 [DEBUG] switch_core_media.c:6793 sofia/default/27876303987@102.220.232.19 Set rtp dtmf delay to 40 2024-06-25 07:46:15.912069 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/27876303987@102.220.232.19! 2024-06-25 07:46:15.912069 [DEBUG] switch_channel.c:3471 (sofia/default/27876303987@102.220.232.19) Callstate Change RINGING -> EARLY 2024-06-25 07:46:15.912069 [DEBUG] mod_sofia.c:2367 Ring SDP: v=0 o=FreeSWITCH 1719263173 1719263174 IN IP4 196.31.25.87 s=FreeSWITCH c=IN IP4 196.31.25.87 t=0 0 m=audio 31202 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv 2024-06-25 07:46:15.912069 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/default/27448734188] 2024-06-25 07:46:15.932067 [DEBUG] switch_ivr_bridge.c:1594 (sofia/default/27448734188) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2024-06-25 07:46:15.932067 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27448734188) Running State Change CS_EXCHANGE_MEDIA 2024-06-25 07:46:15.932067 [DEBUG] switch_core_state_machine.c:612 (sofia/default/27448734188) State EXCHANGE_MEDIA 2024-06-25 07:46:15.932067 [DEBUG] mod_sofia.c:628 SOFIA EXCHANGE_MEDIA 2024-06-25 07:46:15.972071 [DEBUG] switch_rtp.c:6707 Correct audio ip/port confirmed. 2024-06-25 07:46:16.152069 [NOTICE] switch_channel.c:1104 New Channel sofia/default/27118921900@gtsbc.goldtelcloud.co.za [74499757-c593-4a47-ba77-ea6a410b52f2] 2024-06-25 07:46:16.152069 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) Running State Change CS_NEW 2024-06-25 07:46:16.152069 [DEBUG] sofia.c:9376 sofia/default/27118921900@gtsbc.goldtelcloud.co.za receiving invite from 196.31.25.91:5060 version: 1.6.8 64bit 2024-06-25 07:46:16.152069 [DEBUG] sofia.c:9498 1 acls to check for proxy 2024-06-25 07:46:16.152069 [DEBUG] sofia.c:9503 checking 196.31.25.91 against acl proxy_acl 2024-06-25 07:46:16.152069 [INFO] sofia.c:9505 196.31.25.91 is a proxy according to the proxy_acl acl 2024-06-25 07:46:16.152069 [DEBUG] sofia.c:9515 network ip is a proxy 2024-06-25 07:46:16.152069 [DEBUG] sofia.c:9519 found auth ip [X-AUTH-IP] header of [41.4.17.223] 2024-06-25 07:46:16.152069 [DEBUG] sofia.c:9543 IP 196.31.25.91 Rejected by acl "default". Falling back to Digest auth. 2024-06-25 07:46:16.152069 [DEBUG] switch_core_state_machine.c:562 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State NEW 2024-06-25 07:46:16.252068 [DEBUG] sofia.c:2214 detaching session 74499757-c593-4a47-ba77-ea6a410b52f2 2024-06-25 07:46:16.252068 [DEBUG] sofia.c:6858 Channel sofia/default/27876303987@102.220.232.19 entering state [early][183] 2024-06-25 07:46:16.292077 [DEBUG] sofia.c:2322 Re-attaching to session 74499757-c593-4a47-ba77-ea6a410b52f2 2024-06-25 07:46:16.292077 [DEBUG] sofia.c:9376 sofia/default/27118921900@gtsbc.goldtelcloud.co.za receiving invite from 196.31.25.91:5060 version: 1.6.8 64bit 2024-06-25 07:46:16.292077 [DEBUG] sofia.c:9498 1 acls to check for proxy 2024-06-25 07:46:16.292077 [DEBUG] sofia.c:9503 checking 196.31.25.91 against acl proxy_acl 2024-06-25 07:46:16.292077 [INFO] sofia.c:9505 196.31.25.91 is a proxy according to the proxy_acl acl 2024-06-25 07:46:16.292077 [DEBUG] sofia.c:9515 network ip is a proxy 2024-06-25 07:46:16.292077 [DEBUG] sofia.c:9519 found auth ip [X-AUTH-IP] header of [41.4.17.223] 2024-06-25 07:46:16.292077 [DEBUG] sofia.c:9543 IP 196.31.25.91 Rejected by acl "default". Falling back to Digest auth. 2024-06-25 07:46:16.312090 [DEBUG] sofia.c:6858 Channel sofia/default/27118921900@gtsbc.goldtelcloud.co.za entering state [received][100] 2024-06-25 07:46:16.312090 [DEBUG] sofia.c:6868 Remote SDP: v=0 o=DinStar 2038805052 1099526049 IN IP4 41.4.17.223 s=- c=IN IP4 41.4.17.223 t=0 0 m=audio 8012 RTP/AVP 18 0 8 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=oldoip:10.0.0.250 a=oldcip:10.0.0.250 2024-06-25 07:46:16.312090 [DEBUG] sofia.c:7227 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State Change CS_NEW -> CS_INIT 2024-06-25 07:46:16.312090 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) Running State Change CS_INIT 2024-06-25 07:46:16.312090 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State INIT 2024-06-25 07:46:16.312090 [DEBUG] mod_sofia.c:89 sofia/default/27118921900@gtsbc.goldtelcloud.co.za SOFIA INIT 2024-06-25 07:46:16.312090 [DEBUG] switch_core_state_machine.c:40 sofia/default/27118921900@gtsbc.goldtelcloud.co.za Standard INIT 2024-06-25 07:46:16.312090 [DEBUG] switch_core_state_machine.c:48 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State Change CS_INIT -> CS_ROUTING 2024-06-25 07:46:16.312090 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State INIT going to sleep 2024-06-25 07:46:16.312090 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) Running State Change CS_ROUTING 2024-06-25 07:46:16.312090 [DEBUG] switch_channel.c:2249 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) Callstate Change DOWN -> RINGING 2024-06-25 07:46:16.312090 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State ROUTING 2024-06-25 07:46:16.312090 [DEBUG] mod_sofia.c:142 sofia/default/27118921900@gtsbc.goldtelcloud.co.za SOFIA ROUTING 2024-06-25 07:46:16.312090 [DEBUG] switch_core_state_machine.c:236 sofia/default/27118921900@gtsbc.goldtelcloud.co.za Standard ROUTING 2024-06-25 07:46:16.312090 [INFO] mod_dialplan_xml.c:637 Processing 27118921900 <27118921900>->0119751588 in context default 2024-06-25 07:46:18.092129 [NOTICE] sofia.c:988 Hangup sofia/default/27446913718@gtsbc.goldtelcloud.co.za [CS_EXECUTE] [NORMAL_CLEARING] 2024-06-25 07:46:18.092129 [DEBUG] switch_ivr_bridge.c:701 sofia/default/27446913718@gtsbc.goldtelcloud.co.za ending bridge by request from write function 2024-06-25 07:46:18.092129 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/default/27446019550] 2024-06-25 07:46:18.092129 [NOTICE] switch_ivr_bridge.c:884 Hangup sofia/default/27446019550 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:612 (sofia/default/27446019550) State EXCHANGE_MEDIA going to sleep 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446019550) Running State Change CS_HANGUP 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:809 (sofia/default/27446019550) Callstate Change ACTIVE -> HANGUP 2024-06-25 07:46:18.092129 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/default/27446913718@gtsbc.goldtelcloud.co.za] 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27446019550) State HANGUP 2024-06-25 07:46:18.092129 [DEBUG] mod_sofia.c:431 sofia/default/27446019550 Overriding SIP cause 480 with 200 from the other leg 2024-06-25 07:46:18.092129 [DEBUG] mod_sofia.c:437 Channel sofia/default/27446019550 hanging up, cause: NORMAL_CLEARING 2024-06-25 07:46:18.092129 [DEBUG] switch_ivr_bridge.c:1692 sofia/default/27446019550 skip receive message [UNBRIDGE] (channel is hungup already) 2024-06-25 07:46:18.092129 [DEBUG] switch_ivr_bridge.c:1695 sofia/default/27446913718@gtsbc.goldtelcloud.co.za skip receive message [UNBRIDGE] (channel is hungup already) 2024-06-25 07:46:18.092129 [DEBUG] switch_core_session.c:2796 sofia/default/27446913718@gtsbc.goldtelcloud.co.za skip receive message [PHONE_EVENT] (channel is hungup already) 2024-06-25 07:46:18.092129 [DEBUG] mod_sofia.c:490 Sending BYE to sofia/default/27446019550 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:60 sofia/default/27446019550 Standard HANGUP, cause: NORMAL_CLEARING 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27446019550) State HANGUP going to sleep 2024-06-25 07:46:18.092129 [DEBUG] switch_core_session.c:2796 sofia/default/27446913718@gtsbc.goldtelcloud.co.za skip receive message [PHONE_EVENT] (channel is hungup already) 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:609 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State EXECUTE going to sleep 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) Running State Change CS_HANGUP 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:578 (sofia/default/27446019550) State Change CS_HANGUP -> CS_REPORTING 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446019550) Running State Change CS_REPORTING 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27446019550) State REPORTING 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:809 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) Callstate Change ACTIVE -> HANGUP 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State HANGUP 2024-06-25 07:46:18.092129 [DEBUG] mod_sofia.c:437 Channel sofia/default/27446913718@gtsbc.goldtelcloud.co.za hanging up, cause: NORMAL_CLEARING 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:60 sofia/default/27446913718@gtsbc.goldtelcloud.co.za Standard HANGUP, cause: NORMAL_CLEARING 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State HANGUP going to sleep 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:578 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State Change CS_HANGUP -> CS_REPORTING 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) Running State Change CS_REPORTING 2024-06-25 07:46:18.092129 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State REPORTING Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za parsing [default->] continue=false Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Regex (PASS) [] destination_number(0119751588) =~ // break=on-false Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(callstart=2024-06-25 05:46:18) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(call_processed=internal) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(originated_destination_number=27119751588) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(hangup_after_bridge=true) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(continue_on_fail=true) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(fax_enable_t38=true) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(fax_enable_t38_request=true) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action export(t38_passthru=true) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(accountid=881) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(account_type=0) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(resellerid=61) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(accountcode=4463339454) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(call_direction=outbound) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(calltype=STANDARD) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action sched_hangup(+5400 allotted_timeout) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action log(INFO [Customer info] : [Account code: 4463339454, Rategroup Id: 201, Called number: 0119751588]) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action log(INFO Reseller cost = 0.28050 and customer cost is 0.33000 and reseller max length = 90.0000) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(origination_rates=ID:353162311|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.33000|INC:1|RATEGROUP:201|MARKUP:0|ACCID:881||ID:350165786|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.28050|INC:1|RATEGROUP:190|MARKUP:0|ACCID:61) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action limit(db 4463339454 db_4463339454 6/1) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(effective_destination_number=0119751588) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(termination_rates=ID:4281035|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.09000|INC:1|TRUNK:3|PROVIDER:37) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action export(rtp_append_audio_sdp=a=fmtp:18 annexb=no) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(absolute_codec_string=^^:G729:PCMA:PCMU) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action limit_execute(db Transit_JHB_BRY_SBC gw_Transit_JHB_BRY_SBC 500 bridge {absolute_codec_string=^^:G729:PCMA:PCMU}sofia/gateway/Transit_JHB_BRY_SBC/27119751588) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action bridge(sofia/gateway/Transit_JHB_PKL_SBC/27119751588) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action bridge(sofia/gateway/Transit_CPT_BREE_SBC/27119751588) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(effective_destination_number=0119751588) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(termination_rates=ID:4296420|CODE:^271197.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.09000|INC:1|TRUNK:3|PROVIDER:37) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action export(rtp_append_audio_sdp=a=fmtp:18 annexb=no) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action set(absolute_codec_string=^^:G729:PCMA:PCMU) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action limit_execute(db Transit_JHB_BRY_SBC gw_Transit_JHB_BRY_SBC 500 bridge {absolute_codec_string=^^:G729:PCMA:PCMU}sofia/gateway/Transit_JHB_BRY_SBC/27119751588) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action bridge(sofia/gateway/Transit_JHB_PKL_SBC/27119751588) Dialplan: sofia/default/27118921900@gtsbc.goldtelcloud.co.za Action bridge(sofia/gateway/Transit_CPT_BREE_SBC/27119751588) 2024-06-25 07:46:18.152088 [DEBUG] switch_core_state_machine.c:286 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State Change CS_ROUTING -> CS_EXECUTE 2024-06-25 07:46:18.152088 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State ROUTING going to sleep 2024-06-25 07:46:18.152088 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) Running State Change CS_EXECUTE 2024-06-25 07:46:18.152088 [DEBUG] switch_core_state_machine.c:609 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) State EXECUTE 2024-06-25 07:46:18.152088 [DEBUG] mod_sofia.c:197 sofia/default/27118921900@gtsbc.goldtelcloud.co.za SOFIA EXECUTE 2024-06-25 07:46:18.152088 [DEBUG] switch_core_state_machine.c:328 sofia/default/27118921900@gtsbc.goldtelcloud.co.za Standard EXECUTE EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(callstart=2024-06-25 05:46:18) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [callstart]=[2024-06-25 05:46:18] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(call_processed=internal) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [call_processed]=[internal] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(originated_destination_number=27119751588) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [originated_destination_number]=[27119751588] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(hangup_after_bridge=true) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [hangup_after_bridge]=[true] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(continue_on_fail=true) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [continue_on_fail]=[true] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(fax_enable_t38=true) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [fax_enable_t38]=[true] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(fax_enable_t38_request=true) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [fax_enable_t38_request]=[true] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za export(t38_passthru=true) 2024-06-25 07:46:18.152088 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [t38_passthru]=[true] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(accountid=881) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [accountid]=[881] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(account_type=0) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [account_type]=[0] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(resellerid=61) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [resellerid]=[61] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(accountcode=4463339454) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [accountcode]=[4463339454] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(call_direction=outbound) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [call_direction]=[outbound] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(calltype=STANDARD) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [calltype]=[STANDARD] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za sched_hangup(+5400 allotted_timeout) 2024-06-25 07:46:18.152088 [DEBUG] switch_scheduler.c:249 Added task 2738362 switch_ivr_schedule_hangup (74499757-c593-4a47-ba77-ea6a410b52f2) to run at 1719299778 EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za log(INFO [Customer info] : [Account code: 4463339454, Rategroup Id: 201, Called number: 0119751588]) 2024-06-25 07:46:18.152088 [INFO] mod_dptools.c:1713 [Customer info] : [Account code: 4463339454, Rategroup Id: 201, Called number: 0119751588] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za log(INFO Reseller cost = 0.28050 and customer cost is 0.33000 and reseller max length = 90.0000) 2024-06-25 07:46:18.152088 [INFO] mod_dptools.c:1713 Reseller cost = 0.28050 and customer cost is 0.33000 and reseller max length = 90.0000 EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(origination_rates=ID:353162311|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.33000|INC:1|RATEGROUP:201|MARKUP:0|ACCID:881||ID:350165786|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.28050|INC:1|RATEGROUP:190|MARKUP:0|ACCID:61) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [origination_rates]=[ID:353162311|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.33000|INC:1|RATEGROUP:201|MARKUP:0|ACCID:881||ID:350165786|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.28050|INC:1|RATEGROUP:190|MARKUP:0|ACCID:61] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za limit(db 4463339454 db_4463339454 6/1) 2024-06-25 07:46:18.152088 [DEBUG] switch_limit.c:126 incr called: 4463339454_db_4463339454 max:6, interval:1 2024-06-25 07:46:18.152088 [DEBUG] mod_db.c:194 Usage for 4463339454_db_4463339454 is now 1/6 EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(effective_destination_number=0119751588) 2024-06-25 07:46:18.152088 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [effective_destination_number]=[0119751588] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(termination_rates=ID:4281035|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.09000|INC:1|TRUNK:3|PROVIDER:37) 2024-06-25 07:46:18.172058 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [termination_rates]=[ID:4281035|CODE:^2711975.*|DESTINATION:RSA Telkom Geographic|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.09000|INC:1|TRUNK:3|PROVIDER:37] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za export(rtp_append_audio_sdp=a=fmtp:18 annexb=no) 2024-06-25 07:46:18.172058 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [rtp_append_audio_sdp]=[a=fmtp:18 annexb=no] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za set(absolute_codec_string=^^:G729:PCMA:PCMU) 2024-06-25 07:46:18.172058 [DEBUG] mod_dptools.c:1519 SET sofia/default/27118921900@gtsbc.goldtelcloud.co.za [absolute_codec_string]=[^^:G729:PCMA:PCMU] EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za limit_execute(db Transit_JHB_BRY_SBC gw_Transit_JHB_BRY_SBC 500 bridge {absolute_codec_string=^^:G729:PCMA:PCMU}sofia/gateway/Transit_JHB_BRY_SBC/27119751588) 2024-06-25 07:46:18.172058 [DEBUG] switch_limit.c:126 incr called: Transit_JHB_BRY_SBC_gw_Transit_JHB_BRY_SBC max:500, interval:0 2024-06-25 07:46:18.172058 [DEBUG] mod_db.c:194 Usage for Transit_JHB_BRY_SBC_gw_Transit_JHB_BRY_SBC is now 36/500 EXECUTE sofia/default/27118921900@gtsbc.goldtelcloud.co.za bridge({absolute_codec_string=^^:G729:PCMA:PCMU}sofia/gateway/Transit_JHB_BRY_SBC/27119751588) 2024-06-25 07:46:18.172058 [DEBUG] switch_channel.c:1250 sofia/default/27118921900@gtsbc.goldtelcloud.co.za EXPORTING[export_vars] [t38_passthru]=[true] to event 2024-06-25 07:46:18.172058 [DEBUG] switch_channel.c:1250 sofia/default/27118921900@gtsbc.goldtelcloud.co.za EXPORTING[export_vars] [rtp_append_audio_sdp]=[a=fmtp:18 annexb=no] to event 2024-06-25 07:46:18.172058 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables 2024-06-25 07:46:18.172058 [NOTICE] switch_channel.c:1104 New Channel sofia/default/27119751588 [f6e606dd-d733-440b-9de1-c072a5243b43] 2024-06-25 07:46:18.172058 [DEBUG] mod_sofia.c:4813 (sofia/default/27119751588) State Change CS_NEW -> CS_INIT 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27119751588) Running State Change CS_INIT 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27119751588) State INIT 2024-06-25 07:46:18.172058 [DEBUG] mod_sofia.c:89 sofia/default/27119751588 SOFIA INIT 2024-06-25 07:46:18.172058 [DEBUG] sofia_glue.c:1228 sip:196.31.25.91 Setting proxy route to sofia/default/27119751588 2024-06-25 07:46:18.172058 [DEBUG] sofia_glue.c:1257 sofia/default/27119751588 sending invite version: 1.6.8 64bit Local SDP: v=0 o=FreeSWITCH 1719275472 1719275473 IN IP4 196.31.25.87 s=FreeSWITCH c=IN IP4 196.31.25.87 t=0 0 m=audio 18906 RTP/AVP 18 8 0 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 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 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:40 sofia/default/27119751588 Standard INIT 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:48 (sofia/default/27119751588) State Change CS_INIT -> CS_ROUTING 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27119751588) State INIT going to sleep 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27119751588) Running State Change CS_ROUTING 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27119751588) State ROUTING 2024-06-25 07:46:18.172058 [DEBUG] mod_sofia.c:142 sofia/default/27119751588 SOFIA ROUTING 2024-06-25 07:46:18.172058 [DEBUG] switch_ivr_originate.c:67 (sofia/default/27119751588) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27119751588) State ROUTING going to sleep 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27119751588) Running State Change CS_CONSUME_MEDIA 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:621 (sofia/default/27119751588) State CONSUME_MEDIA 2024-06-25 07:46:18.172058 [DEBUG] switch_core_state_machine.c:621 (sofia/default/27119751588) State CONSUME_MEDIA going to sleep 2024-06-25 07:46:18.272084 [DEBUG] sofia.c:6858 Channel sofia/default/27119751588 entering state [calling][0] 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:174 sofia/default/27446019550 Standard REPORTING, cause: NORMAL_CLEARING 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27446019550) State REPORTING going to sleep 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:569 (sofia/default/27446019550) State Change CS_REPORTING -> CS_DESTROY 2024-06-25 07:46:18.412010 [DEBUG] switch_core_session.c:1646 Session 5787226 (sofia/default/27446019550) Locked, Waiting on external entities 2024-06-25 07:46:18.412010 [NOTICE] switch_core_session.c:1664 Session 5787226 (sofia/default/27446019550) Ended 2024-06-25 07:46:18.412010 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/27446019550 [CS_DESTROY] 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:700 (sofia/default/27446019550) Running State Change CS_DESTROY 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27446019550) State DESTROY 2024-06-25 07:46:18.412010 [DEBUG] mod_sofia.c:342 sofia/default/27446019550 SOFIA DESTROY 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:181 sofia/default/27446019550 Standard DESTROY 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27446019550) State DESTROY going to sleep 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:174 sofia/default/27446913718@gtsbc.goldtelcloud.co.za Standard REPORTING, cause: NORMAL_CLEARING 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State REPORTING going to sleep 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:569 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State Change CS_REPORTING -> CS_DESTROY 2024-06-25 07:46:18.412010 [DEBUG] switch_core_session.c:1646 Session 5787222 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) Locked, Waiting on external entities 2024-06-25 07:46:18.412010 [NOTICE] switch_core_session.c:1664 Session 5787222 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) Ended 2024-06-25 07:46:18.412010 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/27446913718@gtsbc.goldtelcloud.co.za [CS_DESTROY] 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:700 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) Running State Change CS_DESTROY 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State DESTROY 2024-06-25 07:46:18.412010 [DEBUG] mod_sofia.c:342 sofia/default/27446913718@gtsbc.goldtelcloud.co.za SOFIA DESTROY 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:181 sofia/default/27446913718@gtsbc.goldtelcloud.co.za Standard DESTROY 2024-06-25 07:46:18.412010 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27446913718@gtsbc.goldtelcloud.co.za) State DESTROY going to sleep 2024-06-25 07:46:18.652069 [DEBUG] switch_scheduler.c:144 Deleting task 2738357 switch_ivr_schedule_hangup (3f593ecd-f908-498b-a14d-b3db8e87b421) 2024-06-25 07:46:19.892072 [DEBUG] sofia.c:6858 Channel sofia/default/27119751588 entering state [proceeding][180] 2024-06-25 07:46:19.892072 [NOTICE] sofia.c:6960 Ring-Ready sofia/default/27119751588! 2024-06-25 07:46:19.892072 [DEBUG] switch_channel.c:3343 (sofia/default/27119751588) Callstate Change DOWN -> RINGING 2024-06-25 07:46:19.892072 [NOTICE] mod_sofia.c:2198 Ring-Ready sofia/default/27118921900@gtsbc.goldtelcloud.co.za! 2024-06-25 07:46:19.892072 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/default/27118921900@gtsbc.goldtelcloud.co.za! 2024-06-25 07:46:20.252071 [DEBUG] sofia.c:6858 Channel sofia/default/27118921900@gtsbc.goldtelcloud.co.za entering state [early][180] 2024-06-25 07:46:21.292045 [ERR] switch_odbc.c:522 ERR: [insert into sip_registrations (call_id,sip_user,sip_host,presence_hosts,contact,status,rpid,expires,user_agent,server_user,server_host,profile_name,hostname,network_ip,network_port,sip_username,sip_realm,mwi_user,mwi_host, orig_server_host, orig_hostname, sub_host, ping_status, ping_count, force_ping) values ('443e038-5b80a929-20a3-65014-7-71244579-7','27116099000', '196.31.25.87','196.31.25.87,196.31.25.87','"" ','Registered(UDP)', 'unknown', 1719294501, 'Ericsson-LG Enterprise iPECS-eMG eMG80 3.0.33', '27116099000', '196.31.25.87', 'default', 'gtss2', '196.31.25.91', '5060','27116099000','gtsbc.goldtelcloud.co.za','27116099000','196.31.25.87','196.31.25.87','gtss2','196.31.25.87', 'Reachable', 0, 0)] [STATE: HY000 CODE 1213 ERROR: [MySQL][ODBC 5.1 Driver][mysqld-5.5.5-10.0.22-MariaDB-0+deb8u1-log]Deadlock found when trying to get lock; try restarting transaction ] 2024-06-25 07:46:21.292045 [ERR] switch_core_sqldb.c:587 ODBC SQL ERR [STATE: HY000 CODE 1213 ERROR: [MySQL][ODBC 5.1 Driver][mysqld-5.5.5-10.0.22-MariaDB-0+deb8u1-log]Deadlock found when trying to get lock; try restarting transaction ] insert into sip_registrations (call_id,sip_user,sip_host,presence_hosts,contact,status,rpid,expires,user_agent,server_user,server_host,profile_name,hostname,network_ip,network_port,sip_username,sip_realm,mwi_user,mwi_host, orig_server_host, orig_hostname, sub_host, ping_status, ping_count, force_ping) values ('443e038-5b80a929-20a3-65014-7-71244579-7','27116099000', '196.31.25.87','196.31.25.87,196.31.25.87','"" ','Registered(UDP)', 'unknown', 1719294501, 'Ericsson-LG Enterprise iPECS-eMG eMG80 3.0.33', '27116099000', '196.31.25.87', 'default', 'gtss2', '196.31.25.91', '5060','27116099000','gtsbc.goldtelcloud.co.za','27116099000','196.31.25.87','196.31.25.87','gtss2','196.31.25.87', 'Reachable', 0, 0) 2024-06-25 07:46:21.292045 [DEBUG] sofia.c:6858 Channel sofia/default/27448734188 entering state [completing][200] 2024-06-25 07:46:21.292045 [DEBUG] sofia.c:6865 Duplicate SDP v=0 o=PortaSIP 4084356539596529243 1 IN IP4 197.97.67.168 s=- t=0 0 m=audio 21386 RTP/AVP 18 101 c=IN IP4 197.97.67.168 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=ptime:20 2024-06-25 07:46:21.292045 [DEBUG] sofia.c:6858 Channel sofia/default/27448734188 entering state [ready][200] 2024-06-25 07:46:21.292045 [NOTICE] sofia.c:7767 Channel [sofia/default/27448734188] has been answered 2024-06-25 07:46:21.292045 [DEBUG] switch_channel.c:3770 (sofia/default/27448734188) Callstate Change EARLY -> ACTIVE 2024-06-25 07:46:21.292045 [DEBUG] mod_sofia.c:814 Local SDP sofia/default/27876303987@102.220.232.19: v=0 o=FreeSWITCH 1719263173 1719263175 IN IP4 196.31.25.87 s=FreeSWITCH c=IN IP4 196.31.25.87 t=0 0 m=audio 31202 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv 2024-06-25 07:46:21.292045 [NOTICE] switch_ivr_bridge.c:618 Channel [sofia/default/27876303987@102.220.232.19] has been answered 2024-06-25 07:46:21.292045 [DEBUG] switch_channel.c:3770 (sofia/default/27876303987@102.220.232.19) Callstate Change EARLY -> ACTIVE 2024-06-25 07:46:21.292045 [DEBUG] sofia.c:6858 Channel sofia/default/27876303987@102.220.232.19 entering state [completed][200] 2024-06-25 07:46:21.312044 [DEBUG] sofia.c:6858 Channel sofia/default/27876303987@102.220.232.19 entering state [ready][200] 2024-06-25 07:46:21.352075 [NOTICE] sofia.c:988 Hangup sofia/default/27876303987@102.220.232.19 [CS_EXECUTE] [NORMAL_CLEARING] 2024-06-25 07:46:21.372107 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/default/27876303987@102.220.232.19] 2024-06-25 07:46:21.372107 [DEBUG] switch_rtp.c:6707 Correct audio ip/port confirmed. 2024-06-25 07:46:21.372107 [DEBUG] switch_ivr_bridge.c:701 sofia/default/27876303987@102.220.232.19 ending bridge by request from write function 2024-06-25 07:46:21.372107 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/default/27448734188] 2024-06-25 07:46:21.372107 [NOTICE] switch_ivr_bridge.c:884 Hangup sofia/default/27448734188 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:612 (sofia/default/27448734188) State EXCHANGE_MEDIA going to sleep 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27448734188) Running State Change CS_HANGUP 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:809 (sofia/default/27448734188) Callstate Change ACTIVE -> HANGUP 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27448734188) State HANGUP 2024-06-25 07:46:21.372107 [DEBUG] mod_sofia.c:431 sofia/default/27448734188 Overriding SIP cause 480 with 200 from the other leg 2024-06-25 07:46:21.372107 [DEBUG] mod_sofia.c:437 Channel sofia/default/27448734188 hanging up, cause: NORMAL_CLEARING 2024-06-25 07:46:21.372107 [DEBUG] switch_ivr_bridge.c:1692 sofia/default/27448734188 skip receive message [UNBRIDGE] (channel is hungup already) 2024-06-25 07:46:21.372107 [DEBUG] switch_ivr_bridge.c:1695 sofia/default/27876303987@102.220.232.19 skip receive message [UNBRIDGE] (channel is hungup already) 2024-06-25 07:46:21.372107 [DEBUG] switch_core_session.c:2796 sofia/default/27876303987@102.220.232.19 skip receive message [PHONE_EVENT] (channel is hungup already) 2024-06-25 07:46:21.372107 [DEBUG] switch_core_session.c:2796 sofia/default/27876303987@102.220.232.19 skip receive message [PHONE_EVENT] (channel is hungup already) 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:609 (sofia/default/27876303987@102.220.232.19) State EXECUTE going to sleep 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27876303987@102.220.232.19) Running State Change CS_HANGUP 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:809 (sofia/default/27876303987@102.220.232.19) Callstate Change ACTIVE -> HANGUP 2024-06-25 07:46:21.372107 [DEBUG] mod_sofia.c:490 Sending BYE to sofia/default/27448734188 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:60 sofia/default/27448734188 Standard HANGUP, cause: NORMAL_CLEARING 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27448734188) State HANGUP going to sleep 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:578 (sofia/default/27448734188) State Change CS_HANGUP -> CS_REPORTING 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27876303987@102.220.232.19) State HANGUP 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27448734188) Running State Change CS_REPORTING 2024-06-25 07:46:21.372107 [DEBUG] mod_sofia.c:437 Channel sofia/default/27876303987@102.220.232.19 hanging up, cause: NORMAL_CLEARING 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27448734188) State REPORTING 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:60 sofia/default/27876303987@102.220.232.19 Standard HANGUP, cause: NORMAL_CLEARING 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27876303987@102.220.232.19) State HANGUP going to sleep 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:578 (sofia/default/27876303987@102.220.232.19) State Change CS_HANGUP -> CS_REPORTING 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27876303987@102.220.232.19) Running State Change CS_REPORTING 2024-06-25 07:46:21.372107 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27876303987@102.220.232.19) State REPORTING 2024-06-25 07:46:21.651974 [DEBUG] switch_core_state_machine.c:174 sofia/default/27448734188 Standard REPORTING, cause: NORMAL_CLEARING 2024-06-25 07:46:21.651974 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27448734188) State REPORTING going to sleep 2024-06-25 07:46:21.651974 [DEBUG] switch_core_state_machine.c:569 (sofia/default/27448734188) State Change CS_REPORTING -> CS_DESTROY 2024-06-25 07:46:21.651974 [DEBUG] switch_core_session.c:1646 Session 5787233 (sofia/default/27448734188) Locked, Waiting on external entities 2024-06-25 07:46:21.651974 [NOTICE] switch_core_session.c:1664 Session 5787233 (sofia/default/27448734188) Ended 2024-06-25 07:46:21.651974 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/27448734188 [CS_DESTROY] 2024-06-25 07:46:21.651974 [DEBUG] switch_core_state_machine.c:700 (sofia/default/27448734188) Running State Change CS_DESTROY 2024-06-25 07:46:21.651974 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27448734188) State DESTROY 2024-06-25 07:46:21.651974 [DEBUG] mod_sofia.c:342 sofia/default/27448734188 SOFIA DESTROY 2024-06-25 07:46:21.651974 [DEBUG] switch_core_state_machine.c:181 sofia/default/27448734188 Standard DESTROY 2024-06-25 07:46:21.651974 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27448734188) State DESTROY going to sleep 2024-06-25 07:46:21.692036 [DEBUG] switch_core_state_machine.c:174 sofia/default/27876303987@102.220.232.19 Standard REPORTING, cause: NORMAL_CLEARING 2024-06-25 07:46:21.692036 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27876303987@102.220.232.19) State REPORTING going to sleep 2024-06-25 07:46:21.692036 [DEBUG] switch_core_state_machine.c:569 (sofia/default/27876303987@102.220.232.19) State Change CS_REPORTING -> CS_DESTROY 2024-06-25 07:46:21.692036 [DEBUG] switch_core_session.c:1646 Session 5787232 (sofia/default/27876303987@102.220.232.19) Locked, Waiting on external entities 2024-06-25 07:46:21.692036 [NOTICE] switch_core_session.c:1664 Session 5787232 (sofia/default/27876303987@102.220.232.19) Ended 2024-06-25 07:46:21.692036 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/27876303987@102.220.232.19 [CS_DESTROY] 2024-06-25 07:46:21.692036 [DEBUG] switch_core_state_machine.c:700 (sofia/default/27876303987@102.220.232.19) Running State Change CS_DESTROY 2024-06-25 07:46:21.692036 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27876303987@102.220.232.19) State DESTROY 2024-06-25 07:46:21.692036 [DEBUG] mod_sofia.c:342 sofia/default/27876303987@102.220.232.19 SOFIA DESTROY 2024-06-25 07:46:21.692036 [DEBUG] switch_core_state_machine.c:181 sofia/default/27876303987@102.220.232.19 Standard DESTROY 2024-06-25 07:46:21.692036 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27876303987@102.220.232.19) State DESTROY going to sleep 2024-06-25 07:46:22.152004 [DEBUG] switch_scheduler.c:144 Deleting task 2738361 switch_ivr_schedule_hangup (a5d94864-7170-4506-84a1-e088245af79a) 2024-06-25 07:46:22.272047 [WARNING] sofia_reg.c:2889 Can't find user [27113915665@196.31.25.87] from 196.31.25.91 You must define a domain called '196.31.25.87' in your directory and add a user with the id="27113915665" attribute and you must configure your device to use the proper domain in it's authentication credentials. 2024-06-25 07:46:22.272047 [WARNING] sofia_reg.c:2889 Can't find user [27317647531@196.31.25.87] from 196.31.25.91 You must define a domain called '196.31.25.87' in your directory and add a user with the id="27317647531" attribute and you must configure your device to use the proper domain in it's authentication credentials. 2024-06-25 07:46:23.632042 [DEBUG] sofia.c:6858 Channel sofia/default/27119751588 entering state [completing][200] 2024-06-25 07:46:23.632042 [DEBUG] sofia.c:6868 Remote SDP: v=0 o=PortaSIP 4523595345405747229 1 IN IP4 197.97.67.168 s=- t=0 0 m=audio 20532 RTP/AVP 8 101 c=IN IP4 197.97.67.168 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2024-06-25 07:46:23.632042 [DEBUG] sofia.c:6858 Channel sofia/default/27119751588 entering state [ready][200] 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:3090 Set Codec sofia/default/27119751588 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2024-06-25 07:46:23.632042 [DEBUG] switch_core_codec.c:111 sofia/default/27119751588 Original read codec set to PCMA:8 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:4681 sofia/default/27119751588 Set 2833 dtmf send payload to 101 recv payload to 101 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/default/27119751588] 196.31.25.87 port 18906 -> 197.97.67.168 port 20532 codec: 8 ms: 20 2024-06-25 07:46:23.632042 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:6763 sofia/default/27119751588 Set 2833 dtmf send payload to 101 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:6770 sofia/default/27119751588 Set 2833 dtmf receive payload to 101 2024-06-25 07:46:23.632042 [DEBUG] switch_core_media.c:6793 sofia/default/27119751588 Set rtp dtmf delay to 40 2024-06-25 07:46:23.632042 [NOTICE] sofia.c:7826 Channel [sofia/default/27119751588] has been answered 2024-06-25 07:46:23.632042 [DEBUG] switch_channel.c:3770 (sofia/default/27119751588) Callstate Change RINGING -> ACTIVE 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:3090 Set Codec sofia/default/27118921900@gtsbc.goldtelcloud.co.za G729/8000 20 ms 160 samples 8000 bits 1 channels 2024-06-25 07:46:23.652065 [DEBUG] switch_core_codec.c:111 sofia/default/27118921900@gtsbc.goldtelcloud.co.za Original read codec set to G729:18 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:4681 sofia/default/27118921900@gtsbc.goldtelcloud.co.za Set 2833 dtmf send payload to 101 recv payload to 101 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/default/27118921900@gtsbc.goldtelcloud.co.za] 196.31.25.87 port 25604 -> 41.4.17.223 port 8012 codec: 18 ms: 20 2024-06-25 07:46:23.652065 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:6763 sofia/default/27118921900@gtsbc.goldtelcloud.co.za Set 2833 dtmf send payload to 101 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:6770 sofia/default/27118921900@gtsbc.goldtelcloud.co.za Set 2833 dtmf receive payload to 101 2024-06-25 07:46:23.652065 [DEBUG] switch_core_media.c:6793 sofia/default/27118921900@gtsbc.goldtelcloud.co.za Set rtp dtmf delay to 40 2024-06-25 07:46:23.652065 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/27118921900@gtsbc.goldtelcloud.co.za! 2024-06-25 07:46:23.652065 [DEBUG] switch_channel.c:3471 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) Callstate Change RINGING -> EARLY 2024-06-25 07:46:23.652065 [DEBUG] mod_sofia.c:814 Local SDP sofia/default/27118921900@gtsbc.goldtelcloud.co.za: v=0 o=FreeSWITCH 1719268779 1719268780 IN IP4 196.31.25.87 s=FreeSWITCH c=IN IP4 196.31.25.87 t=0 0 m=audio 25604 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=fmtp:18 annexb=no a=ptime:20 a=sendrecv 2024-06-25 07:46:23.652065 [NOTICE] switch_ivr_originate.c:3549 Channel [sofia/default/27118921900@gtsbc.goldtelcloud.co.za] has been answered 2024-06-25 07:46:23.652065 [DEBUG] switch_channel.c:3770 (sofia/default/27118921900@gtsbc.goldtelcloud.co.za) Callstate Change EARLY -> ACTIVE 2024-06-25 07:46:23.652065 [DEBUG] sofia.c:6858 Channel sofia/default/27118921900@gtsbc.goldtelcloud.co.za entering state [completed][200] 2024-06-25 07:46:23.652065 [DEBUG] switch_ivr_originate.c:3607 Originate Resulted in Success: [sofia/default/27119751588] 2024-06-25 07:46:23.652065 [DEBUG] switch_ivr_bridge.c:1594 (sofia/default/27119751588) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2024-06-25 07:46:23.652065 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27119751588) Running State Change CS_EXCHANGE_MEDIA 2024-06-25 07:46:23.652065 [DEBUG] switch_core_state_machine.c:612 (sofia/default/27119751588) State EXCHANGE_MEDIA 2024-06-25 07:46:23.652065 [DEBUG] mod_sofia.c:628 SOFIA EXCHANGE_MEDIA 2024-06-25 07:46:23.692072 [NOTICE] sofia.c:988 Hangup sofia/default/27844641830 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2024-06-25 07:46:23.692072 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/default/27844641830] 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:612 (sofia/default/27844641830) State EXCHANGE_MEDIA going to sleep 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27844641830) Running State Change CS_HANGUP 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:809 (sofia/default/27844641830) Callstate Change ACTIVE -> HANGUP 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27844641830) State HANGUP 2024-06-25 07:46:23.692072 [DEBUG] mod_sofia.c:437 Channel sofia/default/27844641830 hanging up, cause: NORMAL_CLEARING 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:60 sofia/default/27844641830 Standard HANGUP, cause: NORMAL_CLEARING 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27844641830) State HANGUP going to sleep 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:578 (sofia/default/27844641830) State Change CS_HANGUP -> CS_REPORTING 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27844641830) Running State Change CS_REPORTING 2024-06-25 07:46:23.692072 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27844641830) State REPORTING 2024-06-25 07:46:23.692072 [DEBUG] switch_rtp.c:6707 Correct audio ip/port confirmed. 2024-06-25 07:46:23.692072 [DEBUG] sofia.c:6858 Channel sofia/default/27118921900@gtsbc.goldtelcloud.co.za entering state [ready][200] 2024-06-25 07:46:23.711967 [DEBUG] switch_ivr_bridge.c:701 sofia/default/27844641830 ending bridge by request from write function 2024-06-25 07:46:23.711967 [DEBUG] switch_ivr_bridge.c:780 BRIDGE THREAD DONE [sofia/default/27113395539@nopa:7011] 2024-06-25 07:46:23.711967 [DEBUG] switch_ivr_bridge.c:1692 sofia/default/27844641830 skip receive message [UNBRIDGE] (channel is hungup already) 2024-06-25 07:46:23.711967 [NOTICE] switch_ivr_bridge.c:1744 Hangup sofia/default/27113395539@nopa:7011 [CS_EXECUTE] [NORMAL_CLEARING] 2024-06-25 07:46:23.711967 [DEBUG] switch_core_session.c:2796 sofia/default/27113395539@nopa:7011 skip receive message [PHONE_EVENT] (channel is hungup already) 2024-06-25 07:46:23.711967 [DEBUG] switch_core_session.c:2796 sofia/default/27113395539@nopa:7011 skip receive message [PHONE_EVENT] (channel is hungup already) 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:609 (sofia/default/27113395539@nopa:7011) State EXECUTE going to sleep 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27113395539@nopa:7011) Running State Change CS_HANGUP 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:809 (sofia/default/27113395539@nopa:7011) Callstate Change ACTIVE -> HANGUP 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27113395539@nopa:7011) State HANGUP 2024-06-25 07:46:23.711967 [DEBUG] mod_sofia.c:431 sofia/default/27113395539@nopa:7011 Overriding SIP cause 480 with 200 from the other leg 2024-06-25 07:46:23.711967 [DEBUG] mod_sofia.c:437 Channel sofia/default/27113395539@nopa:7011 hanging up, cause: NORMAL_CLEARING 2024-06-25 07:46:23.711967 [DEBUG] mod_sofia.c:490 Sending BYE to sofia/default/27113395539@nopa:7011 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:60 sofia/default/27113395539@nopa:7011 Standard HANGUP, cause: NORMAL_CLEARING 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:811 (sofia/default/27113395539@nopa:7011) State HANGUP going to sleep 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:578 (sofia/default/27113395539@nopa:7011) State Change CS_HANGUP -> CS_REPORTING 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27113395539@nopa:7011) Running State Change CS_REPORTING 2024-06-25 07:46:23.711967 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27113395539@nopa:7011) State REPORTING 2024-06-25 07:46:23.971974 [DEBUG] switch_core_state_machine.c:174 sofia/default/27844641830 Standard REPORTING, cause: NORMAL_CLEARING 2024-06-25 07:46:23.971974 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27844641830) State REPORTING going to sleep 2024-06-25 07:46:23.971974 [DEBUG] switch_core_state_machine.c:569 (sofia/default/27844641830) State Change CS_REPORTING -> CS_DESTROY 2024-06-25 07:46:23.971974 [DEBUG] switch_core_session.c:1646 Session 5787179 (sofia/default/27844641830) Locked, Waiting on external entities 2024-06-25 07:46:23.971974 [NOTICE] switch_core_session.c:1664 Session 5787179 (sofia/default/27844641830) Ended 2024-06-25 07:46:23.971974 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/27844641830 [CS_DESTROY] 2024-06-25 07:46:23.971974 [DEBUG] switch_core_state_machine.c:700 (sofia/default/27844641830) Running State Change CS_DESTROY 2024-06-25 07:46:23.971974 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27844641830) State DESTROY 2024-06-25 07:46:23.971974 [DEBUG] mod_sofia.c:342 sofia/default/27844641830 SOFIA DESTROY 2024-06-25 07:46:23.971974 [DEBUG] switch_core_state_machine.c:181 sofia/default/27844641830 Standard DESTROY 2024-06-25 07:46:23.971974 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27844641830) State DESTROY going to sleep 2024-06-25 07:46:23.991975 [INFO] switch_rtp.c:6669 Auto Changing audio port from 41.4.17.223:8012 to 41.4.17.223:36869 2024-06-25 07:46:24.032051 [DEBUG] switch_core_state_machine.c:174 sofia/default/27113395539@nopa:7011 Standard REPORTING, cause: NORMAL_CLEARING 2024-06-25 07:46:24.032051 [DEBUG] switch_core_state_machine.c:897 (sofia/default/27113395539@nopa:7011) State REPORTING going to sleep 2024-06-25 07:46:24.032051 [DEBUG] switch_core_state_machine.c:569 (sofia/default/27113395539@nopa:7011) State Change CS_REPORTING -> CS_DESTROY 2024-06-25 07:46:24.032051 [DEBUG] switch_core_session.c:1646 Session 5787178 (sofia/default/27113395539@nopa:7011) Locked, Waiting on external entities 2024-06-25 07:46:24.032051 [NOTICE] switch_core_session.c:1664 Session 5787178 (sofia/default/27113395539@nopa:7011) Ended 2024-06-25 07:46:24.032051 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/27113395539@nopa:7011 [CS_DESTROY] 2024-06-25 07:46:24.032051 [DEBUG] switch_core_state_machine.c:700 (sofia/default/27113395539@nopa:7011) Running State Change CS_DESTROY 2024-06-25 07:46:24.032051 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27113395539@nopa:7011) State DESTROY 2024-06-25 07:46:24.032051 [DEBUG] mod_sofia.c:342 sofia/default/27113395539@nopa:7011 SOFIA DESTROY 2024-06-25 07:46:24.032051 [DEBUG] switch_core_state_machine.c:181 sofia/default/27113395539@nopa:7011 Standard DESTROY 2024-06-25 07:46:24.032051 [DEBUG] switch_core_state_machine.c:710 (sofia/default/27113395539@nopa:7011) State DESTROY going to sleep 2024-06-25 07:46:24.152048 [DEBUG] switch_scheduler.c:144 Deleting task 2738334 switch_ivr_schedule_hangup (d6d281d1-c2d8-46d1-a5b0-14f8efabbf92) 2024-06-25 07:46:27.392051 [NOTICE] switch_channel.c:1104 New Channel sofia/default/27446903578@197.97.67.136:5060 [be99a2a3-8724-47a8-b870-204e79e1426c] 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446903578@197.97.67.136:5060) Running State Change CS_NEW 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:9376 sofia/default/27446903578@197.97.67.136:5060 receiving invite from 196.31.25.91:5060 version: 1.6.8 64bit 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:9498 1 acls to check for proxy 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:9503 checking 196.31.25.91 against acl proxy_acl 2024-06-25 07:46:27.392051 [INFO] sofia.c:9505 196.31.25.91 is a proxy according to the proxy_acl acl 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:9515 network ip is a proxy 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:9519 found auth ip [X-AUTH-IP] header of [197.97.67.136] 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:9551 IP 197.97.67.136 Approved by acl "default[]". Access Granted. 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:6858 Channel sofia/default/27446903578@197.97.67.136:5060 entering state [received][100] 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:6868 Remote SDP: v=0 o=PortaSIP 2572680169871076604 1 IN IP4 197.97.67.136 s=- t=0 0 m=audio 20740 RTP/AVP 18 8 0 98 c=IN IP4 197.97.67.136 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=yes a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:98 telephone-event/8000 a=fmtp:98 0-15 a=maxptime:40 a=ptime:20 2024-06-25 07:46:27.392051 [DEBUG] sofia.c:7227 (sofia/default/27446903578@197.97.67.136:5060) State Change CS_NEW -> CS_INIT 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:562 (sofia/default/27446903578@197.97.67.136:5060) State NEW 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446903578@197.97.67.136:5060) Running State Change CS_INIT 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27446903578@197.97.67.136:5060) State INIT 2024-06-25 07:46:27.392051 [DEBUG] mod_sofia.c:89 sofia/default/27446903578@197.97.67.136:5060 SOFIA INIT 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:40 sofia/default/27446903578@197.97.67.136:5060 Standard INIT 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:48 (sofia/default/27446903578@197.97.67.136:5060) State Change CS_INIT -> CS_ROUTING 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27446903578@197.97.67.136:5060) State INIT going to sleep 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446903578@197.97.67.136:5060) Running State Change CS_ROUTING 2024-06-25 07:46:27.392051 [DEBUG] switch_channel.c:2249 (sofia/default/27446903578@197.97.67.136:5060) Callstate Change DOWN -> RINGING 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27446903578@197.97.67.136:5060) State ROUTING 2024-06-25 07:46:27.392051 [DEBUG] mod_sofia.c:142 sofia/default/27446903578@197.97.67.136:5060 SOFIA ROUTING 2024-06-25 07:46:27.392051 [DEBUG] switch_core_state_machine.c:236 sofia/default/27446903578@197.97.67.136:5060 Standard ROUTING 2024-06-25 07:46:27.392051 [INFO] mod_dialplan_xml.c:637 Processing 27446903578 <27446903578>->27446913718 in context default Dialplan: sofia/default/27446903578@197.97.67.136:5060 parsing [default->] continue=false Dialplan: sofia/default/27446903578@197.97.67.136:5060 Regex (PASS) [] destination_number(27446913718) =~ // break=on-false Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(callstart=2024-06-25 05:46:27) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(call_processed=internal) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(originated_destination_number=27446913718) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(hangup_after_bridge=true) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(fax_enable_t38=true) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(fax_enable_t38_request=true) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action export(t38_passthru=true) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(accountid=2030) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(account_type=0) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(resellerid=1736) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(accountcode=2826018430) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(call_direction=inbound) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(calltype=DID) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action sched_hangup(+6000 allotted_timeout) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(effective_destination_number=27446913718) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(ringback=%(2000, 4000, 440.0, 480.0)) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(origination_rates=ID:7613|CODE:^.27446913718.*|DESTINATION:Goldtel ported|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|RATEGROUP:501|MARKUP:0|ACCID:2030||ID:2030|CODE:^.27446913718.*|DESTINATION:Goldtel ported|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:1|RATEGROUP:396|MARKUP:0|ACCID:1736) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(DID_Caller=) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(hangup_after_bridge=true) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action set(continue_on_fail=true) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action export(absolute_codec_string=^^:G729:PCMA:PCMU) Dialplan: sofia/default/27446903578@197.97.67.136:5060 Action bridge({sip_invite_to_uri= CS_EXECUTE 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27446903578@197.97.67.136:5060) State ROUTING going to sleep 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446903578@197.97.67.136:5060) Running State Change CS_EXECUTE 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:609 (sofia/default/27446903578@197.97.67.136:5060) State EXECUTE 2024-06-25 07:46:27.532106 [DEBUG] mod_sofia.c:197 sofia/default/27446903578@197.97.67.136:5060 SOFIA EXECUTE 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:328 sofia/default/27446903578@197.97.67.136:5060 Standard EXECUTE EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(callstart=2024-06-25 05:46:27) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [callstart]=[2024-06-25 05:46:27] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(call_processed=internal) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [call_processed]=[internal] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(originated_destination_number=27446913718) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [originated_destination_number]=[27446913718] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(hangup_after_bridge=true) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [hangup_after_bridge]=[true] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(fax_enable_t38=true) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [fax_enable_t38]=[true] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(fax_enable_t38_request=true) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [fax_enable_t38_request]=[true] EXECUTE sofia/default/27446903578@197.97.67.136:5060 export(t38_passthru=true) 2024-06-25 07:46:27.532106 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [t38_passthru]=[true] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(accountid=2030) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [accountid]=[2030] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(account_type=0) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [account_type]=[0] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(resellerid=1736) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [resellerid]=[1736] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(accountcode=2826018430) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [accountcode]=[2826018430] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(call_direction=inbound) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [call_direction]=[inbound] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(calltype=DID) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [calltype]=[DID] EXECUTE sofia/default/27446903578@197.97.67.136:5060 sched_hangup(+6000 allotted_timeout) 2024-06-25 07:46:27.532106 [DEBUG] switch_scheduler.c:249 Added task 2738363 switch_ivr_schedule_hangup (be99a2a3-8724-47a8-b870-204e79e1426c) to run at 1719300387 EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(effective_destination_number=27446913718) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [effective_destination_number]=[27446913718] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(ringback=%(2000, 4000, 440.0, 480.0)) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [ringback]=[%(2000, 4000, 440.0, 480.0)] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(origination_rates=ID:7613|CODE:^.27446913718.*|DESTINATION:Goldtel ported|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|RATEGROUP:501|MARKUP:0|ACCID:2030||ID:2030|CODE:^.27446913718.*|DESTINATION:Goldtel ported|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:1|RATEGROUP:396|MARKUP:0|ACCID:1736) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [origination_rates]=[ID:7613|CODE:^.27446913718.*|DESTINATION:Goldtel ported|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|RATEGROUP:501|MARKUP:0|ACCID:2030||ID:2030|CODE:^.27446913718.*|DESTINATION:Goldtel ported|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:1|RATEGROUP:396|MARKUP:0|ACCID:1736] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(DID_Caller=) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [DID_Caller]=[UNDEF] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(hangup_after_bridge=true) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [hangup_after_bridge]=[true] EXECUTE sofia/default/27446903578@197.97.67.136:5060 set(continue_on_fail=true) 2024-06-25 07:46:27.532106 [DEBUG] mod_dptools.c:1519 SET sofia/default/27446903578@197.97.67.136:5060 [continue_on_fail]=[true] EXECUTE sofia/default/27446903578@197.97.67.136:5060 export(absolute_codec_string=^^:G729:PCMA:PCMU) 2024-06-25 07:46:27.532106 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [absolute_codec_string]=[^^:G729:PCMA:PCMU] EXECUTE sofia/default/27446903578@197.97.67.136:5060 bridge({sip_invite_to_uri= CS_INIT 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446913718@102.220.234.249:8356) Running State Change CS_INIT 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27446913718@102.220.234.249:8356) State INIT 2024-06-25 07:46:27.532106 [DEBUG] mod_sofia.c:89 sofia/default/27446913718@102.220.234.249:8356 SOFIA INIT 2024-06-25 07:46:27.532106 [DEBUG] sofia_glue.c:1228 sip:196.31.25.91;lr;received=sip:102.220.234.249:8356 Setting proxy route to sofia/default/27446913718@102.220.234.249:8356 2024-06-25 07:46:27.532106 [DEBUG] sofia_glue.c:1257 sofia/default/27446913718@102.220.234.249:8356 sending invite version: 1.6.8 64bit Local SDP: v=0 o=FreeSWITCH 1719267855 1719267856 IN IP4 196.31.25.87 s=FreeSWITCH c=IN IP4 196.31.25.87 t=0 0 m=audio 26532 RTP/AVP 18 8 0 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:40 sofia/default/27446913718@102.220.234.249:8356 Standard INIT 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:48 (sofia/default/27446913718@102.220.234.249:8356) State Change CS_INIT -> CS_ROUTING 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:586 (sofia/default/27446913718@102.220.234.249:8356) State INIT going to sleep 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446913718@102.220.234.249:8356) Running State Change CS_ROUTING 2024-06-25 07:46:27.532106 [DEBUG] sofia.c:6858 Channel sofia/default/27446913718@102.220.234.249:8356 entering state [calling][0] 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27446913718@102.220.234.249:8356) State ROUTING 2024-06-25 07:46:27.532106 [DEBUG] mod_sofia.c:142 sofia/default/27446913718@102.220.234.249:8356 SOFIA ROUTING 2024-06-25 07:46:27.532106 [DEBUG] switch_ivr_originate.c:67 (sofia/default/27446913718@102.220.234.249:8356) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:602 (sofia/default/27446913718@102.220.234.249:8356) State ROUTING going to sleep 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:543 (sofia/default/27446913718@102.220.234.249:8356) Running State Change CS_CONSUME_MEDIA 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:621 (sofia/default/27446913718@102.220.234.249:8356) State CONSUME_MEDIA 2024-06-25 07:46:27.532106 [DEBUG] switch_core_state_machine.c:621 (sofia/default/27446913718@102.220.234.249:8356) State CONSUME_MEDIA going to sleep 2024-06-25 07:46:28.072072 [DEBUG] sofia.c:6858 Channel sofia/default/27446913718@102.220.234.249:8356 entering state [proceeding][180] 2024-06-25 07:46:28.072072 [NOTICE] sofia.c:6960 Ring-Ready sofia/default/27446913718@102.220.234.249:8356! 2024-06-25 07:46:28.072072 [DEBUG] switch_channel.c:3343 (sofia/default/27446913718@102.220.234.249:8356) Callstate Change DOWN -> RINGING 2024-06-25 07:46:28.072072 [INFO] switch_ivr_originate.c:1215 Sending early media 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 98@8000 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:3090 Set Codec sofia/default/27446903578@197.97.67.136:5060 G729/8000 20 ms 160 samples 8000 bits 1 channels 2024-06-25 07:46:28.072072 [DEBUG] switch_core_codec.c:111 sofia/default/27446903578@197.97.67.136:5060 Original read codec set to G729:18 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 98@8000 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:4681 sofia/default/27446903578@197.97.67.136:5060 Set 2833 dtmf send payload to 101 recv payload to 101 2024-06-25 07:46:28.072072 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/default/27446903578@197.97.67.136:5060] 196.31.25.87 port 17554 -> 197.97.67.136 port 20740 codec: 18 ms: 20 2024-06-25 07:46:28.072072 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms 2024-06-25 07:46:28.092071 [DEBUG] switch_core_media.c:6763 sofia/default/27446903578@197.97.67.136:5060 Set 2833 dtmf send payload to 101 2024-06-25 07:46:28.092071 [DEBUG] switch_core_media.c:6770 sofia/default/27446903578@197.97.67.136:5060 Set 2833 dtmf receive payload to 101 2024-06-25 07:46:28.092071 [DEBUG] switch_core_media.c:6793 sofia/default/27446903578@197.97.67.136:5060 Set rtp dtmf delay to 40 2024-06-25 07:46:28.092071 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/27446903578@197.97.67.136:5060! 2024-06-25 07:46:28.092071 [DEBUG] switch_channel.c:3471 (sofia/default/27446903578@197.97.67.136:5060) Callstate Change RINGING -> EARLY 2024-06-25 07:46:28.092071 [DEBUG] mod_sofia.c:2367 Ring SDP: v=0 o=FreeSWITCH 1719276834 1719276835 IN IP4 196.31.25.87