2019-11-12 15:44:51.159712 [NOTICE] switch_channel.c:1114 New Channel sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 [99a68ea8-1458-45db-b07c-f6e29e1baff9]
2019-11-12 15:44:51.159712 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) Running State Change CS_NEW (Cur 39 Tot 43413)
2019-11-12 15:44:51.159712 [DEBUG] sofia.c:10164 sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 receiving invite from 41.79.81.110:1564 version: 1.8.7 -8-6047ebddfc 64bit
2019-11-12 15:44:51.159712 [DEBUG] sofia.c:10260 verifying acl "domains" for ip/port 41.79.81.110:0.
2019-11-12 15:44:51.159712 [WARNING] sofia_reg.c:1798 SIP auth challenge (INVITE) on sofia profile 'internal' for [*87201@vpbx-stockbrockers-jhb.bitcovoice.com] from ip 41.79.81.110
2019-11-12 15:44:51.159712 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) State NEW
2019-11-12 15:44:51.159712 [DEBUG] sofia.c:2413 detaching session 99a68ea8-1458-45db-b07c-f6e29e1baff9
2019-11-12 15:44:51.179728 [DEBUG] sofia.c:2522 Re-attaching to session 99a68ea8-1458-45db-b07c-f6e29e1baff9
2019-11-12 15:44:51.179728 [DEBUG] sofia.c:10164 sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 receiving invite from 41.79.81.110:1564 version: 1.8.7 -8-6047ebddfc 64bit
2019-11-12 15:44:51.179728 [DEBUG] sofia.c:10260 verifying acl "domains" for ip/port 41.79.81.110:0.
2019-11-12 15:44:51.179728 [WARNING] sofia_reg.c:1798 SIP auth challenge (REGISTER) on sofia profile 'internal' for [2033@vpbx-linvar-sa.bitcovoice.com] from ip 196.50.253.234
2019-11-12 15:44:51.199727 [DEBUG] sofia.c:11370 Setting NAT mode based on via received
2019-11-12 15:44:51.199727 [DEBUG] sofia.c:7323 Channel sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 entering state [received][100]
2019-11-12 15:44:51.199727 [DEBUG] sofia.c:7333 Remote SDP:
v=0
o=- 20079 20079 IN IP4 192.168.96.93
s=SDP data
c=IN IP4 192.168.96.93
t=0 0
m=audio 12356 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
a=ptime:20

2019-11-12 15:44:51.199727 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2019-11-12 15:44:51.199727 [DEBUG] switch_core_media.c:5566 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2019-11-12 15:44:51.199727 [DEBUG] switch_core_media.c:5511 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2019-11-12 15:44:51.199727 [DEBUG] switch_core_media.c:5427 Set telephone-event payload to 101@8000
2019-11-12 15:44:51.199727 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 G729/8000 20 ms 160 samples 8000 bits 1 channels
2019-11-12 15:44:51.199727 [DEBUG] switch_core_codec.c:111 sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Original read codec set to G729:18
2019-11-12 15:44:51.199727 [DEBUG] switch_core_media.c:5770 Set telephone-event payload to 101@8000
2019-11-12 15:44:51.199727 [DEBUG] switch_core_media.c:5828 sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2019-11-12 15:44:51.199727 [DEBUG] sofia.c:7748 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) State Change CS_NEW -> CS_INIT
2019-11-12 15:44:51.199727 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) Running State Change CS_INIT (Cur 39 Tot 43413)
2019-11-12 15:44:51.199727 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) State INIT
2019-11-12 15:44:51.199727 [DEBUG] mod_sofia.c:93 sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 SOFIA INIT
2019-11-12 15:44:51.199727 [DEBUG] switch_core_state_machine.c:40 sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Standard INIT
2019-11-12 15:44:51.199727 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) State Change CS_INIT -> CS_ROUTING
2019-11-12 15:44:51.199727 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) State INIT going to sleep
2019-11-12 15:44:51.199727 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) Running State Change CS_ROUTING (Cur 39 Tot 43413)
2019-11-12 15:44:51.199727 [DEBUG] switch_channel.c:2293 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) Callstate Change DOWN -> RINGING
2019-11-12 15:44:51.199727 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060) State ROUTING
2019-11-12 15:44:51.199727 [DEBUG] mod_sofia.c:154 sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 SOFIA ROUTING
2019-11-12 15:44:51.199727 [DEBUG] switch_core_state_machine.c:236 sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Standard ROUTING
2019-11-12 15:44:51.199727 [INFO] mod_dialplan_xml.c:637 Processing 4000 <4000>->*87201 in context vpbx-stockbrockers-jhb.bitcovoice.com
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->user_exists] continue=true
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 set(user_exists=false)
2019-11-12 15:44:51.199727 [DEBUG] mod_dptools.c:1615 SET sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 [user_exists]=[false]
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->is_loopback] continue=true
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->bitco.10d] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (PASS) [bitco.10d] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (PASS) [bitco.10d] ${toll_allow}(nat) =~ /nat/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [bitco.10d] destination_number(*87201) =~ /^(\d{10})$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->bitco.International] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (PASS) [bitco.International] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [bitco.International] ${toll_allow}(nat) =~ /int/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->Office Hrs] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [Office Hrs] destination_number(*87201) =~ /^60$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->ring group] continue=
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [ring group] destination_number(*87201) =~ /^50$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->After-Hrs] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [After-Hrs] destination_number(*87201) =~ /^61$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->ring group] continue=
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [ring group] destination_number(*87201) =~ /^51$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [intercept-ext-polycom] destination_number(*87201) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->TC 01] continue=true
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [TC 01] destination_number(*87201) =~ /^70$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->extension-to-voicemail] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [extension-to-voicemail] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->follow-me-destinations] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [follow-me-destinations] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->call forward all] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [call forward all] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->call forward not registered] continue=false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [call forward not registered] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->talking clock date and time] continue=true
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [talking clock date and time] destination_number(*87201) =~ /^\*9172$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->talking clock time] continue=true
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [talking clock time] destination_number(*87201) =~ /^\*9170$/ break=on-false
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 parsing [vpbx-stockbrockers-jhb.bitcovoice.com->talking clock date] continue=true
Dialplan: sofia/internal/4000@vpbx-stockbrockers-jhb.bitcovoice.com:5060 Regex (FAIL) [talking clock date] destination_number(*87201) =~ /^\*9171$/ break=on-false