Troubleshoot Errors that can occur while processing a Sync Policy Action

Introduction

This document describes how we can troubleshoot and resolve Cisco Policy Suite (CPS) errors related to a sync policy action.

Prerequisites

Requirements

Cisco recommends that you have knowledge of these topics:

• Linux Operating System
• Cisco Policy Suite

Components Used

The information in this document is based on Cisco Policy Suite.

The information in this document was created from the devices in a specific lab environment. All of the devices used in this document started with a cleared (default) configuration. If your network is live, ensure that you understand the potential impact of any command.

Problem:  Error occurred while processing a Sync Policy Action

Errors observed in the /var/log/broadhop/consolidated-qns.log log file:

ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Data store is not available: No master DB available: sessionmgrxx-SITE1:27720

ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Duplicate Value for Unique Data Constraint: credential networkId: 61431792343

Example shows the error in 2 different sites and 2 different timestamps:

The diameter response time can increase slightly due to the error and spikes can be observed on grafana as well.

SITE-1 consolidated-qns logs:

SITE1-qns11 2016-10-13 09:44:59,343 [pool-2-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Data store is not available: No master DB available: sessionmgrxx-SITE1:27720
at com.broadhop.spr.dao.impl.mongo.MongoPersistence.searchSubscribers(MongoPersistence.java:433) ~[com.broadhop.spr.dao.mongo_2.3.6.r078013.jar:na]
SITE1-qns04 2016-10-13 10:42:03,629 [pool-2-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
SITE1-qns06 2016-10-13 10:47:20,555 [pool-3-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.

 SITE-1 Mongo Logs:

2016-10-13T08:22:02.330+1100 [conn15604045] command spr.$cmd command: count { count: "subscriber", query: { services_key.code_key: "HWBB" }, fields: {} } planSummary: COLLSCAN keyUpdates:0 numYields:2 locks(micros) r:1297276 reslen:48 700ms
2016-10-13T08:47:02.909+1100 [conn15605855] command spr.$cmd command: count { count: "subscriber", query: { services_key.code_key: "HWBB" }, fields: {} } planSummary: COLLSCAN keyUpdates:0 numYields:1 locks(micros) r:1095391 reslen:48 585ms
2016-10-13T09:37:02.563+1100 [conn15609536] command spr.$cmd command: count { count: "subscriber", query: { services_key.code_key: "HWBB" }, fields: {} } planSummary: COLLSCAN keyUpdates:0 numYields:0 locks(micros) r:519701 reslen:48 519ms
2016-10-13T09:52:02.472+1100 [conn15610667] command spr.$cmd command: count { count: "subscriber", query: { services_key.code_key: "HWBB" }, fields: {} } planSummary: COLLSCAN keyUpdates:0 numYields:1 locks(micros) r:1072306 reslen:48 564ms
2016-10-13T10:27:02.649+1100 [conn15613701] command spr.$cmd command: count { count: "subscriber", query: { services_key.code_key: "HWBB" }, fields: {} } planSummary: COLLSCAN keyUpdates:0 numYields:1 locks(micros) r:657876 reslen:48 504ms

 SITE-2 consolidated-qns logs:

SITE2-qns04 2016-11-18 05:28:33,776 [pool-1361732-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Duplicate Value for Unique Data Constraint: credential networkId: 61431792343
SITE2-qns09 2016-11-17 20:47:59,539 [pool-1361592-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Duplicate Value for Unique Data Constraint: credential networkId: 61431792343
SITE2-qns06 2016-11-17 01:45:15,476 [pool-63652-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Data store is not available: No master DB available: sessionmgr11-SITE1:27720
SITE2-qns12 2016-11-17 01:45:15,514 [pool-63484-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Data store is not available: No master DB available: sessionmgr11-SITE1:27720
SITE2-qns10 2016-11-12 07:40:53,659 [pool-63538-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Duplicate Value for Unique Data Constraint: credential networkId: 61431792343

"An error occured while processing a Sync Policy Action" can be caused by two reasons:

 1. Primary/Master MongoDB is not accessible or is down.
 2. Policy Server (QNS) instance(s) is not able to access the sessionmgr Virtual machine (VM) due to a network issue.

The logs indicate that this is related to a network fluctuation as the sessionmgr VM access exceptions for Sync Policy Action can be observed on most of the QNS VMs. These exceptions are related master SPR DB (sessionmgr11-SITE1:27720) not being reachable. For the same duration there are no errors observed in MongoDB logs. Also, there were no primary to secondary DB failover observed for the same time period.

Solution

“Sync Policy Action“  errors have occurred on SITE1 and SITE2 because of two reasons:

1.

SITE1-qns11 2016-10-13 09:44:59,343 [pool-2-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Data store is not available: No master DB available: sessionmgrxx-SITE1:27720

"Data store is not available".  This clearly looks like case of minor network fluctuations which get resolved in quick successions:

2. 

SITE2-qns04 2016-11-18 05:28:33,776 [pool-1361732-thread-1] ERROR c.b.policy.impl.RulesPolicyService - An error occured while processing a Sync Policy Action.
com.broadhop.spr.exception.SubscriberException: Duplicate Value for Unique Data Constraint: credential networkId: 61431792343

"Duplicate Value for Unique Data Constraint " has no impact on the sytem or subscribers as this exception would be observed when a duplicate request is received from the PCEF.  The original request  was already honored.

These are the steps that Cisco recommends to be performed when "Data store is not available" is observed in the consolidated-qns.log.

Step 1. Check the network path or any router between QNS VMs and the sessionmgr11-SITE1VM.

Step 2. Check the /var/log/messages from QNS VMs and sessionmgr11-SITE1VM.

Step 3. Check on the router via which QNS and sessionmgr11-SITE1 VM are connected

In order to confirm that the "datastore not available" exception occurs while there is an attempt to connect any instance of the DB on sessionmgrxx-xxx:277xx you can run this command for the entire duration (may be for 24hrs) on the sessionmgrxx VM where network issue is being obsered.  The output will be stored at /var/tmp/output.txt. 

while true; do netstat -apn | grep 27720; sleep 1 ; done | tee /var/tmp/output.txt

 In order to stop the netstat command from running simply stop it with CTRL C:

ctrl c

Note In case you observe that there is issue in connecting and resetting TCP connection on sessionmgrxx-xxx. Then we need to repair the database (DB), by deleting the data and recreating the DB from secondary nodes.  ( link to repair / recover db to be published -  )