Very Long Executing Time Of Cmd

[invoso.com]

After last VG update

 

231847.525 6 ------------------------------------------------------------------------------------------------------
231847.525 6 vgEngine version : 7.4.5207.24383 (RELEASE Build)
231847.525 6 Compiled on : 2014-04-04 13:32:46.19
231847.525 6 AssemblyLocation : C:\Program Files (x86)\VoiceGuide\vgEngine.dll
231847.525 6 LastWriteTime : 2014-04-04 04:35:18
231847.525 6 trace lvl=10, encoding=System.Text.ASCIIEncoding (ASCII)
231847.525 6 ------------------------------------------------------------------------------------------------------
231847.525 6 currentTime : 2014-04-07 23:18:47, UTC: 2014-04-07 21:18:47

 

command:

c:\callrecord\ffmpeg_32.exe -i c:\callrecord\$RV[session_id].wav -ab 64k c:\callrecord\$RV[manager]\$RV[session_id].mp3

 

in RUN program module executing

 

before:

191955.516 7 13 5 FindNextVgmTitleInPathList: next module title is=[konwersja ff]
191955.516 7 13 5 t timer clear (force=False)
191955.516 7 13 5 RunModule start Run Program, [konwersja ff], iModuleIdx=548, previous: vgm=535, vgs=9:9
191955.516 7 13 5 state [konwersja ff] Run Program
191955.516 7 13 5 rv replace start [c:\callrecord\ffmpeg_32.exe -i c:\callrecord\$RV[session_id].wav -ab 64k c:\callrecord\$RV[manager]\$RV[session_id].mp3]
191955.516 7 13 5 rv replace end [c:\callrecord\ffmpeg_32.exe -i c:\callrecord\ID20140407191919185.wav -ab 64k c:\callrecord\manager11\ID20140407191919185.mp3]
191955.517 7 13 5 File.Exists(c:\callrecord\ffmpeg_32.exe) is true
191955.517 7 13 5 running program=[c:\callrecord\ffmpeg_32.exe], arguments=[-i c:\callrecord\ID20140407191919185.wav -ab 64k c:\callrecord\manager11\ID20140407191919185.mp3], windowStyle=NormalFocus, timeout=1
191955.517 7 13 5 ShellExe start [c:\callrecord\ffmpeg_32.exe][-i c:\callrecord\ID20140407191919185.wav -ab 64k c:\callrecord\manager11\ID20140407191919185.mp3]
191955.518 7 13 5 Run Program waiting... (processHandle=15184, pid=6488)
191955.518 7 13 5 moh file not specified
191955.518 7 13 5 t timer set 1 sec : EV_TIMEOUT_CHECKONSTATE

191956.298 193 13 5 timer EV_TIMEOUT_CHECKONSTATE
191956.298 193 13 5 q_scr + evScriptEvent 9007 EV_TIMEOUT_CHECKONSTATE
191956.298 7 13 5 q_scr run evScriptEvent sCode=[EV_TIMEOUT_CHECKONSTATE] iActionID=0, crn=0 [0|0|0|0|0][|||||] 00:00:00 max:12|00:00:05.9113381
191956.298 7 13 5 se EV_TIMEOUT_CHECKONSTATE 9007 0|0|0 || LineState=LS_RUN_WAITTILLFINISHED
191956.298 7 13 5 LsRunWaitTillFinished EV_TIMEOUT_CHECKONSTATE lCode2Str=EV_TIMEOUT_CHECKONSTATE
191956.300 7 13 5 Process.HasExited error when test (Process has exited, so the requested information is not available.). Assume completed.
191956.300 7 13 5 task completed. vgm=548, iRunWait=1, iRunWait_ExeResult_NextVgm=0=[]
191956.300 7 13 5 moh not stopping play, bDoNotStopMoh==true
191956.300 7 13 5 ExeResult_NextVgm has not been set. check for Result file.
191956.301 7 13 5 no result file returned from program (VGRUNRESULT_13.TXT).c:\callrecord\ffmpeg_32.exe -i c:\callrecord\$RV[session_id].wav -ab 64k c:\callrecord\$RV[manager]\$RV[session_id].mp3
191956.301 7 13 5 LsRunWaitTillFinished LsRunWaitChooseNext boolExeResult=False
191956.301 7 13 5 FindNextVgmTitleInPathList: next module title is=[check_mp3_file]

 

AFTER update as in attached log file (1st channel)

log_file.zip

[SupportTeam]

Trace shows that the process:

 

