pathd: add 'debug pathd policy' command

Add a new cli command to troubleshoort pathd daemon.
Some traces initially enabled are hidden behind this
cli command.

Signed-off-by: Philippe Guibert <philippe.guibert@6wind.com>

4 files changed, 122 insertions, 44 deletions

diff --git a/doc/user/pathd.rst b/doc/user/pathd.rst
index f0b76f10b..ec107fbe4 100644
--- a/doc/user/pathd.rst
+++ b/doc/user/pathd.rst
@@ -175,7 +175,7 @@ controller and obtain those by means of the PCEP protocol.
 .. image:: images/pathd_initiated_multi.png
 
 Starting
-=============
+========
 
 Default configuration file for *pathd* is :file:`pathd.conf`.  The typical
 location of :file:`pathd.conf` is |INSTALL_PREFIX_ETC|/pathd.conf.
@@ -480,6 +480,12 @@ Configuration Commands
 
    Specify a peer and its precedence in a PCC definition.
 
+Debugging
+---------
+
+.. clicmd:: debug pathd policy
+
+   Enable or disable Pathd policy information.
 
 Introspection Commands
 ----------------------
diff --git a/pathd/path_cli.c b/pathd/path_cli.c
index e5bbd9430..7510f2ad0 100644
--- a/pathd/path_cli.c
+++ b/pathd/path_cli.c
@@ -1096,6 +1096,20 @@ DEFPY_NOSH(show_debugging_pathd, show_debugging_pathd_cmd,
 	cmd_show_lib_debugs(vty);
 	/* nothing to do here */
 	path_ted_show_debugging(vty);
+	path_policy_show_debugging(vty);
+	return CMD_SUCCESS;
+}
+
+DEFPY(debug_path_policy, debug_path_policy_cmd, "[no] debug pathd policy",
+      NO_STR DEBUG_STR
+      "path debugging\n"
+      "policy debugging\n")
+{
+	uint32_t mode = DEBUG_NODE2MODE(vty->node);
+	bool no_debug = no;
+
+	DEBUG_MODE_SET(&path_policy_debug, mode, !no);
+	DEBUG_FLAGS_SET(&path_policy_debug, PATH_POLICY_DEBUG_BASIC, !no_debug);
 	return CMD_SUCCESS;
 }
 
@@ -1294,8 +1308,34 @@ int config_write_segment_routing(struct vty *vty)
 	return 1;
 }
 
