Solved 3CX V15.5.8801.3 voicemail deleting message after pressing #

[nobody]

I use the voicemail since a long time, and have a personal greeting message. Works fine.
But today I setup a new extension and used the default greeting message, what happens seems to be not correct:
The caller is greeted with "record your message and press the # sign" message.
I do that, press # and, a "thank you" message is played. But the voicemail contains 0 messages afterwards.
If I call this extension using an internal phone, it works as expected. After # a the "press 0" messages is played.
It also works correct when making an external call if I just hang up or if I press 0.

Is this a known problem or did I miss something obvious?

 

[YiannisH_3CX]

Hello @nobody

When pressing # after leaving your message the system should prompt you to save the message by pressing 0 like it does with internal calls. If the system does not prompt you to save the message then that could mean that the # was not received correctly. Are you using the same provider when calling in to your extension? Does that always work?

 

[nobody]

I tried different mobile phones and carriers, also a fixed line to call my system:
Calling from German Telekom Mobile to QSC. Behaves the same always.
Calling from German VF to QSC. . Behaves the same always
Calling from German Telekom landline to QSC. Behaves the same always

The wireshark dump show no sip info packets instead it shows rtpevent packets.
I made a test myself, making sure nobody else is calling the same time.
The one keypress of "#" results in 11 RTP Event "DTMF Pound" plus 3 packes with "DTMF Pound (end)".
I have no experience how it should look if it is working ok.

 

[YiannisH_3CX]

From your description it looks like DTMF signals are coming to the PBX as RFC2833 which is what we prefer.
Is the duration in those messages incrementing?
Also in the Invite from the provider do you see any special character in the callers name?

 

[nobody]

The Messages are arriving about every 0.02 seconds.
The duration of the 1st: 160, and increments 160 for every event up to the 11th: 1760
Then, the first event with the "(end)" is 1768, also the next 2 "(end)" events have a duration of 1768
I see only ASCII Characters in the invite headers.
The callers name is
From: "+49CALLERSPHONENUMBER" <sip:[email protected];user=phone>;tag=randomstring
The user part of the From address is +49CALLERSNUMBER

 

[NickD_3CX]

I tried to replicate this but I couldn't, so I am thinking it must be something specific to your case.

What you could do is turn on Verbose logging in 3CX, restart the services, then replicate the scenario where the VMail messages is not saved. Then you could check the 3CXIVR.log file to see if there is any error reported. Usually this file is fairly easy to read.

If you don't see any indication of what could be causing this, maybe you could open a support ticket with the support team or ask a 3CX partner to investigate this.

 

[nobody]

I am one step further, but problem still exists:
I tried the same, this time using german carrier Sipgate. I added a sipgate trunk to the pbx. Using this provider voicemal and the "#" works as expected.
So, It has something to do with QsC. I have both DSL line and VoIP from QsC, and, it is a 3cx supported version.
Also I now remember it previously worked when I use deutsche Telekom.

 

[NickD_3CX]

Could you check the 3CXIVR.log file then? It may give some clue.

 

[nobody]

Thank you for trying to help!

