Long Pause For Dial Out

[iTime]

Hello,

 

I know it has been asked by a few users already, but here it goes again.

VoIP, HMP with VG7.5 environment.

After call out, VG would not start playing the first prompt for a long period of time even after a person says "hello."

It looks like VG (I would say more on Dialogic HMP?) spends about 10 to 30 seconds to decide whether it is answering machine or human answer.

If you see the log, it is very irregular (even if the same phone with the same user is used to take the calls) on how fast VG can detect it is human or AM.

I tried to play with VG.INI settings to improve the detection rate, but no use.

Could you provide better solutions for this issue?

Thanks.

 

 

AMDetection.zip

[SupportTeam]

The only cause of system not being able to detect whether the answering machine or a live person has answered the call is is silence on the line after call is connected.

 

This usually means that nothing was said/played by person/system that answered the call - or (rarely) the 'hello' was said very quickly after answering the call - before one of the carriers connecting the call was able to setup the voice connection path. In the latter case the answering party says hello again a coupe of seconds later and HMP is able to hear that one.

 

In the traces provided we can see a 3 outgoing calls. One was determined to have been answered by a live person within 2 seconds of call being answered, one took 7 seconds to return advice that call was answered by a human, and the 3 call is an example of system just sitting and not hearing anything - and timing out with a 'I did not hear anything' code.

 

One test to do would be to have system dial an IP address of a SIP phone/softphone on your local network - you can then be usually assured that the voice path is set up immediately after recipient indicated that they are answering the the phone.

 

WireShark can be used to confirm how soon after connection the voice path was set up and what sound was in the RTP packets that were being received by HMP.

    Line 982: 191637.182   6   3   1 state Dialing (auto) 17145593112@ld01-05.fs.broadvox.net ... connected, doing answer detection... (DX_PAMDOPTEN)
    Line 990: 191638.912  19   3   1 ev    Dialogic 133,TDX_CALLP, crn=8000001, 10,3,0,CR_CNCT,CON_PVD,

    Line 1451: 191830.917   6   3   1 state Dialing (auto) 17145593112@ld01-05.fs.broadvox.net ... connected, doing answer detection... (DX_PAMDOPTEN)
    Line 1459: 191910.939  19   3   1 ev    Dialogic 133,TDX_CALLP, crn=8000001, 9,0,0,CR_NORB,,

    Line 1777: 191923.929   6   7   2 state Dialing (auto) 17145593112@ld01-05.fs.broadvox.net ... connected, doing answer detection... (DX_PAMDOPTEN)
    Line 1785: 191930.856  19   7   2 ev    Dialogic 133,TDX_CALLP, crn=8000002, 10,3,0,CR_CNCT,CON_PVD,

[iTime]

OK, thanks for the tip.

One more pattern I would like to mention is that VG would not respond for extremely long duration (for Dial-out calls) for the very first call after VG service restarts.

I have been changing VG.INI setting around to optimize AM detection rate and discovered this.

If you see the log, you can see "Dialing...." for several times even after a user said "hello" already. You can see this in Wireshark log that RTP packets have already been being transferred.

This might be one big issue I am facing as this is happening almost every time.

 

Thanks.

 

 

NoAnswer_AfterVGRestart.zip

[SupportTeam]

Not sure why you are seeing the Live/Machine detection problem on the first call after restart.

 

We just did the same test on similar system here and it worked fine on the first call. We restarted service multiple times and the first call always worked fine - with confirmation of 'live person answer' arriving in less then 1 second after 'Hello' was said. (traces attached)

 

To look at this further we may need to obtain the Dialogic RTF trace files for the first call from your system.

 

Please see instructions below on increasing the RTF logging levels, and then please restart the VoiceGuide service, make one outgoing calla and post all the traces (incl WireShark) and the RTF logs.

1. Stop the VoiceGuide service.
2. Stop the Dialogic service.

Please place the attached RtfConfigWin.xml file on your system - unzip first. (file link at very bottom of this post)


for Windows 7, Win2008, Win2012 :
3a. make the hidden directory C:\ProgramData visible
3b. go to C:\ProgramData\Dialogic\HMP\cfg


