Toggle sidebar Toggle sidebar

Voicemail only working internally

Status
Not open for further replies.

oJo

Bronze Partner
Advanced Certified
Joined
Apr 17, 2019
Messages
58
Reaction score
3
We have a very peculiar issue right now. We deployed a new 3CX install and set up one extension as the Voicemail for all routes going to voicemail. For testing, I set a DID directly to the voicemail of the extension. When I call, it plays the standard instructions and a beep, once I press # it says "Thank you and goodbye". No voicemail is saved.
When I call the voicemail internally via another phone, after pressing # it offers options like replay, delete and save. It works flawlessly in that case. I have not been able to figure out what is causing this issue and how to fix it. Does anyone have a clue what might be going wrong here?
 
Can you show us the VM settings page for ext 575 ?
 
Thanks, and can you also check under Management Console > Settings > Parameters:

  1. what does VOICEMAILBOX_PATH have?
  2. what does VOICEMAILBOX_WEBACCESS_URL have?
  3. Exact PBX Version number?
 
JohnS_3CX said:
Thanks, and can you also check under Management Console > Settings > Parameters:

  1. what does VOICEMAILBOX_PATH have?
  2. what does VOICEMAILBOX_WEBACCESS_URL have?
  3. Exact PBX Version number?
Click to expand...
/var/lib/3cxpbx/Instance1/Data/Ivr/Voicemail for both
Version is
16.0.910
 
Ok so what remains to be seen now is via a capture, what does the provider send you in the From:User Part during an incoming call?

This is what makes part of the voicemail recording filename vmail_17771234567_000_20190911141706.wav

Caller was 17771234567 for EXT 000 on 2019-09-11 14:17:06

And if there are invalid characters the file may not be written
 
I'm wondering if it is a trunk Codec, or DTMF (related to Codec choice) issue.
 
Everything is pointing to the direction of packet capture, it would be a good idea to go ahead and run one while making an incoming call and then checking what goes in the From: User Part
 
JohnS_3CX said:
Ok so what remains to be seen now is via a capture, what does the provider send you in the From:User Part during an incoming call?

This is what makes part of the voicemail recording filename vmail_17771234567_000_20190911141706.wav

Caller was 17771234567 for EXT 000 on 2019-09-11 14:17:06

And if there are invalid characters the file may not be written
Click to expand...
The provider sends a Standard E.164 number with +43...
 
Ok then, you might wanna take a look at your 3CXIVR.log file after a call reaches the mailbox

You should see something like:

03/10/2019 14:22:12.283 [000003e9] 1 $record = /var/lib/3cxpbx/Instance1/Data/Ivr/Voicemail/Extensions/000/vmail_17778889999_000_20191003112212.wav

The number in bold should be your DID, then the extension number, then the timestamp
The extension should be that of a regular user in this test.
What does this log show you? Do you see any errors?
 
JohnS_3CX said:
Ok then, you might wanna take a look at your 3CXIVR.log file after a call reaches the mailbox

You should see something like:

03/10/2019 14:22:12.283 [000003e9] 1 $record = /var/lib/3cxpbx/Instance1/Data/Ivr/Voicemail/Extensions/000/vmail_17778889999_000_20191003112212.wav

The number in bold should be your DID, then the extension number, then the timestamp
The extension should be that of a regular user in this test.
What does this log show you? Do you see any errors?
Click to expand...

This is the last entry, I just called the voicemail a minute ago...
30/09/2019 08:02:24.609 [0000669e] /home/repomaster/workspace/16.0.SP2/Sources/Projects/Common/VoIPFileEngine/RawFile.cpp(23) IRawFileBuffer::Prefetch : error = 0, Success
 
nothing before this at all?
 
Set your logs to Verbose, and try again please
 
JohnS_3CX said:
Set your logs to Verbose, and try again please
Click to expand...

Code: 
03/10/2019 14:11:02.988 [00006691] IVR Collect : CONNECTION

03/10/2019 14:11:03.132 [0000669f] /home/repomaster/workspace/16.0.SP2/Sources/Projects/Common/VoIPFileEngine/IMMFileStreamReader.cpp(144) /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/USProgresstone.wav taken from the cache

03/10/2019 14:11:03.132 [0000669f] IVRHandlerTO = 001

03/10/2019 14:11:03.132 [0000669f] IVRHandlerMENU = RecordMessage

03/10/2019 14:11:03.132 [0000669f] FromDispName = +43732censored:ABTEST

03/10/2019 14:11:03.132 [0000669f] IVRHandlerFROM = +43732censored

