Call Hangs On Capture Entered Number Module

[jph2658]

Any thoughts on why the call on device dxxB1C1 hangs on the PagerNumber module?

 

What can be done to prevent this?

 

line status monitor.zip

 

The log files and script iteself are much larger that 500K... so please let me know the best way to get you those.

[jph2658]

Does anyone know why a call would hang on the Capture Entered Number module?

 

Please let me know if additional information is required.

 

 

log.zip

 

PTR.vgs

[SupportTeam]

Please post the vgEngine traces that capture the call, we can then see what has happened during the call.

 

vgEngine traces are located in VoiceGuide's \log\ subdirectory.

 

Please .ZIP up the traces before posting.

[jph2658]

Please let me know if you need further information.

 

[old link removed]

[SupportTeam]

This is a larger script so its not immediately apparent which module we should be looking at.

There is no module titled "Capture Entered Number".

 

What is the title of the module that you are having issues with?

 

The traces uploaded are over 160MB in size. Which call in those traces is the one in which you came across an unexpected hangup?

Can you give us a timestamp?

[SupportTeam]

In another topic created by you you refer mention that module name is: PagerNumber

 

We looked through part of the traces and in all cases that we looked the caller has entered the 7 digit number into the system, and script moved onto the next module (a DB Query type module titled "UserID")

 

If you can advise the timestamp of the problem call we can look through the traces to see what was the problem on that call.

[SupportTeam]

We have merged the two topics together, so all discussion is done in one thread.

[jph2658]

The image of the Line Status Monitor (attached in my first post) is very blurry for some reason, but I was trying to show that for device dxxxB1C1 on row 1, the status is set to [PagerNumber] Number Input 2202820, and the call length is set to about 68011.

Do you know why the call length would be so long, and why it doesn't eventually hang up to free up the line?

What is the title of the module that you are having issues with?
The module it titled PageNumber.

It happened again yesterday (2/20). Below are additional logs for 2/20 if you find them useful. The issue occurred sometime before 5:30 PM EST. Both lines were busy at this point and VoiceGuide was no longer accepting any calls.

[old link removed]

The traces uploaded are over 160MB in size. Which call in those traces is the one in which you came across an unexpected hangup?
The issue is that the call doesn't hangup and keeps the line busy. When I say "hangs on the PagerNumber module", I meant the line never hangs up, and attempts to call it return a busy signal. Also, when looking at the line status monitor, I see the call length is set to a very large number, i.e. 68011.

Can you give us a timestamp?
It happened on 9/19 sometime before 3:30 PM EST, and again on 2/20 sometime before 5:30 PM EST. I can't be sure exactly when, since the only symptoms I see are the high value for call length in the line status monitor and a busy line. If you could help me find that originating call I would be very grateful.

At some point on 9/19, the first line (device dxxxB1C1 on row 1) returned only a busy signal. In order to get the timestamp you're looking for, is it feasible for you to identify the last call received on that line? On 2/20, both lines returned busy signals so it may be easier to identify there.

[SupportTeam]

If you could help me find that originating call I would be very grateful.

The call start time is displayed in the line status. The screenshot posted is too small to read any information from it though...

[SupportTeam]

We found one call that is probably the one that you referred to in first set of logs.

 

It's in the 0219_1156_vgEngine.txt trace file and the call starts at 13:41:18

 

What is unusual about this system is that the Dialogic card is reporting that first two RINGs for that call arrived about half a second apart:

 

134118.375 200 1 ev TDX_CST (CST Event Received)

134118.375 200 1 TDX_CST DE_RINGS data=0 ringcount=1 crn=100003b5 (hli=09E31598, hli->voicedev=1, hli->linedev=1) iCallDirection=1

 

134118.687 200 1 ev TDX_CST (CST Event Received)

134118.687 200 1 TDX_CST DE_RINGS data=0 ringcount=2 crn=100003b5 (hli=09E31598, hli->voicedev=1, hli->linedev=1) iCallDirection=1

 

Traces also show that the VoiceGuide system processes are not running as fast as we usually would expect them to.

 

Are there any other applications running on this system that are utilizing the system heavily?

Are the rings on this telephone line signaled by the Telco at such a rapid rate? This would be very unusual. Most likely whatever is slowing down the system also slowed down Dialogics own low level drivers event processing. This is quite unusual.

 

Can you advise what type of system this is (CPU/RAM/OS/etc) and what is running on this system apart from Dialogic+VoiceGuide?

 

 

The rapid arrival of RING events, combined with them being processed slower then usual led to VoiceGuide internal call accounting becoming a bit confused as to what is actually happening on this line.

 

We have made a new release that handles this combination of events correctly and will post the download link to this new version here in this thread soon.

[SupportTeam]

traces from 20th show similar situation.

 

