Voiceguide Is Rejecting Calls

[bfrank]

Hello guys.

 

It seems that VG is returning busy although there are plenty of open channels. The number of busy responses increase proportional to incoming call volume.

 

The problem gets progressively worse as time goes on. In the beginning of September (last restart) we were rejecting 0 calls. This week we rejected 15-20% of incoming calls.

 

I zipped up part of the ktTel log for 10/06. On this day we rejected at least 590 calls. I also zipped a vgEngine log for 11:00 to 11:44 AM. During this time frame we rejected at least 8 calls. I can't find the problem calls in the logs, but I can see in my CDRs that we rejected calls at the following times:

 

2010-10-06 11:06:11.000

2010-10-06 11:06:20.000

2010-10-06 11:08:08.000

2010-10-06 11:08:25.000

2010-10-06 11:08:25.000

2010-10-06 11:08:33.000

2010-10-06 11:10:29.000

2010-10-06 11:38:38.000

 

UPDATE: By looking at the logs it appears that I'm only accepting calls on 8 lines (out of 24). I now went to the VG Viewer application and "hung up" the stuck ports. This seems to solve the problem.

 

The new version (7.0) was supposed to solve the stuck port issue (see this thread and this one) but actually solved nothing? It just hid it from view, which of course made things worse.

logs.zip

[SupportTeam]

From looking at logs we can see that what is happening here is that either:

 

A: Call are never arriving at system

or

B: HMP is not reporting the incoming calls to VoiceGuide

 

 

Had a look at the ktTel log to see if HMP reported to VoiceGuide that these calls arrived at system:

 

2010-10-06 11:06:11.000

2010-10-06 11:06:20.000

 

 

VoiceGuide logs show that these two calls were not reported to VoiceGuide by HMP.

 

Here are the calls around that time that were reported by HMP to VoiceGuide:

 

110547.803 5380 64 ev GCEV_DETECTED crn=8000015 (setting hli->crn for line 64)

110547.803 5380 64 ev GCEV_OFFERED crn=8000015 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22) (setting hli->crn for line 64)

110547.850 5380 64 ev GCEV_ANSWERED crn=8000015 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22)

 

110550.490 5380 19 ev GCEV_DETECTED crn=8000006 (setting hli->crn for line 19)

110550.490 5380 19 ev GCEV_OFFERED crn=8000006 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22) (setting hli->crn for line 19)

110550.568 5380 19 ev GCEV_ANSWERED crn=8000006 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22)

 

110558.990 5380 16 ev GCEV_DETECTED crn=8000005 (setting hli->crn for line 16)

110558.990 5380 16 ev GCEV_OFFERED crn=8000005 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22) (setting hli->crn for line 16)

110559.068 5380 16 ev GCEV_ANSWERED crn=8000005 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22)

 

110658.146 5380 64 ev GCEV_DETECTED crn=8000015 (setting hli->crn for line 64)

110658.146 5380 64 ev GCEV_OFFERED crn=8000015 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22) (setting hli->crn for line 64)

110658.209 5380 64 ev GCEV_ANSWERED crn=8000015 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22)

 

110711.600 5380 16 ev GCEV_DETECTED crn=8000005 (setting hli->crn for line 16)

110711.600 5380 16 ev GCEV_OFFERED crn=8000005 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22) (setting hli->crn for line 16)

110711.646 5380 16 ev GCEV_ANSWERED crn=8000005 (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22)

 

all the calls that did arrive from VoiceGuide's point of view were answered and then handles with no issues.

 

Given that you say:

 

By looking at the logs it appears that I'm only accepting calls on 8 lines (out of 24). I now went to the VG Viewer application and "hung up" the stuck ports. This seems to solve the problem.

 

How did you determine that the ports were 'stuck'? What was the Line Viewer's status for those stuck ports showing?

Do you perhaps have a screenshot?

 