03/10/2019 14:11:03.132 [0000669f] IVRHandlerIN = 1

03/10/2019 14:11:03.132 [0000669f] IVRHandlerDID = +4372898145555

03/10/2019 14:11:03.132 [0000669f] 58 NEW VML : +43732censored -> 001 (RecordMessage)

03/10/2019 14:11:03.132 [0000669f] 58 ENQUEUE START 0

03/10/2019 14:11:03.132 [0000669f] DR Added new session 58, total 1

03/10/2019 14:11:03.132 [000066a5] 58 PROCESS START 0

03/10/2019 14:11:03.132 [000066a5] 58 $_I = 58

03/10/2019 14:11:03.132 [000066a5] 58 $_A = +43732censored

03/10/2019 14:11:03.132 [000066a5] 58 $_B = 001

03/10/2019 14:11:03.132 [000066a5] 58 $_C =

03/10/2019 14:11:03.132 [000066a5] 58 $_P = #EMPTY

03/10/2019 14:11:03.133 [000066a5] 58 $_V = +4372898145555

03/10/2019 14:11:03.133 [000066a5] 58 $_S = 5060

03/10/2019 14:11:03.133 [000066a5] 58 $_O = 000

03/10/2019 14:11:03.133 [000066a5] 58 PromptSet 03E2DC8C-3382-43e2-A9D5-115F92C847BE

03/10/2019 14:11:03.133 [000066a5] 58 $play_cid = 0

03/10/2019 14:11:03.133 [000066a5] 58 $play_dt = 0

03/10/2019 14:11:03.133 [000066a5] 58 $new_count = 0

03/10/2019 14:11:03.133 [000066a5] 58 $read_count = 0

03/10/2019 14:11:03.133 [000066a5] 58 $position = 0

03/10/2019 14:11:03.133 [000066a5] 58 $vm_box = 001

03/10/2019 14:11:03.133 [000066a5] 58 $ext_num = 001

03/10/2019 14:11:03.133 [000066a5] 58 $caller = +43732censored

03/10/2019 14:11:03.133 [000066a5] 58 $caller_name = +43732censored:ABTEST

03/10/2019 14:11:03.133 [000066a5] 58 $greeting = #RECYAMSG

03/10/2019 14:11:03.133 [000066a5] IVR session has been started for call from +43732censored

03/10/2019 14:11:03.133 [000066a5] 58 Starting 12LambdaAction

03/10/2019 14:11:03.133 [000066a5] 58 $minrec = 2000

03/10/2019 14:11:03.133 [000066a5] 58 Starting 12PromptAction

03/10/2019 14:11:03.133 [000066a5] 58 PLAY id = 1 : $greeting = /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/record_your_message.wav

03/10/2019 14:11:03.133 [000066a5] /home/repomaster/workspace/16.0.SP2/Sources/Projects/Common/VoIPFileEngine/IMMFileStreamReader.cpp(144) /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/record_your_message.wav taken from the cache

03/10/2019 14:11:03.133 [000066a5] 58 Awaiting result

03/10/2019 14:11:08.609 [00006691] Updated: PARAMETER.442

03/10/2019 14:11:08.609 [00006691] IVR Collect : PARAMETER

03/10/2019 14:11:08.611 [00006691] Updated: PARAMETER.444

03/10/2019 14:11:08.611 [00006691] IVR Collect : PARAMETER

03/10/2019 14:11:08.852 [00006691] Updated: PARAMETER.447

03/10/2019 14:11:08.852 [00006691] IVR Collect : PARAMETER

03/10/2019 14:11:11.660 [0000669e] 58 ENQUEUE PROMPT 1

03/10/2019 14:11:11.660 [000066a5] 58 PROCESS PROMPT 1

03/10/2019 14:11:11.660 [000066a5] 58 Continue with new action

03/10/2019 14:11:11.660 [000066a5] 58 Starting 12RecordAction

03/10/2019 14:11:11.660 [000066a5] /home/repomaster/workspace/16.0.SP2/Sources/Projects/Common/VoIPFileEngine/IMMFileStreamReader.cpp(144) /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/beep.wav taken from the cache

03/10/2019 14:11:11.660 [000066a5] 58 PLAY id = 2 : #BEEP = /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/beep.wav

03/10/2019 14:11:11.660 [000066a5] 58 Awaiting result

03/10/2019 14:11:13.439 [0000669e] 58 ENQUEUE PROMPT 2

03/10/2019 14:11:13.439 [000066a5] 58 PROCESS PROMPT 2