091702.826 7 2 1 ShellExe start [c:\callrecord\ffmpeg_32.exe][-i c:\callrecord\ID20140408091148181.wav -ab 64k c:\callrecord\manager11\ID20140408091148181.mp3]

took about 2 minutes to complete.

 

You may want to have the Run Prgram module runa batch file instead - and in the batch file write out to a log when that particular batch file was sterted and when the ffmpeg_32 call within the batch file completed. This way you would be able to confirm whether it is the process of starting the task that takes a long time, or whether ffmpeg_32 call itself does in fact take 2 minutes.

 

Testing with simple batch files that do not do anything other then write out to a log file etc. woudl alos let you verify whether the delay is with the task startup or not.

[invoso.com]

in run program module is 120 seconds timeout and so long waiting now VG to terminate module.

Previous version don't wait to end of timeout but detect when work is done.

 

batch file working 1-3 seconds top convert file.

[SupportTeam]

Can you please run a simple batch file from a Run Program module.

 

The batch file should just do a simple task - like echoing some text to a .txt file etc.

 

We did such a test and it showed that Run Program module had no delays in starting the batch file and detecting when it completed (see trace below)

 

You can then make your batch file gradully more complicated to find which program causes the problem.

 

Most likely the issue you have is a permissions problem when trying to wrote to certain directories when executing a batch file from within a Windows Service.

 

You may want to experiment with reading/writing into different directories from within the batch file ran from the Run Program module.

094611.128   6               ------------------------------------------------------------------------------------------------------
094611.144   6               vgEngine version : 7.4.5207.24383 (RELEASE Build)
094611.144   6               Compiled on      : 2014-04-04 13:32:46.19
094611.144   6               AssemblyLocation : C:\Program Files\VoiceGuide\vgEngine.dll
094611.204   6               LastWriteTime    : 2014-04-04 13:35:18
094611.204   6               trace lvl=10, encoding=System.Text.ASCIIEncoding (ASCII)
094611.204   6               ------------------------------------------------------------------------------------------------------
094611.204   6               currentTime      : 2014-04-09 09:46:11, UTC: 2014-04-08 23:46:11
094611.204   6               log level = 10


100044.817   7   4   1 state [Run Program 12] Run Program
100044.817   7   4   1       File.Exists(c:\echo_test.bat) is true
100044.817   7   4   1       running program=[c:\echo_test.bat], arguments=[], windowStyle=Hide, timeout=1
100044.817   7   4   1       ShellExe start [c:\echo_test.bat][]
100044.818   7   4   1       Run Program waiting... (processHandle=10944, pid=1596)
100044.818   7   4   1       moh file not specified
100044.818   7   4   1 t     timer set   1 sec : EV_TIMEOUT_CHECKONSTATE

100045.845  21   4   1 timer EV_TIMEOUT_CHECKONSTATE
100045.845  21   4   1       q_scr +     evScriptEvent 9007 EV_TIMEOUT_CHECKONSTATE
100045.845   7   4   1       q_scr run   evScriptEvent sCode=[EV_TIMEOUT_CHECKONSTATE] iActionID=0, crn=0 [0|0|0|0|0][|||||] 00:00:00 max:1|00:00:00.0010000
100045.845   7   4   1       se    EV_TIMEOUT_CHECKONSTATE 9007  0|0|0  || LineState=LS_RUN_WAITTILLFINISHED
100045.845   7   4   1       LsRunWaitTillFinished EV_TIMEOUT_CHECKONSTATE lCode2Str=EV_TIMEOUT_CHECKONSTATE
100045.848   7   4   1       Process.HasExited error when test (Process has exited, so the requested information is not available.). Assume completed.
100045.849   7   4   1       task completed. vgm=32, iRunWait=1, iRunWait_ExeResult_NextVgm=0=[]
100045.849   7   4   1       ExeResult_NextVgm has not been set. check for Result file.
100045.849   7   4   1       no result file returned from program (VGRUNRESULT_4.TXT).c:\echo_test.bat
100045.849   7   4   1       LsRunWaitTillFinished LsRunWaitChooseNext boolExeResult=False
100045.849   7   4   1       FindNextVgmTitleInPathList: next module title is=[Play 13]
100045.849   7   4   1       task completed LsRunWaitChooseNext iNextVgm=33
100045.849   7   4   1 t     timer clear (force=False)
100045.849   7   4   1       RunModule start Play, [Play 13], iModuleIdx=33, previous: vgm=32, vgs=3:3