Why a Ring Group loops an incoming call to outbound? Channel gets created in external profile?

Status
Not open for further replies.
E

etsiot

Member
Jan 14, 2018
46
1
8
55
I decided to do a fresh install of 5.1 to a very basic FusionPBX setup (1 POTS, 2 extensions).
Inbound calls work only if the endpoint is a single extension.
If I create a ring group with the 2 extensions and route the inbound call to the ring group, I get a 486 error.

Internal calls work fine as well as outbound calls from either extension.
I have checked SIP profiles, gateway etc. yet don't see any connection to that.

Any ideas?
 
Looking at the log, when having a ring group (ext. 400), I get the impression that the switch is trying to route the incoming call back as an outbound call?

Could someone take a look at the below and confirm?

TIA,


2023-10-05 12:35:47.078858 97.73% [NOTICE] switch_channel.c:1142 New Channel sofia/external/210608aaa4@10.20.30.2 [52b548c4-5e2b-4f8b-90dc-578aaf545b10]
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_NEW (Cur 1 Tot 17)
2023-10-05 12:35:47.078858 97.73% [INFO] sofia.c:10459 sofia/external/210608aaa4@10.20.30.2 receiving invite from 10.20.30.17:5080 version: 1.10.10 -release 64bit call-id: 1111801934-5080-40@BA.CA.DA.BH
2023-10-05 12:35:47.078858 97.73% [DEBUG] sofia.c:10553 verifying acl "providers" for ip/port 10.20.30.17:0.
2023-10-05 12:35:47.078858 97.73% [DEBUG] sofia.c:10582 IP 10.20.30.17 Approved by acl "providers[]". Access Granted.
2023-10-05 12:35:47.078858 97.73% [DEBUG] sofia.c:7493 Channel sofia/external/210608aaa4@10.20.30.2 entering state [received][100]
2023-10-05 12:35:47.078858 97.73% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=210608aaa4 8002 8000 IN IP4 10.20.30.17
s=SIP Call
c=IN IP4 10.20.30.17
t=0 0
m=audio 18386 RTP/AVP 0 8 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16,32-36,54
a=ptime:20

