Long pause after voicemail greeting with VMX locator [REPRISE ;-) ] 2 BUGS CONFIRMED

I understand this might be an oldish issue - but for me it was not a problem - and now that it is it doesn’t seem to be fixed. Version 13 - all recent updates applied. If an extension has VMX Locator enabled (to allow the caller to escape the voicemail to reception or the support queue) there is a LONG delay of about 10 seconds following the greeting.

IF I go to Settings -> Voicemail Admin -> Dialplan Behaviour I can change Msg timeout to 0 - which REDUCES the message timeout to about 6 seconds - not 0. It seems at one point this was acknowleged as a bug:
https://issues.freepbx.org/browse/FREEPBX-5378

And then argued that it was not a bug but a doc error:
https://issues.freepbx.org/browse/FREEPBX-7191

Lorne links people to PBX in a flash here:

Where again, someone says “it’s not a bug”.

Here’s the point. If the timeout is 0 - but that results in a 6-10 second timeout, that IS a bug. Can anyone point me at where to change the code to be more like it used to be? i.e. 0 seconds REALLY being 0 seconds. I want the users to be able to press a key if they want, but not be forced to do so (or wait in silence) for the beep. Ideally I’d probalby trim it to 1 second - but I will be happy if it just follows the setting that exists and seems to be functioning improperly.

Please let me know what you think? If this is answered someoen else just point me there - I didn’t see any relavent answers in my reading.

thanks all!

Mitch

Posting details below - bear with me - I’ve confirmed two bugs. 1 is that initially the settings which appear under

Settings -> Voicemail Admin -> Dialplan Behavior-> Msg timeout: 2

While this seems to be the default, it doesn’t seem to be affective until after you edit the page and save the results. I seem to be able to reproduce this issue.

The same page contains “Direct Dial Mode” - the default which seems to be “Busy” - HOWEVER the real default mode on a new system seems to be Unavailable (until you view this page and save). The first time I visited this page to change my Msg Timeout from 2 to 13 for testing, I noticed the Direct Dial Mode changed as well - at that time I went back to this page to resave it.

So the biggest part of this issue might be that the default settings which appear in the FreePBX gui for a new system don’t actually seem to be applied until you go to the page and press save. If I’d done that, the default timeout of 2 seconds would have been effective.

The other issue though is still true - setting the timeout to 0 does not ACTUALLY produce a 0 - details / proof of that will follow in my next post.

THIS IS A LONG POST AND DOCUMENTS THE PROBLEMS, PLUS A COUPLE WORK AROUNDS.

Hope it helps :slight_smile:

For my tests, I used a DID routed to a voicemail box – to determine the length of the greeting I ran soxi:

soxi /var/spool/asterisk/voicemail/300/1001/unavail.wav
Input File : ‘/var/spool/asterisk/voicemail/300/1001/unavail.wav’
Channels : 1
Sample Rate : 8000
Precision : 16-bit
Duration : 00:00:15.84 = 126720 samples ~ 1188 CDDA sectors
Sample Encoding: 16-bit Signed Integer PCM

Duration of greeting 15.8 seconds.

Initially the settings located at:
Settings -> Voicemail Admin -> Dialplan Behavior-> Msg timeout: 2
Did not seem to be working – so I changed them - unfortunately (or fortunately I didn’t jsut view and press Save - if I did I might have saved a lot of time but not found the bugs :wink: )

My first step was:
Settings -> Voicemail Admin -> Dialplan Behavior-> Msg timeout: 13
Save and Apply

With this setting, the voicemail should play and be followed by 13 seconds of silence. Then we should get a beep. We can see the VMX_TIMEOUT is set to 13