145313.955  5196   3       CtEventProcess idx=4331 : evttype=134(134), crn=0, data=0827AD48(07B81AB0), len=4(4) q: 0/2
145313.955  5196   3 ev    TDX_CST (CST Event Received)
145313.955  5196   3       TDX_CST DE_RINGS data=0 ringcount=1 crn=1000007a (hli=0F8327F0, hli->voicedev=3, hli->linedev=3) iCallDirection=1
145313.955  5196   3       GetCallerIdInfo_OnAnalogLines begin
145314.143  5196   3       CLIDINFO_CMPLT returned
145314.143  5196   3       CLIDINFO_CMPLT error [128]:[Caller ID info/sub-msg not available]
145314.205  5196   3       CLIDINFO_GENERAL error [128]:[Caller ID info/sub-msg not available]
145314.268  5196   3       CLIDINFO_CALLID error [128]:[Caller ID info/sub-msg not available] assign strCLIDINFO_CALLID:
145314.268  5196   3       setting strCLIDINFO_CALLID to NOTAVAILABLE
145314.346  5196   3       CLIDINFO_FRAMETYPE error [128]:[Caller ID info/sub-msg not available]
145314.346  5196   3       caller id frame type: UNKNOWN [0x00]
145314.346  5196   3       pbx sent display information (D42 API) not supported on this card
145314.346  5196   3       pbx sent callid information (D42 API) not supported on this card
145314.361  5196   3 info  ktTel_SR60 v7.3.0, build: Jan  8 2012 13:22:40
145314.361  5196   3       CTelProxy::Event_CallState DE_RINGS iLineCallState=2, hCall=268435578 m_pktTelProxyClient=00691408
145314.361  5196   3 r     CallState DE_RINGS
145314.361  5196   3       CTelProxy::Event_Ring begin (ring count=1)
145314.361  5196   3 r     Ring 1
145314.361  5196   3 r     Dialogic  TDX_CST 134 (0 0 0 DE_RINGS ET_RON )
145314.393  2832   3       iTimer_RingsGoAway=100
145314.549  4796   3 fn    AnswerCall(sXMLOptions=[])
145314.596  4796   3       dx_adjsv (3, SV_VOLUMETBL, SV_ABSPOS, SV_ADD4DB) default call
145314.658  4796           pbx display (3) [1286]:[(null)]
145314.658  4796           pbx callid (3) [1286]:[(null)]
145314.815  5196   3       CtEventProcess idx=4332 : evttype=134(134), crn=0, data=0827AD78(07B81AB0), len=4(4) q: 0/2
145314.815  5196   3 ev    TDX_CST (CST Event Received)
145314.815  5196   3       TDX_CST DE_RINGS data=0 ringcount=2 crn=1000007a (hli=0F8327F0, hli->voicedev=3, hli->linedev=3) iCallDirection=1
145314.815  5196   3       GetCallerIdInfo_OnAnalogLines begin
145314.924  5196   3       CLIDINFO_CMPLT returned
145314.924  5196   3       CLIDINFO_CMPLT error [6]:[Parameter error]
145314.924  4796   3       dx_sethook (3, DX_OFFHOOK) ok (iCallDirection=1)
145314.924  4796   1 fn    PlayStop(iLineId=1, iActionID=0, iParam1=0, iParam1=0, sParam1=, sParam1=)
145314.924  4796   1       PlayStop(hLine=1, iPlayId=0(0x0), iParam1=0, iParam2=0, zsParam1=, zsParam2=)
145314.924  4796   1       dx_stopch call in PlayStop
145314.971  4796   1       dx_stopch 1 ok
145314.971  5196   3       CLIDINFO_GENERAL error [6]:[Parameter error]
145315.002  5196   3       CLIDINFO_CALLID error [6]:[Parameter error] assign strCLIDINFO_CALLID:
145315.002  5196   3       setting strCLIDINFO_CALLID to [Parameter error]
145315.002  5196   3       CLIDINFO_FRAMETYPE error [6]:[Parameter error]
145315.002  5196   3       caller id frame type: UNKNOWN [0x00]
145315.002  5196   3       pbx sent display information (D42 API) not supported on this card
145315.002  5196   3       pbx sent callid information (D42 API) not supported on this card
145315.002  5196   3       CTelProxy::Event_Ring begin (ring count=2)
145315.002  5196   3 r     Ring 2
145315.002  5196   3 r     Dialogic  TDX_CST 134 (0 0 0 DE_RINGS ET_RON )
145315.096  2832   3       iTimer_RingsGoAway=100
145315.377  5196   3       CtEventProcess idx=4333 : evttype=135(135), crn=0, data=0827ADA8(07B81AB0), len=4(4) q: 1/2
145315.377  5196   3 ev    TDX_SETHOOK (SetHook Completed)
145315.393  5196   3       set hli->pCTelProxyhli (in TDX_SETHOOK). current hli->pCTelProxyhli=08248118, pTelClientEvents=08248118
145315.393  5196   3       TDX_SETHOOK - CALL_INBOUND Handler
145315.393  5196   3 r     Dialogic  TDX_SETHOOK 135 (0 0 0 DX_OFFHOOK CALL_INBOUND )
145315.393  5196   3       now calling Event_CallState with CONNECTED
145315.393  5196   3       CTelProxy::Event_CallState TDX_SETHOOK_DX_OFFHOOK iLineCallState=256, hCall=268435578 m_pktTelProxyClient=00691408
145315.393  5196   3 r     CallState TDX_SETHOOK_DX_OFFHOOK
145315.455  5196   3       CtEventProcess idx=4334 : evttype=134(134), crn=0, data=0827ADD8(07B81AB0), len=4(4) q: 0/2
145315.455  5196   3 ev    TDX_CST (CST Event Received)
145315.455  5196   3       TDX_CST DE_LCON data=23336
145315.455  5196   3 r     Dialogic  TDX_CST 134 (23336 0 0 DE_LCON  )