2023-10-05 12:35:47.078858 97.73% [DEBUG] sofia.c:7906 (sofia/external/210608aaa4@10.20.30.2) State Change CS_NEW -> CS_INIT
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:600 (sofia/external/210608aaa4@10.20.30.2) State NEW
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_INIT (Cur 1 Tot 17)
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:624 (sofia/external/210608aaa4@10.20.30.2) State INIT
2023-10-05 12:35:47.078858 97.73% [DEBUG] mod_sofia.c:97 sofia/external/210608aaa4@10.20.30.2 SOFIA INIT
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:40 sofia/external/210608aaa4@10.20.30.2 Standard INIT
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:48 (sofia/external/210608aaa4@10.20.30.2) State Change CS_INIT -> CS_ROUTING
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:624 (sofia/external/210608aaa4@10.20.30.2) State INIT going to sleep
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_ROUTING (Cur 1 Tot 17)
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_channel.c:2399 (sofia/external/210608aaa4@10.20.30.2) Callstate Change DOWN -> RINGING
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:640 (sofia/external/210608aaa4@10.20.30.2) State ROUTING
2023-10-05 12:35:47.078858 97.73% [DEBUG] mod_sofia.c:158 sofia/external/210608aaa4@10.20.30.2 SOFIA ROUTING
2023-10-05 12:35:47.078858 97.73% [DEBUG] switch_core_state_machine.c:230 sofia/external/210608aaa4@10.20.30.2 Standard ROUTING
2023-10-05 12:35:47.078858 97.73% [INFO] mod_dialplan_xml.c:639 Processing 697bbbb999 <697bbbb999>->210608aaa4 in context public
2023-10-05 12:35:47.138870 97.73% [NOTICE] switch_cpp.cpp:1465 [xml_handler] multiple key:dialplan:public
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [public->caller-details] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 export(call_direction=inbound)
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(caller_destination=210608aaa4)
2023-10-05 12:35:47.138870 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [caller_destination]=[210608aaa4]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(caller_id_name=697bbbb999)
2023-10-05 12:35:47.138870 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [caller_id_name]=[697bbbb999]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [public->210608aaa4] continue=false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [210608aaa4] destination_number(210608aaa4) =~ /^(210608aaa4)$/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 export(call_direction=inbound)
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(domain_uuid=906debe1-a1af-40ef-b585-697a0cc0548c) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(domain_uuid=906debe1-a1af-40ef-b585-697a0cc0548c)
2023-10-05 12:35:47.138870 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [domain_uuid]=[906debe1-a1af-40ef-b585-697a0cc0548c]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(domain_name=10.20.30.2) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(domain_name=10.20.30.2)
2023-10-05 12:35:47.138870 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [domain_name]=[10.20.30.2]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action transfer(400 XML 10.20.30.2)
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:281 (sofia/external/210608aaa4@10.20.30.2) State Change CS_ROUTING -> CS_EXECUTE
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:640 (sofia/external/210608aaa4@10.20.30.2) State ROUTING going to sleep
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_EXECUTE (Cur 1 Tot 17)
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:647 (sofia/external/210608aaa4@10.20.30.2) State EXECUTE
2023-10-05 12:35:47.138870 97.73% [DEBUG] mod_sofia.c:213 sofia/external/210608aaa4@10.20.30.2 SOFIA EXECUTE
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:323 sofia/external/210608aaa4@10.20.30.2 Standard EXECUTE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(caller_id_number=697bbbb999)
2023-10-05 12:35:47.138870 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [caller_id_number]=[697bbbb999]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 transfer(400 XML 10.20.30.2)
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_ivr.c:2288 (sofia/external/210608aaa4@10.20.30.2) State Change CS_EXECUTE -> CS_ROUTING
2023-10-05 12:35:47.138870 97.73% [NOTICE] switch_ivr.c:2295 Transfer sofia/external/210608aaa4@10.20.30.2 to XML[400@10.20.30.2]
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:647 (sofia/external/210608aaa4@10.20.30.2) State EXECUTE going to sleep
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_ROUTING (Cur 1 Tot 17)
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:640 (sofia/external/210608aaa4@10.20.30.2) State ROUTING
2023-10-05 12:35:47.138870 97.73% [DEBUG] mod_sofia.c:149 Call appears to be already acknowledged
2023-10-05 12:35:47.138870 97.73% [DEBUG] mod_sofia.c:158 sofia/external/210608aaa4@10.20.30.2 SOFIA ROUTING
2023-10-05 12:35:47.138870 97.73% [DEBUG] switch_core_state_machine.c:230 sofia/external/210608aaa4@10.20.30.2 Standard ROUTING
2023-10-05 12:35:47.138870 97.73% [INFO] mod_dialplan_xml.c:639 Processing 697bbbb999 <697bbbb999>->400 in context 10.20.30.2
2023-10-05 12:35:47.158890 97.73% [NOTICE] switch_cpp.cpp:1465 [xml_handler] multiple key:dialplan:10.20.30.2
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->user_exists] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(user_exists=false)
2023-10-05 12:35:47.218876 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [user_exists]=[false]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(from_user_exists=false)
2023-10-05 12:35:47.238893 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [from_user_exists]=[false]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->caller-details] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [caller-details] ${caller_destination}(210608aaa4) =~ /^$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->global-variables] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->domain-variables] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action export(origination_callee_id_name=${caller_destination})
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(operator=1000)
2023-10-05 12:35:47.238893 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [operator]=[1000]
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->call_direction-outbound] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [call_direction-outbound] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [call_direction-outbound] ${call_direction}(inbound) =~ /^$/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->clear_sip_auto_answer] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->is_loopback] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->call-direction] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [call-direction] ${call_direction}(inbound) =~ /^$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->user_record] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->rtp_has_crypto] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [rtp_has_crypto] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->redial] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [redial] destination_number(400) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->speed_dial] continue=false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [speed_dial] destination_number(400) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->user_hold_music] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->default_caller_id] continue=true
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (FAIL) [default_caller_id] ${call_direction}(inbound) =~ /outbound/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 parsing [10.20.30.2->Nova.10d] continue=false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [Nova.10d] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Regex (PASS) [Nova.10d] destination_number(400) =~ /^(\d{3,10})$/ break=on-false
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 export(call_direction=outbound)
2023-10-05 12:35:47.238893 97.73% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action unset(call_timeout)
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(hangup_after_bridge=true)
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(inherit_codec=true)
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(ignore_display_updates=true)
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(callee_id_number=400)
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607,809)
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action limit(hash ${domain_name} outbound 1 !USER_BUSY)
Dialplan: sofia/external/210608aaa4@10.20.30.2 Action bridge(sofia/gateway/8aabccc2-3a6b-47b0-83ff-aeee51886fce/400)
2023-10-05 12:35:47.238893 97.73% [DEBUG] switch_core_state_machine.c:281 (sofia/external/210608aaa4@10.20.30.2) State Change CS_ROUTING -> CS_EXECUTE
2023-10-05 12:35:47.238893 97.73% [DEBUG] switch_core_state_machine.c:640 (sofia/external/210608aaa4@10.20.30.2) State ROUTING going to sleep
2023-10-05 12:35:47.238893 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_EXECUTE (Cur 1 Tot 17)
2023-10-05 12:35:47.238893 97.73% [DEBUG] switch_core_state_machine.c:647 (sofia/external/210608aaa4@10.20.30.2) State EXECUTE
2023-10-05 12:35:47.238893 97.73% [DEBUG] mod_sofia.c:213 sofia/external/210608aaa4@10.20.30.2 SOFIA EXECUTE
2023-10-05 12:35:47.238893 97.73% [DEBUG] switch_core_state_machine.c:323 sofia/external/210608aaa4@10.20.30.2 Standard EXECUTE
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(RFC2822_DATE=Thu, 05 Oct 2023 12:35:47 +0100)
2023-10-05 12:35:47.238893 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [RFC2822_DATE]=[Thu, 05 Oct 2023 12:35:47 +0100]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 export(origination_callee_id_name=210608aaa4)
2023-10-05 12:35:47.238893 97.73% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [origination_callee_id_name]=[210608aaa4]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 hash(insert/10.20.30.2-last_dial/697bbbb999/400)
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 unset(call_timeout)
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_dptools.c:1816 UNSET [call_timeout]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(hangup_after_bridge=true)
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(effective_caller_id_name=)
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [effective_caller_id_name]=[UNDEF]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(effective_caller_id_number=)
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [effective_caller_id_number]=[UNDEF]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(inherit_codec=true)
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [inherit_codec]=[true]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(ignore_display_updates=true)
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(callee_id_number=400)
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [callee_id_number]=[400]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607,809)
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_dptools.c:1671 SET sofia/external/210608aaa4@10.20.30.2 [continue_on_fail]=[1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607,809]
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 limit(hash 10.20.30.2 outbound 1 !USER_BUSY)
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_limit.c:124 incr called: 10.20.30.2_outbound max:1, interval:0
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_hash.c:193 Usage for 10.20.30.2_outbound is now 1/1
EXECUTE [depth=0] sofia/external/210608aaa4@10.20.30.2 bridge(sofia/gateway/8aabccc2-3a6b-47b0-83ff-aeee51886fce/400)
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_channel.c:1288 sofia/external/210608aaa4@10.20.30.2 EXPORTING[export_vars] [call_direction]=[outbound] to event
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_channel.c:1288 sofia/external/210608aaa4@10.20.30.2 EXPORTING[export_vars] [call_direction]=[outbound] to event
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_channel.c:1288 sofia/external/210608aaa4@10.20.30.2 EXPORTING[export_vars] [call_direction]=[outbound] to event
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_channel.c:1288 sofia/external/210608aaa4@10.20.30.2 EXPORTING[export_vars] [origination_callee_id_name]=[210608aaa4] to event
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_ivr_originate.c:2297 Parsing global variables
2023-10-05 12:35:47.258899 97.73% [NOTICE] switch_channel.c:1142 New Channel sofia/external/400 [4dd53ce7-4d0d-492a-8bc3-92d208a095cf]
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_sofia.c:5110 (sofia/external/400) State Change CS_NEW -> CS_INIT
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/400) Running State Change CS_INIT (Cur 2 Tot 18)
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:624 (sofia/external/400) State INIT
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_sofia.c:97 sofia/external/400 SOFIA INIT
2023-10-05 12:35:47.258899 97.73% [INFO] sofia_glue.c:1659 sofia/external/400 sending invite call-id: (null)
2023-10-05 12:35:47.258899 97.73% [DEBUG] sofia_glue.c:1662 sofia/external/400 sending invite version: 1.10.10 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1696479607 1696479608 IN IP4 10.20.30.2
s=FreeSWITCH
c=IN IP4 10.20.30.2
t=0 0
m=audio 26140 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:40 sofia/external/400 Standard INIT
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:48 (sofia/external/400) State Change CS_INIT -> CS_ROUTING
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:624 (sofia/external/400) State INIT going to sleep
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/400) Running State Change CS_ROUTING (Cur 2 Tot 18)
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:640 (sofia/external/400) State ROUTING
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_sofia.c:158 sofia/external/400 SOFIA ROUTING
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_ivr_originate.c:67 (sofia/external/400) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:640 (sofia/external/400) State ROUTING going to sleep
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/400) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 18)
2023-10-05 12:35:47.258899 97.73% [DEBUG] sofia.c:7493 Channel sofia/external/400 entering state [calling][0]
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:659 (sofia/external/400) State CONSUME_MEDIA
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:659 (sofia/external/400) State CONSUME_MEDIA going to sleep
2023-10-05 12:35:47.338865 97.73% [DEBUG] sofia.c:7493 Channel sofia/external/400 entering state [terminated][486]
2023-10-05 12:35:47.338865 97.73% [NOTICE] sofia.c:8735 Hangup sofia/external/400 [CS_CONSUME_MEDIA] [USER_BUSY]
2023-10-05 12:35:47.338865 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/400) Running State Change CS_HANGUP (Cur 2 Tot 18)
2023-10-05 12:35:47.338865 97.73% [DEBUG] switch_ivr_originate.c:4052 Originate Resulted in Error Cause: 17 [USER_BUSY]
2023-10-05 12:35:47.338865 97.73% [DEBUG] switch_core_state_machine.c:844 (sofia/external/400) Callstate Change DOWN -> HANGUP
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:846 (sofia/external/400) State HANGUP
2023-10-05 12:35:47.358871 97.73% [DEBUG] mod_sofia.c:469 Channel sofia/external/400 hanging up, cause: USER_BUSY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:59 sofia/external/400 Standard HANGUP, cause: USER_BUSY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:846 (sofia/external/400) State HANGUP going to sleep
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:616 (sofia/external/400) State Change CS_HANGUP -> CS_REPORTING
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/400) Running State Change CS_REPORTING (Cur 2 Tot 18)
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:932 (sofia/external/400) State REPORTING
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:168 sofia/external/400 Standard REPORTING, cause: USER_BUSY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:932 (sofia/external/400) State REPORTING going to sleep
2023-10-05 12:35:47.358871 97.73% [INFO] mod_dptools.c:3635 Originate Failed. Cause: USER_BUSY
2023-10-05 12:35:47.358871 97.73% [NOTICE] switch_channel.c:5012 Hangup sofia/external/210608aaa4@10.20.30.2 [CS_EXECUTE] [USER_BUSY]
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:607 (sofia/external/400) State Change CS_REPORTING -> CS_DESTROY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_session.c:1744 Session 18 (sofia/external/400) Locked, Waiting on external entities
2023-10-05 12:35:47.358871 97.73% [NOTICE] switch_core_session.c:1762 Session 18 (sofia/external/400) Ended
2023-10-05 12:35:47.358871 97.73% [NOTICE] switch_core_session.c:1766 Close Channel sofia/external/400 [CS_DESTROY]
2023-10-05 12:35:47.358871 97.73% [DEBUG] mod_hash.c:293 Usage for 10.20.30.2_outbound is now 0
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:735 (sofia/external/400) Running State Change CS_DESTROY (Cur 1 Tot 18)
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_session.c:2979 sofia/external/210608aaa4@10.20.30.2 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:647 (sofia/external/210608aaa4@10.20.30.2) State EXECUTE going to sleep
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_HANGUP (Cur 1 Tot 18)
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:745 (sofia/external/400) State DESTROY
2023-10-05 12:35:47.358871 97.73% [DEBUG] mod_sofia.c:380 sofia/external/400 SOFIA DESTROY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:175 sofia/external/400 Standard DESTROY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:745 (sofia/external/400) State DESTROY going to sleep
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:844 (sofia/external/210608aaa4@10.20.30.2) Callstate Change RINGING -> HANGUP
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:846 (sofia/external/210608aaa4@10.20.30.2) State HANGUP
2023-10-05 12:35:47.358871 97.73% [DEBUG] mod_sofia.c:463 sofia/external/210608aaa4@10.20.30.2 Overriding SIP cause 486 with 486 from the other leg
2023-10-05 12:35:47.358871 97.73% [DEBUG] mod_sofia.c:469 Channel sofia/external/210608aaa4@10.20.30.2 hanging up, cause: USER_BUSY
2023-10-05 12:35:47.358871 97.73% [DEBUG] mod_sofia.c:614 Responding to INVITE with: 486
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:59 sofia/external/210608aaa4@10.20.30.2 Standard HANGUP, cause: USER_BUSY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:846 (sofia/external/210608aaa4@10.20.30.2) State HANGUP going to sleep
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:616 (sofia/external/210608aaa4@10.20.30.2) State Change CS_HANGUP -> CS_REPORTING
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_REPORTING (Cur 1 Tot 18)
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:932 (sofia/external/210608aaa4@10.20.30.2) State REPORTING
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:168 sofia/external/210608aaa4@10.20.30.2 Standard REPORTING, cause: USER_BUSY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:932 (sofia/external/210608aaa4@10.20.30.2) State REPORTING going to sleep
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:607 (sofia/external/210608aaa4@10.20.30.2) State Change CS_REPORTING -> CS_DESTROY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_session.c:1744 Session 17 (sofia/external/210608aaa4@10.20.30.2) Locked, Waiting on external entities
2023-10-05 12:35:47.358871 97.73% [NOTICE] switch_core_session.c:1762 Session 17 (sofia/external/210608aaa4@10.20.30.2) Ended
2023-10-05 12:35:47.358871 97.73% [NOTICE] switch_core_session.c:1766 Close Channel sofia/external/210608aaa4@10.20.30.2 [CS_DESTROY]
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:735 (sofia/external/210608aaa4@10.20.30.2) Running State Change CS_DESTROY (Cur 0 Tot 18)
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:745 (sofia/external/210608aaa4@10.20.30.2) State DESTROY
2023-10-05 12:35:47.358871 97.73% [DEBUG] mod_sofia.c:380 sofia/external/210608aaa4@10.20.30.2 SOFIA DESTROY
2023-10-05 12:35:47.358871 97.73% [DEBUG] switch_core_state_machine.c:175 sofia/external/210608aaa4@10.20.30.2 Standard DESTROY
Click to expand...
 
