Vg 7 Lock Up

[Guest miva]

We have a dial out, conference and record application running on a Dialogic E1 card with VG7. VG Service was restarted this morning (16/01/2008) as part of a daily maintenance routine.

 

The system took a call at 16:13 this afternoon and according to the Line Status Monitor was still going some 30 minutes later. We assumed that the Line Status Monitor was in error in stating that the call was still online as the service we offer rarely takes calls longer than 4 or 5 minutes. Further investigation showed that the recording associated with this conversation was only 1kb in length and that the Log file had not date stamped any further information since "161332.796". We then elected to use the Line Status Monitor to end the call but this was unresponsive. We then tried to stop and restart the VG Service a couple of times to no avail. The only option left was to restart the server that the system resides on.

 

The service is now back up and running but I have the log file that I want you to investigate to advise what went wrong and how to prevent it from happening again. This log file has sensitive information and as such I would feel more comfortable emailing it to you. Please provide an email address and I will send through.

 

Also, I saw in the log file that:

timer set 2 EV_TIMEOUT_READYTOBEGINTRANSFER

 

Does this mean that the system waits 2 seconds to set up the transfer to the outbound leg? Can we reduce this time to make the conferencing appear seamless?

[SupportTeam]

Please email the log files support@voiceguide.com.

 

Does the Dialogic service or whole server itself get restarted on a regular basis, or just the VoiceGuide service?

 

The 2 second delay before the transfer should only happen if the previous module was also a transfer module, and the 2 seconds is the guard time to allow the previous transfer to be retrieved. When we look at the traces we should be able to better see what happened.

[Guest miva]

Email with log file sent.

[SupportTeam]

Trace shows that the Dialogic drivers replied with an error to the 2-line record request.

 

Would you have the "ktTel" trace available? The ktTel trace should give us more information about what caused the error.

 

Trace shows the service did seem to shutdown fine, taking about 2 seconds to close all the lines and exit.

 

 

161327.140 4 2 state [start Recording] type: VB Script

161327.140 4 2 rv replace start:

----------

set vg = CreateObject("vgServices.CommandLink")

vg.Record_2Lines_Start $RV_LINEID, $RV[Conf_LineId_1], $RV[Conf_LineId_2], "d:\Recordings\$RV[PartyB_2_1]\$RV[Filename]", ""

vg.Run_ResultReturn $RV_LINEID, "success"

set vg = Nothing

----------

...

161327.156 4 2 script will be ran from file: C:\Program Files\VoiceGuide\temp\vbs_2_1.vbs

161327.156 4 2 delete existing: C:\Program Files\VoiceGuide\temp\vbs_2_1.vbs

161327.156 4 2 RunVBScriptFile [wscript][C:\Program Files\VoiceGuide\temp\vbs_2_1.vbs][] timeout=60 (vbsPath=C:\Program Files\VoiceGuide\temp), start (new Process)

161327.156 4 2 RunVBScriptFile just started. Handle=7720, Id=3884, StartTime=16/01/2008 4:13:27 PM, HasExited=False

161327.156 4 2 VBScript started [C:\Program Files\VoiceGuide\temp\vbs_2_1.vbs], ProcessHandle=[7720], VbsOrExeProcess.WorkingSet=[708608]

161327.156 4 2 RunModule_Script_AfterScriptStarted start

161327.156 4 2 waiting. iRunWait=1 (process:7720)

161327.156 4 2 timer set 1 EV_TIMEOUT_CHECKONSTATE

161327.343 3 rem vgRemotingCommandLink constructor start, parmameterless

161327.343 3 remoting link constructor activated: vgServices_CommandLink

161327.359 3 2 cl Record_2Lines_Start [2,16,d:\Recordings\Taree\Taree_080116_16132758407.141.wav] options=[]

161327.359 3 2 Record_2Lines_Start [d:\Recordings\Taree\Taree_080116_16132758407.141.wav] ok

161327.375 3 2 cl Run_ResultReturn [success]

161327.375 3 2 rv add [start Recording_ResultReturn]{success}

161327.375 3 2 path {success} found (at offset 3)

161327.375 3 2 FindNextVgmTitleInPathList: next module title is=[Wait]

161327.375 3 2 module's runwait=1, WavPlayHasNowFinished=0, iRunWait_ExeResult_NextVgm=5

161327.375 3 2 timer clear (force=False)

161327.375 3 2 RunModule start [Play,[Wait],5]

161327.375 3 2 state [Wait] Playing

161327.375 3 2 PrepareAndPlayWavAndTts start iModuleIdx=5, iPlayFileIdx=1, bMakeTtsFile=True, sSoundFileIs=