[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:17] Set(“SIP/TEST-0000051a”, “VMX_TIMEOUT=13”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:18] Set(“SIP/TEST-0000051a”, “VMX_REPEAT=1”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:19] Set(“SIP/TEST-0000051a”, “VMX_LOOPS=1”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:20] Set(“SIP/TEST-0000051a”, “LOOPCOUNT=0”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:21] Set(“SIP/TEST-0000051a”, “VMX_REPEAT=1”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:22] Set(“SIP/TEST-0000051a”, “VMX_TIMEOUT=13”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:23] Set(“SIP/TEST-0000051a”, “VMX_LOOPS=1”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:24] Answer(“SIP/TEST-0000051a”, “”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [[email protected]:25] Read(“SIP/TEST-0000051a”, “ACTION,/var/spool/asterisk/voicemail/300/1001/unavail,1,skip,1,13”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] app_read.c: Accepting a maximum of 1 digits.
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] file.c: <SIP/TEST-0000051a> Playing ‘/var/spool/asterisk/voicemail/300/1001/unavail.slin’ (language ‘en’)
[2018-06-19 16:06:40] VERBOSE[13001][C-00000bfb] app_read.c: User entered nothing.

Just looking at the number of seconds elapsed from the timestamps on the logs…
40-12=28 seconds total
28-13=15 and subtracting for the delay I set.
I’m expecting 13 seconds… and 15.8 seconds for the recording – so that works (no fractions of seconds in my timestamps) - and no problem here!

Now lets change it. I went to the same place, and set the delay to 0 (it was showing 13).

Settings -> Voicemail Admin -> Dialplan Behavior-> Msg timeout: 0
Save and Apply

And here’s the same test call:

[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:17] Set(“SIP/TEST-0000051c”, “VMX_TIMEOUT=”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:18] Set(“SIP/TEST-0000051c”, “VMX_REPEAT=1”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:19] Set(“SIP/TEST-0000051c”, “VMX_LOOPS=1”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:20] Set(“SIP/TEST-0000051c”, “LOOPCOUNT=0”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:21] Set(“SIP/TEST-0000051c”, “VMX_REPEAT=1”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:22] Set(“SIP/TEST-0000051c”, “VMX_TIMEOUT=”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:23] Set(“SIP/TEST-0000051c”, “VMX_LOOPS=1”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:24] Answer(“SIP/TEST-0000051c”, “”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:25] Read(“SIP/TEST-0000051c”, “ACTION,/var/spool/asterisk/voicemail/300/1001/unavail,1,skip,1,”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] app_read.c: Accepting a maximum of 1 digits.
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] file.c: <SIP/TEST-0000051c> Playing ‘/var/spool/asterisk/voicemail/300/1001/unavail.slin’ (language ‘en’)
[2018-06-19 16:18:40] VERBOSE[14387][C-00000c05] app_read.c: User entered nothing.

Let’s repeat the same math…
40 seconds – 14 seconds = 26 seconds total elapsed time.
This is the problem. The setting of 0 is not being respected. The default of 10 is applying.

I’m not sure if the global default can be set?

The first thing to note is that the timeout is BLANK – not 0 – it should be 0. This results in the Read command being called without the last parameter.

