Follow me issue with external number

[bassem.elsayed]

Hello All,
i have an issue when activating follow me with external number. the case is:
main extension: 1099
Follow me destination 1 : 1099, Delay=0, timeout = 60
Follow me destination 2 : 17864758773, Delay=30, timeout = 30

when dialing from 1011 to 1099, both 1099 and 17864758773 are ringing in the same time. delay has no effect. check below log:
[
10 : 50 : 57.405902 [NOTICE] mod_sofia.c : 2508 Pre-Answer sofia/internal/1011@xxxxxxx.com!
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 3482 (sofia/internal/1011@xxxxxxx.com) Callstate Change RINGING -> EARLY
10 : 50 : 57.405902 [NOTICE] switch_channel.c : 1104 New Channel loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or [ ]
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 158 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or setup codec G722/8000/20
10 : 50 : 57.405902 [NOTICE] switch_channel.c : 1102 Rename Channel loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or->loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or [ ]
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 1176 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State Change CS_NEW -> CS_INIT
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 603 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL KILL
10 : 50 : 57.405902 [DEBUG] sofia.c : 7291 Channel sofia/internal/1011@xxxxxxx.com entering state [early][183]
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 584 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) Running State Change CS_INIT (Cur 3 Tot 22537)
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 627 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State INIT
10 : 50 : 57.405902 [NOTICE] switch_channel.c : 1104 New Channel loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or [ ]
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 158 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or setup codec G722/8000/20
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 276 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State Change CS_NEW -> CS_INIT
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 603 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL KILL
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 364 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State Change CS_INIT -> CS_ROUTING
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 603 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL KILL
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 627 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State INIT going to sleep
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 584 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) Running State Change CS_INIT (Cur 4 Tot 22538)
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 627 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State INIT
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 364 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State Change CS_INIT -> CS_ROUTING
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 603 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL KILL
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 627 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State INIT going to sleep
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 584 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) Running State Change CS_ROUTING (Cur 4 Tot 22538)
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 643 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State ROUTING
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 396 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL ROUTING
10 : 50 : 57.405902 [DEBUG] switch_ivr_originate.c : 67 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State Change CS_ROUTING -> CS_CONSUME_MEDIA
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 603 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL KILL
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 643 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State ROUTING going to sleep
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 584 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) Running State Change CS_CONSUME_MEDIA (Cur 4 Tot 22538)
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 584 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) Running State Change CS_ROUTING (Cur 4 Tot 22538)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 2249 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) Callstate Change DOWN -> RINGING
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 662 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State CONSUME_MEDIA
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 663 CHANNEL CONSUME_MEDIA
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 662 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State CONSUME_MEDIA going to sleep
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 643 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State ROUTING
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 396 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL ROUTING
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 236 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or Standard ROUTING
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 286 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State Change CS_ROUTING -> CS_EXECUTE
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 603 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL KILL
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 643 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State ROUTING going to sleep
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 584 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) Running State Change CS_EXECUTE (Cur 4 Tot 22538)
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 650 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State EXECUTE
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 438 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL EXECUTE
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 328 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or Standard EXECUTE
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(presence_id=1099@xxxxxxx.com)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [presence_id]=[1099@xxxxxxx.com]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(origination_caller_id_number=)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [origination_caller_id_number]=[UNDEF]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(effective_caller_id_number=)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [effective_caller_id_number]=[UNDEF]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(origination_caller_id_name=)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [origination_caller_id_name]=[UNDEF]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(effective_caller_id_name=)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [effective_caller_id_name]=[UNDEF]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(sip_h_X-accountcode=)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [sip_h_X-accountcode]=[UNDEF]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(fail_on_single_reject=USER_BUSY)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [fail_on_single_reject]=[USER_BUSY]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(instant_ringback=true)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [instant_ringback]=[true]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(ignore_early_media=true)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [ignore_early_media]=[true]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(domain_uuid=3d63d0b0-c83a-4659-8de5-6a8e336d0996)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [domain_uuid]=[3d63d0b0-c83a-4659-8de5-6a8e336d0996]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(sip_invite_domain=xxxxxxx.com)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [sip_invite_domain]=[xxxxxxx.com]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(domain_name=xxxxxxx.com)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [domain_name]=[xxxxxxx.com]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(extension_uuid=44b9c761-2a5f-41a4-81c6-28305bffc033)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [extension_uuid]=[44b9c761-2a5f-41a4-81c6-28305bffc033]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(leg_delay_start=30)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [leg_delay_start]=[30]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(originate_delay_start=30)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [originate_delay_start]=[30]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(sleep=30000)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [sleep]=[30000]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(leg_timeout=30)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [leg_timeout]=[30]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or export(is_follow_me_loopback=true)
10 : 50 : 57.405902 [DEBUG] switch_channel.c : 1296 EXPORT (export_vars) [is_follow_me_loopback]=[true]
EXECUTE loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or transfer(17864758773)
10 : 50 : 57.405902 [DEBUG] switch_ivr.c : 2207 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State Change CS_EXECUTE -> CS_ROUTING
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 603 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL KILL
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 603 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL KILL
10 : 50 : 57.405902 [NOTICE] switch_ivr.c : 2214 Transfer loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or to XML[17864758773@xxxxxxx.com]
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 650 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State EXECUTE going to sleep
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 584 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) Running State Change CS_ROUTING (Cur 4 Tot 22538)
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 643 (loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or) State ROUTING
10 : 50 : 57.405902 [DEBUG] mod_loopback.c : 396 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or CHANNEL ROUTING
10 : 50 : 57.405902 [DEBUG] switch_core_state_machine.c : 236 loopback/export : presence_id=1099@xxxxxxx.com,export : origination_caller_id_number=,export : effective_caller_id_number=,export : or Standard ROUTING
10 : 50 : 57.405902 [INFO] mod_dialplan_xml.c : 637 Processing 1011 <1011>->17864758773 in context xxxxxxx.com
]