Here goes the interesting part of the log:
17/05/2018 10:00:59.158 [00000924] 2 Recording to 'C:/ProgramData/3CX/Instance1/Data/Ivr/Voicemail/Extensions/10/vmail_+49NNNNNNNNNNNNN_10_20180517080059.wav', max duration 120000 ms
17/05/2018 10:00:59.159 [00000924] DR Added session from timer, total 1
17/05/2018 10:00:59.159 [00000924] 2 TM_SET 'REC' for 120000 ms -> 1
17/05/2018 10:00:59.159 [00000924] 2 DTMF buffer:
17/05/2018 10:00:59.159 [00000924] 2 Still awaiting result
17/05/2018 10:01:13.809 [00000bec] 2 ENQUEUE DTMF # of type 1
17/05/2018 10:01:13.809 [00000bec] 2 ENQUEUE DTMF # of type 4
17/05/2018 10:01:13.809 [00000924] 2 PROCESS DTMF # of type 1
17/05/2018 10:01:13.809 [00000924] 2 Locked DTMF type to INBAND
17/05/2018 10:01:13.810 [00000924] 2 DTMF buffer: + #
17/05/2018 10:01:13.810 [00000924] 2 TM_CAN 'REC' -> 1
17/05/2018 10:01:13.810 [00000924] 2 Recording stopped, duration 14600 ms
17/05/2018 10:01:13.810 [00000924] 2 $_R = 14600
17/05/2018 10:01:13.810 [00000924] 2 DTMF buffer: #
17/05/2018 10:01:13.810 [00000924] 2 Continue with new action
17/05/2018 10:01:13.810 [00000924] 2 Starting PromptAction
17/05/2018 10:01:13.810 [00000924] 2 PLAY id = 3 : #SAVMSGCNFRM = C:/ProgramData/3CX/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/SaveMsgCnfrm.wav
17/05/2018 10:01:13.810 [00000924] IMMFileStreamReader.cpp(144) C:/ProgramData/3CX/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/SaveMsgCnfrm.wav taken from the cache
17/05/2018 10:01:13.810 [00000924] 2 Awaiting result
17/05/2018 10:01:13.810 [00000924] 2 PROCESS DTMF # of type 4
17/05/2018 10:01:13.810 [00000924] 2 Locked DTMF type to RFC2833
17/05/2018 10:01:13.810 [00000924] 2 DTMF buffer: + #
17/05/2018 10:01:13.811 [00000924] 2 Cancelling Playback
17/05/2018 10:01:13.811 [00000924] 2 DTMF buffer: #
17/05/2018 10:01:13.811 [00000924] 2 Pushed SaveRecAction, level = 1
17/05/2018 10:01:13.811 [00000924] 2 Continue with new action
17/05/2018 10:01:13.811 [00000924] 2 Starting DeleteFileAction
17/05/2018 10:01:13.811 [00000924] 2 Starting AssignAction
17/05/2018 10:01:13.811 [00000924] 2 $record =
17/05/2018 10:01:13.811 [00000924] 2 Starting GotoAction
17/05/2018 10:01:13.811 [00000924] 2 Stack is cleared
17/05/2018 10:01:13.811 [00000924] 2 Starting PromptAction
17/05/2018 10:01:13.811 [00000924] 2 PLAY id = 4 : #BYE
17/05/2018 10:00:59.159 [00000924] DR Added session from timer, total 1
17/05/2018 10:00:59.159 [00000924] 2 TM_SET 'REC' for 120000 ms -> 1
17/05/2018 10:00:59.159 [00000924] 2 DTMF buffer:
17/05/2018 10:00:59.159 [00000924] 2 Still awaiting result
17/05/2018 10:01:13.809 [00000bec] 2 ENQUEUE DTMF # of type 1
17/05/2018 10:01:13.809 [00000bec] 2 ENQUEUE DTMF # of type 4
17/05/2018 10:01:13.809 [00000924] 2 PROCESS DTMF # of type 1
17/05/2018 10:01:13.809 [00000924] 2 Locked DTMF type to INBAND
17/05/2018 10:01:13.810 [00000924] 2 DTMF buffer: + #
17/05/2018 10:01:13.810 [00000924] 2 TM_CAN 'REC' -> 1
17/05/2018 10:01:13.810 [00000924] 2 Recording stopped, duration 14600 ms
17/05/2018 10:01:13.810 [00000924] 2 $_R = 14600
17/05/2018 10:01:13.810 [00000924] 2 DTMF buffer: #
17/05/2018 10:01:13.810 [00000924] 2 Continue with new action
17/05/2018 10:01:13.810 [00000924] 2 Starting PromptAction
17/05/2018 10:01:13.810 [00000924] 2 PLAY id = 3 : #SAVMSGCNFRM = C:/ProgramData/3CX/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/SaveMsgCnfrm.wav
17/05/2018 10:01:13.810 [00000924] IMMFileStreamReader.cpp(144) C:/ProgramData/3CX/Instance1/Data/Ivr/Prompts/Sets/03E2DC8C-3382-43e2-A9D5-115F92C847BE/SaveMsgCnfrm.wav taken from the cache
17/05/2018 10:01:13.810 [00000924] 2 Awaiting result
17/05/2018 10:01:13.810 [00000924] 2 PROCESS DTMF # of type 4
17/05/2018 10:01:13.810 [00000924] 2 Locked DTMF type to RFC2833
17/05/2018 10:01:13.810 [00000924] 2 DTMF buffer: + #
17/05/2018 10:01:13.811 [00000924] 2 Cancelling Playback
17/05/2018 10:01:13.811 [00000924] 2 DTMF buffer: #
17/05/2018 10:01:13.811 [00000924] 2 Pushed SaveRecAction, level = 1
17/05/2018 10:01:13.811 [00000924] 2 Continue with new action
17/05/2018 10:01:13.811 [00000924] 2 Starting DeleteFileAction
17/05/2018 10:01:13.811 [00000924] 2 Starting AssignAction
17/05/2018 10:01:13.811 [00000924] 2 $record =
17/05/2018 10:01:13.811 [00000924] 2 Starting GotoAction
17/05/2018 10:01:13.811 [00000924] 2 Stack is cleared
17/05/2018 10:01:13.811 [00000924] 2 Starting PromptAction
17/05/2018 10:01:13.811 [00000924] 2 PLAY id = 4 : #BYE

 