[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [[email protected]:25] Read(“SIP/TEST-0000051c”, “ACTION,/var/spool/asterisk/voicemail/300/1001/unavail,1,skip,1,”) in new stack

According to:https://wiki.asterisk.org/wiki/display/AST/Asterisk+13+Application_Read

timeout - The number of seconds to wait for a digit response. If greater than 0, that value will override the default timeout. Can be floating point.

This might mean 0 is an invalid amount, but 0 could be replaced with 0.001 if required.

Further according to: https://wiki.asterisk.org/wiki/display/AST/Asterisk+13+Function_TIMEOUT

The default timeout SHOULD be 5 seconds.

However numerous other sites indicate the default seems to be 10 seconds – which would explain these results.

Settings -> Voicemail Admin -> Dialplan Behavior-> Msg timeout: 1
Save and Apply

[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:16] GotoIf(“SIP/TEST-00000525”, “0?nofile”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:17] Set(“SIP/TEST-00000525”, “VMX_TIMEOUT=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:18] Set(“SIP/TEST-00000525”, “VMX_REPEAT=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:19] Set(“SIP/TEST-00000525”, “VMX_LOOPS=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:20] Set(“SIP/TEST-00000525”, “LOOPCOUNT=0”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:21] Set(“SIP/TEST-00000525”, “VMX_REPEAT=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:22] Set(“SIP/TEST-00000525”, “VMX_TIMEOUT=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:23] Set(“SIP/TEST-00000525”, “VMX_LOOPS=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:24] Answer(“SIP/TEST-00000525”, “”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [[email protected]:25] Read(“SIP/TEST-00000525”, “ACTION,/var/spool/asterisk/voicemail/300/1001/unavail,1,skip,1,1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] app_read.c: Accepting a maximum of 1 digits.
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] file.c: <SIP/TEST-00000525> Playing ‘/var/spool/asterisk/voicemail/300/1001/unavail.slin’ (language ‘en’)
[2018-06-19 17:44:04] VERBOSE[22833][C-00000c29] app_read.c: User entered nothing.

Here we see a value of 1 being passed through properly.

Let’s repeat the same math…
64 seconds – 48 seconds = 16 seconds total elapsed time.

Going a little deeper, this should be customizable per extension if I read the vmx code – though there is no way to edit the values in FreePBX – not sure if this counts as a bug, but maybe a missing feature?

If I run in debug mode (level 1) you can see tht the second setting to VMX_TIMEOUT ([email protected]:22) looks for an ASTDB value we don’t have – so I added it to test:

[2018-06-19 18:13:37] DEBUG[25729][C-00000c34]: db.c:376 db_get_common: Unable to find key ‘1001/vmx/unavail/timeout’ in family ‘AMPUSER’

So, I added the entries:
asterisk -rx ‘database put AMPUSER 1001/vmx/unavail/timeout 0.1’
asterisk -rx ‘database put AMPUSER 1001/vmx/busy/timeout 0.1’
asterisk -rx ‘database put AMPUSER 1001/vmx/temp/timeout 0.1’

[2018-06-19 18:21:51] VERBOSE[26554][C-00000c39] pbx.c: Executing [[email protected]:25] Read(“SIP/TEST-0000052d”, “ACTION,/var/spool/asterisk/voicemail/300/1001/unavail,1,skip,1,0.1”) in new stack
[2018-06-19 18:21:51] VERBOSE[26554][C-00000c39] app_read.c: Accepting a maximum of 1 digits.
[2018-06-19 18:21:51] VERBOSE[26554][C-00000c39] file.c: <SIP/TEST-0000052d> Playing ‘/var/spool/asterisk/voicemail/300/1001/unavail.slin’ (language ‘en’)
[2018-06-19 18:22:07] VERBOSE[26554][C-00000c39] app_read.c: User entered nothing.

And we can see it works (note the 0.1 above)

Then I removed them:
asterisk -rx ‘database del AMPUSER 1001/vmx/unavail/timeout 0.1’
asterisk -rx ‘database del AMPUSER 1001/vmx/busy/timeout 0.1’
asterisk -rx ‘database del AMPUSER 1001/vmx/temp/timeout 0.1’

SUMMARY

  1. A question remains about the global timeout default - if the manual is correct (and it should be 5) why does it seem to be 10 and where is this set. Else the manual needs an update.
  2. So the first bug is that the initial values don’t actually seem to be applied until you view the settings and set them manually.
  3. The second bug is that the value of 0 results in a value of BLANK which results in the system default timeout being used.
  4. The third bug / missing feature might be the ability to edit timeout at a granular level. I’m ok with this not being exposed – just documenting it for others who may come after me. The ability to change specific timeouts for different MODE’s is interesting… you could use a temp mode (vacation) to trigger a different timeout location potentially requiring a caller to press # to leave a voicemail if the user is away (temp greeting active).

Neat stuff.

I know this issue has been posted about a LOT of times – and dismissed a lot of times – people call it a bug – dev’s have rejected it as a bug – but there really IS at least a couple bugs – hopefully this helps someone / hopefully a dev will read this and point it in the correct direction - from what I can see (through many posts in many forums) this has been an issue for a LONG TIME - just no one dug through to figure out why :slight_smile:

Cheers,

Mitch

Thanks for your testing and tips! Changing the value from 0 to 1 resulted in the delay going from 10 seconds to 1 second on my systems.

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