165905.273  5196   1 ev    TDX_CST (CST Event Received)
165905.273  5196   1       TDX_CST DE_RINGS data=0 ringcount=1 crn=1000009c (hli=09583130, hli->voicedev=1, hli->linedev=1) iCallDirection=1
165905.273  5196   1       GetCallerIdInfo_OnAnalogLines begin
165905.633  5196   1       CLIDINFO_CMPLT returned
165905.633  5196   1       CLIDINFO_CMPLT error [128]:[Caller ID info/sub-msg not available]
165905.664  5196   1       CLIDINFO_GENERAL error [128]:[Caller ID info/sub-msg not available]
165905.773  5196   1       CLIDINFO_CALLID error [128]:[Caller ID info/sub-msg not available] assign strCLIDINFO_CALLID:
165905.773  5196   1       setting strCLIDINFO_CALLID to NOTAVAILABLE
165905.804  5196   1       CLIDINFO_FRAMETYPE error [128]:[Caller ID info/sub-msg not available]
165905.804  5196   1       caller id frame type: UNKNOWN [0x00]
165905.804  5196   1       pbx sent display information (D42 API) not supported on this card
165905.804  5196   1       pbx sent callid information (D42 API) not supported on this card
165905.804  5196   1 info  ktTel_SR60 v7.3.0, build: Jan  8 2012 13:22:40
165905.804  5196   1       CTelProxy::Event_CallState DE_RINGS iLineCallState=2, hCall=268435612 m_pktTelProxyClient=00691408
165905.804  5196   1 r     CallState DE_RINGS
165905.820  5196   1       CTelProxy::Event_Ring begin (ring count=1)
165905.820  5196   1 r     Ring 1
165905.820  5196   1 r     Dialogic  TDX_CST 134 (0 0 0 DE_RINGS ET_RON )
165905.820  5196   1       CtEventProcess idx=446 : evttype=134(134), crn=0, data=0824D4D8(07B81AB0), len=4(4) q: 0/2
165905.820  5196   1 ev    TDX_CST (CST Event Received)
165905.820  5196   1       TDX_CST DE_RINGS data=0 ringcount=2 crn=1000009c (hli=09583130, hli->voicedev=1, hli->linedev=1) iCallDirection=1
165905.820  5196   1       GetCallerIdInfo_OnAnalogLines begin
165905.820  4796   1 fn    AnswerCall(sXMLOptions=[])
165905.820  5196   1       CLIDINFO_CMPLT returned
165905.820  5196   1       CLIDINFO_CMPLT error [128]:[Caller ID info/sub-msg not available]
165905.851  4796   1       dx_adjsv (1, SV_VOLUMETBL, SV_ABSPOS, SV_ADD4DB) default call
165905.851  5196   1       CLIDINFO_GENERAL error [128]:[Caller ID info/sub-msg not available]
165905.851  4796           pbx display (1) [1286]:[(null)]
165905.851  4796           pbx callid (1) [1286]:[(null)]
165905.867  4796   1       dx_sethook (1, DX_OFFHOOK) ok (iCallDirection=1)
165905.867  5196   1       CLIDINFO_CALLID error [128]:[Caller ID info/sub-msg not available] assign strCLIDINFO_CALLID:
165905.867  5196   1       setting strCLIDINFO_CALLID to NOTAVAILABLE
165905.898  5196   1       CLIDINFO_FRAMETYPE error [6]:[Parameter error]
165905.898  5196   1       caller id frame type: UNKNOWN [0x00]
165905.898  5196   1       pbx sent display information (D42 API) not supported on this card
165905.898  5196   1       pbx sent callid information (D42 API) not supported on this card
165905.898  5196   1       CTelProxy::Event_Ring begin (ring count=2)
165905.898  5196   1 r     Ring 2
165905.914  5196   1 r     Dialogic  TDX_CST 134 (0 0 0 DE_RINGS ET_RON )
165906.008  2832   1       iTimer_RingsGoAway=100
165906.398  5196   1       CtEventProcess idx=447 : evttype=135(135), crn=0, data=0824D508(07B81AB0), len=4(4) q: 1/2
165906.398  5196   1 ev    TDX_SETHOOK (SetHook Completed)
165906.398  5196   1       set hli->pCTelProxyhli (in TDX_SETHOOK). current hli->pCTelProxyhli=08248118, pTelClientEvents=08248118
165906.398  5196   1       TDX_SETHOOK - CALL_INBOUND Handler
165906.398  5196   1 r     Dialogic  TDX_SETHOOK 135 (0 0 0 DX_OFFHOOK CALL_INBOUND )
165906.398  5196   1       now calling Event_CallState with CONNECTED
165906.398  5196   1       CTelProxy::Event_CallState TDX_SETHOOK_DX_OFFHOOK iLineCallState=256, hCall=268435612 m_pktTelProxyClient=00691408
165906.398  5196   1 r     CallState TDX_SETHOOK_DX_OFFHOOK
165906.414  5196   1       CtEventProcess idx=448 : evttype=134(134), crn=0, data=0824D538(07B81AB0), len=4(4) q: 0/2
165906.414  5196   1 ev    TDX_CST (CST Event Received)
165906.414  5196   1       TDX_CST DE_LCON data=386
165906.414  5196   1 r     Dialogic  TDX_CST 134 (386 0 0 DE_LCON  )