for Windows XP, Win2003 and Win2008-32bit :
3a. go to C:\Program Files\Dialogic\cfg


Then:

4. Backup existing RtfConfigWin.xml,
5. Replace it with attached RtfConfigWin.xml (unzip it first)
6. Shutdown and restart Windows.

7 Start WireShark to capture the SIP packets of the incoming call. (see: www.wireshark.org)
8. Start the Dialogic service.
9. Once Dialogic service has fully started then start the VoiceGuide service.

10. After VoiceGuide service has fully started place a call into system.

11. .ZIP up Dialogic logs (C:\Program Files (x86)\Dialogic\log directory) and VoiceGuide ktTel log and the WireShark .pcap log file that captures the SIP packets.
12. Please post all the above logs here.

iTime calls summary.txt

FirstCallTest.zip

RtfConfigWin.zip

[iTime]

Please find the attached files including HMP log and Wireshark log.

This one took about 40 seconds after the user said "Hello" (several times) for the first outdial.

I disabled "answering machine detection" on VG.INI for this one, but no use.

 

Thanks.

VG_FirstCallSlowAnswer.zip

[SupportTeam]

In the traces provided the vgEngine trace starts at 12:05:21 captures a call that was made at 12:06:36 and answer detection took 12 seconds. CallEvents extract is for that same call.

 

The ktTel trace provided starts at 12:02:50 and ends at 12:05:04 and does not show any calls at all.

 

And the attached WireShark trace captures a call on which delay was 18 seconds, so appears to be a different call as as well.

 

Could you please supply traces that all relate to the same call, that way we can get a clear picture of what is happening on the system.

 

Also, Can you please advise whether this system is running on physical hardware or on a virtual machine? If virtual machine then can you please advise details of the VM environment.

120521.998   5               vgEngine version: 7.5.5795.23444|7.5.5795.23444 DEBUG options75
120521.998   5               Compiled on      : 13-Nov-15 13:01:27.49

120636.820  19   3   1 state Dialing (auto) 17145593112@ld01-05.fs.broadvox.net ...
120639.525  19   3   1 ev    CallState GCEV_CONNECTED, crn=8000001, iEvent=0 ,256,2,4, s1:, s2:, s3:]. build_date: 13-Nov-15 13:01:27.49
120639.526   6   3   1 state Dialing (auto) 17145593112@ld01-05.fs.broadvox.net ... connected
120639.532   6   3   1 state Dialing (auto) 17145593112@ld01-05.fs.broadvox.net ... connected, doing answer detection... (DX_PAMDOPTEN)
120639.548  19   3   1 ev    Dialogic 2133,GCEV_LISTEN, crn=0, 2133,0,0,,,
120651.985  19   3   1 ev    Dialogic 133,TDX_CALLP, crn=8000001, 10,3,0,CR_CNCT,CON_PVD,
120651.990   6   3   1 state Human answer. Start [C:\Program Files (x86)\VoiceGuide\Scripts\IntelliTime\Login.vgs]

[iTime]

Yes, that is the thing: I tried to find the matching ktTel trace but that was the most recent log that was created with the VG restart, which had a trace for Call at 12:05:21.

I can assure you that all the logs were created for the same call including RTF log.

I thought it was weird too in that ktTel was stopped writing further. (I thought it was meant to stop at the beginning of VG start maybe...)

I will try to collect the information again and post them shortly.

 

In the mean time, please see the server information below:

 

OS: Windows Server 2008 R2 (Svc Pack 1)- 64bit

Processor: Intel Xeon 2.27GHz

VM: ESX 4.1

[iTime]

I made another set of logs with a call out that was followed by the server restart.

This time it took about 30 seconds to answer (3:29:17 and 3:29:48), and ktTel log does have information of the call.

 

Please take a look at.

 

Thank you very much again for your help.

VG_FirstCallSlowAnswer_2.zip

[iTime]

Hello,

Any development on this issue?

Thanks.

[SupportTeam]

In the traces provided we can see 13 outgoing calls.

 

