ICM router Requery

[Ayodeji Okanlawon]

Background: ( NB Router time is 2hrs ahead of CUSP Time, so router logs is always +2)

Call comes in to PQ, answered by an agent and was transferred to another queue..

++ ICM selects an agent in new PQ and returns the label for the agent ++

14:36:44:120 ra-rtr Trace: (14492 14493 22632 : 0 0) Connect: CID=(152278,636), EventSelect=104, ServiceType=1, RCID=5001, Label(s)=3006262537
14:36:44:464 ra-rtr Trace: Agent 6169 from PG domain 1. [rdy-0:1,RA*] to [rdy-0+1:1,R]
14:36:44:464 ra-rtr Trace: Agent 6169 from PG domain 1. [rdy-0+1:1,R] to [res-1:1,R]
14:36:45:339 ra-rtr Trace: TIP: TIPUpLink::sendCongestionControlTIPMsg Sent CongestionControlEvent
14:36:48:339 ra-rtr Trace: TIP: TIPUpLink::sendCongestionControlTIPMsg Sent CongestionControlEvent
14:36:50:339 ra-rtr Real Time: SG=3 SC=1 P=4 CT=2 A=1 ASG=4 PQ=3 PQS=7 SCR=1 Total=26 Sent=26.

++ CUSP RX request from CVP +++

2017-12-04 12:36:45.101     RX     
INVITE sip:5553253006262537@cuspna.corp.lab.com.service-now.com;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.126.111:5060;branch=z9hG4bKZhucYNmIVJBWPADWy3nh+w~~1000557
Max-Forwards: 62

++ CUSP sends request to CUCM +++

2017-12-04 12:36:45.103     TX     

INVITE sip:5553253006262537@CUCM-DAL-US.corp.lab.com.service-now.com SIP/2.0
Via: SIP/2.0/TCP 192.168.126.154:5060;branch=z9hG4bK5u4eqtkaXBrX3pDsqX1XLQ~~4024238
Via: SIP/2.0/TCP 192.168.126.111:5060;branch=z9hG4bKZhucYNmIVJBWPADWy3nh+w~~1000557
Max-Forwards: 61

++ However 10sec after router sent label for the agent  and just before agent answered the call, ICM says its rerouting the call and says reroute reason=1 call state=15

14:36:51:339 ra-rtr Trace: TIP: TIPUpLink::sendCongestionControlTIPMsg Sent CongestionControlEvent
14:36:54:339 ra-rtr Trace: TIP: TIPUpLink::sendCongestionControlTIPMsg Sent CongestionControlEvent
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) ReRoute: Reason=1 CallState=15.
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) Dialog handling a reroute request (router requery)
14:36:54:808 ra-rtr Trace: CTPQ(5126, 5007, 37793): CountCallStatus:13(Requeried).
14:36:54:808 ra-rtr Trace: CallType(5126, 37793): Changing InvokeID to 37794.
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) Dialog got ReRoute Requery reason(1).
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) CallInformationInd: CID=(152278,636), PerID=5000, RCKSeqNum=7, Type=0, Code=9, PeripheralTargetID=6169, AbortType=0
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) Dialog resuming (Reroute Requery.) status (1)
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) CID=(152278,636):Requery status 1
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) Script changed CallType from ID 5126 to 5047.
14:36:54:808 ra-rtr Trace: CallType(5047, 37794): Init CT_SL_Timer: Threshold(20 + 2).

+++ ICM then generates another label for the requery +++
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) Correlation id for dialog is (22633).
14:36:54:808 ra-rtr Trace: (14492 14493 22633 : 0 0) TransferToVRU: Label=123456789012, CorID=22633, VRUID=5000, RCID=5001
14:36:54:808 ra-rtr Trace: (14492 14493 22633 : 0 0) TransferConnect sent. Dialog pending.

+++ Meanwhile  at 12:36:55 (1sec after call was pulled back) agent answered the call and cucm sends 200 OK to CUSP +++

2017-12-04 12:36:55.197     RX     
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.126.154:5060;branch=z9hG4bK5u4eqtkaXBrX3pDsqX1XLQ~~4024238
Via: SIP/2.0/TCP 192.168.126.111:5060;branch=z9hG4bKZhucYNmIVJBWPADWy3nh+w~~1000557

