Jump to content


< Back to Forum


 

Vg Not Identify Running Script.


  • Please log in to reply

#1 Maciej 16 August 2016 - 08:46 PM

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


#2 SupportTeam 17 August 2016 - 07:46 AM

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.



#3 Maciej 18 August 2016 - 06:44 PM

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


#4 SupportTeam 18 August 2016 - 07:01 PM

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.



#5 Maciej 18 August 2016 - 09:50 PM

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


#6 SupportTeam 18 August 2016 - 09:57 PM

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.