VG seems to have trouble connecting to SIP

[Guest Jean-Francois]

 

My system is having trouble connecting to the SIP server. The solution I found was to stop VG and restart it. It is really inconvenient because it implies that I am always ready to do this action. When the system does not receive the correct answer from the SIP, it gets bogged down and dials the numbers one at the back of the other without a pause between each attempt. Is it there any way to ask that during a unsuccessful attempt that the system waits some time before another try? I include the files with this post and before publishing it please remove the IP addresses and city name.

Trace_04-23-2018_(2).zip

[SupportTeam]

The attached vgEngine trace covers the time from 18:49 till 19:10.

A few calls can be seen being made at first: one at 184929 and then 5 more at 185146 :

184929.458  22  16   5      1 ev    CallState GCEV_DIALING, crn=8000005, iEvent=0 ,16,0,16, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
185146.158  22   3   1      2 ev    CallState GCEV_DIALING, crn=8000001, iEvent=0 ,16,0,16, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
185146.252  22   7   2      3 ev    CallState GCEV_DIALING, crn=8000002, iEvent=0 ,16,0,16, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
185146.357  22  10   3      4 ev    CallState GCEV_DIALING, crn=8000003, iEvent=0 ,16,0,16, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
185146.457  22  13   4      5 ev    CallState GCEV_DIALING, crn=8000004, iEvent=0 ,16,0,16, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
185146.557  22  16   5      6 ev    CallState GCEV_DIALING, crn=8000005, iEvent=0 ,16,0,16, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41

all of those were answered by the dialed target:

    Line 2135: 184929.591  22  16   5      1 ev    CallState GCEV_CONNECTED, crn=8000005, iEvent=0 ,256,2,4, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
    Line 2604: 185146.302  22   3   1      2 ev    CallState GCEV_CONNECTED, crn=8000001, iEvent=0 ,256,2,4, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
    Line 2705: 185146.362  22   7   2      3 ev    CallState GCEV_CONNECTED, crn=8000002, iEvent=0 ,256,2,4, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
    Line 2806: 185146.482  22  10   3      4 ev    CallState GCEV_CONNECTED, crn=8000003, iEvent=0 ,256,2,4, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
    Line 2894: 185146.572  22  13   4      5 ev    CallState GCEV_CONNECTED, crn=8000004, iEvent=0 ,256,2,4, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41
    Line 2934: 185146.692  22  16   5      6 ev    CallState GCEV_CONNECTED, crn=8000005, iEvent=0 ,256,2,4, s1:, s2:, s3:, build_date: 2018-04-12 16:14:59.41

Afterwards in following 20 minutes over 1800 outgoing calls were made by this system, and 360 of these outgoing calls were answered by the call recipient.

Of those, the first 213 outgoing calls were all reported as being connected, but from the following 1600 calls only about 150 were reported as connected.

Note that this 'Answered' message was not actual call answer, but looks like the VoIP service through which you are sending the calls (which looks to be a: Virtutel Hosted PBX - Asterisk) is just reporting all calls it receives as 'Answered' before it even tries to forward the call. Subsequent call progress testing by VoiceGuide determines that those 'answered' calls were not in fact actually answered.

If you could post the ktTel trace for this day then we can maybe see more information in that file as to what was happening while the last 1600 calls were made.

The WireShark trace attached captures calls that are not in the vgEngine trace, so looks like that trace was taken at a different time then the vgEngine trace.

Please note that we are unable to make any changes to posted attached files. If you are unable to post your traces on this public support forum then please contact support@voiceguide.com to arrange for a Direct Support Plan to be put in place.

 

[Guest Jean-Francois]

Here is the trace. I have included all file from specified date as I rebot VG many time.

Trace-2.zip

[SupportTeam]

Could you also please .ZIP up this entire directory:

C:\Program Files (x86)\Dialogic\HMP\log

and post the .ZIP file here.

 

[SupportTeam]

Traces show that the HPET timer is not enabled on this system.

Can you please try enabling the HPET timer on this system and restarting Windows.