03/10/2019 14:11:13.439 [000066a5] 58 $record = /var/lib/3cxpbx/Instance1/Data/Ivr/Voicemail/Extensions/001/vmail_+43732censored_001_20191003121113.wav

03/10/2019 14:11:13.439 [000066a5] 58 $wav = vmail_+43732censored_001_20191003121113

03/10/2019 14:11:13.439 [000066a5] 58 $author = +43732censored

03/10/2019 14:11:13.439 [000066a5] 58 $created = 20191003121113.00

03/10/2019 14:11:13.439 [000066a5] 58 Recording to '/var/lib/3cxpbx/Instance1/Data/Ivr/Voicemail/Extensions/001/vmail_+43732censored_001_20191003121113.wav', max duration 120000 ms

03/10/2019 14:11:13.440 [000066a5] DR Added session from timer, total 1

03/10/2019 14:11:13.440 [000066a5] 58 TM_SET 'REC' for 120000 ms -> 5

03/10/2019 14:11:13.440 [000066a5] 58 DTMF buffer:

03/10/2019 14:11:13.440 [000066a5] 58 Still awaiting result

03/10/2019 14:11:27.263 [0000669d] 58 ENQUEUE DTMF # of type 1

03/10/2019 14:11:27.264 [000066a5] 58 PROCESS DTMF # of type 1

03/10/2019 14:11:27.264 [000066a5] 58 Locked DTMF type to INBAND

03/10/2019 14:11:27.264 [000066a5] 58 DTMF buffer:  + #

03/10/2019 14:11:27.264 [000066a5] 58 TM_CAN 'REC' -> 5

03/10/2019 14:11:27.264 [000066a5] 58 Recording stopped, duration 13800 ms

03/10/2019 14:11:27.264 [000066a5] 58 $_R = 13800

03/10/2019 14:11:27.264 [000066a5] 58 DTMF buffer: #

03/10/2019 14:11:27.264 [000066a5] 58 Continue with new action

03/10/2019 14:11:27.264 [000066a5] 58 Starting 12PromptAction

03/10/2019 14:11:27.264 [000066a5] 58 PLAY id = 3 : #SAVMSGCNFRM = /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/SaveMsgCnfrm.wav

03/10/2019 14:11:27.264 [000066a5] /home/repomaster/workspace/16.0.SP2/Sources/Projects/Common/VoIPFileEngine/IMMFileStreamReader.cpp(144) /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/SaveMsgCnfrm.wav taken from the cache

03/10/2019 14:11:27.264 [000066a5] 58 Awaiting result

03/10/2019 14:11:27.364 [0000669d] 58 ENQUEUE DTMF # of type 4

03/10/2019 14:11:27.364 [000066a5] 58 PROCESS DTMF # of type 4

03/10/2019 14:11:27.364 [000066a5] 58 Locked DTMF type to RFC2833

03/10/2019 14:11:27.364 [000066a5] 58 DTMF buffer:  + #

03/10/2019 14:11:27.364 [000066a5] 58 Cancelling Playback

03/10/2019 14:11:27.364 [000066a5] 58 DTMF buffer: #

03/10/2019 14:11:27.364 [000066a5] 58 Pushed 13SaveRecAction, level = 1

03/10/2019 14:11:27.364 [000066a5] 58 Continue with new action

03/10/2019 14:11:27.364 [000066a5] 58 Starting 16DeleteFileAction

03/10/2019 14:11:27.364 [000066a5] 58 Starting 12AssignAction

03/10/2019 14:11:27.364 [000066a5] 58 $record =

03/10/2019 14:11:27.364 [000066a5] 58 Starting 10GotoAction

03/10/2019 14:11:27.364 [000066a5] 58 Stack is cleared

03/10/2019 14:11:27.364 [000066a5] 58 Starting 12PromptAction

03/10/2019 14:11:27.364 [000066a5] 58 PLAY id = 4 : #BYE = /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/thankyou_goodbye.wav

03/10/2019 14:11:27.364 [000066a5] /home/repomaster/workspace/16.0.SP2/Sources/Projects/Common/VoIPFileEngine/IMMFileStreamReader.cpp(144) /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/thankyou_goodbye.wav taken from the cache

03/10/2019 14:11:27.364 [000066a5] 58 Awaiting result

03/10/2019 14:11:30.104 [0000669e] 58 ENQUEUE PROMPT 4

03/10/2019 14:11:30.104 [000066a5] 58 PROCESS PROMPT 4

03/10/2019 14:11:30.104 [000066a5] 58 Continue with new action

