One Announcement after another Announcement causes unusual call flow

configuration
freepbx
Tags: #<Tag:0x00007f7026f599f0> #<Tag:0x00007f7026f59888>

#1

I am running FreePBX 15.0.16.75 with Asterisk 17.7.0
Some commercial modules, no custom modules.
32GB memory, 512GB disk, 64bit Intel
Announcements 15.0.3.11

Issue (see following tests)

Test 1 – Works perfectly.
Call passed to Announcement 1 from Inbound route
Announcement 1 completed and destination to IVR works perfectly.

Test 2 – fails
Call passed to Announcement 1 from Inbound route
Announcement 1 completed and destination to Announcement 2 works perfectly.
Announcement 2 plays and then several seconds silence. The destination is the same IVR as used in Test 1.
I then hear a Whisper sound bite that I created for a queue; twice.
Then several seconds silence. The call then goes to the IVR and after that all proceeds correctly.

I know that a solution is to join the sound files and use only 1 Announcement, but this methodology will assist with later maintenance. Additionally it may point to either a bug or a stuff up by me.

Any assistance appreciated.
Regards

Part of the log follows:
SIP has been changed to “999999”
Some comments added for clarity (failed test).

56[2020-10-01 17:59:45] VERBOSE[4271][C-0000001f] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
57[2020-10-01 17:59:45] VERBOSE[4271][C-0000001f] res_agi.c: <SIP/9999999-0000001e>AGI Script sangomacrm.agi completed, returning 0
58[2020-10-01 17:59:45] VERBOSE[4271][C-0000001f] pbx.c: Executing [9999999@from-trunk:24] ExecIf(“SIP/9999999-0000001e”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
59[2020-10-01 17:59:45] VERBOSE[4271][C-0000001f] pbx.c: Executing [9999999@from-trunk:25] Goto(“SIP/9999999-0000001e”, “app-announcement-2,s,1”) in new stack
60[2020-10-01 17:59:45] VERBOSE[4271][C-0000001f] pbx_builtins.c: Goto (app-announcement-2,s,1)
61[2020-10-01 17:59:45] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-2:1] GotoIf(“SIP/9999999-0000001e”, “0?begin”) in new stack
62[2020-10-01 17:59:45] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-2:2] Answer(“SIP/9999999-0000001e”, “”) in new stack
63[2020-10-01 17:59:46] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-2:3] Wait(“SIP/9999999-0000001e”, “1”) in new stack
64[2020-10-01 17:59:47] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-2:4] NoOp(“SIP/9999999-0000001e”, “Playing announcement Thankyou for calling”) in new stack
65[2020-10-01 17:59:47] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-2:5] Playback(“SIP/9999999-0000001e”, “custom/thankyou_for_calling,noanswer”) in new stack
66[2020-10-01 17:59:47] VERBOSE[4271][C-0000001f] file.c: <SIP/9999999-0000001e> Playing ‘custom/thankyou_for_calling.slin’ (language ‘en_AU’)
67[2020-10-01 17:59:49] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-2:6] Goto(“SIP/9999999-0000001e”, “app-announcement-18,s,1”) in new stack
68[2020-10-01 17:59:49] VERBOSE[4271][C-0000001f] pbx_builtins.c: Goto (app-announcement-18,s,1)
69[2020-10-01 17:59:49] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-18:1] GotoIf(“SIP/9999999-0000001e”, “1?begin”) in new stack
70[2020-10-01 17:59:49] VERBOSE[4271][C-0000001f] pbx_builtins.c: Goto (app-announcement-18,s,4)
71[2020-10-01 17:59:49] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-18:4] NoOp(“SIP/9999999-0000001e”, “Playing announcement COVID - changed call procedures”) in new stack
72[2020-10-01 17:59:49] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-18:5] Playback(“SIP/9999999-0000001e”, “custom/COVID_changes,noanswer”) in new stack
73[2020-10-01 17:59:49] VERBOSE[4271][C-0000001f] file.c: <SIP/9999999-0000001e> Playing ‘custom/COVID_changes.slin’ (language ‘en_AU’)
74[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@app-announcement-18:6] Goto(“SIP/9999999-0000001e”, “ivr-2,s,1”) in new stack