+static int path_policy_cli_debug_config_write(struct vty *vty)
+{
+	if (DEBUG_MODE_CHECK(&path_policy_debug, DEBUG_MODE_CONF)) {
+		if (DEBUG_FLAGS_CHECK(&path_policy_debug,
+				      PATH_POLICY_DEBUG_BASIC))
+			vty_out(vty, "debug pathd policy\n");
+		return 1;
+	}
+	return 0;
+}
+
+static int path_policy_cli_debug_set_all(uint32_t flags, bool set)
+{
+	DEBUG_FLAGS_SET(&path_policy_debug, flags, set);
+
+	/* If all modes have been turned off, don't preserve options. */
+	if (!DEBUG_MODE_CHECK(&path_policy_debug, DEBUG_MODE_ALL))
+		DEBUG_CLEAR(&path_policy_debug);
+
+	return 0;
+}
+
 void path_cli_init(void)
 {
+	hook_register(nb_client_debug_config_write,
+		      path_policy_cli_debug_config_write);
+	hook_register(nb_client_debug_set_all, path_policy_cli_debug_set_all);
+
 	install_node(&segment_routing_node);
 	install_node(&sr_traffic_eng_node);
 	install_node(&srte_segment_list_node);
@@ -1311,6 +1351,9 @@ void path_cli_init(void)
 	install_element(ENABLE_NODE, &show_srte_policy_cmd);
 	install_element(ENABLE_NODE, &show_srte_policy_detail_cmd);
 
+	install_element(ENABLE_NODE, &debug_path_policy_cmd);
+	install_element(CONFIG_NODE, &debug_path_policy_cmd);
+
 	install_element(CONFIG_NODE, &segment_routing_cmd);
 	install_element(SEGMENT_ROUTING_NODE, &sr_traffic_eng_cmd);
 	install_element(SR_TRAFFIC_ENG_NODE, &srte_segment_list_cmd);
diff --git a/pathd/pathd.c b/pathd/pathd.c
index e9d7cc6fc..7e3802c73 100644
--- a/pathd/pathd.c
+++ b/pathd/pathd.c
@@ -23,6 +23,8 @@
 #include "lib_errors.h"
 #include "network.h"
 #include "libfrr.h"
+#include <debug.h>
+#include <hook.h>
 
 #include "pathd/pathd.h"
 #include "pathd/path_zebra.h"
@@ -44,6 +46,17 @@ DEFINE_HOOK(pathd_candidate_updated, (struct srte_candidate * candidate),
 DEFINE_HOOK(pathd_candidate_removed, (struct srte_candidate * candidate),
 	    (candidate));
 
+struct debug path_policy_debug;
+
+#define PATH_POLICY_DEBUG(fmt, ...)                                            \
+	do {                                                                   \
+		if (DEBUG_FLAGS_CHECK(&path_policy_debug,                      \
+				      PATH_POLICY_DEBUG_BASIC))                \
+			DEBUGD(&path_policy_debug, "policy: " fmt,             \
+			       ##__VA_ARGS__);                                 \
+	} while (0)
+
+
 static void trigger_pathd_candidate_created(struct srte_candidate *candidate);
 static void trigger_pathd_candidate_created_timer(struct thread *thread);
 static void trigger_pathd_candidate_updated(struct srte_candidate *candidate);
@@ -574,8 +587,7 @@ void srte_policy_apply_changes(struct srte_policy *policy)
 	new_best_candidate = srte_policy_best_candidate(policy);
 
 	if (new_best_candidate != old_best_candidate) {
-		/* TODO: add debug guard. */
-		zlog_debug(
+		PATH_POLICY_DEBUG(
 			"SR-TE(%s, %u): best candidate changed from %s to %s",
 			endpoint, policy->color,
 			old_best_candidate ? old_best_candidate->name : "none",
@@ -617,10 +629,10 @@ void srte_policy_apply_changes(struct srte_policy *policy)
 				   F_SEGMENT_LIST_MODIFIED);
 
 		if (candidate_changed || segment_list_changed) {
-			/* TODO: add debug guard. */
-			zlog_debug("SR-TE(%s, %u): best candidate %s changed",
-				   endpoint, policy->color,
-				   new_best_candidate->name);
+			PATH_POLICY_DEBUG(
+				"SR-TE(%s, %u): best candidate %s changed",
+				endpoint, policy->color,
+				new_best_candidate->name);
 
 			path_zebra_add_sr_policy(
 				policy, new_best_candidate->lsp->segment_list);
@@ -725,7 +737,7 @@ void srte_candidate_set_bandwidth(struct srte_candidate *candidate,
 	char endpoint[46];
 
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug(
+	PATH_POLICY_DEBUG(
 		"SR-TE(%s, %u): candidate %s %sconfig bandwidth set to %f B/s",
 		endpoint, policy->color, candidate->name,
 		required ? "required " : "", bandwidth);
@@ -752,9 +764,10 @@ void srte_lsp_set_bandwidth(struct srte_lsp *lsp, float bandwidth,
 	struct srte_policy *policy = candidate->policy;
 	char endpoint[46];
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug("SR-TE(%s, %u): candidate %s %slsp bandwidth set to %f B/s",
-		   endpoint, policy->color, candidate->name,
-		   required ? "required" : "", bandwidth);
+	PATH_POLICY_DEBUG(
+		"SR-TE(%s, %u): candidate %s %slsp bandwidth set to %f B/s",
+		endpoint, policy->color, candidate->name,
+		required ? "required" : "", bandwidth);
 	SET_FLAG(lsp->flags, F_CANDIDATE_HAS_BANDWIDTH);
 	COND_FLAG(lsp->flags, F_CANDIDATE_REQUIRED_BANDWIDTH, required);
 	lsp->bandwidth = bandwidth;
@@ -772,8 +785,8 @@ void srte_candidate_unset_bandwidth(struct srte_candidate *candidate)
 	struct srte_policy *policy = candidate->policy;
 	char endpoint[46];
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug("SR-TE(%s, %u): candidate %s config bandwidth unset",
-		   endpoint, policy->color, candidate->name);
+	PATH_POLICY_DEBUG("SR-TE(%s, %u): candidate %s config bandwidth unset",
+			  endpoint, policy->color, candidate->name);
 	UNSET_FLAG(candidate->flags, F_CANDIDATE_HAS_BANDWIDTH);
 	UNSET_FLAG(candidate->flags, F_CANDIDATE_REQUIRED_BANDWIDTH);
 	candidate->bandwidth = 0;
@@ -794,8 +807,8 @@ void srte_lsp_unset_bandwidth(struct srte_lsp *lsp)
 	struct srte_policy *policy = candidate->policy;
 	char endpoint[46];
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug("SR-TE(%s, %u): candidate %s lsp bandwidth unset", endpoint,
-		   policy->color, candidate->name);
+	PATH_POLICY_DEBUG("SR-TE(%s, %u): candidate %s lsp bandwidth unset",
+			  endpoint, policy->color, candidate->name);
 	UNSET_FLAG(lsp->flags, F_CANDIDATE_HAS_BANDWIDTH);
 	UNSET_FLAG(lsp->flags, F_CANDIDATE_REQUIRED_BANDWIDTH);
 	SET_FLAG(candidate->flags, F_CANDIDATE_MODIFIED);
@@ -822,7 +835,7 @@ void srte_candidate_set_metric(struct srte_candidate *candidate,
 	struct srte_policy *policy = candidate->policy;
 	char endpoint[46];
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug(
+	PATH_POLICY_DEBUG(
 		"SR-TE(%s, %u): candidate %s %sconfig metric %s (%u) set to %f (is-bound: %s; is_computed: %s)",
 		endpoint, policy->color, candidate->name,
 		required ? "required " : "", srte_candidate_metric_name(type),
@@ -856,7 +869,7 @@ void srte_lsp_set_metric(struct srte_lsp *lsp,
 	struct srte_policy *policy = candidate->policy;
 	char endpoint[46];
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug(
+	PATH_POLICY_DEBUG(
 		"SR-TE(%s, %u): candidate %s %slsp metric %s (%u) set to %f (is-bound: %s; is_computed: %s)",
 		endpoint, policy->color, candidate->name,
 		required ? "required " : "", srte_candidate_metric_name(type),
@@ -891,9 +904,10 @@ void srte_candidate_unset_metric(struct srte_candidate *candidate,
 	struct srte_policy *policy = candidate->policy;
 	char endpoint[46];
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug("SR-TE(%s, %u): candidate %s config metric %s (%u) unset",
-		   endpoint, policy->color, candidate->name,
-		   srte_candidate_metric_name(type), type);
+	PATH_POLICY_DEBUG(
+		"SR-TE(%s, %u): candidate %s config metric %s (%u) unset",
+		endpoint, policy->color, candidate->name,
+		srte_candidate_metric_name(type), type);
 	assert((type > 0) && (type <= MAX_METRIC_TYPE));
 	srte_unset_metric(&candidate->metrics[type - 1]);
 	srte_lsp_unset_metric(candidate->lsp, type);
@@ -915,9 +929,10 @@ void srte_lsp_unset_metric(struct srte_lsp *lsp,
 	struct srte_policy *policy = candidate->policy;
 	char endpoint[46];
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug("SR-TE(%s, %u): candidate %s lsp metric %s (%u) unset",
-		   endpoint, policy->color, candidate->name,
-		   srte_candidate_metric_name(type), type);
+	PATH_POLICY_DEBUG(
+		"SR-TE(%s, %u): candidate %s lsp metric %s (%u) unset",
+		endpoint, policy->color, candidate->name,
+		srte_candidate_metric_name(type), type);
 	assert((type > 0) && (type <= MAX_METRIC_TYPE));
 	srte_unset_metric(&lsp->metrics[type - 1]);
 }
@@ -948,9 +963,10 @@ void srte_candidate_set_objfun(struct srte_candidate *candidate, bool required,
 	SET_FLAG(candidate->flags, F_CANDIDATE_HAS_OBJFUN);
 	COND_FLAG(candidate->flags, F_CANDIDATE_REQUIRED_OBJFUN, required);
 	SET_FLAG(candidate->flags, F_CANDIDATE_MODIFIED);
-	zlog_debug("SR-TE(%s, %u): candidate %s %sobjective function set to %s",
-		   endpoint, policy->color, candidate->name,
-		   required ? "required " : "", objfun_type_name(type));
+	PATH_POLICY_DEBUG(
+		"SR-TE(%s, %u): candidate %s %sobjective function set to %s",
+		endpoint, policy->color, candidate->name,
+		required ? "required " : "", objfun_type_name(type));
 }
 
 /**
@@ -968,7 +984,7 @@ void srte_candidate_unset_objfun(struct srte_candidate *candidate)
 	UNSET_FLAG(candidate->flags, F_CANDIDATE_REQUIRED_OBJFUN);
 	SET_FLAG(candidate->flags, F_CANDIDATE_MODIFIED);
 	candidate->objfun = OBJFUN_UNDEFINED;
-	zlog_debug(
+	PATH_POLICY_DEBUG(
 		"SR-TE(%s, %u): candidate %s objective functions preferences unset",
 		endpoint, policy->color, candidate->name);
 }
@@ -1021,7 +1037,7 @@ void srte_candidate_set_affinity_filter(struct srte_candidate *candidate,
 	SET_FLAG(candidate->flags, filter_type_to_flag(type));
 	SET_FLAG(candidate->flags, F_CANDIDATE_MODIFIED);
 	candidate->affinity_filters[type - 1] = filter;
-	zlog_debug(
+	PATH_POLICY_DEBUG(
 		"SR-TE(%s, %u): candidate %s affinity filter %s set to 0x%08x",
 		endpoint, policy->color, candidate->name,
 		filter_type_name(type), filter);
@@ -1046,9 +1062,10 @@ void srte_candidate_unset_affinity_filter(struct srte_candidate *candidate,
 	UNSET_FLAG(candidate->flags, filter_type_to_flag(type));
 	SET_FLAG(candidate->flags, F_CANDIDATE_MODIFIED);
 	candidate->affinity_filters[type - 1] = 0;
-	zlog_debug("SR-TE(%s, %u): candidate %s affinity filter %s unset",
-		   endpoint, policy->color, candidate->name,
-		   filter_type_name(type));
+	PATH_POLICY_DEBUG(
+		"SR-TE(%s, %u): candidate %s affinity filter %s unset",
+		endpoint, policy->color, candidate->name,
+		filter_type_name(type));
 }
 
 /**
@@ -1095,8 +1112,8 @@ void srte_candidate_status_update(struct srte_candidate *candidate, int status)
 	struct srte_policy *policy = candidate->policy;
 	char endpoint[46];
 	ipaddr2str(&policy->endpoint, endpoint, sizeof(endpoint));
-	zlog_debug("SR-TE(%s, %u): zebra updated status to %d", endpoint,
-		   policy->color, status);
+	PATH_POLICY_DEBUG("SR-TE(%s, %u): zebra updated status to %d", endpoint,
+			  policy->color, status);
 	switch (status) {
 	case ZEBRA_SR_POLICY_DOWN:
 		switch (policy->status) {
@@ -1109,8 +1126,8 @@ void srte_candidate_status_update(struct srte_candidate *candidate, int status)
 		case SRTE_POLICY_STATUS_DOWN:
 			return;
 		default:
-			zlog_debug("SR-TE(%s, %u): policy is DOWN", endpoint,
-				   policy->color);
+			PATH_POLICY_DEBUG("SR-TE(%s, %u): policy is DOWN",
+					  endpoint, policy->color);
 			policy->status = SRTE_POLICY_STATUS_DOWN;
 			break;
 		}
@@ -1120,8 +1137,8 @@ void srte_candidate_status_update(struct srte_candidate *candidate, int status)
 		case SRTE_POLICY_STATUS_UP:
 			return;
 		default:
-			zlog_debug("SR-TE(%s, %u): policy is UP", endpoint,
-				   policy->color);
+			PATH_POLICY_DEBUG("SR-TE(%s, %u): policy is UP",
+					  endpoint, policy->color);
 			policy->status = SRTE_POLICY_STATUS_UP;
 			break;
 		}
@@ -1148,19 +1165,20 @@ void srte_candidate_unset_segment_list(const char *originator, bool force)
 		return;
 	}
 
-	zlog_debug("Unset segment lists for originator %s", originator);
+	PATH_POLICY_DEBUG("Unset segment lists for originator %s", originator);
 
 	/* Iterate the policies, then iterate each policy's candidate path
 	 * to check the candidate path's segment list originator */
 	struct srte_policy *policy;
 	RB_FOREACH (policy, srte_policy_head, &srte_policies) {
-		zlog_debug("Unset segment lists checking policy %s",
-			   policy->name);
+		PATH_POLICY_DEBUG("Unset segment lists checking policy %s",
+				  policy->name);
 		struct srte_candidate *candidate;
 		RB_FOREACH (candidate, srte_candidate_head,
 			    &policy->candidate_paths) {
-			zlog_debug("Unset segment lists checking candidate %s",
-				   candidate->name);
+			PATH_POLICY_DEBUG(
+				"Unset segment lists checking candidate %s",
+				candidate->name);
 			if (candidate->lsp == NULL) {
 				continue;
 			}
@@ -1190,8 +1208,8 @@ void srte_candidate_unset_segment_list(const char *originator, bool force)
 				    sizeof(segment_list->originator))
 				    == 0
 			    || force) {
-				zlog_debug("Unset segment list %s",
-					   segment_list->name);
+				PATH_POLICY_DEBUG("Unset segment list %s",
+						  segment_list->name);
 				SET_FLAG(segment_list->flags,
 					 F_SEGMENT_LIST_DELETED);
 				SET_FLAG(candidate->flags,
@@ -1222,6 +1240,12 @@ const char *srte_origin2str(enum srte_protocol_origin origin)
 	}
 }
 
+void path_policy_show_debugging(struct vty *vty)
+{
+	if (DEBUG_FLAGS_CHECK(&path_policy_debug, PATH_POLICY_DEBUG_BASIC))
+		vty_out(vty, "  Path policy debugging is on\n");
+}
+
 void pathd_shutdown(void)
 {
 	path_ted_teardown();
diff --git a/pathd/pathd.h b/pathd/pathd.h
index 81d7aa910..7ad20044c 100644
--- a/pathd/pathd.h
+++ b/pathd/pathd.h
@@ -43,6 +43,10 @@ enum srte_protocol_origin {
 	SRTE_ORIGIN_LOCAL = 3,
 };
 
+extern struct debug path_policy_debug;
+
+#define PATH_POLICY_DEBUG_BASIC 0x01
+
 enum srte_policy_status {
 	SRTE_POLICY_STATUS_UNKNOWN = 0,
 	SRTE_POLICY_STATUS_DOWN = 1,
@@ -444,6 +448,7 @@ void srte_candidate_status_update(struct srte_candidate *candidate, int status);
 void srte_candidate_unset_segment_list(const char *originator, bool force);
 const char *srte_origin2str(enum srte_protocol_origin origin);
 void pathd_shutdown(void);
+void path_policy_show_debugging(struct vty *vty);
 
 /* path_cli.c */
 void path_cli_init(void);