IVR message being skipped straight to the IVR exit action

[Jimbob]

I should have left FusionPBX alone when I had it working!

I have been playing around and now the IVR message no longer plays when I call the destination number.

When the external number is dialed it just rings and then transfers to the ring group, which I have set as the exit action for the IVR.

If I call the IVR extension from internal extension the IVR work as expected.

Would anyone have an idea what might be preventing the IVR message from playing?

The log message is as follows:

2024-01-15 19:40:58.479577 97.17% [DEBUG] switch_channel.c:3912 (sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk) Callstate Change EARLY -> ACTIVE
EXECUTE [depth=0] sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk sleep(1000)
EXECUTE [depth=0] sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk set(hangup_after_bridge=true)
2024-01-15 19:40:59.479577 96.63% [DEBUG] mod_dptools.c:1671 SET sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/external/XXXXXXXXREDACTEDXXXXXXXXXsipconnect.sipgate.co.uk set(ringback=%(400,200,400,450);%(400,2000,400,450))
2024-01-15 19:40:59.479577 96.63% [DEBUG] mod_dptools.c:1671 SET sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk [ringback]=[%(400,200,400,450);%(400,2000,400,450)]
EXECUTE [depth=0] sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk set(transfer_ringback=%(400,200,400,450);%(400,2000,400,450))
2024-01-15 19:40:59.479577 96.63% [DEBUG] mod_dptools.c:1671 SET sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk [transfer_ringback]=[%(400,200,400,450);%(400,2000,400,450)]
EXECUTE [depth=0] sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk set(ivr_menu_uuid=06ef3548-cfa9-400d-8c7e-521f61bc3d39)
2024-01-15 19:40:59.479577 96.63% [DEBUG] mod_dptools.c:1671 SET sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk [ivr_menu_uuid]=[06ef3548-cfa9-400d-8c7e-521f61bc3d39]
EXECUTE [depth=0] sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk ivr(06ef3548-cfa9-400d-8c7e-521f61bc3d39)
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:746 switch_ivr_menu_stack_xml_add binding 'menu-exit'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:746 switch_ivr_menu_stack_xml_add binding 'menu-sub'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:746 switch_ivr_menu_stack_xml_add binding 'menu-exec-app'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:746 switch_ivr_menu_stack_xml_add binding 'menu-play-sound'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:746 switch_ivr_menu_stack_xml_add binding 'menu-back'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:746 switch_ivr_menu_stack_xml_add binding 'menu-top'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:883 building menu '06ef3548-cfa9-400d-8c7e-521f61bc3d39'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:968 binding menu action 'menu-exec-app' to '1'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:968 binding menu action 'menu-exec-app' to '/^(\d{2,11})$/'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:968 binding menu action 'menu-exec-app' to '/^(\d{2,11})$/'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:968 binding menu action 'menu-exec-app' to '/^(\d{2,11})$/'
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_menu.c:486 Executing IVR menu 06ef3548-cfa9-400d-8c7e-521f61bc3d39
2024-01-15 19:40:59.499572 96.63% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@16000hz 1 channels 20ms
2024-01-15 19:41:08.519608 96.07% [DEBUG] switch_ivr_play_say.c:2010 done playing file /var/lib/freeswitch/recordings/tel.domain.com/IVR-Domain-16000.wav
2024-01-15 19:41:08.519608 96.07% [DEBUG] switch_ivr_menu.c:378 waiting for 5/5 digits t/o 1000
2024-01-15 19:41:09.519625 96.00% [DEBUG] switch_ivr_menu.c:425 digits ''
2024-01-15 19:41:09.519625 96.00% [DEBUG] switch_ivr_menu.c:516 Maximum timeouts
2024-01-15 19:41:09.519625 96.00% [DEBUG] switch_ivr_menu.c:676 exit-sound '(null)'
EXECUTE [depth=0] sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk transfer(6000 XML tel.domain.com)

Any thoughts would be appreciated?

 

[Jimbob]

I am struggling to make any progress with this.

The IVR plays intermittently at the moment. I get the following extra lines in the log file when the IVR does play:

2024-01-21 17:08:14.011048 93.53% [DEBUG] switch_ivr_play_say.c:1561 Codec Activated L16@16000hz 1 channels 20ms
-----extra logs start-----
2024-01-21 17:08:16.531040 93.10% [DEBUG] sofia.c:7493 Channel sofia/external/XXXXXXXXREDACTEDXXXXXXXXX@sipconnect.sipgate.co.uk entering state [ready][200]
2024-01-21 17:08:17.011053 93.10% [DEBUG] switch_rtp.c:7503 Correct audio ip/port confirmed.
2024-01-21 17:08:17.031037 93.10% [DEBUG] switch_rtp.c:1774 rtcp_stats_init: audio ssrc[1800219119] base_seq[20179]
2024-01-21 17:08:21.531090 93.70% [DEBUG] switch_rtp.c:6933 Correct audio RTCP ip/port confirmed.
2024-01-21 17:08:23.051029 93.67% [DEBUG] switch_ivr_play_say.c:2010 done playing file /var/lib/freeswitch/recordings/tel.domain.com/IVR-Domain-16000.wav
-----extra logs end-----
2024-01-21 17:08:23.051029 93.67% [DEBUG] switch_ivr_menu.c:378 waiting for 5/5 digits t/o 1000

It looks to me like the audio port and ip are unable to be confirmed on some occasions. I am not sure how to trouble shoot this at the moment though.