[NickD_3CX]

I think I know what must be happening, but its weird that I can't replicate this with a QSC Trunk.

As you are comfortable with using Wireshark, could you make another capture and check if you are receiving the DTMF both In-Band and with RFC2833?


If the duration of the In-band and RFC2833 overlap 100%, then this shouldn't a problem because the system acknowledges them as one, but if there is an offset, the system may read the first '#' as 2 digits, causing the behavior you are describing....

 

[nobody]

When I open the graph of the packets and use the "G" function to goto the first and the last packet where the DTMF signals are plotted this matches the packet range in the wireshark window.
However when I look at the time I get confused:
The player tells: 21:25:18.899 to 21:25:19.200 is the sound of the #
Wireshark tells: 21:24:49.548 to 21:24:39.808
But that cannot be true. Must be an error in wireshark(?)

At the time when the # is pressed several packets arrive out of sequence.
I attached a screenshot. Why does this happen? just when I press "#" all other packets did not show this behaviour.

 

[NickD_3CX]

Actually I don't think that it is a Wireshark error, because this would absolutely explain the IVR log. If you check 2 specific lines:
...
17/05/2018 10:01:13.809 [00000924] 2 Locked DTMF type to INBAND
...
17/05/2018 10:01:13.810 [00000924] 2 Locked DTMF type to RFC2833
...

The IVR first hears the In-band DTMF because it does not overlap correctly with the RFC2833. Then for the same reason it interprets the same DTMF '#' tone again, so the result is as if you pressed the '#' tone 2 times.

Try doing what is written in the Deutsche Telefon guide in the paragraph "3CX - DTMF Setting" which you can find here: https://www.3cx.com/partners/sip-trunks/#h.56m4oqa5or90

 

[nobody]

You are correct regarding the incorrect overlap, but the times wireshark shows are several seconds, also in the Graph it fits perfect. And. the IVRlog show only a difference of 1ms, which I guess is well in range for a correct overlap.
But disabling the recognition of the DTMF tones by 3cx fixes the problem anyway - Thank you! I really hope this does not create another Problem somewhere else. I also found out, if I make a call from QsC to QsC, the problem is not present!

This case shows again, that VoiP should have been never implemented the way it is.

 

[NickD_3CX]

It shouldn't create any other problems, but bare in mind that now 3CX strips all inband DTMF tones, so if yo have any legacy device connected through an ATA to 3CX that relies on inband DTMF tones and your ATA does not convert back to Inband from RFC2833, that may not work.

Most providers nowadays that I come across actually do this at the provider level, strip the Inband DTMF completely before sending it to the PBX, obviously QsC is not one of them....

I am glad though that it works now!