Ring groups failing

Status
Not open for further replies.
P

paulwollner

New Member
Oct 16, 2020
4
0
1
47
Hello everyone,

I have a n installation of fusionpbx which has been for a year and a half now. Until now everything has been in order, but yesterday issues started cropping up.

There have been no changes to the system, however yesterday issues started cropping up with ring-groups. Calling in to a ring group fails with LOSE_RACE. We can see the endpoints get the INVITE followed with a CANCEL. Going through the logs, I cannot find a reason for the failure. I have included the logs below. I would appreciate any feedback on the what the possible cause could be.

The only error I can see is: 2022-03-12 14:29:00.747799 97.40% [ERR] switch_ivr_async.c:226 Digit parser DPTOOLS: Error Setting realm to 'local'
I do not know if that is indeed a concern.


ialplan: sofia/external/0827869006@192.168.30.14 Action export(call_direction=inbound) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 export(call_direction=inbound)


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[inbound]


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(domain_uuid=e018fe64-5cff-483d-a377-6d206c2eb63f) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(domain_uuid=e018fe64-5cff-483d-a377-6d206c2eb63f)


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [domain_uuid]=[e018fe64-5cff-483d-a377-6d206c2eb63f]


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(domain_name=bm.pbx.aoc.net) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(domain_name=bm.pbx.aoc.net)


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [domain_name]=[bm.pbx.aoc.net]


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(hangup_after_bridge=true) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(hangup_after_bridge=true)


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [hangup_after_bridge]=[true]


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(continue_on_fail=true) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(continue_on_fail=true)


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [continue_on_fail]=[true]


Dialplan: sofia/external/0827869006@192.168.30.14 Action transfer(9952 XML bm.pbx.aoc.net)


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:281 (sofia/external/0827869006@192.168.30.14) State Change CS_ROUTING -> CS_EXECUTE


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:640 (sofia/external/0827869006@192.168.30.14) State ROUTING going to sleep


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/external/0827869006@192.168.30.14) Running State Change CS_EXECUTE (Cur 1 Tot 7)


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:647 (sofia/external/0827869006@192.168.30.14) State EXECUTE


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_sofia.c:213 sofia/external/0827869006@192.168.30.14 SOFIA EXECUTE


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:323 sofia/external/0827869006@192.168.30.14 Standard EXECUTE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(caller_id_number=0827869006)


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [caller_id_number]=[0827869006]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 transfer(9952 XML bm.pbx.aoc.net)


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_ivr.c:2289 (sofia/external/0827869006@192.168.30.14) State Change CS_EXECUTE -> CS_ROUTING


2022-03-12 14:29:00.647803 97.40% [NOTICE] switch_ivr.c:2296 Transfer sofia/external/0827869006@192.168.30.14 to XML[9952@bm.pbx.aoc.net]


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:647 (sofia/external/0827869006@192.168.30.14) State EXECUTE going to sleep


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/external/0827869006@192.168.30.14) Running State Change CS_ROUTING (Cur 1 Tot 7)


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:640 (sofia/external/0827869006@192.168.30.14) State ROUTING


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_sofia.c:149 Call appears to be already acknowledged


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_sofia.c:158 sofia/external/0827869006@192.168.30.14 SOFIA ROUTING


2022-03-12 14:29:00.647803 97.40% [DEBUG] switch_core_state_machine.c:230 sofia/external/0827869006@192.168.30.14 Standard ROUTING


2022-03-12 14:29:00.647803 97.40% [INFO] mod_dialplan_xml.c:639 Processing 27827869006 <0827869006>->9952 in context bm.pbx.aoc.net


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->user_exists] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [user_exists] () =~ // break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(user_exists=false)


2022-03-12 14:29:00.647803 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [user_exists]=[false]


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(from_user_exists=false)


2022-03-12 14:29:00.667794 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [from_user_exists]=[false]


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->saraphone_is_caller_callee_saraphone] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [saraphone_is_caller_callee_saraphone] () =~ // break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Action lua(/var/www/fusionpbx/app/saraphone/saraphone.lua)


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->call-direction] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [call-direction] ${call_direction}(inbound) =~ /^(inbound|outbound|local)$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->caller-details] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [caller-details] ${caller_destination}(27218563161) =~ /^$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->global-variables] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [global-variables] () =~ // break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(timezone=Africa/Johannesburg) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(timezone=Africa/Johannesburg)