Doing some more testing, when inbound call is transferred to an extension, an internal channel is created
2023-10-06 07:38:39.270482 97.33% [DEBUG] switch_ivr_originate.c:2297 Parsing global variables
2023-10-06 07:38:39.270482 97.33% [NOTICE] switch_channel.c:1142 New Channel sofia/internal/112@10.20.30.5:5060 [4cd7e97d-e55f-43bf-99ca-244b9c1e9746]
2023-10-06 07:38:39.270482 97.33% [DEBUG] mod_sofia.c:5110 (sofia/internal/112@10.20.30.5:5060) State Change CS_NEW -> CS_INIT
Click to expand...

However, when the call is transferred to a ring group, an external channel is created instead:

2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_ivr_originate.c:2297 Parsing global variables
2023-10-05 12:35:47.258899 97.73% [NOTICE] switch_channel.c:1142 New Channel sofia/external/400 [4dd53ce7-4d0d-492a-8bc3-92d208a095cf]
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_sofia.c:5110 (sofia/external/400) State Change CS_NEW -> CS_INIT
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:581 (sofia/external/400) Running State Change CS_INIT (Cur 2 Tot 18)
2023-10-05 12:35:47.258899 97.73% [DEBUG] switch_core_state_machine.c:624 (sofia/external/400) State INIT
2023-10-05 12:35:47.258899 97.73% [DEBUG] mod_sofia.c:97 sofia/external/400 SOFIA INIT
2023-10-05 12:35:47.258899 97.73% [INFO] sofia_glue.c:1659 sofia/external/400 sending invite call-id: (null)
2023-10-05 12:35:47.258899 97.73% [DEBUG] sofia_glue.c:1662 sofia/external/400 sending invite version: 1.10.10 -release 64bit
Click to expand...

Is this the way it should be?
 
I have done some more testing over the weekend, and always come up to the same conclusion, the ring group creates a channel in the external profile, looping the call back, eventually creating a busy message.
FusionPBX is a great tool but documentation is so much restricted to trivial config, that many issues can't be resolved without external help.

Can someone more experienced, or with access to more advanced documentation shed some light?
 
Status
Not open for further replies.
Top Bottom