invoso.com Report post Posted 08/16/2016 10:46 AM VG not found working script in channel. (red lines below), no data in cdr_in file and not forwarding to termination script. 105156.091 7 7 3 state [subprojects] Evaluate [$RV[id_projektu]$RV[manager_id]] 105156.091 7 7 3 rv replace start [$RV[id_projektu]$RV[manager_id]] 105156.091 7 7 3 rv replace end [53220] 105156.091 7 7 3 eval [53220] 105156.091 7 7 3 eval InvokeMember Eval returned 105156.091 7 7 3 rvns add subprojects_Input|53220 105156.091 7 7 3 rvns add subprojects|53220 105156.091 7 7 3 creating new (non-global) rv : subprojects 105156.091 7 7 3 rvns add subprojects|53220 105156.091 7 7 3 Eval Expr result:[53220] stored in RV[subprojects] 105156.091 7 7 3 path {53220} not found 105156.091 7 7 3 matching path not found [53220], try boolean paths. 105156.091 7 7 3 ex: ScriptIo.VGMTYPE_EVALEXPR [53220] could not be converted to boolean. Take Success path as string non-empty. 105156.091 7 7 3 FindNextVgmTitleInPathList: next module title is=[play powitanie projektu] 105156.091 7 7 3 matching path found (Boolean True) 105156.091 7 7 3 t timer clear (force=False) 105156.091 7 7 3 RunModule start Play, [play powitanie projektu], iModuleIdx=2, previous: vgm=142, vgs=1:1 105156.091 7 7 3 [play powitanie projektu] VGMTYPE_PLAY run start 105156.091 7 7 3 answering the call (picking up the line) 0 105156.092 7 7 3 crn set using crn_NewCallArriving in AnswerTheCall 105156.092 7 7 3 t timer clear (force=True) 105156.092 7 7 3 ktTel_AnswerCall_Enqueue source=AnswerTheCall 105156.092 7 7 3 q_tel + cmd_AnswerCall 2d003c7 [0,0,0,0,0][||||] 105156.092 7 7 3 ktTel_LineAnswerCall => 105156.092 8 7 3 q_tel run cmd_AnswerCall 2d003c7 00:00:00 max:4|00:00:00.1410080 105156.095 8 7 3 ev ktTel_Completion (generic) 10000 0,gc_AnswerCall_Completion_Error, crn=2d003c7, 65,65,0,Function is not supported in this state|Function is not supported in this state,, 105156.095 8 7 3 q_scr + evktTelCompletion 0 gc_AnswerCall_Completion_Error 105156.095 7 7 3 q_scr run evktTelCompletion sCode=[gc_AnswerCall_Completion_Error] iActionID=0, crn=0 [65|65|0|0|0][Function is not supported in this state|Function is not supported in this state|||||] 00:00:00 max:5|00:00:00.1500086 105156.095 7 7 3 note gc_AnswerCall_Completion_Error - issuing resetlinedev 105156.095 7 7 3 L1_set ResetLineDevUnderway (iState=LS_MODULE_TRANSITION) 105156.095 7 7 3 q_tel + cmd_ResetLineDev 0 [0,0,0,0,0][||||] 105156.095 8 7 3 q_tel run cmd_ResetLineDev 0 00:00:00 max:4|00:00:00.1410080 105156.097 21 7 3 ev CallState GCEV_DISCONNECTED, crn=2d003c7, iEvent=0 ,16384,0,64, s1:, s2:, s3:]. build_date: 10-Jul-15 12:01:32.48 105156.097 21 7 3 q_scr + evCallState 0 GCEV_DISCONNECTED 105156.097 7 7 3 q_scr run evCallState sCode=[GCEV_DISCONNECTED] iActionID=0, crn=2d003c7 [16384|0|64|0|0][|||||] 00:00:00 max:5|00:00:00.1500086 105156.097 21 7 3 ev Dialogic 2054,GCEV_RESETLINEDEV, crn=0, 2054,0,0,,, 105156.097 7 7 3 callstate crn_event=2d003c7 0|GCEV_DISCONNECTED state=16384|Disconnected calldirection=0 gcCallState=64 [||], ScriptState=LS_MODULE_TRANSITION 105156.097 21 7 3 L2=Running_BeforeAnswerCall, L1=ResetLineDevUnderway (GCEV_RESETLINEDEV) 105156.097 7 7 3 LineEvCallState L1_current=ResetLineDevUnderway crn_event=2d003c7,ev=0,GCEV_DISCONNECTED,0, sParam1= 105156.097 7 7 3 LineEvCallState LINECALLSTATE_DISCONNECTED begin 105156.097 7 7 3 crn_NewCallArriving received disconnected event before being answered 105156.097 21 7 3 TsReset [GCEV_RESETLINEDEV], OtherLegLid=-1 105156.097 21 7 3 TsResetAndClearOtherLegIds iConferenceOtherLegLid unknown. TsReset wil be called for current line only 105156.097 21 q_tel + cmd_TsReset 0 [0,0,0,0,0][dtiB1T3||||] 105156.097 21 7 3 OtherLegLid_ClearBoth exit as already .iConferenceOtherLegLid<=0, caller:GCEV_RESETLINEDEV 105156.097 21 7 3 set crn_connected=0 (called from _RESETLINEDEV) 105156.097 21 7 3 LineState_ResetLineDev_Clean : begin 105156.097 21 7 3 L1_set Null (iState=LS_MODULE_TRANSITION) 105156.097 21 7 3 L1_set ignore new linestate set as ResetLineDevUnderway L1state=ResetLineDevUnderway 105156.097 21 7 3 L2_set Idle_WaitingForNextCall (called from LineState_ResetLineDev_Clean) 105156.097 21 7 3 strThisCallIsInboundOrOutbound clear 105156.097 7 7 3 in LINECALLSTATE_DISCONNECTED iState=LS_MODULE_TRANSITION 105156.097 21 7 3 eval objSC_UsedForEvalExpr != null 105156.097 7 7 3 HangupCall (LineEvCallState_DISCONNECTED) crn_in=2d003c7, L1=ResetLineDevUnderway, L2=Idle_WaitingForNextCall, lPlayId=0, lRecId=0 105156.097 7 7 3 ccrn_connected=0, crn_NewCallArriving=0, crn_CurrentMakeCall=0, crn_InProcessOfReleasing=0 105156.097 7 7 3 rv add Hangup Source|LineEvCallState_DISCONNECTED 105156.097 21 7 3 eval ReleaseObject call 105156.097 7 7 3 HangupCall sScriptToRunOnHangup=[termination.vgs] 105156.097 7 7 3 no script running on this line. AfterHangup script will not be ran. 105156.097 7 7 3 rv add DropCall_Source|play powitanie projektu 105156.097 8 q_tel run cmd_TsReset 0 00:00:00 max:4|00:00:00.1410080 105156.098 7 7 3 WARN HangupCall current L2state_Script=Idle_WaitingForNextCall 105156.098 21 7 3 LineState_ResetLineDev_Clean : end. iIvrDev=3, bChannelIsBlocked=False 105156.098 21 7 3 in resetlinedev handler: LineState_ResetLineDev_Clean returned iIvrDev=3 105156.098 21 7 3 state Waiting for a call 105156.098 21 7 3 t timer set 5,5 sec : EV_TIMEOUT_AFTERIDLE_ALLOWOUT 105156.098 7 7 3 WARN type of call not determined 105156.098 7 7 3 state Hanging up... [LineEvCallState_DISCONNECTED] 105156.098 7 7 3 WriteToLogFiles_CurrScriptOnly begin 105156.098 7 7 3 WriteToLogFiles_CurrScriptOnly : LineState.iVgsIdx<=0 105156.098 7 7 3 RvSaveToLogFiles_CurrAndStack iScriptCallStack_LastUsed_Idx=0 105156.098 7 7 3 L2_set Idle_WaitingForNextCall (called from HangupCall) 105156.098 7 7 3 t timer set 3 sec : EV_TIMEOUT_AFTERIDLE_ALLOWOUT 105156.098 7 7 3 GoOnHoook_IssueDropCall start (crn_in=2d003c7, crn_connected=0, crn_makecall=0, crn_NewCallArriving=0, crn_InProcessOfReleasing=0, L1=Null_InGuardTimeAfterEndOfCall) 105156.098 7 7 3 t timer set 20 sec : EV_TIMEOUT_WAITFORIDLEAFTERDropCall 105156.098 7 7 3 set crn_InProcessOfReleasing=2d003c7 105156.098 7 7 3 not setting crn_CurrentConnected to 0 as crn_CurrentConnected=0 and evnt crn=2d003c7 105156.098 7 7 3 set crn_connected=0 (called from GoOnHoook_IssueDropCall) 105156.098 7 7 3 q_tel + cmd_DropCall 2d003c7 [0,0,0,0,0][||||] 105156.098 7 7 3 GoOnHoook_IssueDropCall end 105156.105 8 7 3 q_tel run cmd_DropCall 2d003c7 00:00:00.0070004 max:4|00:00:00.1410080 105156.108 21 7 3 ev Dialogic 2054,GCEV_RESETLINEDEV, crn=0, 2054,0,0,,, 105156.108 21 7 3 L2=Idle_WaitingForNextCall, L1=Null_InGuardTimeAfterEndOfCall (GCEV_RESETLINEDEV) 105156.108 21 7 3 TsReset [GCEV_RESETLINEDEV], OtherLegLid=-1 105156.108 21 7 3 TsResetAndClearOtherLegIds iConferenceOtherLegLid unknown. TsReset wil be called for current line only 105156.108 21 q_tel + cmd_TsReset 0 [0,0,0,0,0][dtiB1T3||||] 105156.108 21 7 3 OtherLegLid_ClearBoth exit as already .iConferenceOtherLegLid<=0, caller:GCEV_RESETLINEDEV 105156.108 8 q_tel run cmd_TsReset 0 00:00:00 max:4|00:00:00.1410080 105156.108 21 7 3 set crn_connected=0 (called from _RESETLINEDEV) 105156.108 21 7 3 LineState_ResetLineDev_Clean : begin 105156.108 21 7 3 L1_set Null (iState=LS_MODULE_TRANSITION) 105156.108 21 7 3 L2_set Idle_WaitingForNextCall (called from LineState_ResetLineDev_Clean) 105156.108 21 7 3 strThisCallIsInboundOrOutbound clear 105156.108 21 7 3 LineState_ResetLineDev_Clean : end. iIvrDev=3, bChannelIsBlocked=False 105156.108 21 7 3 in resetlinedev handler: LineState_ResetLineDev_Clean returned iIvrDev=3 105156.108 21 7 3 state Waiting for a call 105156.108 21 7 3 t timer set 5,5 sec : EV_TIMEOUT_AFTERIDLE_ALLOWOUT 105156.108 21 7 3 timer set case EV_TIMEOUT_WAITFORIDLEAFTERDropCall->EV_TIMEOUT_AFTERIDLE_ALLOWOUT allowed Share this post Link to post
SupportTeam Report post Posted 08/16/2016 09:46 PM Attached trace shows that during the call answer attempt the Dialogic drivers reported that call answer could not be done - this can happen in situations where the call is already disconnected on the line (but the event hasn't yet been issued back to VoiceGuide). We can see that the DISCONNECTED event was received by VoiceGuide 2ms after the failed call answer - so we can see that the above scenario is what happened here. As call was never connected no CDR would be created. The "onHangup" scripts are intended to run when an existing connected call is ended (hung up). Current versions of software could be modified to extend functionality to ensure the running of the onHangup script in the rare cases where the AnswerCall was issued but failed as call was already hung up from the other side - like in the case that is seen here. Share this post Link to post
invoso.com Report post Posted 08/18/2016 08:44 AM Similar problem, again VG v7.5.6058.32621 not forwarding to termination script. I think it's version problem not VG global or DIALOGIC. It happen only on server with version described above. Short after connecting both channels 15 and 33 OTHER_LEG_DISCONNECTED not finishing processes on channel 15 and VG not forwarding to termination script. next log shows something like this: 091418.194 9 43 15 CallExistsOnLine true (not yet released) crn=28802d3 091414.026 9 43 15 path {OTHER_LEG_CONNECTED} not found 091414.026 9 43 15 q_scr run evScriptEvent sCode=[XFER_ANN_ACCEPTED] iActionID=0, crn=0 [0|0|0|0|0][|||||] 00:00:00.0010000 max:6|00:00:00.0260015 091414.026 9 43 15 se XFER_ANN_ACCEPTED 0 0|0|0 || LineState=LS_XFER_7_WAITOUTCOMEOUTGOINGCALL_REQUESTXFERSIDE 091414.026 9 43 15 LsXfer_7_dc_WaitOutcomeOutgoingCall_InLeg : [XFER_ANN_ACCEPTED], 0(EV_UNKNOWN_0),0,0,0,,,), xferType=32, leg2=98 091414.026 9 43 15 x7_dc_in before XFER_ANN_ACCEPTED test. sCode=XFER_ANN_ACCEPTED 091414.026 9 43 15 TwoCalls_Bridge 43<=>98 (dtiB1T15<=>dtiB2T3) 091414.026 9 43 15 q_tel + cmd_PlayStop [0,0,0,0,0][||||] 091414.026 9 43 15 play PlaySoundStop ok 091414.026 9 43 15 TwoCalls_Bridge iConferenceOtherLegLid_crn set to crn_CurrentConnected 28802d3 091414.026 10 43 15 q_tel run cmd_PlayStop 0 00:00:00 max:5|00:00:00.1670096 091414.026 9 98 33 TwoCalls_Bridge iConferenceOtherLegLid_crn set to crn_CurrentConnected 28802d3 091414.027 9 43 15 rvns add TsRoutedTo|98 091414.027 9 98 33 rvns add TsRoutedTo|43 091414.027 9 98 33 rvns add Conf_DevName_1|dtiB1T15 091414.027 9 98 33 rvns add Conf_LineId_1|43 091414.027 9 98 33 rvns add Conf_LineNbr_1|15 091414.027 9 98 33 rv add Conf_DevName_2|dtiB2T3 091414.027 9 98 33 rv add Conf_LineId_2|98 091414.028 9 98 33 rv add Conf_LineNbr_2|33 091414.028 9 43 15 rvns add Conf_DevName_1|dtiB1T15 091414.028 9 43 15 rvns add Conf_LineId_1|43 091414.028 9 43 15 rvns add Conf_LineNbr_1|15 091414.028 9 43 15 rv add Conf_DevName_2|dtiB2T3 091414.028 9 43 15 rv add Conf_LineId_2|98 091414.028 9 43 15 rv add Conf_LineNbr_2|33 091414.029 9 43 15 rvns add Transfer Call fa with CALLER ID_DevName_1|dtiB1T15 091414.029 9 43 15 rvns add Transfer Call fa with CALLER ID_LineId_1|43 091414.029 9 43 15 rvns add Transfer Call fa with CALLER ID_LineNbr_1|15 091414.029 9 43 15 rv add Transfer Call fa with CALLER ID_DevName_2|dtiB2T3 091414.029 9 43 15 rv add Transfer Call fa with CALLER ID_LineId_2|98 091414.029 9 43 15 rv add Transfer Call fa with CALLER ID_LineNbr_2|33 091414.030 9 q_tel + cmd_TsRoute 0 [0,0,0,0,0][dtiB1T15||dtiB2T3||] 091414.030 9 43 15 tsroute dtiB1T15<=>dtiB2T3 SC_FULLDUP returned 091414.030 9 98 33 state from iLineId : vgmidx=194, strVgmTitle=Transfer Call fa with CALLER ID 091414.030 9 43 15 state [Transfer Call fa with CALLER ID] in_leg 15 <=> 33 422715555 091414.030 9 98 33 state [Transfer Call fa with CALLER ID] out_leg 15 <=> 33 422715555 ... 091414.052 9 43 15 state [connecting result fa= connected rch] DB Query 091414.052 9 43 15 rv replace start [$RV[connection_string]] 091414.052 9 43 15 rv replace end [ODBC; Driver=PostgreSQL Unicode; Server=ip; Port=5432; Database=db;UID=user;PWD=pass;] 091414.052 9 43 15 rv replace start ------------------------------ UPDATE polaczenia_unreached SET reason='połączono', transfer_achieved=now(), reaction_time_un= ( SELECT CEIL(extract(epoch FROM (now()-transfer_start))) FROM polaczenia_unreached WHERE session_id='$RV[session_id]' AND id=(SELECT MAX(id) FROM polaczenia_unreached WHERE session_id='$RV[session_id]' ) ) WHERE session_id='$RV[session_id]' AND id=(SELECT MAX(id) FROM polaczenia_unreached WHERE session_id='$RV[session_id]' ); UPDATE polaczenia SET transfer_call_timestamp=now(), effect='polaczono' WHERE session_id='$RV[session_id]'; UPDATE polaczenia SET reaction_time=(extract(epoch FROM (transfer_call_timestamp-start_transfer))-0) WHERE session_id='$RV[session_id]' AND effect='polaczono'; UPDATE polaczenia SET waiting_time=extract(epoch FROM (transfer_call_timestamp-menu_decision)) WHERE session_id='$RV[session_id]' AND menu_decision IS NOT NULL AND transfer_call_timestamp IS NOT NULL ------------------------------ 091414.053 9 43 15 dbstrDatabaseName=[] strDbConnectString=[ODBC; Driver=PostgreSQL Unicode; Driver=PostgreSQL Unicode; Server=ip; Port=5432; Database=db;UID=user;PWD=pass;] sAdoNetFactoriesAvailable=[|System.Data.Odbc|System.Data.OleDb|System.Data.OracleClient|System.Data.SqlClient|System.Data.SQLite|Npgsql|] 091414.053 9 43 15 db did not find ado.net data provider : 091414.053 9 43 15 dbPlayOnHoldFile 091414.053 9 43 15 moh file not specified 091414.053 21 43 15 ev CallState GCEV_DISCONNECTED, crn=28802d3, iEvent=0 ,16384,0,64, s1:, s2:, s3:]. build_date: 02-Aug-16 17:07:21.55 091414.053 21 43 15 q_scr + evCallState 0 GCEV_DISCONNECTED 091414.053 9 43 15 db using ado.net ODBC data provider : OdbcConnection/OdbcCommand/etc 091414.054 9 43 15 db suggested ODBC connect string format if System DSN defined: DSN=ddd;Uid=xxx;Pwd=yyy; 091414.054 9 43 15 dbodbc RunQuery_Odbc [connecting result fa= connected rch], db=[], connect=[ Driver=PostgreSQL Unicode; Driver=PostgreSQL Unicode; Server=ip; Port=5432; Database=db;UID=user;PWD=pass;], sql=[UPDATE polaczenia_unreached SET reason='połączono', transfer_achieved=now(), reaction_time_un= ( SELECT CEIL(extract(epoch FROM (now()-transfer_start))) FROM polaczenia_unreached WHERE session_id='ID20160818_091407_41_15_54802' AND id=(SELECT MAX(id) FROM polaczenia_unreached WHERE session_id='ID20160818_091407_41_15_54802' ) ) WHERE session_id='ID20160818_091407_41_15_54802' AND id=(SELECT MAX(id) FROM polaczenia_unreached WHERE session_id='ID20160818_091407_41_15_54802' ); UPDATE polaczenia SET transfer_call_timestamp=now(), effect='polaczono' WHERE session_id='ID20160818_091407_41_15_54802'; UPDATE polaczenia SET reaction_time=(extract(epoch FROM (transfer_call_timestamp-start_transfer))-0) WHERE session_id='ID20160818_091407_41_15_54802' AND effect='polaczono'; UPDATE polaczenia SET waiting_time=extract(epoch FROM (transfer_call_timestamp-menu_decision)) WHERE session_id='ID20160818_091407_41_15_54802' AND menu_decision IS NOT NULL AND transfer_call_timestamp IS NOT NULL ] 091414.054 9 43 15 dbodbc thread init (threadpool) 091414.054 9 43 15 dbodbc thread started (threadpool) 091414.054 31 43 15 dbodbc connection create call. m_strOdbcConnectString= Driver=PostgreSQL Unicode; Server=ip; Port=5432; Database=db;UID=user;PWD=pass; 091414.054 9 43 15 t timer set 30 sec : EV_TIMEOUT_HANGUP 091414.054 31 43 15 dbodbc connection open call. 091414.054 9 43 15 RunModule finish 091414.054 9 43 15 q_scr run evCallState sCode=[GCEV_DISCONNECTED] iActionID=0, crn=28802d3 [16384|0|64|0|0][|||||] 00:00:00.0010000 max:6|00:00:00.0260015 091414.054 9 43 15 callstate crn_event=28802d3 0|GCEV_DISCONNECTED state=16384|Disconnected calldirection=0 gcCallState=64 [||], ScriptState=LS_DBQUERY 091414.054 9 43 15 LineEvCallState L1_current=Connected crn_event=28802d3,ev=0,GCEV_DISCONNECTED,0, sParam1= 091414.055 9 43 15 LineEvCallState LINECALLSTATE_DISCONNECTED begin 091414.055 9 43 15 TsReset [LineEvCallState_LINECALLSTATE_DISCONNECTED], OtherLegLid=98 091414.055 10 43 15 q_tel run cmd_SilenceDetectSet 0 00:00:00.0130007 max:5|00:00:00.1670096 091414.055 9 q_tel + cmd_TsReset 0 [0,0,0,0,0][dtiB1T15||dtiB2T3||] 091414.055 10 43 15 q_tel run cmd_RecTwoLinesStart 0 00:00:00.0120007 max:5|00:00:00.1670096 091414.055 9 43 15 OtherLegLid_ClearBoth 43 98 caller:LineEvCallState_LINECALLSTATE_DISCONNECTED 091414.055 9 98 33 OtherLegLid_ClearBoth 43 98 caller:LineEvCallState_LINECALLSTATE_DISCONNECTED 091414.055 10 q_tel run cmd_TsReset 0 00:00:00 max:5|00:00:00.1670096 091414.055 9 43 15 send OTHER_LEG_DISCONNECTED to OtherLegLid=98 091414.055 9 98 33 q_scr + evScriptEvent 0 OTHER_LEG_DISCONNECTED 091414.055 9 43 15 LINECALLSTATE_DISCONNECTED: clear crn_connected, set crn_InProcessOfReleasing, set L1=Disconnected 091414.055 9 43 15 L1_set Disconnected (iState=LS_DBQUERY) 091414.055 9 43 15 in LINECALLSTATE_DISCONNECTED iState=LS_DBQUERY 091414.055 9 43 15 HangupCall qScr add (LineEvCallState_DISCONNECTED) crn_in=28802d3, L1=Disconnected, L2=Running_Normal, lPlayId=0, lRecId=880250 091414.056 9 43 15 q_scr + cmdHangupCall 0 091414.056 9 98 33 q_scr run evScriptEvent sCode=[OTHER_LEG_DISCONNECTED] iActionID=0, crn=0 [0|0|0|0|0][|||||] 00:00:00.0010001 max:6|00:00:00.0260015 091414.056 9 98 33 se OTHER_LEG_DISCONNECTED 0 0|0|0 || LineState=LS_XFER_9_WAITENDCALL_DialingSide 091414.056 9 98 33 LsXfer_9_WaitEndCall_OutLeg : [0:OTHER_LEG_DISCONNECTED] 0,0,0 ,, 091414.056 9 98 33 hanging up 2nd leg of call (other_leg cause) 091414.056 9 98 33 HangupCall qScr add (xfer_9_leg2 remote) crn_in=0, L1=Connected, L2=Running_Normal, lPlayId=0, lRecId=0 091414.056 9 98 33 q_scr + cmdHangupCall 0 091414.056 9 43 15 q_scr run cmdHangupCall sCode=[] iActionID=0, crn=28802d3 [0|0|0|0|0][LineEvCallState_DISCONNECTED|||||] 00:00:00 max:6|00:00:00.0260015 091414.056 9 43 15 HangupCall qScr exec (LineEvCallState_DISCONNECTED) crn_in=28802d3, L1=Disconnected, L2=Running_Normal, lPlayId=0, lRecId=880250 091414.056 9 43 15 HangupCall crn_connected=0, crn_NewCallArriving=0, crn_CurrentMakeCall=0, crn_InProcessOfReleasing=28802d3 091414.057 9 43 15 RecSoundStop begin trunc100ms=0, sCaller=Line_Hangup_Main, lRecId=880250 091414.057 9 43 15 RecSoundStop lRec_Id_InProcessOfStopping=880250, lRecId=0 091414.057 9 43 15 q_tel + cmd_RecordStop [0,0,0,0,0][||||] 091414.057 9 43 15 rv add Hangup Source|LineEvCallState_DISCONNECTED 091414.057 9 43 15 HangupCall sScriptToRunOnHangup=[C:\Program Files (x86)\VoiceGuide\Scripts\manager\manager_termination.vgs] 091414.057 9 43 15 HangupCall lRec_Id_InProcessOfStopping=880250, wait till recording cmpletes 091414.057 9 43 15 t timer set 4 sec : EV_TIMEOUT_RunAfterHangupScript 091414.057 9 98 33 q_scr run cmdHangupCall sCode=[] iActionID=0, crn=0 [0|0|0|0|0][xfer_9_leg2 remote|||||] 00:00:00.0010000 max:6|00:00:00.0260015 091414.057 9 98 33 HangupCall qScr exec (xfer_9_leg2 remote) crn_in=0, L1=Connected, L2=Running_Normal, lPlayId=0, lRecId=0 091414.057 9 98 33 HangupCall crn_connected=28802d4, crn_NewCallArriving=0, crn_CurrentMakeCall=0, crn_InProcessOfReleasing=0 091414.057 9 98 33 rv add Hangup Source|xfer_9_leg2 remote 091414.058 9 98 33 HangupCall sScriptToRunOnHangup=[C:\Program Files (x86)\VoiceGuide\Scripts\manager\manager_termination.vgs] 091414.058 9 98 33 no script running on this line. AfterHangup script will not be ran. 091414.058 9 98 33 rv add DropCall_Source|bypas_email_report 091414.058 9 98 33 crn 0 set to crn_connected 28802d4 091414.058 9 98 33 L1_set Disconnect_Pending (iState=LS_XFER_9_WAITENDCALL_DialingSide) 091414.058 9 98 33 state Hanging up... [xfer_9_leg2 remote] 091414.058 9 98 33 logs not written as LogEntryWritten=1 091414.058 9 98 33 L2_set Idle_WaitingForNextCall (called from HangupCall) 091414.058 9 98 33 t timer set 3 sec : EV_TIMEOUT_AFTERIDLE_ALLOWOUT 091414.058 9 98 33 GoOnHoook_IssueDropCall start (crn_in=28802d4, crn_connected=28802d4, crn_makecall=0, crn_NewCallArriving=0, crn_InProcessOfReleasing=0, L1=Disconnect_Pending) 091414.058 9 98 33 t timer set 20 sec : EV_TIMEOUT_WAITFORIDLEAFTERDropCall 091414.058 9 98 33 GoOnHoook_IssueDropCall: set crn_InProcessOfReleasing=28802d4 091414.058 9 98 33 clear crn_connected 091414.059 9 98 33 set crn_connected=0 (called from GoOnHoook_IssueDropCall) 091414.059 9 98 33 q_tel + cmd_DropCall 28802d4 [0,0,0,0,0][||||] 091414.059 9 98 33 GoOnHoook_IssueDropCall end 091414.068 31 43 15 dbodbc connection open returned. 091414.068 31 43 15 dbodbc m_strSQL=[UPDATE polaczenia_unreached SET reason='połączono', transfer_achieved=now(), reaction_time_un= ( SELECT CEIL(extract(epoch FROM (now()-transfer_start))) FROM polaczenia_unreached WHERE session_id='ID20160818_091407_41_15_54802' AND id=(SELECT MAX(id) FROM polaczenia_unreached WHERE session_id='ID20160818_091407_41_15_54802' ) ) WHERE session_id='ID20160818_091407_41_15_54802' AND id=(SELECT MAX(id) FROM polaczenia_unreached WHERE session_id='ID20160818_091407_41_15_54802' ); UPDATE polaczenia SET transfer_call_timestamp=now(), effect='polaczono' WHERE session_id='ID20160818_091407_41_15_54802'; UPDATE polaczenia SET reaction_time=(extract(epoch FROM (transfer_call_timestamp-start_transfer))-0) WHERE session_id='ID20160818_091407_41_15_54802' AND effect='polaczono'; UPDATE polaczenia SET waiting_time=extract(epoch FROM (transfer_call_timestamp-menu_decision)) WHERE session_id='ID20160818_091407_41_15_54802' AND menu_decision IS NOT NULL AND transfer_call_timestamp IS NOT NULL ] 091414.069 10 43 15 q_tel run cmd_RecordStop 0 00:00:00.0120007 max:5|00:00:00.1670096 091414.069 10 98 33 q_tel run cmd_DropCall 28802d4 00:00:00.0100006 max:5|00:00:00.1670096 091414.085 31 43 15 dbcompleted. SqlQueryType=NONQUERY, RowsCount=3, sRv=[connecting result fa= connected rch_RowCount]{3} 091414.085 31 43 15 rvns add connecting result fa= connected rch_RowCount|3 091414.085 31 43 15 dbcompleted. iRunWait=1, WavPlayWasStarted=0, WavPlayHasNowFinished=0 091414.085 31 43 15 dbcompleted. iRowsAffected=3 091414.085 31 43 15 FindNextVgmTitleInPathList: next module title is=[store_used_ports] 091414.085 31 43 15 RunModule_AddToTaskQueue [Database Query,[store_used_ports],329] 091414.085 31 43 15 q_scr + evScriptEvent 9800 CMD_RUN_SAME_MODULE_AGAIN 091414.085 9 43 15 q_scr run evScriptEvent sCode=[CMD_RUN_SAME_MODULE_AGAIN] iActionID=0, crn=0 [0|0|0|0|0][|||||] 00:00:00 max:6|00:00:00.0260015 091414.085 9 43 15 se CMD_RUN_SAME_MODULE_AGAIN 9800 0|0|0 || LineState=LS_DBQUERY 091414.085 9 43 15 t timer clear (force=False) 091414.085 9 43 15 RunModule start 091414.085 31 43 15 dbodbc query completed. 091414.085 9 43 15 RunModule start Database Query, [store_used_ports], iModuleIdx=329, previous: vgm=329, vgs=4:4 091414.085 9 43 15 state [store_used_ports] DB Query 091414.085 9 43 15 rv replace start [$RV[connection_string]] 091414.086 9 43 15 rv replace end [ODBC; Driver=PostgreSQL Unicode; Server=ip; Port=5432; Database=db;UID=user;PWD=pass;] 091414.086 9 43 15 rv replace start ------------------------------ UPDATE polaczenia SET outbound_port= $RV[Conf_LineNbr_2], initial_port=$RV_PORTNUMBER WHERE session_id='$RV[session_id]' ------------------------------ 091414.086 9 43 15 rv replace end [UPDATE polaczenia SET outbound_port= 33, initial_port=15 WHERE session_id='ID20160818_091407_41_15_54802' ] 091414.086 9 43 15 dbstrDatabaseName=[] strDbConnectString=[ODBC; Driver=PostgreSQL Unicode; Server=ip; Port=5432; Database=db;UID=user;PWD=pass;] sAdoNetFactoriesAvailable=[|System.Data.Odbc|System.Data.OleDb|System.Data.OracleClient|System.Data.SqlClient|System.Data.SQLite|Npgsql|] 091414.086 9 43 15 db did not find ado.net data provider : 091414.086 9 43 15 dbPlayOnHoldFile Share this post Link to post
SupportTeam Report post Posted 08/18/2016 09:01 AM Port 15 does appear to start the "OnHangup" script: 091414.057 9 43 15 HangupCall sScriptToRunOnHangup=[C:\Program Files (x86)\VoiceGuide\Scripts\manager\manager_termination.vgs] ... 091414.085 31 43 15 RunModule_AddToTaskQueue [Database Query,[store_used_ports],329] 091414.085 9 43 15 state [store_used_ports] DB Query Port 33 does not start the "OnHangup" script as it looks like no script was running on that line: 091414.058 9 98 33 no script running on this line. AfterHangup script will not be ran. This is a different situation to the previously posted trace. Share this post Link to post
invoso.com Report post Posted 08/18/2016 11:50 AM VG shows 091414.055 9 43 15 OtherLegLid_ClearBoth 43 98 caller:LineEvCallState_LINECALLSTATE_DISCONNECTED caller finished call and in this moment VG should terminating call but still working and forwarding thread on channel 15 to next module 091414.085 31 43 15 FindNextVgmTitleInPathList: next module title is=[store_used_ports] 091414.085 31 43 15 RunModule_AddToTaskQueue [Database Query,[store_used_ports],329] instead of to termination script 091414.057 9 43 15 rv add Hangup Source|LineEvCallState_DISCONNECTED 091414.057 9 43 15 HangupCall sScriptToRunOnHangup=[C:\Program Files (x86)\VoiceGuide\Scripts\manager\manager_termination.vgs] 091414.057 9 43 15 HangupCall lRec_Id_InProcessOfStopping=880250, wait till recording cmpletes 091414.057 9 43 15 t timer set 4 sec : EV_TIMEOUT_RunAfterHangupScript Share this post Link to post
SupportTeam Report post Posted 08/18/2016 11:57 AM Could you please post a fuller trace excerpt, that includes the entire call from the start of call to at least 5 seconds after hangup. Please include both the vgEngine and ktTel traces for that time. We can then see a complete picture of what is happening on that call and can comment on it. Please .ZIP up the trace and post as an attachment. Share this post Link to post
