10-15 second pause before the IVR announcement plays

flavigne · February 12, 2025, 9:22pm

We just recently updated our Sound Recordings for our main IVR and now the first announcement only starts playing after 10-15 seconds.

Looking at the Asterisk Logs we can see the SIP connection is established the moment call is made but still the announcement is delayed. The IVR interactions behave normally once it gets going.

We already tried changing the following settings in the IVR:

Enable Direct Dial = Disabled
Force Strict Dial Timeout = No Legacy
Timeout = 3

Are current DNS are set to:

127.0.0.1
8.8.8.8

We are currently running Asterisk 20.5.2, all modules have been updated to the latest versions and the PBX has been rebooted several times.

Anyone run into this issue?

david55 · February 12, 2025, 9:29pm

There isn’t enough information to be clear what the situation is here, but I wonder if you are the describing the effect you get when a router needs outgoing traffic, to build rules for incoming traffic, or you don’t have a correct media address, in a NAT situation, so the remote side need to receive media before it can learn the correct address to which to send its media.

flavigne · February 12, 2025, 10:19pm

This PBX has been running for years without any issues and we never had any issues until today after updating the System recordings for the IVR. We replaced and uploaded 2 new WAV files to the System Recordings, Saved & Applied the new settings.

Inbound Route > Time Conditions > Time Group > IVR > Day-IVR or Night-IVR

flavigne · February 12, 2025, 10:39pm

Here’s a call log:

[2025-02-12 17:24:14] VERBOSE[3998][C-00000027] netsock2.c: Using SIP RTP TOS bits 184
[2025-02-12 17:24:14] VERBOSE[3998][C-00000027] netsock2.c: Using SIP RTP CoS mark 5
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [5551234567@from-trunk:1] NoOp("SIP/voip.ms-00000026", "Catch-All DID Match - Found 5551234567 - You probably want a DID for this.") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [5551234567@from-trunk:2] Set("SIP/voip.ms-00000026", "__FROM_DID=5551234567") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [5551234567@from-trunk:3] Goto("SIP/voip.ms-00000026", "ext-did,s,1") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx_builtins.c: Goto (ext-did,s,1)
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:1] Set("SIP/voip.ms-00000026", "__DIRECTION=INBOUND") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:2] Gosub("SIP/voip.ms-00000026", "sub-record-check,s,1(in,s,dontcare)") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/voip.ms-00000026", "0?initialized") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:2] Set("SIP/voip.ms-00000026", "__REC_STATUS=INITIALIZED") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:3] Set("SIP/voip.ms-00000026", "NOW=1739399054") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:4] Set("SIP/voip.ms-00000026", "__DAY=12") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:5] Set("SIP/voip.ms-00000026", "__MONTH=02") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:6] Set("SIP/voip.ms-00000026", "__YEAR=2025") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:7] Set("SIP/voip.ms-00000026", "__TIMESTR=20250212-172414") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:8] Set("SIP/voip.ms-00000026", "__FROMEXTEN=unknown") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:9] Set("SIP/voip.ms-00000026", "__MON_FMT=wav") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/voip.ms-00000026", "Recordings initialized") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/voip.ms-00000026", "0?Set(ARG3=dontcare)") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:12] Set("SIP/voip.ms-00000026", "REC_POLICY_MODE_SAVE=") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/voip.ms-00000026", "0?Set(REC_STATUS=NO)") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/voip.ms-00000026", "2?checkaction") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx_builtins.c: Goto (sub-record-check,s,17)
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/voip.ms-00000026", "1?sub-record-check,in,1") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx_builtins.c: Goto (sub-record-check,in,1)
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/voip.ms-00000026", "Inbound Recording Check to s") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [in@sub-record-check:2] Set("SIP/voip.ms-00000026", "FROMEXTEN=unknown") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/voip.ms-00000026", "10?Set(FROMEXTEN=8881234567)") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/voip.ms-00000026", "recordcheck,1(dontcare,in,s)") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/voip.ms-00000026", "Starting recording check against dontcare") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/voip.ms-00000026", "dontcare") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/voip.ms-00000026", "") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [in@sub-record-check:5] Return("SIP/voip.ms-00000026", "") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:3] Set("SIP/voip.ms-00000026", "CHANNEL(tonezone)=us") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:4] ExecIf("SIP/voip.ms-00000026", "0?Set(__FROM_DID=s)") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:5] Set("SIP/voip.ms-00000026", "returnhere=1") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:6] Gosub("SIP/voip.ms-00000026", "app-blacklist-check,s,1()") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/voip.ms-00000026", "0?blacklisted") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/voip.ms-00000026", "CALLED_BLACKLIST=1") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/voip.ms-00000026", "") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:7] Set("SIP/voip.ms-00000026", "CDR(did)=5551234567") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:8] GotoIf("SIP/voip.ms-00000026", "0?") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:9] ExecIf("SIP/voip.ms-00000026", "0 ?Set(CALLERID(name)=8881234567)") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:10] Set("SIP/voip.ms-00000026", "__MOHCLASS=") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:11] Set("SIP/voip.ms-00000026", "__REVERSAL_REJECT=FALSE") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:12] GotoIf("SIP/voip.ms-00000026", "1?post-reverse-charge") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx_builtins.c: Goto (ext-did,s,14)
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:14] NoOp("SIP/voip.ms-00000026", "") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:15] Set("SIP/voip.ms-00000026", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:16] Set("SIP/voip.ms-00000026", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:17] Set("SIP/voip.ms-00000026", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:18] Set("SIP/voip.ms-00000026", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:19] NoOp("SIP/voip.ms-00000026", "CallerID Entry Point") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:20] Set("SIP/voip.ms-00000026", "FAX_DEST=ext-fax^11^1") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:21] Set("SIP/voip.ms-00000026", "FAXOPT(faxdetect)=yes") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:22] Answer("SIP/voip.ms-00000026", "") in new stack
[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:23] Wait("SIP/voip.ms-00000026", "4") in new stack
[2025-02-12 17:24:18] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:24] Set("SIP/voip.ms-00000026", "FAX_DEST=ext-fax^11^1") in new stack
[2025-02-12 17:24:18] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:25] Set("SIP/voip.ms-00000026", "FAXOPT(faxdetect)=yes") in new stack
[2025-02-12 17:24:18] WARNING[28698][C-00000027] res_fax.c: Attempt to attach a FAX detect on channel (SIP/voip.ms-00000026) with FAX detect already running.
[2025-02-12 17:24:18] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:26] Answer("SIP/voip.ms-00000026", "") in new stack
[2025-02-12 17:24:18] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:27] Wait("SIP/voip.ms-00000026", "4") in new stack
[2025-02-12 17:24:22] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:28] Set("SIP/voip.ms-00000026", "FAX_DEST=ext-fax^11^1") in new stack
[2025-02-12 17:24:22] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:29] Set("SIP/voip.ms-00000026", "FAXOPT(faxdetect)=yes") in new stack
[2025-02-12 17:24:22] WARNING[28698][C-00000027] res_fax.c: Attempt to attach a FAX detect on channel (SIP/voip.ms-00000026) with FAX detect already running.
[2025-02-12 17:24:22] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:30] Answer("SIP/voip.ms-00000026", "") in new stack
[2025-02-12 17:24:22] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:31] Wait("SIP/voip.ms-00000026", "4") in new stack
[2025-02-12 17:24:26] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:32] Set("SIP/voip.ms-00000026", "__CRM_DIRECTION=INBOUND") in new stack
[2025-02-12 17:24:26] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:33] Set("SIP/voip.ms-00000026", "__CRM_SOURCE=8881234567") in new stack
[2025-02-12 17:24:26] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:34] Set("SIP/voip.ms-00000026", "__CRM_LINKEDID=1739399054.127") in new stack
[2025-02-12 17:24:26] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:35] AGI("SIP/voip.ms-00000026", "sangomacrm.agi,true") in new stack
[2025-02-12 17:24:26] VERBOSE[28698][C-00000027] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] res_agi.c: sangomacrm.agi,true: LINKEDID: 1739399054.127
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] res_agi.c: sangomacrm.agi,true: SOURCE: 8881234567
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] res_agi.c: sangomacrm.agi,true: DESTINATION: 
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] res_agi.c: sangomacrm.agi,true: DIRECTION: INBOUND
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] res_agi.c: sangomacrm.agi,true: EXTTOCALL: 
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] res_agi.c: sangomacrm.agi,true: START
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] res_agi.c: sangomacrm.agi,true: SCRIPT: php /var/www/html/admin/modules/sangomacrm/importOne.php 'eyJ1dWlkIjoiMTczOTM5OTA1NC4xMjciLCJzb3VyY2UiOiI1MTQ5NjYyMDY4IiwiZGVzdGluYXRpb24iOiIiLCJkaXJlY3Rpb24iOiJJTkJPVU5EIiwidHlwZSI6IlNUQVJUIiwienVsdV9yYXdfdHlwZSI6IiIsInp1bHVfdHlwZSI6IiIsInp1bHVfdXJsIjoiIiwiZXh0dG9jYWxsIjoiIiwiY251bSI6IjUxNDk2NjIwNjgiLCJjbmFtIjoiS3lvIENvbnNlaWwgNTE0OTY2MjA2OCIsImNhbGxwb3AiOnRydWUsInZvaWNlbWFpbCI6IiIsImZyb21fZGlkIjoiNTE0OTkwMTA5MSJ9' > /dev/null 2>&1 &
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] res_agi.c: <SIP/voip.ms-00000026>AGI Script sangomacrm.agi completed, returning 0
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:36] ExecIf("SIP/voip.ms-00000026", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:37] Goto("SIP/voip.ms-00000026", "timeconditions,1,1") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx_builtins.c: Goto (timeconditions,1,1)
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:1] Set("SIP/voip.ms-00000026", "DB(TC/1/INUSESTATE)=INUSE") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:2] Set("SIP/voip.ms-00000026", "DB(TC/1/NOT_INUSESTATE)=NOT_INUSE") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:3] NoOp("SIP/voip.ms-00000026", "TIMENOW: 17:24,Wed,12,Feb,America/Toronto") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:4] NoOp("SIP/voip.ms-00000026", "TIMEMATCHED: FALSE") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:5] GotoIfTime("SIP/voip.ms-00000026", "09:00-17:00,mon-fri,*,*,America/Toronto?truestate") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:6] GotoIf("SIP/voip.ms-00000026", "0?truegoto") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:7] ExecIf("SIP/voip.ms-00000026", "0?Set(DB(TC/1)=)") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:8] Set("SIP/voip.ms-00000026", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:9] ExecIf("SIP/voip.ms-00000026", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [1@timeconditions:10] GotoIf("SIP/voip.ms-00000026", "1?ivr-2,s,1") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx_builtins.c: Goto (ivr-2,s,1)
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:1] Set("SIP/voip.ms-00000026", "TIMEOUT_LOOPCOUNT=0") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:2] Set("SIP/voip.ms-00000026", "INVALID_LOOPCOUNT=0") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:3] Set("SIP/voip.ms-00000026", "_IVR_CONTEXT_ivr-2=") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:4] Set("SIP/voip.ms-00000026", "_IVR_CONTEXT=ivr-2") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:5] Set("SIP/voip.ms-00000026", "__IVR_RETVM=") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:6] GotoIf("SIP/voip.ms-00000026", "1?skip") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx_builtins.c: Goto (ivr-2,s,8)
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:8] Set("SIP/voip.ms-00000026", "IVR_MSG=custom/EN_FR_Night_20250212") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:9] Set("SIP/voip.ms-00000026", "TIMEOUT(digit)=3") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] func_timeout.c: Digit timeout set to 3.000
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ivr-2:10] ExecIf("SIP/voip.ms-00000026", "1?Background(custom/EN_FR_Night_20250212)") in new stack
[2025-02-12 17:24:27] VERBOSE[28698][C-00000027] file.c: <SIP/voip.ms-00000026> Playing 'custom/EN_FR_Night_20250212.slin' (language 'fr')
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Spawn extension (ivr-2, s, 10) exited non-zero on 'SIP/voip.ms-00000026'
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Executing [h@ivr-2:1] Hangup("SIP/voip.ms-00000026", "") in new stack
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Spawn extension (ivr-2, h, 1) exited non-zero on 'SIP/voip.ms-00000026'
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] app_stack.c: SIP/voip.ms-00000026 Internal Gosub(crm-hangup,s,1) start
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Executing [s@crm-hangup:1] NoOp("SIP/voip.ms-00000026", "Sending Hangup to CRM") in new stack
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Executing [s@crm-hangup:2] NoOp("SIP/voip.ms-00000026", "HANGUP CAUSE: 16") in new stack
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Executing [s@crm-hangup:3] ExecIf("SIP/voip.ms-00000026", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Executing [s@crm-hangup:4] NoOp("SIP/voip.ms-00000026", "MASTER CHANNEL: 1739399054.127 = 1739399054.127") in new stack
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Executing [s@crm-hangup:5] GotoIf("SIP/voip.ms-00000026", "0?return") in new stack
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Executing [s@crm-hangup:6] Set("SIP/voip.ms-00000026", "__CRM_HANGUP=1") in new stack
[2025-02-12 17:24:34] VERBOSE[28698][C-00000027] pbx.c: Executing [s@crm-hangup:7] AGI("SIP/voip.ms-00000026", "sangomacrm.agi") in new stack

slobera · February 13, 2025, 1:27pm

Call starts at 17:24:14 and you Wait for 4 secs

[2025-02-12 17:24:14] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:23] Wait("SIP/voip.ms-00000026", "4") in new stack

Then you have another Wait for 4 secs at 17:24:18

[2025-02-12 17:24:18] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:27] Wait("SIP/voip.ms-00000026", "4") in new stack

And then another one at 17:24:22

[2025-02-12 17:24:22] VERBOSE[28698][C-00000027] pbx.c: Executing [s@ext-did:31] Wait("SIP/voip.ms-00000026", "4") in new stack

Finally the call goes to the IVR at at 17:24:27, and then the EN_FR_Night_20250212 sounds it’s at the same time.

You should take a look at your fax detection or your wait time inside your inbound route.

flavigne · February 13, 2025, 2:57pm

Yes! I adjusted the wait time and disabled the Detect Fax on 2 Inbound routes that didn’t require this option. Now the IVR starts after 3 seconds. Thank you very much!

shahin · February 13, 2025, 3:27pm

Good catch Fax detection delay…

system · February 20, 2025, 3:27pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.