2022-03-12 14:29:00.667794 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [timezone]=[Africa/Johannesburg]


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->domain-variables] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [domain-variables] () =~ // break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Action export(origination_callee_id_name=${destination_number})


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->is_loopback] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->user_record] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [user_record] ${call_direction}(inbound) =~ /^inbound$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^outbound$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_exists}(false) =~ /^true$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${call_direction}(inbound) =~ /^local$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->redial] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [redial] destination_number(9952) =~ /^(redial|\*870)$/ break=on-true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [redial] () =~ // break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->speed_dial] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [speed_dial] destination_number(9952) =~ /^\*0(.*)$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->default_caller_id] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(emergency_caller_id_name=)


2022-03-12 14:29:00.667794 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [emergency_caller_id_name]=[UNDEF]


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(emergency_caller_id_number=)


2022-03-12 14:29:00.667794 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [emergency_caller_id_number]=[UNDEF]


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(outbound_caller_id_name=)


2022-03-12 14:29:00.667794 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [outbound_caller_id_name]=[UNDEF]


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(outbound_caller_id_number=)


2022-03-12 14:29:00.667794 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [outbound_caller_id_number]=[UNDEF]


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->user_hold_music] continue=true


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_hold_music] ${hold_music}(local_stream://default) =~ /^$/ break=never


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmgeorge-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmgeorge-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmgeorge-fusion.00d5d] ${accountcode}() =~ /^8479116585$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmmontagu-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmmontagu-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmmontagu-fusion.00d5d] ${accountcode}() =~ /^0336831417$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmcaladon-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmcaladon-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmcaladon-fusion.00d5d] ${accountcode}() =~ /^7782227405$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmesummersetwest-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmesummersetwest-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmesummersetwest-fusion.00d5d] ${accountcode}() =~ /^3789184574$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmrobertson-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmrobertson-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmrobertson-fusion.00d5d] ${accountcode}() =~ /^0250956320$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmgordonsbay-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmgordonsbay-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmgordonsbay-fusion.00d5d] ${accountcode}() =~ /^5024514731$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmhermanus-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmhermanus-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmhermanus-fusion.00d5d] ${accountcode}() =~ /^9668313539$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmwc-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmwc-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmwc-fusion.00d5d] ${accountcode}() =~ /^0941390006$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->cgrt-bmbedasdorp-fusion.00d5d] continue=false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [cgrt-bmbedasdorp-fusion.00d5d] ${user_exists}(false) =~ /false/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (FAIL) [cgrt-bmbedasdorp-fusion.00d5d] ${accountcode}() =~ /^7558878880$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 parsing [bm.pbx.aoc.net->bm Gordons Bay Ring Group] continue=


Dialplan: sofia/external/0827869006@192.168.30.14 Regex (PASS) [bm Gordons Bay Ring Group] destination_number(9952) =~ /^9952$/ break=on-false


Dialplan: sofia/external/0827869006@192.168.30.14 Action ring_ready()


Dialplan: sofia/external/0827869006@192.168.30.14 Action set(ring_group_uuid=79bf6c7e-60af-41ed-9f12-94f56321dcdf)


Dialplan: sofia/external/0827869006@192.168.30.14 Action lua(app.lua ring_groups)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_core_state_machine.c:281 (sofia/external/0827869006@192.168.30.14) State Change CS_ROUTING -> CS_EXECUTE


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_core_state_machine.c:640 (sofia/external/0827869006@192.168.30.14) State ROUTING going to sleep


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/external/0827869006@192.168.30.14) Running State Change CS_EXECUTE (Cur 1 Tot 7)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_core_state_machine.c:647 (sofia/external/0827869006@192.168.30.14) State EXECUTE


2022-03-12 14:29:00.667794 97.40% [DEBUG] mod_sofia.c:213 sofia/external/0827869006@192.168.30.14 SOFIA EXECUTE


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_core_state_machine.c:323 sofia/external/0827869006@192.168.30.14 Standard EXECUTE


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 lua(/var/www/fusionpbx/app/saraphone/saraphone.lua)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 ------------ BEGIN ----------------------------------------------------------


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 domain_name: bm.pbx.aoc.net


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 destination_number: 9952


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 caller_id_number: 0827869006


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 username: 0827869006


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 saraphone_destination_user_agent:


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 saraphone_caller_user_agent:


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 saraphone_bind: false


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 export(saraphone_bind=true)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [saraphone_bind]=[true]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 export(saraphone_is_both=true)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [saraphone_is_both]=[true]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(saraphone_local,*299,exec:execute_extension,saraphone_hold XML bm.pbx.aoc.net,aleg,bleg)