161327.375 3 2 PrepareAndPlayWavAndTTS sPlayFile=none

161327.375 3 2 state [Wait] Playing wav (none)

161327.375 3 2 ScriptEventCode EV_PLAY_FINISHED, code=8001, state=1100

161327.375 3 2 LsPlayMsg EV_PLAY_FINISHED,EV_PLAY_FINISHED

161327.375 3 2 path {EV_PLAY_FINISHED} not found

161327.375 3 2 timer set 5 EV_TIMEOUT_REPLAYMSG

161327.453 9 2 ev Dialogic 137,TDX_ERROR,0,0,0,,,

161327.453 9 2 ScriptEventCode TDX_ERROR, code=137, state=1101

161327.453 9 2 LsPlayMsgFinished EV_UNKNOWN_137,TDX_ERROR

161327.453 9 2 path {TDX_ERROR} not found

 

...

 

164915.593 5 ------------------------------------------------------------------------------------------------------

164915.593 5 VgEngine Shutdown begin

164915.593 5 ------------------------------------------------------------------------------------------------------

 

...

 

164917.671 5 ------------------------------------------------------------------------------------------------------

164917.671 5 VgEngine Shutdown end

164917.671 5 ------------------------------------------------------------------------------------------------------

 

[Guest miva]

The KtTel has been sent to support email address.

 

The log file may show that the service stopped correctly but the interaction with the server showed otherwise. Just as when re-starting the service a new log file was created each time, yet the service icon in the system try indicated that it hadnt started yet and Line Status Monitor was unable to connect to VG either.

[SupportTeam]

Looks like something did happen on the Dialogic driver layer as the log shows that on a service restart attempt the Dialogic drivers would not even open the individual channels. We can see in log file lines like this:

 

165009.015 0704 gc_OpenEx :N_dtiB1T1:P_ISDN error (opening digital line)

...

165033.015 0704 gc_OpenEx :N_dtiB1T2:P_ISDN error (opening digital line)

...

165057.015 0704 gc_OpenEx :N_dtiB1T3:P_ISDN error (opening digital line)

...etc

 

VoiceGuide service did not start as it could not open the Dialogic channels.

 

Log shows that after the Dialogic service was restarted at 165344.875 the channels were then able to be opened properly.

 

Hard to say what could have caused the Dialogic to suddenly issue TDX_ERROR responses. Trace shows that immediately before the problem occurred there is a TDX_ERROR which arrived without any command being issued on the line that would warrant such a response (trace below).

 

Also, the events which we would expect to receive to indicate progress of the outgoing call were not sent to VoiceGuide by the Dialogic drivers.

 

What model Dialogic card and what SR drivers are used on this system?

How long was it since the Dialogic service itself was restarted on that system?

 

 

 

155846.984 2612 016 raise ev Dialogic GCEV_RELEASECALL 2137 (2137 0 0 )

155846.984 2612 002 CtEventProcess (from store) idx=903, iDev=2, lEvtType=2137, pEvtData=0x6ebc168, lEvtDataLen=28, (store: evinque=0, maxever=1)

155846.984 2612 002 metaevent: cclibid=0x2, crn=0x2009237, evtdatap=0x17008588, evtdev=0x2, evtlen=0x1c, evttype=0x859, extevtdatap=0x0, flags=0x1, linedev=0x2, magicno=0xbad012fb, rfu1=0x2, usrattr=0x1f1008 (usrattr=hli)

155846.984 2612 002 ev GCEV_RELEASECALL

155846.984 2612 002 raise ev Dialogic GCEV_RELEASECALL 2137 (2137 0 0 )

(15 minute gap here awaing next call...)

161324.718 2612 002 CtEventProcess (from store) idx=904, iDev=2, lEvtType=2135, pEvtData=0x6ebc198, lEvtDataLen=28, (store: evinque=1, maxever=1)

161324.718 2612 002 metaevent: cclibid=0x2, crn=0x0, evtdatap=0xc3370e8, evtdev=0x2, evtlen=0x1c, evttype=0x857, extevtdatap=0x0, flags=0x1, linedev=0x2, magicno=0xbad012fb, rfu1=0x2, usrattr=0x1f1008 (usrattr=hli)

161324.718 2612 002 ev GCEV_DETECTED

161324.718 2612 002 CtEventProcess (from store) idx=905, iDev=2, lEvtType=2084, pEvtData=0x6ebc1c8, lEvtDataLen=28, (store: evinque=0, maxever=1)