kindly advise.
Thank you.

 

[Kenny Riley]

What version of FusionPBX are you using?

 

[bassem.elsayed]

Version 4.4.5

 

[Kenny Riley]

We're on 4.5 and the follow me delay seems to be working.. Maybe someone running 4.4 can chime in here because last I recall the inner workings of follow me on 4.4 vs 4.5 are night and day.. Follow me has had its slew of issues so I wouldn't be surprised if that's broken.

 

[bassem.elsayed]

what is 4.5. as i know the latest stable release is 4.4.
where did you get 4.5?

 

[Kenny Riley]

4.4 is the latest Stable Branch. 4.5 is the Master Branch.

 

[bassem.elsayed]

can you please send us sample dial string from 4.5 with first destination is extension and second destination is external number.

 

[Kenny Riley]

I'd be happy to, but we have over 400 endpoints on our system and it would be impossible for me to grab the fs_cli output of the call without being inundated with logs from various other calls happening on the system at the same time.

I'm not sure of how to isolate the logs to a specific call but I'm more than happy to if you want to tell me how. I did however do a test and confirm that the follow me delay is working on our system running 4.5

 

[bassem.elsayed]

i don't need the log. just from fusionpbx -> accounts -> extensions -> xxx -> advanced -> dialstring
for xxx extension has a follow me with first destination is extension and second destination is external number.

 

[Kenny Riley]

Ah of course -- here you go! I masked the real external number and replaced it with 214-970-1234 FYI

{ignore_early_media=true}[presence_id=101@XXXXXX.net,fail_on_single_reject=USER_BUSY,sip_h_X-accountcode=${accountcode},instant_ringback=true,ignore_early_media=true,domain_uuid=ba8076f6-b6cc-4fbd-a8c5-42e5f79ae8a6,sip_invite_domain=XXXXXX.net,domain_name=XXXXXX.net,domain=XXXXXX.net,extension_uuid=315eed4d-e586-4c11-8510-666b16447519,leg_delay_start=0,originate_delay_start=0,leg_timeout=30]${sofia_contact(*/101@XXXXXX.net)},loopback/export:presence_id=101@XXXXXX.net\,export:effective_caller_id_number=${cond(${from_user_exists} == true ?  : ${effective_caller_id_number})}\,export:effective_caller_id_name=${cond(${from_user_exists} == true ?  : ${effective_caller_id_name})}\,export:sip_h_X-accountcode=${accountcode}\,export:fail_on_single_reject=USER_BUSY\,export:instant_ringback=true\,export:ignore_early_media=true\,export:domain_uuid=ba8076f6-b6cc-4fbd-a8c5-42e5f79ae8a6\,export:sip_invite_domain=XXXXXX.net\,export:domain_name=XXXXXX.net\,export:extension_uuid=315eed4d-e586-4c11-8510-666b16447519\,export:leg_delay_start=30\,export:originate_delay_start=30\,export:sleep=30000\,export:leg_timeout=30\,export:is_follow_me_loopback=true\,transfer:2149701234/XXXXXX.net/inline

 

[bassem.elsayed]

we tried it. same issue. both destinations ringing at the same time.

 

[gflow]

we tried it. same issue. both destinations ringing at the same time.

Did you end up fixing this issue, im having the same problem with the same version of fusion as you.