If problems still persist then please post ktTel traces and the .ZIP'ed up contents of the C:\Program Files (x86)\Dialogic\HMP\log directory.

NB. Command to enable HPET is:

bcdedit /set useplatformclock true

and restart Windows after running the above command.

[Guest Jean-Francois]

 

Here are the files requested. 

On the system I have run hpettool64 /t and the awnser is hpet is hadware & BIOS supported and is enabled on this system.

Anyway I ran the bcdedit command and restarted Windows.

 

log_(1).zip

[SupportTeam]

Traces show the HPET timer is now enabled. From 0426_ktTel.txt :

016 092639.987  5664           HPET enabled. QueryPerformanceFrequency 14.32MHz (quad=14318180)

 

previous ktTel traces show that HPET was disabled. eg. from yesterday's 0425_ktTel.txt trace (and same can be seen in previous traces) :
 

016 200013.359  6308     WARN  HPET not enabled. Enable HPET timer and restart Windows. QueryPerformanceFrequency -1610612736MHz (quad=15064847973355386)

 

Traces show that no outgoing calls were made after enabling the HPET timer.

If you encounter problems on outgoing calls in future please .ZIP up VoiceGuide traces for that day, and in addition please .ZIP up this entire directory:

C:\Program Files (x86)\Dialogic\HMP\log

and post as well.

 

A WireShark trace capturing the calls would also help. It is possible that the hosted PBX service through which you are sending the calls is just throttling the number of calls that are being sent through their service...

[Guest Jean-Francois]

Trace for 04/28. Same problem back.

log_04_28.zip

[SupportTeam]

No WireShark traces were included in the attached files.

What is happening here is that the outgoing calls are being declined by the hosted PBX though which you are sending out these calls. (Virtutel)

WireShark traces that show the SIP messages sent between VoiceGuide and the Virtutel Hosted PBX will show that clearly.

 

VoiceGuide traces show the timestamps of the calls that were 'accepted' by this PBX for further dialing. Looks like at 9:30AM - when the dialing began on April 28 - the PBX service that you are using only allowed up to simultaneous 10 calls at a time and the rest of calls that are sent to the hosted PBX were just dropped/disconnected immediately by them.
 

518 093001.128  2128   3 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
680 093001.188  2128   7 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
717 093001.248  2128  10 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
760 093001.308  2128  13 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
796 093001.368  2128  16 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
824 093001.398  2128  19 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
868 093001.458  2128  22 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
904 093001.518  2128  25 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
932 093001.548  2128  28 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
968 093001.608  2128  31 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)


869 093034.056  2128   3 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
011 093034.116  2128  10 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
096 093034.176  2128  13 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
124 093034.206  2128  16 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
260 093034.266  2128  31 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
351 093034.326  2128  34 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
379 093034.356  2128  37 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
464 093034.416  2128  40 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
549 093034.476  2128  43 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)


908 093106.144  2128  25 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
993 093106.204  2128  37 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
316 093107.224  2128   3 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
359 093107.284  2128   7 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
395 093107.344  2128  10 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
423 093107.374  2128  19 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
467 093107.434  2128  22 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
503 093107.494  2128  28 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
531 093107.524  2128  31 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)
790 093110.314  2128  34 ev    GCEV_CONNECTED (ktTel_HMP30vista v7.5.19, Apr 12 2018 14:26:25)

 

You should limit your system to only send out maximum 10 calls at a time, or speak to the service provider that is hosting this Asterisk system through which you are sending out the calls to allow more then 10 simultaneous calls.

Further advice would be to switch to using a proper telco SIP trunk that advises actual call progress - instead of sending the calls through a hosted PBX that reports every call that it accepts for further dialing as immediately 'connected'.

 

On April 27th between 5:30PM and 8:21PM your PBX was accepting the 14 simultaneous calls that were being made by VoiceGuide. 4587 calls were accepted by the PBX for further dialing in that time. (about 27 accepted calls/min)

From 8:21PM till 8:45PM the PBX started declining calls over some threshold and only accepted 474 calls for further dialing in that time (about 20 accepted calls/min), and immediately declined all other calls presented to it when some internal limit was exceeded. This reduction would match a change from 14 simultaneous calls to a 10 simultaneous calls limit.

 