At this time I hear the sound bite for a Whisper in 1 one of my queues which plays twice with a couple of seconds in between. There in no logging of this occurring!
After that the IVR proceeds correctly.

75[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx_builtins.c: Goto (ivr-2,s,1)
76[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:1] Set(“SIP/9999999-0000001e”, “TIMEOUT_LOOPCOUNT=0”) in new stack
77[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:2] Set(“SIP/9999999-0000001e”, “INVALID_LOOPCOUNT=0”) in new stack
78[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:3] Set(“SIP/9999999-0000001e”, “_IVR_CONTEXT_ivr-2=”) in new stack
79[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:4] Set(“SIP/9999999-0000001e”, “_IVR_CONTEXT=ivr-2”) in new stack
80[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:5] Set(“SIP/9999999-0000001e”, “__IVR_RETVM=”) in new stack
81[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:6] GotoIf(“SIP/9999999-0000001e”, “1?skip”) in new stack
82[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx_builtins.c: Goto (ivr-2,s,8)
83[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:8] Set(“SIP/9999999-0000001e”, “IVR_MSG=custom/Select_from_options&custom/Press_1_car_park&custom/Press_2_to_pay&custom/Press_3_appointment&custom/Press_4_other_reason&custom/Press_9_to_hear_again”) in new stack
84[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:9] Set(“SIP/9999999-0000001e”, “DIGITS=”) in new stack
85[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:10] Set(“SIP/9999999-0000001e”, “IVREXT=”) in new stack
86[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:11] Set(“SIP/9999999-0000001e”, “NODEFOUND=0”) in new stack
87[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:12] Set(“SIP/9999999-0000001e”, “LOCALEXT=0”) in new stack
88[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:13] Set(“SIP/9999999-0000001e”, “DIREXT=0”) in new stack
89[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:14] ExecIf(“SIP/9999999-0000001e”, “0?Set(DIGITS=)”) in new stack
90[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:15] While(“SIP/9999999-0000001e”, "1 ") in new stack
91[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] pbx.c: Executing [s@ivr-2:16] Read(“SIP/9999999-0000001e”, “IVREXT,custom/Select_from_options&custom/Press_1_car_park&custom/Press_2_to_pay&custom/Press_3_appointment&custom/Press_4_other_reason&custom/Press_9_to_hear_again,1,0,10”) in new stack
92[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] app_read.c: Accepting a maximum of 1 digits.
93[2020-10-01 18:00:16] VERBOSE[4271][C-0000001f] file.c: <SIP/9999999-0000001e> Playing ‘custom/Select_from_options.alaw’ (language ‘en_AU’)
94[2020-10-01 18:00:19] VERBOSE[4271][C-0000001f] file.c: <SIP/9999999-0000001e> Playing ‘custom/Press_1_car_park.alaw’ (language ‘en_AU’)
95[2020-10-01 18:00:22] VERBOSE[4271][C-0000001f] file.c: <SIP/9999999-0000001e> Playing ‘custom/Press_2_to_pay.alaw’ (language ‘en_AU’)
96[2020-10-01 18:00:25] VERBOSE[4271][C-0000001f] file.c: <SIP/9999999-0000001e> Playing ‘custom/Press_3_appointment.alaw’ (language ‘en_AU’)
97[2020-10-01 18:00:27] VERBOSE[4271][C-0000001f] file.c: <SIP/9999999-0000001e> Playing ‘custom/Press_4_other_reason.alaw’ (language ‘en_AU’)
98[2020-10-01 18:00:31] VERBOSE[4271][C-0000001f] file.c: <SIP/9999999-0000001e> Playing ‘custom/Press_9_to_hear_again.alaw’ (language ‘en_AU’)


#2

Found the issue. My fault, an inadvertently concatenated sound file. Sorry.