[Freeswitch-users] Routing calls to registered user.

20 Sep 2017

      Hi Guys

Knocking my head against this. I am trying to route calls to registered endpoints. But it is not working.

The log of the whole call is as follows

2017-09-20 23:31:49.230782 [NOTICE] switch_channel.c:1104 New Channel sofia/external/07966677711@185.8.92.3 [a923b79f-e080-416c-934c-af13b570f813]
2017-09-20 23:31:49.230782 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_NEW (Cur 1 Tot 16430)
2017-09-20 23:31:49.230782 [DEBUG] sofia.c:9873 sofia/external/07966677711@185.8.92.3 receiving invite from 185.8.92.3:5062 version: 1.6.19 git febfb38 2017-09-14 23:14:02Z 64bit
2017-09-20 23:31:49.270606 [DEBUG] sofia.c:7084 Channel sofia/external/07966677711@185.8.92.3 entering state [received][100]
2017-09-20 23:31:49.270606 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=FreeSWITCH 1505928870 1505928871 IN IP4 185.8.92.3
s=FreeSWITCH
c=IN IP4 185.8.92.3
t=0 0
m=audio 17854 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20

2017-09-20 23:31:49.270606 [DEBUG] sofia.c:7486 (sofia/external/07966677711@185.8.92.3) State Change CS_NEW -> CS_INIT
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:603 (sofia/external/07966677711@185.8.92.3) State NEW
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_INIT (Cur 1 Tot 16430)
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:627 (sofia/external/07966677711@185.8.92.3) State INIT
2017-09-20 23:31:49.270606 [DEBUG] mod_sofia.c:90 sofia/external/07966677711@185.8.92.3 SOFIA INIT
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:40 sofia/external/07966677711@185.8.92.3 Standard INIT
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:48 (sofia/external/07966677711@185.8.92.3) State Change CS_INIT -> CS_ROUTING
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:627 (sofia/external/07966677711@185.8.92.3) State INIT going to sleep
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_ROUTING (Cur 1 Tot 16430)
2017-09-20 23:31:49.270606 [DEBUG] switch_channel.c:2249 (sofia/external/07966677711@185.8.92.3) Callstate Change DOWN -> RINGING
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:643 (sofia/external/07966677711@185.8.92.3) State ROUTING
2017-09-20 23:31:49.270606 [DEBUG] mod_sofia.c:143 sofia/external/07966677711@185.8.92.3 SOFIA ROUTING
2017-09-20 23:31:49.270606 [ERR] mod_xml_radius.c:933 Result of true match: 185.35.229.6 == ^185\.35\.229\.30 
2017-09-20 23:31:49.270606 [ERR] mod_xml_radius.c:930 Didn't match: inbound == ^outbound 
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:236 sofia/external/07966677711@185.8.92.3 Standard ROUTING
2017-09-20 23:31:49.270606 [INFO] mod_dialplan_xml.c:637 Processing 07966677711 <07966677711>->443307881011 in context public
Dialplan: sofia/external/07966677711@185.8.92.3 parsing [public->unloop] continue=false
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/external/07966677711@185.8.92.3 parsing [public->outside_call] continue=true
Dialplan: sofia/external/07966677711@185.8.92.3 Absolute Condition [outside_call]
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(outside_call=true) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/external/07966677711@185.8.92.3 parsing [public->call_debug] continue=true
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/external/07966677711@185.8.92.3 parsing [public->rejections] continue=false
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (FAIL) [rejections] ${radius_auth_result}() =~ /2/ break=on-false
Dialplan: sofia/external/07966677711@185.8.92.3 parsing [public->timedouts] continue=false
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (FAIL) [timedouts] ${radius_auth_result}() =~ /1/ break=on-false
Dialplan: sofia/external/07966677711@185.8.92.3 parsing [public->JeraSoft VCS Routing] continue=false
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (PASS) [JeraSoft VCS Routing] destination_number(443307881011) =~ /^(.+)$/ break=on-false
Dialplan: sofia/external/07966677711@185.8.92.3 Action export(nolocal:h323-call-origin=originate) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(sip_h_X-accountcode=${accountcode}) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(call_direction=outbound) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(hangup_after_bridge=true) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(continue_on_fail=true) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(inherit_codec=true) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(call_timeout=20) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(fail_on_single_reject=USER_BUSY) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(origination_caller_id_name=${sip_req_user}) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(origination_caller_id_number=${sip_from_user}) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(SRCGWIP=src-gw-ip=${network_addr}) INLINE
EXECUTE sofia/external/07966677711@185.8.92.3 set(SRCGWIP=src-gw-ip=185.8.92.3)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [SRCGWIP]=[src-gw-ip=185.8.92.3]
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(CALLID=h323-conf-id=${uuid}) INLINE
EXECUTE sofia/external/07966677711@185.8.92.3 set(CALLID=h323-conf-id=a923b79f-e080-416c-934c-af13b570f813)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [CALLID]=[h323-conf-id=a923b79f-e080-416c-934c-af13b570f813]
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(CALLINGNUMBER=${caller_id_number}) INLINE
EXECUTE sofia/external/07966677711@185.8.92.3 set(CALLINGNUMBER=07966677711)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [CALLINGNUMBER]=[07966677711]
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(CALLEDNUMBER=${destination_number}) INLINE
EXECUTE sofia/external/07966677711@185.8.92.3 set(CALLEDNUMBER=443307881011)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [CALLEDNUMBER]=[443307881011]
Dialplan: sofia/external/07966677711@185.8.92.3 Action auth_function(in ${DIALED_NUMBER}, in ${USERNAME}, in ${PASSWD}, out AUTH_RESULT) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action export(credit_time=${credit_time}) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action export(cisco_service_info=${cisco_service_info) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action export(sip_redirect_context=redirect) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action transfer(443307881011 XML ipauth) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action hangup(${bridge_hangup_cause}) 
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:286 (sofia/external/07966677711@185.8.92.3) State Change CS_ROUTING -> CS_EXECUTE
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:643 (sofia/external/07966677711@185.8.92.3) State ROUTING going to sleep
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_EXECUTE (Cur 1 Tot 16430)
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:650 (sofia/external/07966677711@185.8.92.3) State EXECUTE
2017-09-20 23:31:49.270606 [DEBUG] mod_sofia.c:198 sofia/external/07966677711@185.8.92.3 SOFIA EXECUTE
2017-09-20 23:31:49.270606 [DEBUG] switch_core_state_machine.c:328 sofia/external/07966677711@185.8.92.3 Standard EXECUTE
EXECUTE sofia/external/07966677711@185.8.92.3 set(outside_call=true)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [outside_call]=[true]
EXECUTE sofia/external/07966677711@185.8.92.3 export(RFC2822_DATE=Wed, 20 Sep 2017 23:31:49 +0100)
2017-09-20 23:31:49.270606 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Wed, 20 Sep 2017 23:31:49 +0100]
EXECUTE sofia/external/07966677711@185.8.92.3 export(nolocal:h323-call-origin=originate)
2017-09-20 23:31:49.270606 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [h323-call-origin]=[originate]
EXECUTE sofia/external/07966677711@185.8.92.3 set(sip_h_X-accountcode=)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [sip_h_X-accountcode]=[UNDEF]
EXECUTE sofia/external/07966677711@185.8.92.3 set(call_direction=outbound)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [call_direction]=[outbound]
EXECUTE sofia/external/07966677711@185.8.92.3 set(hangup_after_bridge=true)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [hangup_after_bridge]=[true]
EXECUTE sofia/external/07966677711@185.8.92.3 set(continue_on_fail=true)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [continue_on_fail]=[true]
EXECUTE sofia/external/07966677711@185.8.92.3 set(inherit_codec=true)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [inherit_codec]=[true]
EXECUTE sofia/external/07966677711@185.8.92.3 set(call_timeout=20)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [call_timeout]=[20]
EXECUTE sofia/external/07966677711@185.8.92.3 set(fail_on_single_reject=USER_BUSY)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [fail_on_single_reject]=[USER_BUSY]
EXECUTE sofia/external/07966677711@185.8.92.3 set(origination_caller_id_name=443307881011)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [origination_caller_id_name]=[443307881011]
EXECUTE sofia/external/07966677711@185.8.92.3 set(origination_caller_id_number=07966677711)
2017-09-20 23:31:49.270606 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [origination_caller_id_number]=[07966677711]
EXECUTE sofia/external/07966677711@185.8.92.3 auth_function(in , in 07966677711, in , out AUTH_RESULT)
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:301 allocate initial structure.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:313 initialzed configuration.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set authserver := 185.35.229.30:1812:h4nn4h.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set dictionary := /usr/local/freeswitch/conf/dictionaries/dictionary.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set seqfile := /var/run/radius.seq.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set mapfile := /usr/local/etc/radiusclient/port-id-map.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set default_realm := .
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set radius_timeout := 3.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set radius_retries := 2.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set radius_deadtime := 0.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:318 set bindaddr := 185.35.229.6.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:371 ... radius: User-Name: 07966677711
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:380 ... radius: User-Password: 
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:391 ... radius: Called-station-Id is empty, ignoring...
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:413 Handle attribute: h323-conf-id
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:439 ... dictionary data: id:24, vendor id:9, attr type:0, attr name:h323-conf-id (589848)
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:444 ... radius: key:h323-conf-id, value:CALLID (h323-conf-id=a923b79f-e080-416c-934c-af13b570f813) as string
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:413 Handle attribute: Cisco-AVPair
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:439 ... dictionary data: id:1, vendor id:9, attr type:0, attr name:Cisco-AVPair (589825)
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:444 ... radius: key:Cisco-AVPair, value:SRCGWIP (src-gw-ip=185.8.92.3) as string
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:413 Handle attribute: Cisco-AVPair
2017-09-20 23:31:49.270606 [ERR] mod_rad_auth.c:178 Undefined channel variable: SRCGWNAME.
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:439 ... dictionary data: id:1, vendor id:9, attr type:0, attr name:Cisco-AVPair (589825)
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:444 ... radius: key:Cisco-AVPair, value:SRCGWNAME () as string
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:413 Handle attribute: Cisco-AVPair
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:439 ... dictionary data: id:1, vendor id:9, attr type:0, attr name:Cisco-AVPair (589825)
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:444 ... radius: key:Cisco-AVPair, value:request-type=number (request-type=number) as string
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:413 Handle attribute: Calling-Station-Id
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:439 ... dictionary data: id:31, vendor id:0, attr type:0, attr name:Calling-Station-Id (31)
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:444 ... radius: key:Calling-Station-Id, value:CALLINGNUMBER (07966677711) as string
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:413 Handle attribute: Called-Station-Id
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:439 ... dictionary data: id:30, vendor id:0, attr type:0, attr name:Called-Station-Id (30)
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:444 ... radius: key:Called-Station-Id, value:CALLEDNUMBER (443307881011) as string
2017-09-20 23:31:49.270606 [DEBUG] mod_rad_auth.c:491 sending radius packet ...
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:497 RADIUS Authentication OK
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:519 Handle attribute: CREDIT_TIME
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:522 	attribute (CREDIT_TIME) found in radius packet
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:523 	set variable credit_time := 7199
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:519 Handle attribute: CISCO_SERVICE_INFO
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:522 	attribute (CISCO_SERVICE_INFO) found in radius packet
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:523 	set variable cisco_service_info := 200
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:519 Handle attribute: RADIUS_RETURN_CODE
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:522 	attribute (RADIUS_RETURN_CODE) found in radius packet
2017-09-20 23:31:49.290658 [DEBUG] mod_rad_auth.c:523 	set variable return_code := 16
EXECUTE sofia/external/07966677711@185.8.92.3 export(credit_time=7199)
2017-09-20 23:31:49.290658 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [credit_time]=[7199]
EXECUTE sofia/external/07966677711@185.8.92.3 export(cisco_service_info=200)
2017-09-20 23:31:49.290658 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [cisco_service_info]=[200]
EXECUTE sofia/external/07966677711@185.8.92.3 export(sip_redirect_context=redirect)
2017-09-20 23:31:49.290658 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [sip_redirect_context]=[redirect]
EXECUTE sofia/external/07966677711@185.8.92.3 transfer(443307881011 XML ipauth)
2017-09-20 23:31:49.290658 [DEBUG] switch_ivr.c:2165 (sofia/external/07966677711@185.8.92.3) State Change CS_EXECUTE -> CS_ROUTING
2017-09-20 23:31:49.290658 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/07966677711@185.8.92.3 to XML[443307881011@ipauth]
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:650 (sofia/external/07966677711@185.8.92.3) State EXECUTE going to sleep
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_ROUTING (Cur 1 Tot 16430)
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:643 (sofia/external/07966677711@185.8.92.3) State ROUTING
2017-09-20 23:31:49.290658 [DEBUG] mod_sofia.c:143 sofia/external/07966677711@185.8.92.3 SOFIA ROUTING
2017-09-20 23:31:49.290658 [ERR] mod_xml_radius.c:933 Result of true match: 185.35.229.6 == ^185\.35\.229\.30 
2017-09-20 23:31:49.290658 [ERR] mod_xml_radius.c:930 Didn't match: inbound == ^outbound 
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:236 sofia/external/07966677711@185.8.92.3 Standard ROUTING
2017-09-20 23:31:49.290658 [INFO] mod_dialplan_xml.c:637 Processing 07966677711 <07966677711>->443307881011 in context ipauth
Dialplan: sofia/external/07966677711@185.8.92.3 parsing [ipauth->Auth Calls] continue=false
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (PASS) [Auth Calls] ${cisco_service_info}(200) =~ /^200$/ break=never
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(execute_on_answer=sched_hangup +${credit_time} alloted_timeout) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action bridge({sip_invite_from_uri=sip:${sip_from_user}@${sip_network_ip}}sofia/external/${destination_number}@185.35.229.30:5060) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action hangup(${bridge_hangup_cause}) 
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (FAIL) [Auth Calls] ${cisco_service_info}(200) =~ /^101$/ break=on-true
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (FAIL) [Auth Calls] ${cisco_service_info}(200) =~ /^221$/ break=on-true
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (FAIL) [Auth Calls] ${cisco_service_info}(200) =~ /^201$/ break=on-true
Dialplan: sofia/external/07966677711@185.8.92.3 Absolute Condition [Auth Calls]
Dialplan: sofia/external/07966677711@185.8.92.3 Action log(INFO  Were in the IPauth Context!!) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action log(INFO  credit_time=${credit_time}) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action log(INFO  cisco_service_info=${cisco_service_info}) 
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:286 (sofia/external/07966677711@185.8.92.3) State Change CS_ROUTING -> CS_EXECUTE
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:643 (sofia/external/07966677711@185.8.92.3) State ROUTING going to sleep
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_EXECUTE (Cur 1 Tot 16430)
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:650 (sofia/external/07966677711@185.8.92.3) State EXECUTE
2017-09-20 23:31:49.290658 [DEBUG] mod_sofia.c:198 sofia/external/07966677711@185.8.92.3 SOFIA EXECUTE
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:328 sofia/external/07966677711@185.8.92.3 Standard EXECUTE
EXECUTE sofia/external/07966677711@185.8.92.3 set(execute_on_answer=sched_hangup +7199 alloted_timeout)
2017-09-20 23:31:49.290658 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [execute_on_answer]=[sched_hangup +7199 alloted_timeout]
EXECUTE sofia/external/07966677711@185.8.92.3 bridge({sip_invite_from_uri=sip:07966677711@185.8.92.3}sofia/external/443307881011@185.35.229.30:5060)
2017-09-20 23:31:49.290658 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 20 Sep 2017 23:31:49 +0100] to event
2017-09-20 23:31:49.290658 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [h323-call-origin]=[originate] to event
2017-09-20 23:31:49.290658 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [credit_time]=[7199] to event
2017-09-20 23:31:49.290658 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [cisco_service_info]=[200] to event
2017-09-20 23:31:49.290658 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [sip_redirect_context]=[redirect] to event
2017-09-20 23:31:49.290658 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-09-20 23:31:49.290658 [NOTICE] switch_channel.c:1104 New Channel sofia/external/443307881011@185.35.229.30:5060 [848843db-cad9-48a8-a4bd-2ac6b6b77dff]
2017-09-20 23:31:49.290658 [DEBUG] mod_sofia.c:4819 (sofia/external/443307881011@185.35.229.30:5060) State Change CS_NEW -> CS_INIT
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:584 (sofia/external/443307881011@185.35.229.30:5060) Running State Change CS_INIT (Cur 2 Tot 16431)
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:627 (sofia/external/443307881011@185.35.229.30:5060) State INIT
2017-09-20 23:31:49.290658 [DEBUG] mod_sofia.c:90 sofia/external/443307881011@185.35.229.30:5060 SOFIA INIT
2017-09-20 23:31:49.290658 [DEBUG] sofia_glue.c:1295 sofia/external/443307881011@185.35.229.30:5060 sending invite version: 1.6.19 git febfb38 2017-09-14 23:14:02Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1505929783 1505929784 IN IP4 185.35.229.6
s=FreeSWITCH
c=IN IP4 185.35.229.6
t=0 0
m=audio 16926 RTP/AVP 8 101 13
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