161324.718 2612 002 metaevent: cclibid=0x2, crn=0x2009239, evtdatap=0xc3370e8, evtdev=0x2, evtlen=0x1c, evttype=0x824, extevtdatap=0x0, flags=0x1, linedev=0x2, magicno=0xbad012fb, rfu1=0x2, usrattr=0x1f1008 (usrattr=hli)

161324.718 2612 002 ev GCEV_OFFERED (ktTel_SR60 v7.0.4, Nov 15 2007 17:17:27)

161324.718 2612 002 raise ev Dialogic GCEV_OFFERED 2084 (2084 0 0 )

161324.718 2612 002 raise ev CallState LINE_CALLSTATE-LINECALLSTATE_OFFERING

161324.718 2612 002 OnOffered_GetCallerID start (with CallerID report)

161324.718 2612 002 could not retrieve CALLNAME

161324.718 2612 002 CTelProxy::Event_CallerId begin. name=, ...

161324.718 2612 002 raise ev CallerId

161324.718 2612 002 fn LineAnswerCall(sXMLOptions=[])

161324.718 2612 002 CTelProxy::Event_CallerId end

161324.765 2612 002 CtEventProcess (from store) idx=906, iDev=2, lEvtType=2050, pEvtData=0x6ebc1f8, lEvtDataLen=28, (store: evinque=0, maxever=1)

161324.765 2612 002 metaevent: cclibid=0x2, crn=0x2009239, evtdatap=0xc3370e8, evtdev=0x2, evtlen=0x1c, evttype=0x802, extevtdatap=0x0, flags=0x1, linedev=0x2, magicno=0xbad012fb, rfu1=0x2, usrattr=0x1f1008 (usrattr=hli)

161324.765 2612 002 ev GCEV_ANSWERED (ktTel_SR60 v7.0.4, Nov 15 2007 17:17:27)

161324.765 2612 002 dx_setevtmsk(3, [MASK]) => 0

161324.781 2612 002 dx_setdigtyp(3, DM_DTMF) => 0

161324.781 2612 002 dx_clrdigbuf(3) => 0

161324.781 2612 002 streaming not enabled in this version.

161324.781 2612 route resources (dtiB1T1) call

161324.781 2612 002 Route_VoiceResource_To_dti begin dxxxB1C1:3 to dtiB1T1:2 (linedev=2)

161324.781 2612 002 raise ev Dialogic GCEV_ANSWERED 2050 (2050 0 0 )

161324.781 2612 002 raise ev CallState LINE_CALLSTATE-LINECALLSTATE_CONNECTED

161324.781 2612 003 CtEventProcess (from store) idx=907, iDev=3, lEvtType=137, pEvtData=0x6ebc228, lEvtDataLen=0, (store: evinque=0, maxever=1)

161324.781 2612 003 ev TDX_ERROR (Error Event)

161324.781 2612 003 TDX_ERROR hli=2035720 chdev=3 [96]:[Command not supported]

161324.781 2612 002 raise ev Dialogic TDX_ERROR 137 (0 0 0 )

161324.796 2612 003 dx_stopch call in TDX_ERROR

161324.796 2612 003 dx_stopch 3 ok (issued from within TDX_ERROR handler)

161324.796 2612 003 clearing dwPlayId and iRecId

[Guest miva]

The Dialogic Card is the D/300 JCT.

The Dialogic Release drivers are System Release 6.0 Build 61.

 

Is it possible to get VG to email us when the TDX_ERROR (161327.453 9 2 ev Dialogic 137,TDX_ERROR,0,0,0,,,) is encountered? I would ask if it could call us but I assume if the Dialogic Card is having issues then dialling out is possibly ot the best option let alone an option at all.

 

It would have been some time since the Dialogic service was re-started. We are looking at making this a 24/7 system in the very near future so if the Dialogic Service needs to be re-started, how often would you suggest?

 

Can you also confirm that we would have been better placed to try and restart the Dialogic Service instead of re-starting the PC, even though the end result would be the same?

 

 

 

[SupportTeam]

First thing would be to update to latest SR6.0. Current version is the SU171.

 

It'd be a good idea to automate a Dialogic service restart on a weekly basis. It's fairly easy to automate this by calling net start/stop commands from a batch file.

 

It would be possible to setup some extra monitoring, where for example VoiceGuide writes to a special log file whenever it encounters this type of error response from Dialogic and some monitoring program could then detect the file being created and could do appropriate alerting, or VoiceGuide does the alerting (email etc) itself. If you would like to implement something along those lines please contact sales@voiceguide.com along with your requirements.