2022-03-12 14:29:00.667794 97.40% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'saraphone_local'


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *299/saraphone_local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c1d4878


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(saraphone_local,*399,exec:execute_extension,saraphone_hold XML bm.pbx.aoc.net,peer,peer)


2022-03-12 14:29:00.667794 97.40% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'saraphone_local'


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *399/saraphone_local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c1d4a50


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(saraphone_local,*499,exec:execute_extension,saraphone_dx XML bm.pbx.aoc.net,aleg,bleg)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *499/saraphone_local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c1d4c28


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(saraphone_local,*599,exec:execute_extension,saraphone_dx XML bm.pbx.aoc.net,peer,peer)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *599/saraphone_local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c1d4df8


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(saraphone_local,*699,exec:execute_extension,saraphone_att_xfer XML bm.pbx.aoc.net,aleg,bleg)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *699/saraphone_local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c1d4fd8


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(saraphone_local,*799,exec:execute_extension,saraphone_att_xfer XML bm.pbx.aoc.net,peer,peer)


2022-03-12 14:29:00.667794 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *799/saraphone_local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c1d51c0


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 digit_action_set_realm(saraphone_local)


2022-03-12 14:29:00.687800 97.40% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'saraphone_local'


2022-03-12 14:29:00.687800 97.40% [DEBUG] switch_cpp.cpp:1465 7da1a652-b97a-4221-b5aa-6d43d405a652 ------------ END ----------------------------------------------------------


2022-03-12 14:29:00.687800 97.40% [DEBUG] switch_cpp.cpp:1209 sofia/external/0827869006@192.168.30.14 destroy/unlink session from object


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(RFC2822_DATE=Sat, 12 Mar 2022 14:29:00 +0200)


2022-03-12 14:29:00.687800 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [RFC2822_DATE]=[Sat, 12 Mar 2022 14:29:00 +0200]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 export(origination_callee_id_name=9952)


2022-03-12 14:29:00.687800 97.40% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [origination_callee_id_name]=[9952]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 hash(insert/bm.pbx.aoc.net-last_dial/0827869006/9952)


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 ring_ready()


2022-03-12 14:29:00.687800 97.40% [NOTICE] mod_sofia.c:2515 Ring-Ready sofia/external/0827869006@192.168.30.14!


2022-03-12 14:29:00.687800 97.40% [DEBUG] sofia.c:7499 Channel sofia/external/0827869006@192.168.30.14 entering state [early][180]


2022-03-12 14:29:00.687800 97.40% [NOTICE] mod_dptools.c:1122 Ring Ready sofia/external/0827869006@192.168.30.14!


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(ring_group_uuid=79bf6c7e-60af-41ed-9f12-94f56321dcdf)


2022-03-12 14:29:00.687800 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [ring_group_uuid]=[79bf6c7e-60af-41ed-9f12-94f56321dcdf]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 lua(app.lua ring_groups)


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 ring_ready()


2022-03-12 14:29:00.687800 97.40% [NOTICE] mod_dptools.c:1122 Ring Ready sofia/external/0827869006@192.168.30.14!


2022-03-12 14:29:00.687800 97.40% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('call_timeout', '30')


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] domain_name: bm.pbx.aoc.net


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] destination_number: 150


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] destination_delay: 0


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] destination_timeout: 30


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] destination_prompt:


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] domain_name: bm.pbx.aoc.net


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] destination_number: 151


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] destination_delay: 0


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] destination_timeout: 30


2022-03-12 14:29:00.707801 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] destination_prompt:


2022-03-12 14:29:00.727800 97.40% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('ringback', 'tone_stream://;loops=-1')


2022-03-12 14:29:00.727800 97.40% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('transfer_ringback', 'tone_stream://;loops=-1')


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(uuids=b20316da-ea24-4074-b426-b65f48eb94e0)


2022-03-12 14:29:00.727800 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [uuids]=[b20316da-ea24-4074-b426-b65f48eb94e0]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 export(sip_h_Alert-Info=)


2022-03-12 14:29:00.727800 97.40% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [sip_h_Alert-Info]=[UNDEF]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(group_confirm_key=exec)


