MR PIM Active But Showing Socket Errors
From DocWiki
Contents |
Scenario Setup
System Console
- Stop EAAS process
UCCE
- Rename user.cisco.cmb to user.cisco.cmbb
- Cycle MR PG on both sides
Problem Statement
Intermittent routing issues have been observed. MR PIM shows ACTIVE, but is disconnecting due to socket errors.
Note: With Windows 2008 R2, these process windows would not be seen. Instead, the above would be observed using EMSMON or by dumping logs to text files.
Message Flow
In a normal startup, the MR PIM should follow the below flow:
- OPEN_REQ
- OPEN_RESP
- MR_REGISTER_VARIABLES_REQ
- MR_REGISTER_VARIABLES_RESP
- ROUTING_ENABLED_EVENT
- Routing Client successfully ACTIVATED
In this case, we are seeing:
- OPEN_REQ
- OPEN_RESP
- CLOSE_REQ
- CLOSE_RESP
The MR is never registering the ECC Variables.
EAAS Logs
The EAAS logs will provide guidance as to where the failure is occurring.
2011-06-05 23:16:08.080 GMT-0400 <@> ERROR <@> [788:Thread-369] <@> ProcessId:4184 <@> PID:1 <@> UID:12 <@> HttpSessionId: <@> com.cisco.ipcc.mr.ECCVariableRegistrar <@> checkICMMandatoryECCVariables <@> Please check/correct at ICM the spelling of the following ecc variables and restart EAAS process and instance.user.cisco.cmb <@>
2011-06-05 23:16:08.080 GMT-0400 <@> ERROR <@> [788:Thread-369] <@> ProcessId:4184 <@> PID:1 <@> UID:12 <@> HttpSessionId: <@> com.cisco.ipcc.mr.SessionManager <@> handleOpenRequest() <@> Failure in handling OPEN_REQ from MR session will be terminated sessionId=362 EAASInstanceId=1008 <@>
java.lang.NullPointerException
EAAS is unable to register user.cisco.cmb, which explains what we saw in the MR PIM logs.
ECC Variable Naming
EIM/WIM
By default, EIM/WIM looks for ECC Variables with specific names. These variables are set on the File Server in C:\CIM\eService\config\ipcc\egicm_ecc_variables_name.properties
# Name of ECC Variables used for Blended Collaboration and Callback queues
# Structure of this file is ecc variable name = unique identifier in CIM Code
user.cim.activity.id = 1
user.wim.customer.name = 2
user.cisco.cmb = 3
user.cisco.cmb.callclass = 4
We know that EAAS is looking for user.cisco.cmb correctly, so the issue must be on the UCCE side.
UCCE
Navigate to Configuration Manager > Expanded Call Variable List and look for user.cisco.cmb. Here we can see that the variable name has been typed incorrectly as "user.cisco.cmbb". Remove the extra "b" and save.
Cycle EAAS!
The EAAS process must be restarted once the ECC Variable names in UCCE have been updated.
23:58:28:603 pg2A-pim2 Attempting to connect to MR application at IP address 10.77.30.32 port 38101.
23:58:28:603 pg2A-pim2 Trace: Transport: Making connection attempt to host1: 43srvc port: 38101
23:58:28:603 pg2A-pim2 Connection to MR application established.
23:58:28:603 pg2A-pim2 Trace: PG->Application:
Message = OPEN_REQ; Length = 20 bytes
InvokeID = (66403500) Hex 03f53cac
HeartbeatInterval = (5000) Hex 00001388
MsgInterfaceRev = (1) Hex 00000001
Hostname: icm751
VersionNumber:
23:58:28:713 pg2A-pim2 Trace: Application->PG:
Message = OPEN_RESP; Length = 25 bytes
Invoke ID = (66403500) Hex 03f53cac
Prior Failure = (0) Hex 00000000
Status = (0) Hex 00000000
Hostname:
VersionNumber: 7.0.0.0
23:58:28:713 pg2A-pim2 Peripheral 5006 sending OPC PIM_OK_ACK acknowledgment for command PIM_SET_ACTIVE_REQ (TransID=0).
23:58:28:713 pg2A-pim2 ProcessPIMSetActiveReq: Peripheral 5006 ACTIVATED.
23:58:28:713 pg2A-pim2 Attempting to ACTIVATE Peripheral's Routing Client.
23:58:28:713 pg2A-pim2 Failed an attempt to ACTIVATE the Peripheral's Routing Client. Will retry.
23:58:28:791 pg2A-pim2 Trace: Application->PG:
Message = MR_REGISTER_VARIABLES_REQ; Length = 136 bytes
InvokeID = (1) Hex 00000001
Call Variable Mask: (1023) Hex 000003ff
NumberOfVariables = (5) Hex 00000005
NumberOfArrayElements = (0) Hex 00000000
ECC Variable Name: user.cim.activity.id
Value:
ECC Variable Name: user.wim.customer.name
Value:
ECC Variable Name: user.cisco.cmb
Value:
ECC Variable Name: user.cisco.cmb.callclass
Value:
ECC Variable Name: user.cim.activity.priority
Value:
23:58:28:791 pg2A-pim2 Trace: Media Routing Application registered ECC variable: "user.cim.activity.id"
23:58:28:791 pg2A-pim2 Trace: Media Routing Application registered ECC variable: "user.wim.customer.name"
23:58:28:791 pg2A-pim2 Trace: Media Routing Application registered ECC variable: "user.cisco.cmb"
23:58:28:791 pg2A-pim2 Trace: Media Routing Application registered ECC variable: "user.cisco.cmb.callclass"
23:58:28:791 pg2A-pim2 Trace: Media Routing Application registered ECC variable: "user.cim.activity.priority"
23:58:28:791 pg2A-pim2 Trace: ICM->Application:
Message = MR_REGISTER_VARIABLES_RESP; Length = 8 bytes
Invoke ID = (1) Hex 00000001
Status = (0) Hex 00000000
23:58:29:994 pg2A-pim2 Trace: MR_Peripheral::ProcessThisINRCMessage. INRC message: 2.
23:58:29:994 pg2A-pim2 Peripheral's Routing Client successfully ACTIVATED.
23:58:29:994 pg2A-pim2 Trace: MR_Peripheral::On_OPC_RoutingEnabledEvent:
ROUTING_ENABLED_EVENT RCID=0 PID=0
23:58:29:994 pg2A-pim2 Trace: PG->Application:
Message = ROUTING_ENABLED_EVENT; Length = 0 bytes
23:58:30:041 pg2A-pim2 Trace: MR_Peripheral::ProcessThisINRCMessage. INRC message: 2.
23:58:30:041 pg2A-pim2 Peripheral's Routing Client successfully ACTIVATED.
Impact to CMB
How does this impact CMB? Place a callback request and observe that this fails as well.
Resolution
This scenario stressed the importance of items being configured as documented. Items such as Media Classes, Media Routing Domains, and ECC variables must be configured correctly for the integrated connections to come up properly.
The log message in the initial problem statement was misleading, as the root cause is something far from a socket error.
