Problems With Dtmf Detection.

[lucasklos]

Hello,
We have a VoIP setup, where the calls go from Cisco Extensions to CallManager and then to HMP+Voiceguide

The problem we're having is that when the caller dials the same digit more than once in sequence only one instance is recognized.
For instance if 21775 is typed what we see from voiceguide is 2175. But, when we call the IVR from a softphone, the digits are recognized properly.

We are using HMP (update 291) and VoiceGuide 7.2 on a Windows 7 Computer (32bits)

In the next link you will find:
0706_0127_vgEngine
0706_KtTel
20120706_CallTroubleshoot (a wireshark pcap trace, with calls using Cisco Extension)
20120706_CallTroubleshoot_Softphone (a wireshark pcap file with a call made from Softphone)
script_log.csv (vg script log file)

The calls we made for testing (the ones you will see on the traces) are:
From Cisco extentions (just digists entered by the caller):

Call 1: 2 2 1 7 7 5 2 1 7 7 5 # (voiceguide only recognized )
Call 2: 2 2 1 7 7 5 # 2 1 7 7 5 #
Call 3: 2 9 6 0 1 9 #

From these calls, most of the repeated numbers where not recognized (if the time delay between digits is long, sometimes the numbers are recognized)

From softphone (just digists entered by the caller):

3 3 2 1 7 7 5 2 1 7 7 5 2 1 7 7 5

These were all recognized properly, from the softphone everything works as expected.

Do you have any idea about what could be happening?
Please, let me know if you need any other information from our side.

Thanks!
Regards,

Lucas

[SupportTeam]

It looks like in both cases the DTMF signals are received by VoiceGuide/HMP using RFC 2833.

 

The source of problem is that it looks like when 'dialing from Cisco extension' the telephone handset plays a tone on the line, and then call goes through some equipment that tries to convert from DTMF tones heard on line to RFC 2833, and that equipment is not working well.

 

Whatever is doing the DTMF->RFC2833 is not recognizing two closely pressed tones as two separate tones, it considers them as one tone, and sends out only one RFC2833 packet.

 

 

We can see in 'Cisco Extension' calls that a DTMF tone was clamped (sound was removed from transmission). Tail end of clamped DTMF tone can be seen/heard in SIP call player.

 

You will need to determine what is doing the DTMF conversion/clamping and fix it.

 

Alternatively you can ensure that the 'Cisco extension' sends RFC2833 instead of playing DTMF tones - but you would then need to ensure that all equipment that is ever used to access the IVR sends RFC2833 (like the sofphone which looks like is configiured to just send RFC2833).

 

 

You do not need to do DTMF->RFC2833 conversion. HMP will recognize DTMF tones on line and report them - but then of course you need to ensure that your networking system never drops/delays any IP packets... otherwise a tone with packets dropped in the middle may be recognized as two tones...

 

 

DTMF tone detection problems like these, and intermittent quality loss due to dropped packets, are reasons why some sites chose to go ahead with non-VoIP systems for IVRs, and ensure that telephony traffic between Telco and IVR does not go over VoIP.

Edited 07/07/2012 11:04 AM by SupportTeam

[lucasklos]

Thank you for your reply!

 

How can I see that "a DTMF tone was clamped (sound was removed from transmission)" looking at the wireshark trace?

 

I see that the RFC2833 events are there for each digit pressed, but I can't see the part that is causing issues.

 

Is there any configuration file where I can set HMP to use only RFC2833? Which is it?

 

Thanks in advance.

[SupportTeam]

How can I see that "a DTMF tone was clamped (sound was removed from transmission)" looking at the wireshark trace?

Tail end of clamped DTMF tone can be seen/heard in SIP call player.

 

I see that the RFC2833 events are there for each digit pressed, but I can't see the part that is causing issues.

Well, no, they are not all there. That's the problem... that they are NOT there for every digit that was pressed by caller...

 