Dialogic traces from C:\Program Files (x86)\Dialogic\HMP\log  were also not included.

We need the corresponding Dialogic traces to further confirm correct operation.

[Guest Jean-Francois]

Trace for 04/28. Same problem back.

0430_vgService.zip

Dialogic_log.zip

WS_04-30-18.pcapng

[Guest Jean-Francois]

This one is shorter and have multiple errors.

2-0430_0000_vgEngine.zip

ncm-2_04-30-2018.zip

WS_04-30-18-2.pcapng

[SupportTeam]

Can you please unzip the attached file and then replace Dialogic HMP's RtfConfigWin.xml file with the version contained in the .ZIP

Better Dialogic RTF logging is enabled by replacing the RtfConfigWin.xml file with one attached.

On most versions of Windows the RtfConfigWin.xml file file is in: C:\ProgramData\Dialogic\HMP\cfg

Then please change the VoiceGuide's Config.xml file and enable only the first 10 lines for outbound calls by set the <AllowDialOut> setting on other channels to 1 on the first 10 channels, and 0 on the rest.

After changing the files please restart both Dialogic HMP and the VoiceGuide.

If you still encounter problems please post the VoiceGuide traces and .ZIP of Dialogic traces from C:\Program Files (x86)\Dialogic\HMP\log  directory.

[SupportTeam]

Attaching RtfConfigWin.zip :

RtfConfigWin.zip

[Guest Jean-Francois]

10 Lines is it for testing purpose only? My license with VG are at 20 lines and my ISP provider is 14 but with no limit for thesting.

[SupportTeam]

Yes. For testing.

Previously supplied traces show that your SIP provider is only allowing 10 simultaneous calls, and any calls made while there are 10 simultaneous calls present were immediately disconnected.

[Guest Jean-Francois]

It supposed to allow me with 20 channels. Did you see somethings in this trace? I do it with 14 lines.

 

WS_05-01-18.pcapng

HMP_05-01-2018_log.zip

05012018_log.zip

[SupportTeam]

The VoiceGuide license you have can do up to 20 channels.

But the PBX service that you are using only allowed up to simultaneous 10 calls at a time and the rest of calls that are sent to the hosted PBX were just dropped/disconnected immediately by them.

[Guest Jean-Francois]

With 10 lines, same problem.

WS-2_05-01-18.pcapng

Dialogic-2-05-01-2018log.zip

log-2-05-01-2018.zip

[SupportTeam]

Thanks for the traces. We will take a look at them now and advise.

[Guest Jean-Francois]

Old Dialogic Trace

Dialogic_Old_Trace_log.zip

[SupportTeam]

We are unable to reproduce this problem on our test systems.

We have tested on a few different systems with same version of HMP and VoiceGuide, with sizes similar to yours and significantly larger ones as well.

We put 100's of thousands of outgoing calls out through those systems and the issues that you encountered did not occur. Calls were made into an Asterisk PBX, like your calls are.

At this stage could you please update system to this version of VoiceGuide:

[link removed. use v7.5.20 onwards]

This version contains some more debugging that may help us see more information, and handles the NOTIFY messages in different way. (we did include in our tests the same NOTIFY messages that were sent by the remote Asterisk PBX to your system).

 

To change from one release of VoiceGuide v7 to another:

1. Stop VoiceGuide Service and exit all VoiceGuide programs. (eg Script Designer, Line Status Monitor, etc) and all other programs.

2. Run the VoiceGuide install and install into same directory as existing installation. (Do NOT uninstall the previous VoiceGuide installation).

3. Start VoiceGuide service.

Running a VoiceGuide install over the top of an existing install will NOT overwrite existing configuration or license files (Config.xml, ConfigLine.xml, VG.INI, etc) and will not remove any of users script or sound files, and will not remove any log files etc.

 

When problem occurs again can you search in CallEvents log for first occurrence of '0 length' call and the please .ZIP up and post the CallEvents log and ktTel log and the Dialogic log file that covers that time, and the previous Dialogic log file as well.