Question is why is the call been pulled back.

What does the reroute reason = 1 and call state=15 mean?

Is this a timer issue of some sort somewhere. NB that the timeout on the step 1 used for this PQ=0

[Senthil Kumar Sankar]

Hello,

The ReRoute Reason Code 1 is  REQUERY_ROUTE_SELECT_FAILURE (1)

"Routing client generated an error code from ReRouteReq msg indicating a Route Select failure."

So basically need to check on CVP logs and VRUPIM logs as on why there was this reposnse.

Table 2 RequeryStatus Variables

Requery Status Variable	Description
REQUERY_ANSWER (0)	Script ends. The call was successfully sent to the chosen target. Note    This variable is used internally by the CallRouter. You cannot test for this variable in an IF node.
REQUERY_ROUTE_SELECT_FAILURE (1)	Routing client generated an error code from ReRouteReq msg indicating a Route Select failure.
REQUERY_CALLED_PARTY_BUSY (2)	Routing client generated error code from ReRouteReq msg indicating the called party is busy.
REQUERY_NO_ANSWER (3)	Routing client generated an error code from ReRouteReq msg indicating no answer.
REQUERY_ERROR (4)	CallRouter generated an error code. The attempt to send the call to target failed because the target was not reachable (i.e., busy, ring no answer).
REQUERY_TIMED_OUT (5)	The attempt to send the call to a target failed because the Routing Client did not respond within the DivertOnBusyCallTimeout period. The script ends. Note    This variable is used internally by the CallRouter. You cannot test for this variable in an IF node.
REQUERY_ABORTED (6)	The attempt to send the call to a target failed because the caller hung up or the call was lost. In the case of ABANDON and DISCONNECT, the CallRouter assumes the call has ended and ends the script. The RequeryStatus value is set to 6, indicating REQUERY_ABORTED. Note    This variable is used internally by the CallRouter. You cannot test for this variable in an IF node.

Regards,

Senthil Kumar

[Ayodeji Okanlawon]

Thank you for pointing me in the right direction. Indeed it was CVP that was sending the connect failure reason of 1 and a reroute request. But I couldnt correlate this properly because there seem to be a time offset between CVP's PG and Router, hence request/response from CVP are arriving a few ms late to router

Here is how I figured this out

++ PG sent script result at 14:36:44:738 ++
14:36:44:738 PG1B-pim2 Trace: VRU->PG:RUN_SCRIPT_RESULT(142 bytes):DID=14493 SendSeqNo=2 InvID=1 ResultCode=1 CED=No NewTrans=0

+++ Router received it at 14:36:44:120 ( a time offset of 618ms) +++
14:36:44:120 ra-rtr Trace: (14492 14493 22632 : 0 0) Dialog resuming (Script response received (success).) status (0)

++ CVP Received 488 media not acceptable at 14:36:55.120 ++
31298650: 192.168.126.111: Dec 04 2017 14:36:55.120 -0600: %_TransactionManagement-7-com.dynamicsoft.DsLibs.DsUALibs.DsSipLlApi.TransactionManagement: processMessage(): ----- BEGINING PROCESSING NEW MESSAGE ------
SIP/2.0 488 Not Acceptable Media

+++ CVP PG Sent a connect Failure at 14:36:55:426 To Router ( if you deduct 618ms from this, it will be 14:36:54:808 on router )

14:36:55:426 PG1B-pim2 Trace: VRU->PG:EVENT_REPORT(16 bytes):DID=14492 SendSeq#=3 EventCode=ConnectFailure(1)
14:36:55:426 PG1B-pim2 Trace: ToRouter_ReRouteReq:REROUTE_REQ RCID=5001 PID=5000 GrpDelKey=0 Reason=1

+++ Router receives reroute due to call failure from CVP-PG at 14:36:54:808 +++
14:36:54:808 ra-rtr Trace: (14492 14493 22632 : 0 0) ReRoute: Reason=1 CallState=15.

[piyush aghera]

Hi Ayodeji,

I am having exact same problem with PCCE 11.6, so can you please tell me what was done to resolve this issue ?\\

Thanks.

[piyush aghera]

I am in the same boat.  May I know what was done to resolve this issue ?