THIS IS A LONG POST AND DOCUMENTS THE PROBLEMS, PLUS A COUPLE WORK AROUNDS.
Hope it helps
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 )
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 [vmx@macro-vm:17] Set(“SIP/TEST-0000051a”, “VMX_TIMEOUT=13”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [vmx@macro-vm:18] Set(“SIP/TEST-0000051a”, “VMX_REPEAT=1”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [vmx@macro-vm:19] Set(“SIP/TEST-0000051a”, “VMX_LOOPS=1”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [vmx@macro-vm:20] Set(“SIP/TEST-0000051a”, “LOOPCOUNT=0”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [vmx@macro-vm:21] Set(“SIP/TEST-0000051a”, “VMX_REPEAT=1”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [vmx@macro-vm:22] Set(“SIP/TEST-0000051a”, “VMX_TIMEOUT=13”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [vmx@macro-vm:23] Set(“SIP/TEST-0000051a”, “VMX_LOOPS=1”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [vmx@macro-vm:24] Answer(“SIP/TEST-0000051a”, “”) in new stack
[2018-06-19 16:06:12] VERBOSE[13001][C-00000bfb] pbx.c: Executing [vmx@macro-vm: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 [vmx@macro-vm:17] Set(“SIP/TEST-0000051c”, “VMX_TIMEOUT=”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [vmx@macro-vm:18] Set(“SIP/TEST-0000051c”, “VMX_REPEAT=1”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [vmx@macro-vm:19] Set(“SIP/TEST-0000051c”, “VMX_LOOPS=1”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [vmx@macro-vm:20] Set(“SIP/TEST-0000051c”, “LOOPCOUNT=0”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [vmx@macro-vm:21] Set(“SIP/TEST-0000051c”, “VMX_REPEAT=1”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [vmx@macro-vm:22] Set(“SIP/TEST-0000051c”, “VMX_TIMEOUT=”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [vmx@macro-vm:23] Set(“SIP/TEST-0000051c”, “VMX_LOOPS=1”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [vmx@macro-vm:24] Answer(“SIP/TEST-0000051c”, “”) in new stack
[2018-06-19 16:18:14] VERBOSE[14387][C-00000c05] pbx.c: Executing [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm:16] GotoIf(“SIP/TEST-00000525”, “0?nofile”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm:17] Set(“SIP/TEST-00000525”, “VMX_TIMEOUT=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm:18] Set(“SIP/TEST-00000525”, “VMX_REPEAT=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm:19] Set(“SIP/TEST-00000525”, “VMX_LOOPS=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm:20] Set(“SIP/TEST-00000525”, “LOOPCOUNT=0”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm:21] Set(“SIP/TEST-00000525”, “VMX_REPEAT=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm:22] Set(“SIP/TEST-00000525”, “VMX_TIMEOUT=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm:23] Set(“SIP/TEST-00000525”, “VMX_LOOPS=1”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm:24] Answer(“SIP/TEST-00000525”, “”) in new stack
[2018-06-19 17:43:48] VERBOSE[22833][C-00000c29] pbx.c: Executing [vmx@macro-vm: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 (vmx@macro-vm: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 [vmx@macro-vm: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
- 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.
- 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.
- The second bug is that the value of 0 results in a value of BLANK which results in the system default timeout being used.
- 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
Cheers,
Mitch