7 of these calls did get categorized within 2 seconds of the call being answered (so that would be within 1 second of 'hello' being said). 3 are at around the 5 second mark and 3 take 10+ seconds.

 

 

We tried sending this RTF log + WireShark capture to Dialogic for a comment, but looks like we cannot get any comment from them on this as it looks like HMP drivers used on this system were not purchased through us so we cannot raise this through our support channel. Recommend that you forward the Dialogic RTF log and WireShark trace through your HMP supplier for comment from Dialogic as to why the captured call took so long to categorize. Dialogic should come back with advice as to what they believe is happening on this system and maybe offer advice about settings or other parameters that could be looked at, or whether there is anything with the system setup that should be looked at.

 

Perhaps the volume of the sound received from the other end is just too low? (it does look to be on the quiet side based on WireShark capture). If so, then you may need to speak to your SIP service provider about that.

 

 

 

As mentioned before, we have not been able to replicate this issue on our test systems so we do not have any of our own traces from our own system that we could forward to Dialogic.

 

You did mention before that the pattern that you see here is that the calls affected seem to often be just after VG service restarts, and in the traces provided the VoiceGuide service was restarted 6 times and the Dialogic service restarted twice.

The tests that we did to try to replicate this included VoiceGuide and Dialogic service restarts, but maybe there is something specific to your system setup or the SIP connections made from it that affects the calls after restart or after SIP registration renewal? Maybe the SIP service provider has some setting that affects volume and that is adapted on successive call attempts?

 

If this system is making outgoing calls right now then have you tied seeing how it behaves after it is just left to run? If we have 100s of call records we could then better see if the problems are mainly affecting the first few calls only?

 

 

 

 

Line 531: 003 123034.321 2984 fn Initialize
Line 546: 018 123215.035 2984 Waiting until the Dialogic system service starts....
Line 1123: 594 124021.620 1432 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 1139: 610 124027.117 1432 2 ev TDX_CALLP (Call Progress Completed)

Line 1310: 780 124914.520 1432 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 1326: 796 124925.259 1432 2 ev TDX_CALLP (Call Progress Completed)

Line 1457: 003 125418.827 3404 fn Initialize
Line 2002: 547 125436.814 2912 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 2018: 563 125438.374 2912 2 ev TDX_CALLP (Call Progress Completed)

Line 2189: 733 125557.858 2912 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 2205: 749 125600.017 2912 2 ev TDX_CALLP (Call Progress Completed)

Line 2397: 003 125833.530 3476 fn Initialize
Line 2942: 547 125849.000 4644 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 2958: 563 125851.400 4644 2 ev TDX_CALLP (Call Progress Completed)

Line 3156: 759 125944.019 4644 7 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 3172: 775 125946.063 4644 6 ev TDX_CALLP (Call Progress Completed)

Line 3447: 003 130154.836 3396 fn Initialize
Line 4470: 547 130247.171 4060 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 4486: 563 130319.095 4060 2 ev TDX_CALLP (Call Progress Completed)

Line 3925: 003 130229.127 2228 fn Initialize
Line 4671: 746 130357.142 4060 7 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 4706: 781 130359.211 4060 6 ev TDX_CALLP (Call Progress Completed)

Line 4892: 965 130423.990 4060 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 4908: 981 130429.034 4060 2 ev TDX_CALLP (Call Progress Completed)

Line 5115: 187 130520.056 4060 7 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 5131: 203 130522.199 4060 6 ev TDX_CALLP (Call Progress Completed)

Line 5336: 406 130630.725 4060 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 5352: 422 130632.764 4060 2 ev TDX_CALLP (Call Progress Completed)

Line 7441: 482 141917.329 4060 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 7457: 498 141922.183 4060 2 ev TDX_CALLP (Call Progress Completed)

Line 7595: 003 152234.944 3064 fn Initialize
Line 7610: 018 152345.534 3064 Waiting until the Dialogic system service starts....
Line 8188: 595 152920.713 5080 3 ev GCEV_CONNECTED (ktTel_HMP30vista v7.5.0, Nov 5 2015 13:16:17)
Line 8204: 611 152948.198 5080 2 ev TDX_CALLP (Call Progress Completed)