2022-03-12 14:29:00.727800 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [group_confirm_key]=[exec]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(group_confirm_file=lua /usr/share/freeswitch/scripts/confirm.lua)


2022-03-12 14:29:00.727800 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [group_confirm_file]=[lua /usr/share/freeswitch/scripts/confirm.lua]


2022-03-12 14:29:00.727800 97.40% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('ringback', 'tone_stream://;loops=-1')


2022-03-12 14:29:00.727800 97.40% [DEBUG] switch_cpp.cpp:773 CoreSession::setVariable('transfer_ringback', 'tone_stream://;loops=-1')


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(uuids=b20316da-ea24-4074-b426-b65f48eb94e0,e0a9468c-1b25-405e-9e5a-b56eec41a7b8)


2022-03-12 14:29:00.727800 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [uuids]=[b20316da-ea24-4074-b426-b65f48eb94e0,e0a9468c-1b25-405e-9e5a-b56eec41a7b8]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 export(sip_h_Alert-Info=)


2022-03-12 14:29:00.727800 97.40% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [sip_h_Alert-Info]=[UNDEF]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(group_confirm_key=exec)


2022-03-12 14:29:00.747799 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [group_confirm_key]=[exec]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(group_confirm_file=lua /usr/share/freeswitch/scripts/confirm.lua)


2022-03-12 14:29:00.747799 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [group_confirm_file]=[lua /usr/share/freeswitch/scripts/confirm.lua]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(ignore_early_media=true)


2022-03-12 14:29:00.747799 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [ignore_early_media]=[true]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(hangup_after_bridge=true)


2022-03-12 14:29:00.747799 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [hangup_after_bridge]=[true]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 set(continue_on_fail=true)


2022-03-12 14:29:00.747799 97.40% [DEBUG] mod_dptools.c:1685 SET sofia/external/0827869006@192.168.30.14 [continue_on_fail]=[true]


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(local,*2,exec:record_session,/var/lib/freeswitch/recordings/bm.pbx.aoc.net/archive/2022/Mar/12/7da1a652-b97a-4221-b5aa-6d43d405a652.wav,peer)


2022-03-12 14:29:00.747799 97.40% [INFO] switch_ivr_async.c:221 Digit parser DPTOOLS: Setting realm to 'local'


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *2/local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c27c920


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(local,*5,api:uuid_record,7da1a652-b97a-4221-b5aa-6d43d405a652 mask /var/lib/freeswitch/recordings/bm.pbx.aoc.net/archive/2022/Mar/12/7da1a652-b97a-4221-b5aa-6d43d405a652.wav,peer)


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *5/local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c27cbd8


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bind_digit_action(local,*6,api:uuid_record,7da1a652-b97a-4221-b5aa-6d43d405a652 unmask /var/lib/freeswitch/recordings/bm.pbx.aoc.net/archive/2022/Mar/12/7da1a652-b97a-4221-b5aa-6d43d405a652.wav,peer)


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_ivr_async.c:346 Digit parser DPTOOLS: binding *6/local/0 callback: 0x7f0aa00471f0 data: 0x7f0a9c27cea8


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 digit_action_set_realm(local)


2022-03-12 14:29:00.747799 97.40% [ERR] switch_ivr_async.c:226 Digit parser DPTOOLS: Error Setting realm to 'local'


2022-03-12 14:29:00.747799 97.40% [NOTICE] switch_cpp.cpp:1465 [ring group] app_data: {ignore_early_media=true}[sip_invite_domain=bm.pbx.aoc.net,domain_name=bm.pbx.aoc.net,call_direction=inbound,confirm=false,leg_timeout=30,leg_delay_start=0,dialed_extension=150,extension_uuid=d830b545-50b6-4211-8ae4-509b12889b5c]user/150@bm.pbx.aoc.net,[sip_invite_domain=bm.pbx.aoc.net,domain_name=bm.pbx.aoc.net,call_direction=inbound,confirm=false,leg_timeout=30,leg_delay_start=0,dialed_extension=151,extension_uuid=e85ffe6c-cf25-44e2-8a60-00a44a70e878]user/151@bm.pbx.aoc.net