VoiceGuide detects/reports all RFC2833 events that have been received by it. But looks like RFC2833 events were not sent to VoiceGuide for every digit that caller pressed.

 

Is there any configuration file where I can set HMP to use only RFC2833? Which is it?

Don't think so. But even if there were, this is not something that would resolve the problem of missing RFC2833.

Edited 07/11/2012 11:20 PM by SupportTeam

[lucasklos]

Thanks!

 

Sorry for all the questions...

 

I've managed to get another pcap, from other device between Call Manager and the IVR server.

Could you please check if in this capture is seen that a DTMF tone was clamped?

I can see, using RTP player, some differences between this new pcap file and the one I uploaded previously, but I'm not sure how It should look like.

 

The digits pressed in this call are: 2 2 1 7 7 5 # 2 1 7 7 5 # 2 1 7 7 5 #

 

Thanks in advance.

 

Regards!

IVR2.zip

[SupportTeam]

There is no evidence of clamped tones in this file.

 

If tones are clamped then usually the tail end of clamped DTMF tone can be seen/heard in SIP call player.

 

What was the device used? Was the device set to send DTMF tones or RFC2833 ?

[lucasklos]

Sorry for the late response.

The device used to capture that last trace was just a switch, using port mirroring.

 

What I don't understand is why the digits are not recognized given though that all the RTP event packets are reaching the IVR server?

 

Because, if the problem is the audio part, Isn't there a way to ignore that audio part? I really don't need it.

 

I see that in HMP there is a setting “Setting Receive-only RFC 2833 Mode":

"In receive-only RFC 2833 mode, this additional transmit audio latency is reduced."

 

Do you know if there is any setting on HMP that we could enable to see more detailed logs? For example, I think It could be useful to know how HMP is handling the packets that it is receiving.

 

Any ideas?

 

Thank you very much!

[lucasklos]

Another thing, Cisco Call Manager is set to send RFC2833 (see attached, under Destination Details)

Thanks!

[SupportTeam]

VoiceGuide on HMP will automatically detect RFC-2833 events. There are no special setting that need to be made in HMP or in VoiceGuide to let it detect RFC 2833. It works 'out of the box'.

 

You report that all key presses are correctly detected when calling VoiceGuide+HMP from a softphone, but not all key presses are reported by HMP/VoiceGuide when calling from a Cisco phone.

 

Was the WireShark trace made on the same computer on which VoiceGuide/HMP is running?

Is the Win7 install running directly on the hardware, and not through some virtual machine?

 

 

Can you please do following:

 

1. Stop VoiceGuide service.

2. Delete all log files from VoiceGuide's \log\ subdirectory.

3. Edit Config.xml file to have VoiceGuide run the demo Credit Card Payment script.

4. Start VoiceGuide service.

5. Start WireShark. Make sure the WireShark trace is running on same computer as VoiceGuide+HMP, and that you are not running VoiceGuide+HMP on a virtual machine.

6. Make a call from softphone and jut press "1" 5 times. Press the keys as quickly as you like.

7. Make a call from the Cisco phone and press "2" 5 times. Press the keys as quickly as you like.

8. Save the WireShark trace.

9. .ZIP up the Wireshark trace and VoiceGuide traces and post them here.

[lucasklos]

Hello,

I'm attached the requested log and traces.

FYI, I have updated VoiceGuide and HMP to the latest version available on the respectives website.

 

The zip file attached contains:

VG_Logs folder: The log folder in the root of VoiceGuide installation

HMP_log folder: with the log contained in the log folder of HMP installation

Wireshark_capture folder: with the wireshark trace collected during the calls.

VG_Config folder: with Config.xml and vg.ini files (just in case they are needed).

 

Thanks in advance for any help!

 

Regards!

Log_Traces.zip

[SupportTeam]

Traces show that "11111" was detected on the 1st call:

 

171131.345  5956   3 ev    GCEV_ANSWERED crn=8000001