[SupportTeam]

Version which handles the 'two rapid RINGs" situation can be downloaded here:

[old link removed]

To update system just stop VoiceGuide service and then run the install and install over the top of existing system.


You should also look into what other programs are overloading this system.

[jph2658]

The following new issues were reported with the custom version sent on 2/22/2012. The good news is, the new version (7.3.0_120222) appears to fix the ‘two rapid RINGs’ situation, so thank you there. However, new issues are occurring. We’re running the exact same script with no changes other than installing the new version.

Query Database modules

Many of the Query Database modules now take the fail path and we’re wondering why. For example [TaskCount] takes the fail path when TaskCount_RowCount is 0. We want it to take the success pass, so that TaskCount_RowCount can be used in the next module [HasTask]. We’re running the exact same script we ran in the previous version (6.0.0.3391), and the script works in the old version and not in the new.

The issue is not limited to [TaskCount], any Query Database module may experience this issue if it’s RowCount is 0. Take a look at the call on 2012-03-08 13:34:36. You’ll see: Hangup Source oVgmDbQuery_AdoNetCommon_Completed PathNotDefined. We know that particular error is because there is no fail path defined, but that’s not what we’re worried about. We’re concerned with why the module is sending us on the fail path. What can be done to resolve this?

Performance

The performance of the application has slowed to a crawl. Transitions between modules take longer than they did in the previous version (6.0.0.3391). Any ideas on what is going on there?

 

[old link removed]

[SupportTeam]

The good news is, the new version (7.3.0_120222) appears to fix the ‘two rapid RINGs’ situation, so thank you there.

OK, thanks for letting us know this issue is now fixed.

 

 

takes the fail path when TaskCount_RowCount is 0

The "Fail" path will be taken if the database query returns no rows.

 

Please see the "Paths" section of the Help file entry on the Database Query module: http://www.voiceguide.com/vghelp/source/html/moddbquery.htm

 

And in the script that you attach we see that the script is already going to different modules depending on whether the database query module does retrieve any data from database or not.

eg: in module [userID] we see paths:

on {success} goto [userID Found]

on {fail} goto [userID Missing]

 

 

looking through a frw other modules we note that in module [TaskCount] we see paths:

on {success} goto [HasTask]

on {fail} goto [TaskCount]

 

the on {fail} goto [TaskCount] path sets up an infinite loop. This path should be deleted.

 

 

 

If you would like for script to proceed to next module regardless of whether the database query module has retrieved any data or not then you will need to have both "on {success} ..." and "on {fail} ... " paths pointing to that next module.

 

 

Transitions between modules take longer than they did in the previous version (6.0.0.3391)

v7 has slightly higher system requirements then v6. Do you have sufficient RAM in system to run Microsoft's .NET ?

Please start a new topic indicating what type of system you are using (CPU/RAM/Windows version etc.) and if anything else is running on this system at the same time, and we can then better answer any questions on this. A module transition should take very little time (a few milliseconds at most).