The previous 'stuck' lines problem were caused by HMP/VoiceGuide not receiving SIP packets from other systems confirming calls have been disconnected after the RFC3515 Refer transfer was made. (see: http://voiceguide.com/forums/index.php?showtopic=6469 ) Perhaps we are now seeing another similar problem where SIP signaling packets not arriving.

[SupportTeam]

Can you .ZIP up and post the VoiceGuide traces which capture when you manually pressed the 'hangup call' button for the 'stuck' ports.

 

This will let us see what the system did at the time the 'hangup call' button was pressed and from there we may see what state the channel was in.

 

Ultimately it would be best to get the VoiceGuide ktTel traces capturing the last call handled by each of the 'stuck' channels. This way we would be able to see what unusual activity happened on the channel during that last call that may have led to the port being 'stuck'.

 

Since the last VoiceGuide service restart was over a month ago then there would a few files to search through, but the the last trace file that contains activity for a particular channel can be identified by grepping the ktTel traces for the channel id and finding which trace last had activity on that channel.

[bfrank]

I went back to see when a particular channel stopped working. According to the logs, line ID 37 stopped accepting calls on 9/2/2010 somewhere around 15:12:00. I attached the logs for that time frame to this post. Please see if you can find anything that may have caused the issue.

 

RE:

How did you determine that the ports were 'stuck'? What was the Line Viewer's status for those stuck ports showing?

 

By noticing how channels dropped out of the logs throughout September, one by one, until there were eight left. I then observed how the Status Viewer hunts and assigns lines, and saw that only 8 were being utilized. Then I noticed (silly me for overlooking this before) that the column showing Last Call End Time showed end times way back in the past for all the "stuck" ports. That's when I hung them up manually and they went back into rotation.

logs-for-9-2-10.zip

[SupportTeam]

Trace shows that last action attempted on channel with LineId of 37 (port 12) before problems arose was an RFC3515 transfer.

 

The HMP drivers reported that the RFC3515 transfer failed.

 

Can you please post these traces (.ZIPed):

 

- vgEngine trace file which is next after 0902_1433_vgEngine.txt (probably called 0902_1515_vgEngine.txt)

- ktTel and vgEngine which capture the time when you manually issued the 'Hangup' command on these lines.

- Dialogic RTF trace which covers Sept 2nd (see: C:\Program Files\Dialogic\log)

 

 

 

Relevant trace extracts below.

 

grep " 37 12 " *_vgEngine.txt > id37vge.txt

 

151131.875  6  37  12 state [DoTransfer] Blind Hookflash Transfer to 213477362223@201.161.45.52
151131.875  6  37  12       xfer  RFC3515 transfer to 213477362223@201.161.45.52
151131.875  6  37  12       timer set   completed lTimeLeft250msUnits=120, iTimeoutCode=9001
151131.875 19  37  12 ev    Dialogic 2049,GCEV_TASKFAIL, crn=800000c, 2049,0,0,,,
151131.875  6  37  12       scriptevent GCEV_TASKFAIL  param1:, param2:, param3:
151131.875  6  37  12       LsXfer_1_Start : 2049(EV_UNKNOWN_2049),GCEV_TASKFAIL,2049,0,0,,,
151131.875  6  37  12       path {GCEV_TASKFAIL} not found
151131.890 19  37  12 ev    Dialogic 2054,GCEV_RESETLINEDEV, crn=0, 2054,0,0,,,
151131.890 19  37  12       LineState_Reinit_CleanLineState : begin
151131.890 19  37  12       ls    set   Null_InGuardTimeAfterEndOfCall   (scriptstate=LS_XFER_1_START)
151131.890 19  37  12       ScriptWorkingMode set Idle_WaitingForNextCall, (called from LineState_Reinit_CleanLineState)
151131.890 19  37  12 state Waiting for a call...
151131.890  6  37  12       scriptevent GCEV_RESETLINEDEV  param1:, param2:, param3:
151131.890  6  37  12       LsXfer_1_Start : 2054(EV_UNKNOWN_2054),GCEV_RESETLINEDEV,2054,0,0,,,
151131.890  6  37  12       path {GCEV_RESETLINEDEV} not found
151201.875  6  37  12       scriptevent EV_TIMEOUT_HANGUP  param1:, param2:, param3:
151201.875  6  37  12       LsXfer_1_Start : 9001(EV_TIMEOUT_HANGUP),EV_TIMEOUT_HANGUP,0,0,0,,,
151201.875  6  37  12       path {EV_TIMEOUT_HANGUP} not found
151201.875  6  37  12       HangupCall, source=LsDefaultHandlers:EV_TIMEOUT_HANGUP, WorkModeScript=Idle_WaitingForNextCall, yLineStateAppPov=[Null_InGuardTimeAfterEndOfCall], lPlayId=0, lRecId=0
151201.875  6  37  12                   moduleTitle=[DoTransfer]
151201.875  6  37  12       ScriptWorkingMode set Stopping, (called from HangupCall)
151201.875  6  37  12       ls    set   Disconnect_Pending   (scriptstate=LS_ENDINGCALL)
151201.875  6  37  12 state Hanging up... [LsDefaultHandlers:EV_TIMEOUT_HANGUP]
151201.875  6  37  12       rv    add [Hangup Source]{LsDefaultHandlers:EV_TIMEOUT_HANGUP}
151201.875  6  37  12       GoOnHoook_IssueDropCall start (hCall_crn=0)
151201.875  6  37  12       timer set   completed lTimeLeft250msUnits=40, iTimeoutCode=9101
151201.875  6  37  12       GoOnHoook_IssueDropCall end
151201.875 19  37  12 ev    Dialogic 2049,GCEV_TASKFAIL, crn=800000c, 2049,0,0,,,
151201.875  6  37  12       scriptevent GCEV_TASKFAIL  param1:, param2:, param3:
151201.875  6  37  12       LsEndingCall GCEV_TASKFAIL 2049 
151201.875 19  37  12 ev    Dialogic 2054,GCEV_RESETLINEDEV, crn=0, 2054,0,0,,,
151201.875 19  37  12       LineState_Reinit_CleanLineState : begin
151201.875 19  37  12       ls    set   Null_InGuardTimeAfterEndOfCall   (scriptstate=LS_ENDINGCALL)
151201.875 19  37  12       ScriptWorkingMode set Idle_WaitingForNextCall, (called from LineState_Reinit_CleanLineState)
151201.875 19  37  12 state Waiting for a call...
151201.875  6  37  12       scriptevent GCEV_RESETLINEDEV  param1:, param2:, param3:
151201.875  6  37  12       LsEndingCall GCEV_RESETLINEDEV 2054 
151201.875 19  37  12 ev    Dialogic 2054,GCEV_RESETLINEDEV, crn=0, 2054,0,0,,,
151201.875 19  37  12       LineState_Reinit_CleanLineState : begin
151201.875 19  37  12       ls    set   Null_InGuardTimeAfterEndOfCall   (scriptstate=LS_ENDINGCALL)
151201.875 19  37  12       ScriptWorkingMode set Idle_WaitingForNextCall, (called from LineState_Reinit_CleanLineState)
151201.875 19  37  12 state Waiting for a call...
151201.875  6  37  12       scriptevent GCEV_RESETLINEDEV  param1:, param2:, param3:
151201.875  6  37  12       LsEndingCall GCEV_RESETLINEDEV 2054 
151211.875  6  37  12       scriptevent EV_TIMEOUT_WAITFORIDLEAFTERDropCall  param1:, param2:, param3:
151211.875  6  37  12 state Hanging up call...(2)
151211.875  6  37  12       ls    set   Null   (scriptstate=LS_ENDINGCALL)
151211.875  6  37  12       no script running on this line. AfterHangup script will not be ran.
151211.875  6  37  12       AllScritpsCompleted_Cleanup start
151211.875  6  37  12       ScriptWorkingMode set Idle_WaitingForNextCall, (called from AllScritpsCompleted_Cleanup)
151211.875  6  37  12       WriteToLogFiles_CurrScriptOnly begin
151211.875  6  37  12       WriteToLogFiles_CurrScriptOnly : LineState.iVgsIdx<=0
151211.875  6  37  12       RvSaveToLogFiles_CurrAndStack iScriptCallStack_LastUsed_Idx=0
151211.875  6  37  12       LineState_Reinit_CleanLineState : begin
151211.875  6  37  12       ls    set   Null_InGuardTimeAfterEndOfCall   (scriptstate=LS_ENDINGCALL)
151211.875  6  37  12       ls    set   ignore new linestate set as current linestate is Null
151211.875  6  37  12       ScriptWorkingMode set Idle_WaitingForNextCall, (called from LineState_Reinit_CleanLineState)
151211.875  6  37  12       timer set   completed lTimeLeft250msUnits=12, iTimeoutCode=9013
151211.875  6  37  12 state Waiting for a call...
151211.875  6  37  12       ScriptWorkingMode set Idle_WaitingForNextCall, (called from LineState_Reinit_AndReleaseCall)
151211.875 19  37  12 ev    Dialogic 2054,GCEV_RESETLINEDEV, crn=0, 2054,0,0,,,
151211.875 19  37  12       LineState_Reinit_CleanLineState : begin
151211.875 19  37  12       ls    set   Null_InGuardTimeAfterEndOfCall   (scriptstate=LS_NULL_AWAITINGCALLS)
151211.875 19  37  12       ls    set   ignore new linestate set as current linestate is Null
151211.875 19  37  12       ScriptWorkingMode set Idle_WaitingForNextCall, (called from LineState_Reinit_CleanLineState)
151211.875 19  37  12 state Waiting for a call...
151211.875  6  37  12       scriptevent GCEV_RESETLINEDEV  param1:, param2:, param3:
151211.875  6  37  12       LsAwaitingCalls GCEV_RESETLINEDEV
151214.875  6  37  12       scriptevent EV_TIMEOUT_AFTERIDLE_ALLOWOUT  param1:, param2:, param3:
151214.875  6  37  12       ls    set   Null   (scriptstate=LS_NULL_AWAITINGCALLS)

 

 

 

grep " 37 " *_ktTel.txt > id37kt.txt

 

151131.875  1640  37 fn    TransferBlind(37,0,213477362223@201.161.45.52,77918140)
151131.875  1640  37       TelDriver_TransferBlind start
151131.875  1640  37       TelDriver_TransferBlind no SIP: or TA: prefix specified. Adding SIP: prefix to the transfer destination.
151131.875  1640  37       CallTransfer_Invoke start
151131.875  1640  37       gc_InvokeXfer SIP:213477362223@201.161.45.52
151131.875  1640  37       gc_InvokeXfer SIP:213477362223@201.161.45.52 ok
151131.875  5380  37       CtEventProcess idx=2211 : evttype=2049(2049), crn=800000c, data=091C2218(08901C60), len=8(8) q: 0/12
151131.875  5380  37 ev    GCEV_TASKFAIL crn=800000c
151131.875  5380  37       gc_ErrorInfo gcValue=10(0xa), gcMsg=[Function is not supported], ccLibId=0, ccLibName=[GLOBALCALL], ccValue=0xa, ccMsg=[Function is not supported], additionalInfo=[]
151131.875  5380  37       t_info: gcValue=137(0x89) gcMsg=[CCLIB specific] ccLibId=8 ccLibName=[GC_H3R_LIB] ccValue=[0x6] ccMsg=[iPERR_INTERNAL - see rtf log] additionalinfo=[]
151131.875  5380  37 r     Dialogic  GCEV_TASKFAIL 2049 (2049 0 0   )
151131.875  5380  37       calling gc_ResetLineDev. taskfail_crn=800000c, hli->crn=800000c
151131.890  5380  37       CtEventProcess idx=2212 : evttype=2054(2054), crn=0, data=091C2248(08901C60), len=8(8) q: 0/12
151131.890  5380  37 ev    GCEV_RESETLINEDEV - gc_ResetLineDev function completed
151131.890  5380  37       SetChanStateInServiceAndWaitCall call from GCEV_RESETLINEDEV
151131.890  5380  37       SetChanStateInServiceAndWaitCall: gc_setchanstate not called in this version.
151131.890  5380  37       gc_WaitCall call in SetChanStateInServiceAndWaitCall
151131.890  5380  37       gc_WaitCall ok 
151131.890  5380  37 r     Dialogic  GCEV_RESETLINEDEV 2054 (2054 0 0   )
151201.875  1640  37 fn    DropCall(sLineId=37, sXMLOptions=[], crn=0)
151201.875  1640  37       TelDriver_DropCall(sXMLOptions=[], crn_in=0)
151201.875  1640  37       clearing sDTMFsReceivedBeforeCallAnswer in TelDriver_DropCall
151201.875  1640  37       gc_DropCall iCrnToDrop=800000c cause=16:GC_NORMAL_CLEARING (nocausetag)
151201.875  1640  37 ERROR gc_DropCall iCrnToDrop=800000c
151201.875  1640  37       gc_ErrorInfo gcValue=137(0x89), gcMsg=[CCLIB specific], ccLibId=8, ccLibName=[GC_H3R_LIB], ccValue=0x6, ccMsg=[iPERR_INTERNAL - see rtf log], additionalInfo=[]
151201.875  1640  37       gc_ResetLineDev ok (called from gc_DropCall_ERROR)
151201.875  5380  37       CtEventProcess idx=2245 : evttype=2049(2049), crn=800000c, data=091C2878(08901C60), len=8(8) q: 1/12
151201.875  5380  37 ev    GCEV_TASKFAIL crn=800000c
151201.875  5380  37       gc_ErrorInfo gcValue=10(0xa), gcMsg=[Function is not supported], ccLibId=0, ccLibName=[GLOBALCALL], ccValue=0xa, ccMsg=[Function is not supported], additionalInfo=[]
151201.875  5380  37       t_info: gcValue=1014(0x3f6) gcMsg=[unknown error or result] ccLibId=8 ccLibName=[GC_H3R_LIB] ccValue=[0x42] ccMsg=[iPEC_InternalReasonNormal] additionalinfo=[]
151201.875  5380  37 r     Dialogic  GCEV_TASKFAIL 2049 (2049 0 0   )
151201.875  5380  37       calling gc_ResetLineDev. taskfail_crn=800000c, hli->crn=800000c
151201.875  5380  37       CtEventProcess idx=2246 : evttype=2054(2054), crn=0, data=091C28A8(08901C60), len=8(8) q: 0/12
151201.875  5380  37 ev    GCEV_RESETLINEDEV - gc_ResetLineDev function completed
151201.875  5380  37       SetChanStateInServiceAndWaitCall call from GCEV_RESETLINEDEV
151201.875  5380  37       SetChanStateInServiceAndWaitCall: gc_setchanstate not called in this version.
151201.875  5380  37       gc_WaitCall call in SetChanStateInServiceAndWaitCall
151201.875  5380  37       gc_WaitCall ok 
151201.875  5380  37 r     Dialogic  GCEV_RESETLINEDEV 2054 (2054 0 0   )
151201.875  5380  37       CtEventProcess idx=2247 : evttype=2054(2054), crn=0, data=091C28D8(08901C60), len=8(8) q: 0/12
151201.875  5380  37 ev    GCEV_RESETLINEDEV - gc_ResetLineDev function completed
151201.875  5380  37       SetChanStateInServiceAndWaitCall call from GCEV_RESETLINEDEV
151201.875  5380  37       SetChanStateInServiceAndWaitCall: gc_setchanstate not called in this version.
151201.875  5380  37       gc_WaitCall call in SetChanStateInServiceAndWaitCall
151201.875  5380  37 ERROR gc_WaitCall
151201.875  5380  37       gc_ErrorInfo gcValue=65(0x41), gcMsg=[Function is not supported in this state], ccLibId=8, ccLibName=[GC_H3R_LIB], ccValue=0x9, ccMsg=[iPERR_INVALID_STATE], additionalInfo=[]
151201.875  5380  37 r     Dialogic  GCEV_RESETLINEDEV 2054 (2054 0 0   )
151211.875  1640  37 fn    ResetLineDev(sLineId=37, Param1=0)
151211.875  1640  37       gc_ResetLineDev ok (called from TelDriver_ResetLineDev)
151211.875  5380  37       CtEventProcess idx=2258 : evttype=2054(2054), crn=0, data=091C2AE8(08901C60), len=8(8) q: 0/12
151211.875  5380  37 ev    GCEV_RESETLINEDEV - gc_ResetLineDev function completed
151211.875  5380  37       SetChanStateInServiceAndWaitCall call from GCEV_RESETLINEDEV
151211.875  5380  37       SetChanStateInServiceAndWaitCall: gc_setchanstate not called in this version.
151211.875  5380  37       gc_WaitCall call in SetChanStateInServiceAndWaitCall
151211.875  5380  37       gc_WaitCall ok 
151211.875  5380  37 r     Dialogic  GCEV_RESETLINEDEV 2054 (2054 0 0   )
151933.015  5380  37       CtEventProcess idx=2672 : evttype=2135(2135), crn=800000c, data=091C7888(08901C60), len=8(8) q: 1/12
151933.015  5380  37 ev    GCEV_DETECTED crn=800000c (setting hli->crn for line 37)
151933.015  5380  37       CtEventProcess idx=2673 : evttype=2084(2084), crn=800000c, data=091C78B8(08901C60), len=8(8) q: 0/12
151933.015  5380  37 ev    GCEV_OFFERED crn=800000c (ktTel_HMP30 v7.1.0, Jun 16 2010 14:54:22)  (setting hli->crn for line 37)
151933.015  5380  37       calling CIPStateMachine_NullGcevOffered next
151933.015  5380  37       CIPStateMachine_NullGcevOffered START. sets the coders negotionation and other call paramters
151933.015  5380  37       RemoteEndsProposedCoders parm_data_buf=0xd7f97ef, parm_data_size=329
151933.015  5380  37       parm_data_ext: data_size=42, parm_ID=1, pData=0xd7f97f4, pInternal=0xd7f97ef, set_ID=12315, version=256
151933.015  5380  37       parm_data_ext: data_size=37, parm_ID=2, pData=0xd7f9823, pInternal=0xd7f981e, set_ID=12315, version=256
151933.015  5380  37       parm_data_ext: data_size=37, parm_ID=16, pData=0xd7f984d, pInternal=0xd7f9848, set_ID=12315, version=256
151933.015  5380  37       parm_data_ext: data_size=58, parm_ID=18, pData=0xd7f9877, pInternal=0xd7f9872, set_ID=12315, version=256
151933.015  5380  37       parm_data_ext: data_size=44, parm_ID=19, pData=0xd7f98b6, pInternal=0xd7f98b1, set_ID=12315, version=256
151933.015  5380  37       parm_data_ext: data_size=38, parm_ID=16, pData=0xd7f98e7, pInternal=0xd7f98e2, set_ID=12300, version=256
151933.015  5380  37       parm_data_ext: data_size=38, parm_ID=16, pData=0xd7f9912, pInternal=0xd7f990d, set_ID=12300, version=256
151933.015  5380  37       gc_util_next_parm_ex returned 'There are no more parms in the GC_PARM_BLK'
151933.015  5380  37       SetTxRxVoiceChannelCoders begin
151933.015  5380  37       codec order: 1:ULaw, 2:ALaw
151933.015  5380  37       SetTxRxVoiceChannelCoders txcoders=6, rxcoders=6
151933.015  5380  37       gc_SetUserInfo(GCTGT_GCLIB_CRN, 0x800000c, gcParmBlk=0xe3fecf0, GC_SINGLECALL) ok
151933.015  5380  37       protocol is SIP
151933.015  5380  37       gc_GetCallInfo ORIGINATION_ADDRESS_SIP=[sip:816@216.48.184.52;user=phone;tag=6998657592610064597]
151933.015  5380  37       gc_GetCallInfo DESTINATION_ADDRESS_SIP=[sip:18002978124@192.168.202.250;user=phone]
151933.015  5380  37       gc_GetCallInfo IP_CALLID=[6998657592610064597-1283455151-13842]
151933.015  5380  37       gc_GetCallInfo ORIGINATION_ADDRESS=[816@216.48.184.52]
151933.015  5380  37       gc_GetCallInfo DESTINATION_ADDRESS=[18002978124@192.168.202.250]
151933.015  5380  37       calling OnGcEvOffered_GetCallerID next
151933.015  5380  37       OnGcEvOffered_GetCallerID start (with CallerID report)
151933.015  5380  37       OnGcEvOffered_GetCallerID gc_GetCRN: crn=0x800000c (setting hli->crn for line 37)
151933.015  5380  37       gc_ErrorInfo gcValue=10(0xa), gcMsg=[Function is not supported], ccLibId=0, ccLibName=[GLOBALCALL], ccValue=0xa, ccMsg=[Function is not supported], additionalInfo=[]
151933.015  5380  37 ERROR gc_GetNetCRV in offered failed. hli->crn=0x800000c
151933.015  5380  37       could not retrieve CALLNAME
151933.015  5380  37       raising LINECALLSTATE_OFFERING next (with cid data)
151933.015  5380  37       CTelProxy::Event_CallState GCEV_OFFERED iLineCallState=2, hCall=134217740 m_pktTelProxyClient=006917D4
151933.015  5380  37 r     CallState GCEV_OFFERED

[bfrank]

I attached 3 zip files:

 

- 0902_1515_vgEngine.zip (log following the log I attached to the last post)

- 1007_1500_vgEngine.zip (log of the "hangup" actions)

- 1007_ktTel.zip (ktTel log of same)

 

The "hangup" actions occurred somewhere around 15:20.

 

I couldn't find any Dialogic rtf trace logs for 9/2 - it looks like the logs get deleted after a day or two. Do they get archived somewhere?

0902_1515_vgEngine.zip

1007_1500_vgEngine.zip

1007_ktTel.zip

[SupportTeam]

It looks like the fix for recovery from this situation is already in the latest version of VoiceGuide.

Please update your system to this version: [old link removed]


To determine cause of RFC3515 transfers failing we would need to see RTF log capturing such a failure. To capture the RTF log recommend daily grepping of VoiceGuide trace files for:

GCEV_TASKFAIL

and if found then save all the Dialogic RTF logs and post them here along with VoiceGuide traces.

It is possible that the RFC3515 transfers are failing as there are no more licenses available for HMP to make the outgoing call. (RFC3515 transfers require a new call to be made before transfer is effected). Recommend the maximum number of calls sent to system is 1 less then the system capacity, allowing VoiceGuide/HMP to always use the 'unused' license for the outgoing call.

[bfrank]

OK, I will monitor for GCEV_TASKFAIL and catch the Dialogic RTF logs. Stay tuned.

 

One question, though. The logs from 9/2/10 I posted earlier show:

 

151201.875 6 37 12 path {EV_TIMEOUT_HANGUP} not found
151201.875 6 37 12 HangupCall, source=LsDefaultHandlers:EV_TIMEOUT_HANGUP, WorkModeScript=Idle_WaitingForNextCall, yLineStateAppPov=[Null_InGuardTimeAfterEndOfCall], lPlayId=0, lRecId=0
151201.875 6 37 12 moduleTitle=[DoTransfer]
151201.875 6 37 12 ScriptWorkingMode set Stopping, (called from HangupCall)

 

The [DoTransfer] module does specify paths for both {timeout 30} and {fail}, so I wonder why it wasn't followed? Furthermore, why didn't the cleanup script run for this call when it ended? It was specified as the "script to run when script ends" in the script properties.

[SupportTeam]

Looks like any failure reports (GCEV_TASKFAIL events) from Dialogic layer during the SIP REFER (RFC3515) transfer are currently handled in a way that results in the call termination and the 'on hangup' script not being ran.

 

We will try to look into whether in case of SIP REFER (RFC3515) transfer failure it is still OK to proceed with the remainder of he script (and hence take the 'fail' path form the module).

 

An important factor in deciding how they can be handled would be the RTF logs from your system. When you have these available please post them here and we can then see how/if software should be modified to best handle this situation.