171134.088  5956   2 ev    TDX_CST (CST Event Received)
171134.088  5956   2       TDX_CST DE_DIGITS data=49 [1], KeysUsed=0
171134.089  5956   3 r     dtmf 1

171134.747  5956   2 ev    TDX_CST (CST Event Received)
171134.747  5956   2       TDX_CST DE_DIGITS data=49 [1], KeysUsed=0
171134.747  5956   3 r     dtmf 1

171135.468  5956   2 ev    TDX_CST (CST Event Received)
171135.468  5956   2       TDX_CST DE_DIGITS data=49 [1], KeysUsed=0
171135.468  5956   3 r     dtmf 1

171136.249  5956   2 ev    TDX_CST (CST Event Received)
171136.249  5956   2       TDX_CST DE_DIGITS data=49 [1], KeysUsed=0
171136.249  5956   3 r     dtmf 1

171136.875  5956   2 ev    TDX_CST (CST Event Received)
171136.875  5956   2       TDX_CST DE_DIGITS data=49 [1], KeysUsed=0
171136.875  5956   3 r     dtmf 1

171144.647  5956   3 ev    GCEV_DISCONNECTED crn=8000001

 

WireShark frames:

 

132	10.501113	10.61.69.208	10.56.69.54	SIP/SDP	1037	Request: INVITE sip:10.56.69.54, with session description

385	13.215557	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1
393	13.291064	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1 (end)

443	13.873604	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1
450	13.950101	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1 (end)

511	14.696917	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1
515	14.716653	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1 (end)

576	15.440854	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1
582	15.463936	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1 (end)

629	15.863598	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1
634	15.893484	10.61.69.208	10.56.69.54	RTP EVENT	60	Payload type=RTP Event, DTMF One 1 (end)

1390	24.432483	10.61.69.208	10.56.69.54	SIP	467	Request: BYE sip:10.56.69.54

 

 

 

and that a single "2" was detected on the second call, 4.2 seconds after call was answered:

 

171651.648  5956   7 ev    GCEV_ANSWERED crn=8000002

171655.849  5956   6 ev    TDX_CST (CST Event Received)
171655.849  5956   6       TDX_CST DE_DIGITS data=50 [2], KeysUsed=0
171655.849  5956   7 r     dtmf 2

171712.011  5956   7 ev    GCEV_DISCONNECTED crn=8000002

 

Wireshark frames:

 

4426	330.891320	10.56.74.33	10.56.69.54	SIP/SDP	1163	Request: INVITE sip:1055@10.56.69.54:5060, with session description

4924	334.967885	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2
4948	335.087816	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2 (end)

4963	335.207809	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2
4982	335.307762	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2 (end)

5003	335.487733	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2
5027	335.627685	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2 (end)

5040	335.747688	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2
5060	335.867695	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2 (end)

5075	335.987592	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2
5097	336.107573	10.56.74.38	10.56.69.54	RTP EVENT	70	Payload type=RTP Event, DTMF Two 2 (end)

6741	351.277923	10.56.74.33	10.56.69.54	SIP	551	Request: BYE sip:1055@10.56.69.54:5060

 

 

on 1st call:

 

RTP frames were not sent while the RTP EVENT messages were sent,

RTP EVENT messages had 80ms 'on' time, 400-700ms 'off' time

 

on 2nd call:

 

RTP frames continued to be sent while the RTP EVENT messages were sent.

RTP EVENT messages has 80-112ms 'on' time, 120-180ms 'off' time

 

 

Looks like 16ms window is used when sending the RTP.

HMP 3.0 Service Update 323 used.

 

Will contact Dialogic regarding this and advise.

 

 

 

 

 

 

NB. Please remove this <Dialer> section from the VoiceGuide Config.xml file:

<Dialer>