03/10/2019 14:11:30.104 [000066a5] 58 Starting 10ExitAction

03/10/2019 14:11:30.104 [000066a5] 58 Stack is cleared

03/10/2019 14:11:30.104 [000066a5] 58 End of script logic!

03/10/2019 14:11:30.104 [000066a5] 58 Logic finished

03/10/2019 14:11:30.104 [000066a5] 58 Closing Media...

03/10/2019 14:11:30.104 [000066a5] 58 Ending session in Media

03/10/2019 14:11:30.104 [000066a5] IVR session has been finished for established call from +43732censored

03/10/2019 14:11:30.104 [0000669f] DR Session 58 has been ended by PBX, total 0

03/10/2019 14:11:30.104 [0000669f] 58 DELETE

03/10/2019 14:11:30.104 [0000669f] RTP frees ports 12134, 12135

03/10/2019 14:11:30.124 [0000669d] RTP receiver is removed for call object 0x7fb8280c5000 on socket (16)

03/10/2019 14:11:30.124 [0000669d] RTCP receiver is removed for call object 0x7fb8280c5000 on socket (17)

03/10/2019 14:11:30.157 [00006691] Deleted: CONNECTION.1009

03/10/2019 14:11:30.157 [00006691] IVR Collect : CONNECTION

03/10/2019 14:11:30.159 [00006691] Deleted: CONNECTION.1008

03/10/2019 14:11:30.159 [00006691] IVR Collect : CONNECTION

03/10/2019 14:11:30.223 [00006691] Updated: PARAMETER.459

03/10/2019 14:11:30.223 [00006691] IVR Collect : PARAMETER

03/10/2019 14:11:30.291 [0000669f] RTP closing port pair 12134, 12135
 
Your provider seems to be sending the DTMF key press of the pound character # twice. If you call a mailbox internally, and after leaving a message press # two times quickly, you will cause the exact same behavior.

The technical explanation is that they send it both as in-band and as RFC2833. This causes two key presses of #.

So the solution is to speak with your provider, and ask them to either send DTMF either as in-band or as RFC2833 (but not both). https://www.3cx.com/blog/voip-howto/dtmf-rfc2833/
 
JohnS_3CX said:
Your provider seems to be sending the DTMF key press of the pound character # twice. If you call a mailbox internally, and after leaving a message press # two times quickly, you will cause the exact same behavior.

The technical explanation is that they send it both as in-band and as RFC2833. This causes two key presses of #.

So the solution is to speak with your provider, and ask them to either send DTMF either as in-band or as RFC2833 (but not both). https://www.3cx.com/blog/voip-howto/dtmf-rfc2833/
Click to expand...
That does sound like an explanation. I have approced the telephony provider about this, but they insist that they only send inband. Can you tell me how to confirm this with the logs to prove it to them?
 
That should be easy:
  1. Go to activity log and start a capture.
  2. Call into your DID from a mobile or external line and after the beep, leave a message and press # only one time.
  3. The problem should now occur, and the call will end.
  4. Stop the capture now, and download it off the system.
  5. Open it in wireshark to inspect the call
When there is a DTMF even you will see it in RFC2833 form, but in the capture audio stream playback you should also hear the button being pressed (in-band DTMF sent as audio).

Now you should have the evidence to prove that they send you this and you can ask them to adjust their side to either send in-band only, or send RFC2833 only
 
JohnS_3CX said:
That should be easy:
  1. Go to activity log and start a capture.
  2. Call into your DID from a mobile or external line and after the beep, leave a message and press # only one time.
  3. The problem should now occur, and the call will end.
  4. Stop the capture now, and download it off the system.
  5. Open it in wireshark to inspect the call
When there is a DTMF even you will see it in RFC2833 form, but in the capture audio stream playback you should also hear the button being pressed (in-band DTMF sent as audio).

Now you should have the evidence to prove that they send you this and you can ask them to adjust their side to either send in-band only, or send RFC2833 only
Click to expand...

Just for completeness, is there any way to set the 3CX system to only process one or the other?
 
We do not support this. The system must process both because you never know if a call will arrive with one method or the other. If you have both then you have duplicate signalling.
 
If you make use of a low bit-rate Codec, on your external trunks (if supported by your provider), then Audio DTMF will normally not be passed. This can create other issues, depending on the Codecs used internally, on the sets..namely transcoding.
 
Status
Not open for further replies.

Latest Posts

Forum statistics

Threads
112,061
Messages
590,552
Members
165,011
Latest member
m3373
3CX Logo Footer Copyright © Sitemap Privacy
Top Bottom