EXECUTE [depth=0] sofia/external/0827869006@192.168.30.14 bridge({ignore_early_media=true}[sip_invite_domain=bm.pbx.aoc.net,domain_name=bm.pbx.aoc.net,call_direction=inbound,confirm=false,leg_timeout=30,leg_delay_start=0,dialed_extension=150,extension_uuid=d830b545-50b6-4211-8ae4-509b12889b5c]user/150@bm.pbx.aoc.net,[sip_invite_domain=bm.pbx.aoc.net,domain_name=bm.pbx.aoc.net,call_direction=inbound,confirm=false,leg_timeout=30,leg_delay_start=0,dialed_extension=151,extension_uuid=e85ffe6c-cf25-44e2-8a60-00a44a70e878]user/151@bm.pbx.aoc.net)


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [call_direction]=[inbound] to event


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [call_direction]=[inbound] to event


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [saraphone_bind]=[true] to event


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [saraphone_is_both]=[true] to event


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [origination_callee_id_name]=[9952] to event


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables


2022-03-12 14:29:00.747799 97.40% [DEBUG] switch_ivr_originate.c:2843 Parsing session specific variables


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [call_direction]=[inbound] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [call_direction]=[inbound] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [saraphone_bind]=[true] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [saraphone_is_both]=[true] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [origination_callee_id_name]=[9952] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables


2022-03-12 14:29:00.767798 97.40% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/150@105.186.192.222:5060 [3ac149d5-7fd6-4d12-894d-fdea4c1e6ae8]


2022-03-12 14:29:00.767798 97.40% [DEBUG] mod_sofia.c:5121 (sofia/internal/150@105.186.192.222:5060) State Change CS_NEW -> CS_INIT


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:3151 sofia/internal/150@105.186.192.222:5060 Setting leg timeout to 30


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:3151 sofia/internal/150@105.186.192.222:5060 Setting leg timeout to 30


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:2843 Parsing session specific variables


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/150@105.186.192.222:5060) Running State Change CS_INIT (Cur 2 Tot 8)


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/150@105.186.192.222:5060) State INIT


2022-03-12 14:29:00.767798 97.40% [DEBUG] mod_sofia.c:97 sofia/internal/150@105.186.192.222:5060 SOFIA INIT


2022-03-12 14:29:00.767798 97.40% [DEBUG] sofia_glue.c:1620 sip:150@105.186.192.222:5060 Setting proxy route to sofia/internal/150@105.186.192.222:5060


2022-03-12 14:29:00.767798 97.40% [INFO] sofia_glue.c:1651 sofia/internal/150@105.186.192.222:5060 sending invite call-id: (null)


2022-03-12 14:29:00.767798 97.40% [DEBUG] sofia_glue.c:1654 sofia/internal/150@105.186.192.222:5060 sending invite version: 1.10.7 -release-19-883d2cb662 64bit


Local SDP:


v=0


o=FreeSWITCH 1647062058 1647062059 IN IP4 X.X.X.248


s=FreeSWITCH


c=IN IP4 X.X.X.248


t=0 0


m=audio 26082 RTP/AVP 18 9 0 8 101 13


a=rtpmap:18 G729/8000


a=fmtp:18 annexb=no


a=rtpmap:9 G722/8000


a=rtpmap:0 PCMU/8000


a=rtpmap:8 PCMA/8000


a=rtpmap:101 telephone-event/8000


a=fmtp:101 0-15


a=rtpmap:13 CN/8000


a=ptime:20


a=sendrecv





2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:40 sofia/internal/150@105.186.192.222:5060 Standard INIT


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/150@105.186.192.222:5060) State Change CS_INIT -> CS_ROUTING


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/150@105.186.192.222:5060) State INIT going to sleep


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/150@105.186.192.222:5060) Running State Change CS_ROUTING (Cur 2 Tot 8)


2022-03-12 14:29:00.767798 97.40% [DEBUG] sofia.c:7499 Channel sofia/internal/150@105.186.192.222:5060 entering state [calling][0]


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/150@105.186.192.222:5060) State ROUTING


2022-03-12 14:29:00.767798 97.40% [DEBUG] mod_sofia.c:158 sofia/internal/150@105.186.192.222:5060 SOFIA ROUTING


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:67 (sofia/internal/150@105.186.192.222:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/150@105.186.192.222:5060) State ROUTING going to sleep


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/150@105.186.192.222:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 8)


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/150@105.186.192.222:5060) State CONSUME_MEDIA


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/150@105.186.192.222:5060) State CONSUME_MEDIA going to sleep


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [call_direction]=[inbound] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [call_direction]=[inbound] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [saraphone_bind]=[true] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [saraphone_is_both]=[true] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_channel.c:1269 sofia/external/0827869006@192.168.30.14 EXPORTING[export_vars] [origination_callee_id_name]=[9952] to event


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables


2022-03-12 14:29:00.767798 97.40% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/151@105.186.192.222:1024 [58e00a48-34ec-45ce-9a39-c3d441375dfb]


2022-03-12 14:29:00.767798 97.40% [DEBUG] mod_sofia.c:5121 (sofia/internal/151@105.186.192.222:1024) State Change CS_NEW -> CS_INIT


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:3151 sofia/internal/151@105.186.192.222:1024 Setting leg timeout to 30


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:3151 sofia/internal/151@105.186.192.222:1024 Setting leg timeout to 30


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/151@105.186.192.222:1024) Running State Change CS_INIT (Cur 3 Tot 9)


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/151@105.186.192.222:1024) State INIT


2022-03-12 14:29:00.767798 97.40% [DEBUG] mod_sofia.c:97 sofia/internal/151@105.186.192.222:1024 SOFIA INIT


2022-03-12 14:29:00.767798 97.40% [DEBUG] sofia_glue.c:1620 sip:151@105.186.192.222:1024 Setting proxy route to sofia/internal/151@105.186.192.222:1024


2022-03-12 14:29:00.767798 97.40% [INFO] sofia_glue.c:1651 sofia/internal/151@105.186.192.222:1024 sending invite call-id: (null)


2022-03-12 14:29:00.767798 97.40% [DEBUG] sofia_glue.c:1654 sofia/internal/151@105.186.192.222:1024 sending invite version: 1.10.7 -release-19-883d2cb662 64bit


Local SDP:


v=0


o=FreeSWITCH 1647070382 1647070383 IN IP4 X.X.X.248


s=FreeSWITCH


c=IN IP4 X.X.X.248


t=0 0


m=audio 17758 RTP/AVP 18 9 0 8 101 13


a=rtpmap:18 G729/8000


a=fmtp:18 annexb=no


a=rtpmap:9 G722/8000


a=rtpmap:0 PCMU/8000


a=rtpmap:8 PCMA/8000


a=rtpmap:101 telephone-event/8000


a=fmtp:101 0-15


a=rtpmap:13 CN/8000


a=ptime:20


a=sendrecv





2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:40 sofia/internal/151@105.186.192.222:1024 Standard INIT


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/151@105.186.192.222:1024) State Change CS_INIT -> CS_ROUTING


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/151@105.186.192.222:1024) State INIT going to sleep


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/151@105.186.192.222:1024) Running State Change CS_ROUTING (Cur 3 Tot 9)


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/151@105.186.192.222:1024) State ROUTING


2022-03-12 14:29:00.767798 97.40% [DEBUG] mod_sofia.c:158 sofia/internal/151@105.186.192.222:1024 SOFIA ROUTING


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_ivr_originate.c:67 (sofia/internal/151@105.186.192.222:1024) State Change CS_ROUTING -> CS_CONSUME_MEDIA


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/151@105.186.192.222:1024) State ROUTING going to sleep


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/151@105.186.192.222:1024) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 9)


2022-03-12 14:29:00.767798 97.40% [DEBUG] sofia.c:7499 Channel sofia/internal/151@105.186.192.222:1024 entering state [calling][0]


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/151@105.186.192.222:1024) State CONSUME_MEDIA


2022-03-12 14:29:00.767798 97.40% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/151@105.186.192.222:1024) State CONSUME_MEDIA going to sleep


2022-03-12 14:29:00.967804 97.40% [DEBUG] sofia.c:7499 Channel sofia/internal/151@105.186.192.222:1024 entering state [proceeding][180]


2022-03-12 14:29:00.967804 97.40% [NOTICE] sofia.c:7610 Ring-Ready sofia/internal/151@105.186.192.222:1024!


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_channel.c:3494 (sofia/internal/151@105.186.192.222:1024) Callstate Change DOWN -> RINGING


2022-03-12 14:29:00.967804 97.40% [INFO] switch_ivr_originate.c:1295 Sending early media


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_core_media.c:8777 AUDIO RTP [sofia/external/0827869006@192.168.30.14] X.X.X.248 port 29120 -> 102.222.164.126 port 27650 codec: 18 ms: 20


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_core_media.c:8997 Activating RTCP PORT 27651


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_rtp.c:5017 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 27651


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_rtp.c:2776 Setting RTCP remote addr to 102.222.164.126:27651 2


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_core_media.c:9089 sofia/external/0827869006@192.168.30.14 Set 2833 dtmf send payload to 100


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_core_media.c:9096 sofia/external/0827869006@192.168.30.14 Set 2833 dtmf receive payload to 100


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_core_media.c:9119 sofia/external/0827869006@192.168.30.14 Set rtp dtmf delay to 40