2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:40 sofia/external/443307881011@185.35.229.30:5060 Standard INIT
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:48 (sofia/external/443307881011@185.35.229.30:5060) State Change CS_INIT -> CS_ROUTING
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:627 (sofia/external/443307881011@185.35.229.30:5060) State INIT going to sleep
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:584 (sofia/external/443307881011@185.35.229.30:5060) Running State Change CS_ROUTING (Cur 2 Tot 16431)
2017-09-20 23:31:49.290658 [DEBUG] sofia.c:7084 Channel sofia/external/443307881011@185.35.229.30:5060 entering state [calling][0]
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:643 (sofia/external/443307881011@185.35.229.30:5060) State ROUTING
2017-09-20 23:31:49.290658 [DEBUG] mod_sofia.c:143 sofia/external/443307881011@185.35.229.30:5060 SOFIA ROUTING
2017-09-20 23:31:49.290658 [DEBUG] switch_ivr_originate.c:67 (sofia/external/443307881011@185.35.229.30:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-09-20 23:31:49.290658 [ERR] mod_xml_radius.c:930 Didn't match: 185.35.229.30:5060 == ^185\.35\.229\.30 
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:643 (sofia/external/443307881011@185.35.229.30:5060) State ROUTING going to sleep
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:584 (sofia/external/443307881011@185.35.229.30:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 16431)
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:662 (sofia/external/443307881011@185.35.229.30:5060) State CONSUME_MEDIA
2017-09-20 23:31:49.290658 [DEBUG] switch_core_state_machine.c:662 (sofia/external/443307881011@185.35.229.30:5060) State CONSUME_MEDIA going to sleep
2017-09-20 23:31:49.350696 [DEBUG] sofia.c:6540 Redirect: Transfering to joehouse XML redirect
2017-09-20 23:31:49.350696 [DEBUG] switch_ivr.c:2165 (sofia/external/07966677711@185.8.92.3) State Change CS_EXECUTE -> CS_ROUTING
2017-09-20 23:31:49.350696 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/07966677711@185.8.92.3 to XML[joehouse@redirect]
2017-09-20 23:31:49.350696 [NOTICE] sofia.c:6549 Hangup sofia/external/443307881011@185.35.229.30:5060 [CS_CONSUME_MEDIA] [REDIRECTION_TO_NEW_DESTINATION]
2017-09-20 23:31:49.350696 [DEBUG] sofia.c:1453 Channel is already hungup.
2017-09-20 23:31:49.350696 [DEBUG] sofia.c:1453 Channel is already hungup.
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:584 (sofia/external/443307881011@185.35.229.30:5060) Running State Change CS_HANGUP (Cur 2 Tot 16431)
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:850 (sofia/external/443307881011@185.35.229.30:5060) Callstate Change DOWN -> HANGUP
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:852 (sofia/external/443307881011@185.35.229.30:5060) State HANGUP
2017-09-20 23:31:49.350696 [DEBUG] mod_sofia.c:438 Channel sofia/external/443307881011@185.35.229.30:5060 hanging up, cause: REDIRECTION_TO_NEW_DESTINATION
2017-09-20 23:31:49.350696 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/external/443307881011@185.35.229.30:5060
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:60 sofia/external/443307881011@185.35.229.30:5060 Standard HANGUP, cause: REDIRECTION_TO_NEW_DESTINATION
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:852 (sofia/external/443307881011@185.35.229.30:5060) State HANGUP going to sleep
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:619 (sofia/external/443307881011@185.35.229.30:5060) State Change CS_HANGUP -> CS_REPORTING
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:584 (sofia/external/443307881011@185.35.229.30:5060) Running State Change CS_REPORTING (Cur 2 Tot 16431)
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:938 (sofia/external/443307881011@185.35.229.30:5060) State REPORTING
2017-09-20 23:31:49.350696 [ERR] mod_xml_radius.c:930 Didn't match: 185.35.229.30:5060 == ^185\.35\.229\.30 
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:174 sofia/external/443307881011@185.35.229.30:5060 Standard REPORTING, cause: REDIRECTION_TO_NEW_DESTINATION
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:938 (sofia/external/443307881011@185.35.229.30:5060) State REPORTING going to sleep
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:610 (sofia/external/443307881011@185.35.229.30:5060) State Change CS_REPORTING -> CS_DESTROY
2017-09-20 23:31:49.350696 [DEBUG] switch_core_session.c:1665 Session 16431 (sofia/external/443307881011@185.35.229.30:5060) Locked, Waiting on external entities
2017-09-20 23:31:49.350696 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]
2017-09-20 23:31:49.350696 [NOTICE] switch_core_session.c:1683 Session 16431 (sofia/external/443307881011@185.35.229.30:5060) Ended
2017-09-20 23:31:49.350696 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/443307881011@185.35.229.30:5060 [CS_DESTROY]
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:741 (sofia/external/443307881011@185.35.229.30:5060) Running State Change CS_DESTROY (Cur 1 Tot 16431)
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:751 (sofia/external/443307881011@185.35.229.30:5060) State DESTROY
2017-09-20 23:31:49.350696 [DEBUG] mod_sofia.c:343 sofia/external/443307881011@185.35.229.30:5060 SOFIA DESTROY
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:181 sofia/external/443307881011@185.35.229.30:5060 Standard DESTROY
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:751 (sofia/external/443307881011@185.35.229.30:5060) State DESTROY going to sleep
2017-09-20 23:31:49.350696 [INFO] mod_dptools.c:3436 Originate Failed.  Cause: ORIGINATOR_CANCEL
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:650 (sofia/external/07966677711@185.8.92.3) State EXECUTE going to sleep
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_ROUTING (Cur 1 Tot 16431)
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:643 (sofia/external/07966677711@185.8.92.3) State ROUTING
2017-09-20 23:31:49.350696 [DEBUG] mod_sofia.c:143 sofia/external/07966677711@185.8.92.3 SOFIA ROUTING
2017-09-20 23:31:49.350696 [ERR] mod_xml_radius.c:933 Result of true match: 185.35.229.6 == ^185\.35\.229\.30 
2017-09-20 23:31:49.350696 [ERR] mod_xml_radius.c:930 Didn't match: inbound == ^outbound 
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:236 sofia/external/07966677711@185.8.92.3 Standard ROUTING
2017-09-20 23:31:49.350696 [INFO] mod_dialplan_xml.c:637 Processing 07966677711 <07966677711>->joehouse in context redirect
Dialplan: sofia/external/07966677711@185.8.92.3 parsing [redirect->Redirect Calls] continue=false
Dialplan: sofia/external/07966677711@185.8.92.3 Regex (PASS) [Redirect Calls] ${sip_redirect_contact_0}(<sip:joehouse@185.35.229.6>;src_number=07966677711;q=1.00) =~ /^<sip:(.+)\@185.35.229.6(.+)$/ break=on-true
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(process_cdr=true) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action log(ALERT Local User) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action set(accountcode=jerasoftoutbound) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action log(ALERT joehouse) 
Dialplan: sofia/external/07966677711@185.8.92.3 Action bridge(user/joehouse@sip.biznetuk.com) 
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:286 (sofia/external/07966677711@185.8.92.3) State Change CS_ROUTING -> CS_EXECUTE
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:643 (sofia/external/07966677711@185.8.92.3) State ROUTING going to sleep
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_EXECUTE (Cur 1 Tot 16431)
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:650 (sofia/external/07966677711@185.8.92.3) State EXECUTE
2017-09-20 23:31:49.350696 [DEBUG] mod_sofia.c:198 sofia/external/07966677711@185.8.92.3 SOFIA EXECUTE
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:328 sofia/external/07966677711@185.8.92.3 Standard EXECUTE
EXECUTE sofia/external/07966677711@185.8.92.3 set(process_cdr=true)
2017-09-20 23:31:49.350696 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [process_cdr]=[true]
EXECUTE sofia/external/07966677711@185.8.92.3 log(ALERT Local User)
2017-09-20 23:31:49.350696 [ALERT] mod_dptools.c:1742 Local User
EXECUTE sofia/external/07966677711@185.8.92.3 set(accountcode=jerasoftoutbound)
2017-09-20 23:31:49.350696 [DEBUG] mod_dptools.c:1548 SET sofia/external/07966677711@185.8.92.3 [accountcode]=[jerasoftoutbound]
EXECUTE sofia/external/07966677711@185.8.92.3 log(ALERT joehouse)
2017-09-20 23:31:49.350696 [ALERT] mod_dptools.c:1742 joehouse
EXECUTE sofia/external/07966677711@185.8.92.3 bridge(user/joehouse@sip.biznetuk.com)
2017-09-20 23:31:49.350696 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [RFC2822_DATE]=[Wed, 20 Sep 2017 23:31:49 +0100] to event
2017-09-20 23:31:49.350696 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [h323-call-origin]=[originate] to event
2017-09-20 23:31:49.350696 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [credit_time]=[7199] to event
2017-09-20 23:31:49.350696 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [cisco_service_info]=[200] to event
2017-09-20 23:31:49.350696 [DEBUG] switch_channel.c:1250 sofia/external/07966677711@185.8.92.3 EXPORTING[export_vars] [sip_redirect_context]=[redirect] to event
2017-09-20 23:31:49.350696 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2017-09-20 23:31:49.350696 [WARNING] mod_dptools.c:4184 Can't find user [joehouse@sip.biznetuk.com]
2017-09-20 23:31:49.350696 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [SUBSCRIBER_ABSENT]
2017-09-20 23:31:49.350696 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 20 [SUBSCRIBER_ABSENT]
2017-09-20 23:31:49.350696 [INFO] mod_dptools.c:3436 Originate Failed.  Cause: SUBSCRIBER_ABSENT
2017-09-20 23:31:49.350696 [NOTICE] switch_core_state_machine.c:385 sofia/external/07966677711@185.8.92.3 has executed the last dialplan instruction, hanging up.
2017-09-20 23:31:49.350696 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/external/07966677711@185.8.92.3 [CS_EXECUTE] [NORMAL_CLEARING]
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:650 (sofia/external/07966677711@185.8.92.3) State EXECUTE going to sleep
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_HANGUP (Cur 1 Tot 16431)
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:850 (sofia/external/07966677711@185.8.92.3) Callstate Change RINGING -> HANGUP
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:852 (sofia/external/07966677711@185.8.92.3) State HANGUP
2017-09-20 23:31:49.350696 [DEBUG] mod_sofia.c:438 Channel sofia/external/07966677711@185.8.92.3 hanging up, cause: NORMAL_CLEARING
2017-09-20 23:31:49.350696 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:60 sofia/external/07966677711@185.8.92.3 Standard HANGUP, cause: NORMAL_CLEARING
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:852 (sofia/external/07966677711@185.8.92.3) State HANGUP going to sleep
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:619 (sofia/external/07966677711@185.8.92.3) State Change CS_HANGUP -> CS_REPORTING
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:584 (sofia/external/07966677711@185.8.92.3) Running State Change CS_REPORTING (Cur 1 Tot 16431)
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:938 (sofia/external/07966677711@185.8.92.3) State REPORTING
2017-09-20 23:31:49.350696 [ERR] mod_xml_radius.c:933 Result of true match: 185.35.229.6 == ^185\.35\.229\.30 
2017-09-20 23:31:49.350696 [ERR] mod_xml_radius.c:930 Didn't match: inbound == ^outbound 
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:174 sofia/external/07966677711@185.8.92.3 Standard REPORTING, cause: NORMAL_CLEARING
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:938 (sofia/external/07966677711@185.8.92.3) State REPORTING going to sleep
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:610 (sofia/external/07966677711@185.8.92.3) State Change CS_REPORTING -> CS_DESTROY
2017-09-20 23:31:49.350696 [DEBUG] switch_core_session.c:1665 Session 16430 (sofia/external/07966677711@185.8.92.3) Locked, Waiting on external entities
2017-09-20 23:31:49.350696 [NOTICE] switch_core_session.c:1683 Session 16430 (sofia/external/07966677711@185.8.92.3) Ended
2017-09-20 23:31:49.350696 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/07966677711@185.8.92.3 [CS_DESTROY]
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:741 (sofia/external/07966677711@185.8.92.3) Running State Change CS_DESTROY (Cur 0 Tot 16431)
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:751 (sofia/external/07966677711@185.8.92.3) State DESTROY
2017-09-20 23:31:49.350696 [DEBUG] mod_sofia.c:343 sofia/external/07966677711@185.8.92.3 SOFIA DESTROY
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:181 sofia/external/07966677711@185.8.92.3 Standard DESTROY
2017-09-20 23:31:49.350696 [DEBUG] switch_core_state_machine.c:751 (sofia/external/07966677711@185.8.92.3) State DESTROY going to sleep

its saying there is no endpoint registered yet the output of show registrations shows there is

freeswitch@BiznetukSBC1> show registrations 
reg_user,realm,token,url,expires,network_ip,network_port,network_proto,hostname,metadata,registration_uuid
joehouse,sip.biznetuk.com,1030250472@192_168_1_101,sofia/internal/sip:joehouse@185.35.230.2:5382,1505947110,185.35.230.2,5382,udp,BiznetukSBC1,,60484000-aa2d-4b21-9d58-11e7d4155f1e

1 total.

Any ideas?

[Freeswitch-users] Routing calls to registered user.

Joseph Waite