<OutDialQue_ADODB_Provider>VistaDB.NET20</OutDialQue_ADODB_Provider>
<OutDialQue_Database>vgDb.vdb3</OutDialQue_Database>
<OutDialQue_ConnectString>Data Source='$DATABASE';Open Mode=NonexclusiveReadWrite</OutDialQue_ConnectString>
<OutDialQue_SqlPrefix></OutDialQue_SqlPrefix>
<OutDialQue_SqlSuffix>ORDER BY Priority ASC</OutDialQue_SqlSuffix>

</Dialer>

[lucasklos]

Thanks!

I have removed the Dialer section on Config.xml.

 

Is there any other thing to look at while waiting for Dialogic reply?

 

Regards.

 

Lucas.

[SupportTeam]

For calls that come from the equipment whose DTMFs are not being all detected:

 

Can you tell us form your experience how far apart the DTMF tones need to be in order for them to be detected?

 

How were the DTMFs generated in the trace that showed the "RTP EVENT messages has 80-112ms 'on' time, 120-180ms 'off' time" ?

Were the five "2" tones pressed manually, with the five "2"s all pressed in one second or were these generated automatically by some speed-dial command etc?

[lucasklos]

Hello,

From the tests we have made, we have to wait at least 4 seconds between 2 digits (in this example between the first and the second "2") for them to be detected.

 

The five "2" tones were generated manually, using a Cisco Phone.

 

Regards.

[SupportTeam]

Could you please make a test call from Cisco phone with five "2"s pressed one or two seconds apart, and post the traces as before.

 

Can you indicate the model of the Cisco phone used and the other components in the environment through which the call is handled/routed.

[lucasklos]

Hello,

Attached is the trace and log files of the call you suggested.

Also I'm attaching another capture (file called "Call-16Aug") taken directly from the switch where the phone is connected to.

 

The next list of devices are between the phone used for some test calls (output taken using tracert):

 

1. WS-C3560E-12D 12.2(53)SE C3560E-UNIVERSALK9-M (10.56.69.253)

2. cisco WS-C6509-E s72033_rp-IPSERVICESK9_WAN-M), Version 12.2(33)SXH4 (10.56.254.1)

3. WS-C3750E-24PD 12.2(53)SE C3750E-UNIVERSALK9-M (10.56.254.42)

4. WS-C3750G-24PS 12.2(53)SE C3750-IPBASEK9-M (10.56.254.122)

Platform: Cisco IP Phone 7960

 

Thanks!

 

Regards.

CallTraceAndLog.zip

Call1-16Aug.zip

[SupportTeam]

Could you please collect system snapshot by executing:

C:\Program Files\Dialogic\bin\its_sysinfo.exe

 

and then .ZIP up its output and post it here.

[lucasklos]

Hi,

Attached is the output of its_sysinfo.exe.

Regards,

its_sysinfo(1).zip

[SupportTeam]

We have created a version that uses a different approach in Dialogic HMP to detect RFC2833 events.

Please ensure that you are using HMP3.0 SU323 or later on your system, then update system to this version of VoiceGuide:

[old link deleted]

Please post traces as before if you encounter any issues.

[lucasklos]

Hello,

Thanks for the reply.

 

I couldn't test the version you provided using Cisco phone but I have tested using a Softphone and I have a new problem:

When pressing "*", "0" or "#", voiceguide recognize "0", but wireshark trace shows that the digit is the correct one.

Please take a look at the log and pcap files I'm attaching to this post.

 

Best regards.

Lucas

CallTrace_Softphone.zip

[SupportTeam]

Please update system to this version of VoiceGuide:

[old link deleted]

Please post traces as before if you encounter any issues.


To update:

1. Stop VoiceGuide service and close any VoiceGuide programs.
2. Install over the top of existing installation.
3. Start VoiceGuide service (it it hasn't started automatically after install)

[lucasklos]

Hello,

Still having the same problem (when repeated numbers are pressed, voiceguide only recognize the first one)

Attached please find a pcap trace and logs files.

 

Regards

Call2_20120829.zip

[SupportTeam]

The version that is being ran is not the version that was supplied to be used ( VoiceGuide_7.3.2_120828_C126223.exe ).

 

Please download and install the version that was provided two posts back.

 

The install should be done over the top of existing version.

 

Only one instance/installation of VoiceGuide should be present on system.

Edited 08/30/2012 12:44 PM by SupportTeam
VoiceGuide_7.3.2_120827_C126223.exe changed to VoiceGuide_7.3.2_120828_C126223.exe

[lucasklos]

Ok,

i should install version 7.3.1,

then version 7.3.2 provided on 08/27/12

and then the latest version provided.

 

I will try that and let you know

[SupportTeam]

Just run the VoiceGuide_7.3.2_120828_C126223.exe. No need to install anything previously first.

 

VoiceGuide_7.3.2_120828_C126223.exe is a full install, not a 'patch'.

 

When you install it over top of existing install it keeps all the configuration files, and just updates all the .EXEs/.DLLs etc.

Edited 08/30/2012 12:45 PM by SupportTeam
VoiceGuide_7.3.2_120827_C126223.exe changed to VoiceGuide_7.3.2_120828_C126223.exe

[lucasklos]

VoiceGuide_7.3.2_120827_C126223.exe has a problem reported a few posts back ('*' and '#' where recognized as '0').

After that, you provided VoiceGuide_7.3.2_120828_C126223.exe, which fixes this problem ('*' and '#' where recognized as '0'), but the issue with repeated number is still happening.

 

To collect the latest traces I posted, I used VoiceGuide_7.3.2_120828_C126223.exe.

 

Should the problem with repeated digits be fixed on VoiceGuide_7.3.2_120828_C126223.exe?

 

Thanks!

[SupportTeam]

Wrong filename was quoted in our last two posts. It should be VoiceGuide_7.3.2_120828_C126223.exe - as you correctly noticed.

 

The last log files that you posted (Call2_20120829.zip) were not taken from VoiceGuide_7.3.2_120828_C126223.exe

Those logs were created with an older version of VoiceGuide.

[SupportTeam]

Header of vgEngine trace included in Call2_20120829.zip shows us that it's an older version.

 

104400.629  5               ------------------------------------------------------------------------------------------------------
104400.629  5               vgEngine version : 7.3.4538.25968 (RELEASE Build)
104400.629  5               created on       : 2012-06-04 13:25:36.57
104400.629  5               AssemblyLocation : C:\Program Files\VoiceGuide\vgEngine.dll
104400.629  5               LastWriteTime    : 2012-06-06 01:22:12
104400.629  5               trace lvl=10, trace file encoding=System.Text.ASCIIEncoding (ASCII)
104400.629  5               ------------------------------------------------------------------------------------------------------

[lucasklos]

That's odd.

Just in case I will completelly unninstall the older version, install VoiceGuide_7.3.2_120828_C126223.exe and restore the configuration files.

 

Thanks!

[lucasklos]

Hello,

I have unninstall the older version and then install the new one, and the issue with repeated number is solved.

But, another issue came up regarding to the "Verify entered number" script in GetNumbers module.

If the verification is not successful, the system doesn't play the audio file for that case. In fact, it remains waiting on the module, doesn't ask to re-enter the number nor goes to the next module.

 

When all the verification pass, everything is working fine.

 

For example, in the attached logs the first call made was:

2 to select option to enter the "EnterUserID" module.

System asks for UserId, entered 33333 and then pressed # to confirm.

 

Any ideas what could it be?

 

I'm also attaching the script we use.

 

Thanks!

logs_20120830.zip

AIMS-IVR_Flow.vgs

[SupportTeam]

Thanks for letting us know the keypress detection issue is now solved.

 

As for the "verification is not successful" handling:

 

As an immediate workaround please add a path EV_MODGETNBRS_VERIFY_FAIL to that module. The EV_MODGETNBRS_VERIFY_FAIL path will be taken when the verification fails.

 

Please also stat a new topic about this - we can post any fixes for this issue in that new topic.

 

 

154710.529  6   3   1 state [EnterUserID] Number Input 33333
154710.529  6   3   1       path {33333} not found
154710.529  6   3   1 t     timer set   6 sec : EV_TIMEOUT_ENTERDATA
154711.699 16   3   1 ev    dtmf #   (134217729,35,10)
154711.699 16   3   1       q scr add   evScriptEvent 35 #
154711.699  6   3   1       q scr run   evScriptEvent sCode=[#] iActionID=0, crn=0[0|0|0|0|0][|||||] 2|00:00:00.0120012
154711.699  6   3   1       scriptevent #  0|0|0  || LineState=LS_GETNBRS_RXDIGITS
154711.699  6   3   1       LsGetNbrsRxDigits #,#
154711.699  6   3   1 t     timer clear (force=False)
154711.699  6   3   1       rv    add   [EnterUserID]{33333}
154711.699  6   3   1       d     added EnterUserID | 33333
154711.699  6   3   1       d     added EnterUserID | 33333
154711.699  6   3   1       run verification
154711.699  6   3   1       rv    replace start 
------------------------------
On Error Resume Next
Err.Clear

Set vg = CreateObject("vgServices.CommandLink")
Dim result
Dim crashBody

If Len("$RV_ENTEREDNUMBER")<7 Then
Set objFSO = CreateObject("Scripting.FileSystemObject")
Set oFile = objFSO.OpenTextFile("$RV[VBSFunctionsFile]", 1)
sText = oFile.ReadAll
oFile.Close
ExecuteGlobal sText

isAvailable = TestConnection("$RV[serverAddress]")

If isAvailable = 1 Then

	Dim messageXML
	Set messageXML = CreateObject("MSXML2.DOMDocument.6.0")

	messageXML.LoadXML (GenerateXMLValidateUser("$RV_ENTEREDNUMBER"))

	xmlHttp = SendRequest("$RV[serverAddress]", messageXML, "ValidateIVRUser")

	textResponse = GetResponse(xmlHttp)

	If textResponse = 1 Then
		result = "verify_passed"
	ElseIf textResponse = 0 Then
		result = "verify_failed"
	Else
		crashBody = GenerateHTMLBody("$RV_STARTTIME", 0, "Unknown","EnterUserID",$RV_LINEID,"$RV[DlgcVoice]","$RV[DlgcNetwork]",xmlHttp)
		SendCrash  crashBody, "$RV[CrashFrom]", "$RV[CrashTo]", "$RV[EmailUser]", "$RV[EmailPassword]", "$RV[sMTPServer]", "$RV[sMTPServerPort]"
		result = "error"
	End If

Else
	result = "unavailable"
End If

Else
result = "verify_failed"
End If

If Err.Number <>0 Then
crashBody = GenerateHTMLBody("$RV_STARTTIME", Err.Number, Err.Description,"EnterUserID",$RV_LINEID,"$RV[DlgcVoice]","$RV[DlgcNetwork]",xmlHttp)
SendCrash  crashBody, "$RV[CrashFrom]", "$RV[CrashTo]", "$RV[EmailUser]", "$RV[EmailPassword]", "$RV[sMTPServer]", "$RV[sMTPServerPort]"
vg.Run_ResultReturn $RV_LINEID, "error"
Else
vg.Run_ResultReturn $RV_LINEID, result
End If

Set vg = Nothing
Set objFSO = Nothing
Set oFile = Nothing
Set sText = Nothing
Set messageXML = Nothing
Set xmlHttp = Nothing
Set textResponse = Nothing

------------------------------
154711.701  6               rv    dbg   rv_retrieve did not find [EmailUser] ( 45 6d 61 69 6c 55 73 65 72)
154711.701  6               rv    dbg   rv_retrieve did not find [EmailPassword] ( 45 6d 61 69 6c 50 61 73 73 77 6f 72 64)
154711.701  6               rv    dbg   rv_retrieve did not find [EmailUser] ( 45 6d 61 69 6c 55 73 65 72)
154711.701  6               rv    dbg   rv_retrieve did not find [EmailPassword] ( 45 6d 61 69 6c 50 61 73 73 77 6f 72 64)
154711.707  6   3   1       copy of verification script ran: vbs_3_3.vbs
154711.707  6   3   1       current objVbsOrExeProcess=System.Diagnostics.Process (wscript)
154711.707  6   3   1       current objVbsOrExeProcess details : id=3100, handle=4808, hasExited=True, startTime=8/30/2012 3:46:55 PM, exitTime=8/30/2012 3:46:58 PM
154711.707  6   3   1       RunVBScriptFile [wscript][C:\Program Files\VoiceGuide\temp\vbs_3_3.vbs][] timeout=0 (vbsPath=C:\Program Files\VoiceGuide\temp), start (new Process)
154711.707  6   3   1       objVbsOrExeProcess.Start call
154711.714  6   3   1       RunVBScriptFile just started. Handle=4816, Id=3252, StartTime=8/30/2012 3:47:11 PM, HasExited=False
154711.714  6   3   1       Run Script (getnbrs) waiting. iRunWait=1, processHandle=4816, pid=3252
154711.714  6   3   1 t     timer set   1 sec : EV_TIMEOUT_CHECKONSTATE
154712.693  4   3   1 timer EV_TIMEOUT_CHECKONSTATE
154712.693  4   3   1       q scr add   evScriptEvent 9007 EV_TIMEOUT_CHECKONSTATE
154712.693  6   3   1       q scr run   evScriptEvent sCode=[EV_TIMEOUT_CHECKONSTATE] iActionID=0, crn=0[0|0|0|0|0][|||||] 2|00:00:00.0120012
154712.693  6   3   1       scriptevent EV_TIMEOUT_CHECKONSTATE  0|0|0  || LineState=LS_GETNBRS_RXDIGITS
154712.693  6   3   1       LsGetNbrsRxDigits EV_TIMEOUT_CHECKONSTATE,EV_TIMEOUT_CHECKONSTATE
154712.693  6   3   1       path {EV_TIMEOUT_CHECKONSTATE} not found
154712.693  6   3   1       Process.HasExited is false (awaiting process end or COM function call) handle=4816, id=3252, StartTime=8/30/2012 3:47:11 PM
154712.694  6   3   1       .ExitTime returned error.
154712.694  6   3   1       verify task still running (processHandle=4816, pid=3252)
154712.694  6   3   1 t     timer set   1 sec : EV_TIMEOUT_CHECKONSTATE
154712.863 19               remoting link constructor activated: vgServices_CommandLink
154712.917 19   3   1 rem   Run_ResultReturn [verify_failed] 13
154712.917 19   3   1       q scr add   cmdRun_ResultReturn 0 
154712.917  6   3   1       q scr run   cmdRun_ResultReturn sCode=[] iActionID=0, crn=0[0|0|0|0|0][verify_failed|||||] 2|00:00:00.0120012
154712.917  6   3   1       q scr add   evScriptEvent 9220 EV_MODGETNBRS_VERIFY_FAIL
154712.917  6   3   1       q scr run   evScriptEvent sCode=[EV_MODGETNBRS_VERIFY_FAIL] iActionID=0, crn=0[0|0|0|0|0][|||||] 2|00:00:00.0120012
154712.917  6   3   1       scriptevent EV_MODGETNBRS_VERIFY_FAIL  0|0|0  || LineState=LS_GETNBRS_RXDIGITS
154712.917  6   3   1       LsGetNbrsRxDigits EV_UNKNOWN_9220,EV_MODGETNBRS_VERIFY_FAIL
154712.917  6   3   1       path {EV_MODGETNBRS_VERIFY_FAIL} not found
154712.917  6   3   1       GetNbr EV_MODGETNBRS_VERIFY_FAIL
154712.917  6   3   1       GetNbr set iCurrReplayCount to 2, max iReplayCount=5