2022-03-12 14:29:00.967804 97.40% [DEBUG] mod_sofia.c:2610 Ring SDP:


v=0


o=FreeSWITCH 1647059020 1647059021 IN IP4 X.X.X.248


s=FreeSWITCH


c=IN IP4 X.X.X.248


t=0 0


m=audio 29120 RTP/AVP 18 100


a=rtpmap:18 G729/8000


a=fmtp:18 annexb=no


a=rtpmap:100 telephone-event/8000


a=fmtp:100 0-15


a=silenceSupp:eek:ff - - - -


a=ptime:20


a=sendrecv


a=rtcp:29121 IN IP4 X.X.X.248





2022-03-12 14:29:00.967804 97.40% [NOTICE] mod_sofia.c:2613 Pre-Answer sofia/external/0827869006@192.168.30.14!


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_channel.c:3622 (sofia/external/0827869006@192.168.30.14) Callstate Change RINGING -> EARLY


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_ivr_originate.c:1353 Raw Codec Activation Success L16@8000hz 1 channel 20ms


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_core_codec.c:223 sofia/external/0827869006@192.168.30.14 Push codec L16:100


2022-03-12 14:29:00.967804 97.40% [DEBUG] switch_ivr_originate.c:1385 Play Ringback File [tone_stream://;loops=-1]


2022-03-12 14:29:00.987795 97.40% [DEBUG] sofia.c:7499 Channel sofia/external/0827869006@192.168.30.14 entering state [early][183]


2022-03-12 14:29:00.987795 97.40% [DEBUG] switch_core_codec.c:248 sofia/external/0827869006@192.168.30.14 Restore previous codec G729:18.


2022-03-12 14:29:00.987795 97.40% [NOTICE] switch_ivr_originate.c:3799 Hangup sofia/internal/150@105.186.192.222:5060 [CS_CONSUME_MEDIA] [LOSE_RACE]


2022-03-12 14:29:01.007787 97.40% [NOTICE] switch_ivr_originate.c:3799 Hangup sofia/internal/151@105.186.192.222:1024 [CS_CONSUME_MEDIA] [LOSE_RACE]


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/150@105.186.192.222:5060) Running State Change CS_HANGUP (Cur 3 Tot 9)


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/150@105.186.192.222:5060) Callstate Change DOWN -> HANGUP


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 502 [LOSE_RACE]


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/150@105.186.192.222:5060) State HANGUP


2022-03-12 14:29:01.007787 97.40% [DEBUG] mod_sofia.c:468 Channel sofia/internal/150@105.186.192.222:5060 hanging up, cause: LOSE_RACE


2022-03-12 14:29:01.007787 97.40% [DEBUG] mod_sofia.c:536 Sending CANCEL to sofia/internal/150@105.186.192.222:5060


2022-03-12 14:29:01.007787 97.40% [INFO] mod_dptools.c:3653 Originate Failed. Cause: LOSE_RACE


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:59 sofia/internal/150@105.186.192.222:5060 Standard HANGUP, cause: LOSE_RACE


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/150@105.186.192.222:5060) State HANGUP going to sleep


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/150@105.186.192.222:5060) State Change CS_HANGUP -> CS_REPORTING


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/150@105.186.192.222:5060) Running State Change CS_REPORTING (Cur 3 Tot 9)


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_cpp.cpp:1209 sofia/external/0827869006@192.168.30.14 destroy/unlink session from object


2022-03-12 14:29:01.007787 97.40% [NOTICE] switch_core_state_machine.c:382 sofia/external/0827869006@192.168.30.14 has executed the last dialplan instruction, hanging up.


2022-03-12 14:29:01.007787 97.40% [NOTICE] switch_core_state_machine.c:384 Hangup sofia/external/0827869006@192.168.30.14 [CS_EXECUTE] [NORMAL_CLEARING]


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:647 (sofia/external/0827869006@192.168.30.14) State EXECUTE going to sleep


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/external/0827869006@192.168.30.14) Running State Change CS_HANGUP (Cur 3 Tot 9)


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:844 (sofia/external/0827869006@192.168.30.14) Callstate Change EARLY -> HANGUP


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/150@105.186.192.222:5060) State REPORTING


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:168 sofia/internal/150@105.186.192.222:5060 Standard REPORTING, cause: LOSE_RACE


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/150@105.186.192.222:5060) State REPORTING going to sleep


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:846 (sofia/external/0827869006@192.168.30.14) State HANGUP


