2019-06-10 16:33:44.646270 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/202@connec.cpbx.co.za:5060 [649a8a76-4fc0-45df-b8d6-32848e8e7312] 2019-06-10 16:33:44.646270 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_NEW (Cur 3 Tot 37375) 2019-06-10 16:33:44.646270 [DEBUG] sofia.c:9873 sofia/internal/202@connec.cpbx.co.za:5060 receiving invite from 160.119.232.78:5239 version: 1.6.20 -37-987c9 b9 64bit 2019-06-10 16:33:44.646270 [DEBUG] sofia.c:10044 IP 160.119.232.78 Rejected by acl "domains". Falling back to Digest auth. 2019-06-10 16:33:44.646270 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [00497822780875@connec.cpbx.co.za] from ip 160.119.232.78 2019-06-10 16:33:44.646270 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/202@connec.cpbx.co.za:5060) State NEW 2019-06-10 16:33:44.646270 [DEBUG] sofia.c:2334 detaching session 649a8a76-4fc0-45df-b8d6-32848e8e7312 2019-06-10 16:33:44.706276 [DEBUG] sofia.c:2442 Re-attaching to session 649a8a76-4fc0-45df-b8d6-32848e8e7312 2019-06-10 16:33:44.706276 [DEBUG] sofia.c:9873 sofia/internal/202@connec.cpbx.co.za:5060 receiving invite from 160.119.232.78:5239 version: 1.6.20 -37-987c9 b9 64bit 2019-06-10 16:33:44.706276 [DEBUG] sofia.c:10044 IP 160.119.232.78 Rejected by acl "domains". Falling back to Digest auth. 2019-06-10 16:33:44.726278 [DEBUG] sofia.c:7084 Channel sofia/internal/202@connec.cpbx.co.za:5060 entering state [received][100] 2019-06-10 16:33:44.726278 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=202 5457184 1912527719 IN IP4 160.119.232.78 s=A conversation c=IN IP4 160.119.232.78 t=0 0 m=audio 10320 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1] 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:3061 Set Codec sofia/internal/202@connec.cpbx.co.za:5060 G729/8000 20 ms 160 samples 8000 bits 1 chann els 2019-06-10 16:33:44.726278 [DEBUG] switch_core_codec.c:111 sofia/internal/202@connec.cpbx.co.za:5060 Original read codec set to G729:18 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 2019-06-10 16:33:44.726278 [DEBUG] switch_core_media.c:4767 sofia/internal/202@connec.cpbx.co.za:5060 Set 2833 dtmf send payload to 101 recv payload to 101 2019-06-10 16:33:44.726278 [DEBUG] sofia.c:7507 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_NEW -> CS_INIT 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_INIT (Cur 3 Tot 37375) 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/202@connec.cpbx.co.za:5060) State INIT 2019-06-10 16:33:44.726278 [DEBUG] mod_sofia.c:90 sofia/internal/202@connec.cpbx.co.za:5060 SOFIA INIT 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:40 sofia/internal/202@connec.cpbx.co.za:5060 Standard INIT 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_INIT -> CS_ROUTING 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/202@connec.cpbx.co.za:5060) State INIT going to sleep 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_ROUTING (Cur 3 Tot 373 75) 2019-06-10 16:33:44.726278 [DEBUG] switch_channel.c:2249 (sofia/internal/202@connec.cpbx.co.za:5060) Callstate Change DOWN -> RINGING 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/202@connec.cpbx.co.za:5060) State ROUTING 2019-06-10 16:33:44.726278 [DEBUG] mod_sofia.c:143 sofia/internal/202@connec.cpbx.co.za:5060 SOFIA ROUTING 2019-06-10 16:33:44.726278 [DEBUG] switch_core_state_machine.c:236 sofia/internal/202@connec.cpbx.co.za:5060 Standard ROUTING 2019-06-10 16:33:44.726278 [INFO] mod_dialplan_xml.c:637 Processing 202 <202>->00497822780875 in context connec.cpbx.co.za 2019-06-10 16:33:44.726278 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fe0bc24d870 Connected. 2019-06-10 16:33:44.726278 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fe0bc24d870 released. Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->user_exists] continue=true Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_exists] () =~ // break=on-false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fe0bc24d870 Connected. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fe0bc24d870 released. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(user_exists=false) 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [user_exists]=[false] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->caller-details] continue=true Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(caller_destination=${destination_number}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(caller_destination=00497822780875) 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [caller_destination]=[00497822780875] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(caller_id_name=${caller_id_name}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(caller_id_name=202) 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [caller_id_name]=[202] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(caller_id_number=${caller_id_number}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(caller_id_number=202) 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [caller_id_number]=[202] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->variables] continue=true Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [variables] () =~ // break=on-false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action export(origination_callee_id_name=${destination_number}) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->call-direction] continue=true Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 ANTI-Action export(call_direction=local) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->user_record] continue=true Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] () =~ // break=on-false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fe0bc24d870 Connected. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fe0bc24d870 released. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7fe0bc24d870 Connected. 2019-06-10 16:33:44.746271 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7fe0bc24d870 released. EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(user_record=) 2019-06-10 16:33:44.746271 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [user_record]=[UNDEF] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(from_user_exists=true) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [from_user_exists]=[true] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(from_user_record=all) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [from_user_record]=[all] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_record}(all) =~ /^all$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_session=true) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_session=true) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_session]=[true] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^inbound$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^outbound$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [user_record] ${from_user_record}(all) =~ /^local$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [user_record] ${record_session}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_path=${recordings_dir}/${domain_name}/archive/${strftime(%Y)}/${strftime(%b)}/${strftim e(%d)}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_path=/var/lib/freeswitch/recordings/connec.cpbx.co.za/archive/2019/Jun/10) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_path]=[/var/lib/freeswitch/recordings/connec.cpbx .co.za/archive/2019/Jun/10] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_name=${uuid}.${record_ext}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_name=649a8a76-4fc0-45df-b8d6-32848e8e7312.mp3) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_name]=[649a8a76-4fc0-45df-b8d6-32848e8e7312.mp3] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(recording_follow_transfer=true) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(recording_follow_transfer=true) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [recording_follow_transfer]=[true] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_append=true) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_append=true) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_append]=[true] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(record_in_progress=true) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(record_in_progress=true) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [record_in_progress]=[true] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(execute_on_answer=record_session ${record_path}/${record_name}) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->redial] continue=true Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [redial] destination_number(00497822780875) =~ /^(redial|\*870)$/ break=on-true Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [redial] () =~ // break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->speed_dial] continue=false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [speed_dial] destination_number(00497822780875) =~ /^\*0(.*)$/ break=on-false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->default_caller_id] continue=true Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(emergency_caller_id_name=) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [emergency_caller_id_name]=[UNDEF] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(emergency_caller_id_number=) 2019-06-10 16:33:44.786267 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [emergency_caller_id_number]=[UNDEF] Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(0100210777) =~ /^$/ break=never Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 parsing [connec.cpbx.co.za->WS-Connec.d420] continue=false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [WS-Connec.d420] ${user_exists}(false) =~ /false/ break=on-false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Regex (PASS) [WS-Connec.d420] destination_number(00497822780875) =~ /^(\d{4,20})$/ break=on-false Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(sip_h_X-accountcode=${accountcode}) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action export(call_direction=outbound) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action unset(call_timeout) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(effective_caller_id_name=${outbound_caller_id_name}) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(effective_caller_id_number=${outbound_caller_id_number}) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(inherit_codec=true) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(ignore_display_updates=true) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(callee_id_number=00497822780875) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action set(continue_on_fail=true) Dialplan: sofia/internal/202@connec.cpbx.co.za:5060 Action bridge(sofia/gateway/8bfbc79d-cf27-4364-a463-b5227af7f55a/00497822780875) 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_ROUTING -> CS_EXECUTE 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/202@connec.cpbx.co.za:5060) State ROUTING going to sleep 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_EXECUTE (Cur 3 Tot 373 75) 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/202@connec.cpbx.co.za:5060) State EXECUTE 2019-06-10 16:33:44.786267 [DEBUG] mod_sofia.c:198 sofia/internal/202@connec.cpbx.co.za:5060 SOFIA EXECUTE 2019-06-10 16:33:44.786267 [DEBUG] switch_core_state_machine.c:328 sofia/internal/202@connec.cpbx.co.za:5060 Standard EXECUTE EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 export(origination_callee_id_name=00497822780875) 2019-06-10 16:33:44.786267 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[00497822780875] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(RFC2822_DATE=Mon, 10 Jun 2019 16:33:44 +0200) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [RFC2822_DATE]=[Mon, 10 Jun 2019 16:33:44 +0200] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 export(call_direction=local) 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[local] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(execute_on_answer=record_session /var/lib/freeswitch/recordings/connec.cpbx.co.za/archive/2019/Jun/10/6 49a8a76-4fc0-45df-b8d6-32848e8e7312.mp3) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [execute_on_answer]=[record_session /var/lib/freeswitch/r ecordings/connec.cpbx.co.za/archive/2019/Jun/10/649a8a76-4fc0-45df-b8d6-32848e8e7312.mp3] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 hash(insert/connec.cpbx.co.za-last_dial/202/00497822780875) EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(sip_h_X-accountcode=) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [sip_h_X-accountcode]=[UNDEF] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 export(call_direction=outbound) 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[outbound] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 unset(call_timeout) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(hangup_after_bridge=true) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [hangup_after_bridge]=[true] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(effective_caller_id_name=Connec Telecoms) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [effective_caller_id_name]=[Connec Telecoms] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(effective_caller_id_number=0100210777) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [effective_caller_id_number]=[0100210777] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(inherit_codec=true) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [inherit_codec]=[true] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(ignore_display_updates=true) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [ignore_display_updates]=[true] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(callee_id_number=00497822780875) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [callee_id_number]=[00497822780875] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 set(continue_on_fail=true) 2019-06-10 16:33:44.806263 [DEBUG] mod_dptools.c:1548 SET sofia/internal/202@connec.cpbx.co.za:5060 [continue_on_fail]=[true] EXECUTE sofia/internal/202@connec.cpbx.co.za:5060 bridge(sofia/gateway/8bfbc79d-cf27-4364-a463-b5227af7f55a/00497822780875) 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1250 sofia/internal/202@connec.cpbx.co.za:5060 EXPORTING[export_vars] [domain_name]=[connec.cpbx.co.za] t o event 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1250 sofia/internal/202@connec.cpbx.co.za:5060 EXPORTING[export_vars] [origination_callee_id_name]=[00497 822780875] to event 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1250 sofia/internal/202@connec.cpbx.co.za:5060 EXPORTING[export_vars] [call_direction]=[outbound] to even t 2019-06-10 16:33:44.806263 [DEBUG] switch_channel.c:1250 sofia/internal/202@connec.cpbx.co.za:5060 EXPORTING[export_vars] [call_direction]=[outbound] to even t 2019-06-10 16:33:44.806263 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2019-06-10 16:33:44.806263 [NOTICE] switch_channel.c:1104 New Channel sofia/external/00497822780875 [92645798-c180-439c-ad16-5a1f5de4a620] 2019-06-10 16:33:44.806263 [DEBUG] mod_sofia.c:4819 (sofia/external/00497822780875) State Change CS_NEW -> CS_INIT 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_INIT (Cur 4 Tot 37376) 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:627 (sofia/external/00497822780875) State INIT 2019-06-10 16:33:44.806263 [DEBUG] mod_sofia.c:90 sofia/external/00497822780875 SOFIA INIT 2019-06-10 16:33:44.806263 [DEBUG] sofia_glue.c:1295 sofia/external/00497822780875 sending invite version: 1.6.20 -37-987c9b9 64bit Local SDP: v=0 o=FreeSWITCH 1560159566 1560159567 IN IP4 192.168.255.2 s=FreeSWITCH c=IN IP4 192.168.255.2 t=0 0 m=audio 17658 RTP/AVP 18 0 8 101 13 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-16 a=rtpmap:13 CN/8000 a=ptime:20 a=sendrecv 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:40 sofia/external/00497822780875 Standard INIT 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:48 (sofia/external/00497822780875) State Change CS_INIT -> CS_ROUTING 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:627 (sofia/external/00497822780875) State INIT going to sleep 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_ROUTING (Cur 4 Tot 37376) 2019-06-10 16:33:44.806263 [DEBUG] sofia.c:7084 Channel sofia/external/00497822780875 entering state [calling][0] 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:643 (sofia/external/00497822780875) State ROUTING 2019-06-10 16:33:44.806263 [DEBUG] mod_sofia.c:143 sofia/external/00497822780875 SOFIA ROUTING 2019-06-10 16:33:44.806263 [DEBUG] switch_ivr_originate.c:67 (sofia/external/00497822780875) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:643 (sofia/external/00497822780875) State ROUTING going to sleep 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 37376) 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:662 (sofia/external/00497822780875) State CONSUME_MEDIA 2019-06-10 16:33:44.806263 [DEBUG] switch_core_state_machine.c:662 (sofia/external/00497822780875) State CONSUME_MEDIA going to sleep 2019-06-10 16:33:45.086474 [DEBUG] sofia.c:7084 Channel sofia/external/00497822780875 entering state [calling][0] 2019-06-10 16:33:45.186294 [DEBUG] sofia.c:6257 Remote Reason: 16 2019-06-10 16:33:45.186294 [DEBUG] sofia.c:7084 Channel sofia/external/00497822780875 entering state [terminated][480] 2019-06-10 16:33:45.186294 [NOTICE] sofia.c:8273 Hangup sofia/external/00497822780875 [CS_CONSUME_MEDIA] [NORMAL_CLEARING] 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_HANGUP (Cur 4 Tot 37376) 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:850 (sofia/external/00497822780875) Callstate Change DOWN -> HANGUP 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:852 (sofia/external/00497822780875) State HANGUP 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:438 Channel sofia/external/00497822780875 hanging up, cause: NORMAL_CLEARING 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:60 sofia/external/00497822780875 Standard HANGUP, cause: NORMAL_CLEARING 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:852 (sofia/external/00497822780875) State HANGUP going to sleep 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:619 (sofia/external/00497822780875) State Change CS_HANGUP -> CS_REPORTING 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:584 (sofia/external/00497822780875) Running State Change CS_REPORTING (Cur 4 Tot 37376) 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:938 (sofia/external/00497822780875) State REPORTING 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:174 sofia/external/00497822780875 Standard REPORTING, cause: NORMAL_CLEARING 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:938 (sofia/external/00497822780875) State REPORTING going to sleep 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:610 (sofia/external/00497822780875) State Change CS_REPORTING -> CS_DESTROY 2019-06-10 16:33:45.186294 [DEBUG] switch_core_session.c:1665 Session 37376 (sofia/external/00497822780875) Locked, Waiting on external entities 2019-06-10 16:33:45.186294 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 16 [NORMAL_CLEARING] 2019-06-10 16:33:45.186294 [NOTICE] switch_core_session.c:1683 Session 37376 (sofia/external/00497822780875) Ended 2019-06-10 16:33:45.186294 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/00497822780875 [CS_DESTROY] 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:741 (sofia/external/00497822780875) Running State Change CS_DESTROY (Cur 3 Tot 37376) 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:751 (sofia/external/00497822780875) State DESTROY 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:343 sofia/external/00497822780875 SOFIA DESTROY 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:181 sofia/external/00497822780875 Standard DESTROY 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:751 (sofia/external/00497822780875) State DESTROY going to sleep 2019-06-10 16:33:45.186294 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NORMAL_CLEARING 2019-06-10 16:33:45.186294 [NOTICE] switch_core_state_machine.c:385 sofia/internal/202@connec.cpbx.co.za:5060 has executed the last dialplan instruction, han ging up. 2019-06-10 16:33:45.186294 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/202@connec.cpbx.co.za:5060 [CS_EXECUTE] [NORMAL_CLEARING] 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/202@connec.cpbx.co.za:5060) State EXECUTE going to sleep 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_HANGUP (Cur 3 Tot 3737 6) 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/202@connec.cpbx.co.za:5060) Callstate Change RINGING -> HANGUP 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/202@connec.cpbx.co.za:5060) State HANGUP 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:432 sofia/internal/202@connec.cpbx.co.za:5060 Overriding SIP cause 480 with 480 from the other leg 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:438 Channel sofia/internal/202@connec.cpbx.co.za:5060 hanging up, cause: NORMAL_CLEARING 2019-06-10 16:33:45.186294 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:60 sofia/internal/202@connec.cpbx.co.za:5060 Standard HANGUP, cause: NORMAL_CLEARING 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/202@connec.cpbx.co.za:5060) State HANGUP going to sleep 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_HANGUP -> CS_REPORTING 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_REPORTING (Cur 3 Tot 3 7376) 2019-06-10 16:33:45.186294 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/202@connec.cpbx.co.za:5060) State REPORTING 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:174 sofia/internal/202@connec.cpbx.co.za:5060 Standard REPORTING, cause: NORMAL_CLEARING 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/202@connec.cpbx.co.za:5060) State REPORTING going to sleep 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/202@connec.cpbx.co.za:5060) State Change CS_REPORTING -> CS_DESTROY 2019-06-10 16:33:45.306276 [DEBUG] switch_core_session.c:1665 Session 37375 (sofia/internal/202@connec.cpbx.co.za:5060) Locked, Waiting on external entities 2019-06-10 16:33:45.306276 [NOTICE] switch_core_session.c:1683 Session 37375 (sofia/internal/202@connec.cpbx.co.za:5060) Ended 2019-06-10 16:33:45.306276 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/202@connec.cpbx.co.za:5060 [CS_DESTROY] 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/202@connec.cpbx.co.za:5060) Running State Change CS_DESTROY (Cur 2 Tot 373 76) 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/202@connec.cpbx.co.za:5060) State DESTROY 2019-06-10 16:33:45.306276 [DEBUG] mod_sofia.c:343 sofia/internal/202@connec.cpbx.co.za:5060 SOFIA DESTROY 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:181 sofia/internal/202@connec.cpbx.co.za:5060 Standard DESTROY 2019-06-10 16:33:45.306276 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/202@connec.cpbx.co.za:5060) State DESTROY going to sleep