2022-03-12 14:29:01.007787 97.40% [DEBUG] mod_sofia.c:468 Channel sofia/external/0827869006@192.168.30.14 hanging up, cause: NORMAL_CLEARING


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/150@105.186.192.222:5060) State Change CS_REPORTING -> CS_DESTROY


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_session.c:1753 Session 8 (sofia/internal/150@105.186.192.222:5060) Locked, Waiting on external entities


2022-03-12 14:29:01.007787 97.40% [NOTICE] switch_core_session.c:1771 Session 8 (sofia/internal/150@105.186.192.222:5060) Ended


2022-03-12 14:29:01.007787 97.40% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/150@105.186.192.222:5060 [CS_DESTROY]


2022-03-12 14:29:01.007787 97.40% [DEBUG] mod_sofia.c:613 Responding to INVITE with: 480


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/150@105.186.192.222:5060) Running State Change CS_DESTROY (Cur 2 Tot 9)


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/150@105.186.192.222:5060) State DESTROY


2022-03-12 14:29:01.007787 97.40% [DEBUG] mod_sofia.c:379 sofia/internal/150@105.186.192.222:5060 SOFIA DESTROY


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:175 sofia/internal/150@105.186.192.222:5060 Standard DESTROY


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:59 sofia/external/0827869006@192.168.30.14 Standard HANGUP, cause: NORMAL_CLEARING


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:846 (sofia/external/0827869006@192.168.30.14) State HANGUP going to sleep


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:616 (sofia/external/0827869006@192.168.30.14) State Change CS_HANGUP -> CS_REPORTING


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/external/0827869006@192.168.30.14) Running State Change CS_REPORTING (Cur 2 Tot 9)


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:932 (sofia/external/0827869006@192.168.30.14) State REPORTING


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/150@105.186.192.222:5060) State DESTROY going to sleep


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/151@105.186.192.222:1024) Running State Change CS_HANGUP (Cur 2 Tot 9)


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/151@105.186.192.222:1024) Callstate Change RINGING -> HANGUP


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/151@105.186.192.222:1024) State HANGUP


2022-03-12 14:29:01.007787 97.40% [DEBUG] mod_sofia.c:468 Channel sofia/internal/151@105.186.192.222:1024 hanging up, cause: LOSE_RACE


2022-03-12 14:29:01.007787 97.40% [DEBUG] mod_sofia.c:536 Sending CANCEL to sofia/internal/151@105.186.192.222:1024


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:59 sofia/internal/151@105.186.192.222:1024 Standard HANGUP, cause: LOSE_RACE


2022-03-12 14:29:01.007787 97.40% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/151@105.186.192.222:1024) State HANGUP going to sleep
 
T

thebitguru

New Member
Dec 16, 2018
11
0
1
Hi, Paul,

What are the users encountering when this happens?

Unfortunately, I don't have a solution for your issue, but I am troubleshooting a similar issue and had related question that might be meaningful.

Does anyone know what the percentage shown on many lines is (97.40%)?

Thanks
 
P

paulwollner

New Member
Oct 16, 2020
4
0
1
47
thebitguru said:
Hi, Paul,

What are the users encountering when this happens?

Unfortunately, I don't have a solution for your issue, but I am troubleshooting a similar issue and had related question that might be meaningful.

Does anyone know what the percentage shown on many lines is (97.40%)?

Thanks
Click to expand...
Hello there,

I have absolutely zero idea why my issue cropped up. I eventually did an update which left me with the same results. I did however have some errors in lua: /usr/share/freeswitch/scripts/app/ring_groups/index.lua

The line: if (tonumber(row.destination_timeout) > 0) then
complained that desitination_timeout was not a number.

I had coded the value to 30 as a temporary workaround.

Later I did another schema update as well as a permissions update and behaviour returned to normal.

I still have no idea why the issue happened in the first place. But right now all is working.

I do not understand the percentage value in the logs either. I will do some investigations.

Regards
 
Status
Not open for further replies.
Top Bottom