kernel-netlink: Consistently print mark in log messages only if set

1 files changed, 82 insertions, 108 deletions

diff --git a/src/libcharon/plugins/kernel_netlink/kernel_netlink_ipsec.c b/src/libcharon/plugins/kernel_netlink/kernel_netlink_ipsec.c
index fbeff9181..4f7548c49 100644
--- a/src/libcharon/plugins/kernel_netlink/kernel_netlink_ipsec.c
+++ b/src/libcharon/plugins/kernel_netlink/kernel_netlink_ipsec.c
@@ -1229,6 +1229,17 @@ METHOD(kernel_ipsec_t, get_cpi, status_t,
 }
 
 /**
+ * Format the mark for debug messages
+ */
+static void format_mark(char *buf, int buflen, mark_t mark)
+{
+	if (mark.value)
+	{
+		snprintf(buf, buflen, " (mark %u/0x%08x)", mark.value, mark.mask);
+	}
+}
+
+/**
  * Add a XFRM mark to message if required
  */
 static bool add_mark(struct nlmsghdr *hdr, int buflen, mark_t mark)
@@ -1253,7 +1264,7 @@ METHOD(kernel_ipsec_t, add_sa, status_t,
 	kernel_ipsec_add_sa_t *data)
 {
 	netlink_buf_t request;
-	char *alg_name;
+	char *alg_name, markstr[32] = "";
 	struct nlmsghdr *hdr;
 	struct xfrm_usersa_info *sa;
 	uint16_t icv_size = 64, ipcomp = data->ipcomp;
@@ -1294,10 +1305,10 @@ METHOD(kernel_ipsec_t, add_sa, status_t,
 	}
 
 	memset(&request, 0, sizeof(request));
+	format_mark(markstr, sizeof(markstr), id->mark);
 
-	DBG2(DBG_KNL, "adding SAD entry with SPI %.8x and reqid {%u}  (mark "
-		 "%u/0x%08x)", ntohl(id->spi), data->reqid, id->mark.value,
-		 id->mark.mask);
+	DBG2(DBG_KNL, "adding SAD entry with SPI %.8x and reqid {%u}%s",
+		 ntohl(id->spi), data->reqid, markstr);
 
 	hdr = &request.hdr;
 	hdr->nlmsg_flags = NLM_F_REQUEST | NLM_F_ACK;
@@ -1600,17 +1611,8 @@ METHOD(kernel_ipsec_t, add_sa, status_t,
 
 	if (this->socket_xfrm->send_ack(this->socket_xfrm, hdr) != SUCCESS)
 	{
-		if (id->mark.value)
-		{
-			DBG1(DBG_KNL, "unable to add SAD entry with SPI %.8x  (mark "
-				 "%u/0x%08x)", ntohl(id->spi), id->mark.value,
-				 id->mark.mask);
-		}
-		else
-		{
-			DBG1(DBG_KNL, "unable to add SAD entry with SPI %.8x",
-				 ntohl(id->spi));
-		}
+		DBG1(DBG_KNL, "unable to add SAD entry with SPI %.8x%s", ntohl(id->spi),
+			 markstr);
 		goto failed;
 	}
 
@@ -1737,11 +1739,13 @@ METHOD(kernel_ipsec_t, query_sa, status_t,
 	struct xfrm_usersa_info *sa = NULL;
 	status_t status = FAILED;
 	size_t len;
+	char markstr[32] = "";
 
 	memset(&request, 0, sizeof(request));
+	format_mark(markstr, sizeof(markstr), id->mark);
 
-	DBG2(DBG_KNL, "querying SAD entry with SPI %.8x  (mark %u/0x%08x)",
-		 ntohl(id->spi), id->mark.value, id->mark.mask);
+	DBG2(DBG_KNL, "querying SAD entry with SPI %.8x%s", ntohl(id->spi),
+		 markstr);
 
 	hdr = &request.hdr;
 	hdr->nlmsg_flags = NLM_F_REQUEST;
@@ -1775,19 +1779,9 @@ METHOD(kernel_ipsec_t, query_sa, status_t,
 				{
 					struct nlmsgerr *err = NLMSG_DATA(hdr);
 
-					if (id->mark.value)
-					{
-						DBG1(DBG_KNL, "querying SAD entry with SPI %.8x  (mark "
-							 "%u/0x%08x) failed: %s (%d)", ntohl(id->spi),
-							 id->mark.value, id->mark.mask,
-							 strerror(-err->error), -err->error);
-					}
-					else
-					{
-						DBG1(DBG_KNL, "querying SAD entry with SPI %.8x "
-							 "failed: %s (%d)", ntohl(id->spi),
-							 strerror(-err->error), -err->error);
-					}
+					DBG1(DBG_KNL, "querying SAD entry with SPI %.8x%s failed: "
+						 "%s (%d)", ntohl(id->spi), markstr,
+						 strerror(-err->error), -err->error);
 					break;
 				}
 				default:
@@ -1802,8 +1796,8 @@ METHOD(kernel_ipsec_t, query_sa, status_t,
 
 	if (sa == NULL)
 	{
-		DBG2(DBG_KNL, "unable to query SAD entry with SPI %.8x",
-			 ntohl(id->spi));
+		DBG2(DBG_KNL, "unable to query SAD entry with SPI %.8x%s",
+			 ntohl(id->spi), markstr);
 	}
 	else
 	{
@@ -1835,6 +1829,7 @@ METHOD(kernel_ipsec_t, del_sa, status_t,
 	netlink_buf_t request;
 	struct nlmsghdr *hdr;
 	struct xfrm_usersa_id *sa_id;
+	char markstr[32] = "";
 
 	/* if IPComp was used, we first delete the additional IPComp SA */
 	if (data->cpi)
@@ -1851,9 +1846,10 @@ METHOD(kernel_ipsec_t, del_sa, status_t,
 	}
 
 	memset(&request, 0, sizeof(request));
+	format_mark(markstr, sizeof(markstr), id->mark);
 
-	DBG2(DBG_KNL, "deleting SAD entry with SPI %.8x  (mark %u/0x%08x)",
-		 ntohl(id->spi), id->mark.value, id->mark.mask);
+	DBG2(DBG_KNL, "deleting SAD entry with SPI %.8x%s", ntohl(id->spi),
+		 markstr);
 
 	hdr = &request.hdr;
 	hdr->nlmsg_flags = NLM_F_REQUEST | NLM_F_ACK;
@@ -1874,23 +1870,14 @@ METHOD(kernel_ipsec_t, del_sa, status_t,
 	switch (this->socket_xfrm->send_ack(this->socket_xfrm, hdr))
 	{
 		case SUCCESS:
-			DBG2(DBG_KNL, "deleted SAD entry with SPI %.8x  (mark %u/0x%08x)",
-				 ntohl(id->spi), id->mark.value, id->mark.mask);
+			DBG2(DBG_KNL, "deleted SAD entry with SPI %.8x%s",
+				 ntohl(id->spi), markstr);
 			return SUCCESS;
 		case NOT_FOUND:
 			return NOT_FOUND;
 		default:
-			if (id->mark.value)
-			{
-				DBG1(DBG_KNL, "unable to delete SAD entry with SPI %.8x  (mark "
-					 "%u/0x%08x)", ntohl(id->spi), id->mark.value,
-					 id->mark.mask);
-			}
-			else
-			{
-				DBG1(DBG_KNL, "unable to delete SAD entry with SPI %.8x",
-					 ntohl(id->spi));
-			}
+			DBG1(DBG_KNL, "unable to delete SAD entry with SPI %.8x%s",
+				 ntohl(id->spi), markstr);
 			return FAILED;
 	}
 }
@@ -1913,6 +1900,7 @@ METHOD(kernel_ipsec_t, update_sa, status_t,
 	uint32_t replay_esn_len = 0;
 	kernel_ipsec_del_sa_t del = { 0 };
 	status_t status = FAILED;
+	char markstr[32] = "";
 
 	/* if IPComp is used, we first update the IPComp SA */
 	if (data->cpi)
@@ -1932,9 +1920,10 @@ METHOD(kernel_ipsec_t, update_sa, status_t,
 	}
 
 	memset(&request, 0, sizeof(request));
+	format_mark(markstr, sizeof(markstr), id->mark);
 
-	DBG2(DBG_KNL, "querying SAD entry with SPI %.8x for update",
-		 ntohl(id->spi));
+	DBG2(DBG_KNL, "querying SAD entry with SPI %.8x%s for update",
+		 ntohl(id->spi), markstr);
 
 	/* query the existing SA first */
 	hdr = &request.hdr;
@@ -1983,8 +1972,8 @@ METHOD(kernel_ipsec_t, update_sa, status_t,
 	}
 	if (out_sa == NULL)
 	{
-		DBG1(DBG_KNL, "unable to update SAD entry with SPI %.8x",
-			 ntohl(id->spi));
+		DBG1(DBG_KNL, "unable to update SAD entry with SPI %.8x%s",
+			 ntohl(id->spi), markstr);
 		goto failed;
 	}
 
@@ -1994,13 +1983,13 @@ METHOD(kernel_ipsec_t, update_sa, status_t,
 	/* delete the old SA (without affecting the IPComp SA) */
 	if (del_sa(this, id, &del) != SUCCESS)
 	{
-		DBG1(DBG_KNL, "unable to delete old SAD entry with SPI %.8x",
-			 ntohl(id->spi));
+		DBG1(DBG_KNL, "unable to delete old SAD entry with SPI %.8x%s",
+			 ntohl(id->spi), markstr);
 		goto failed;
 	}
 
-	DBG2(DBG_KNL, "updating SAD entry with SPI %.8x from %#H..%#H to %#H..%#H",
-		 ntohl(id->spi), id->src, id->dst, data->new_src,
+	DBG2(DBG_KNL, "updating SAD entry with SPI %.8x%s from %#H..%#H to "
+		 "%#H..%#H", ntohl(id->spi), markstr, id->src, id->dst, data->new_src,
 		 data->new_dst);
 	/* copy over the SA from out to request */
 	hdr = &request.hdr;
@@ -2080,7 +2069,7 @@ METHOD(kernel_ipsec_t, update_sa, status_t,
 	else
 	{
 		DBG1(DBG_KNL, "unable to copy replay state from old SAD entry with "
-			 "SPI %.8x", ntohl(id->spi));
+			 "SPI %.8x%s", ntohl(id->spi), markstr);
 	}
 	if (lifetime)
 	{
@@ -2097,13 +2086,13 @@ METHOD(kernel_ipsec_t, update_sa, status_t,
 	else
 	{
 		DBG1(DBG_KNL, "unable to copy usage stats from old SAD entry with "
-			 "SPI %.8x", ntohl(id->spi));
+			 "SPI %.8x%s", ntohl(id->spi), markstr);
 	}
 
 	if (this->socket_xfrm->send_ack(this->socket_xfrm, hdr) != SUCCESS)
 	{
-		DBG1(DBG_KNL, "unable to update SAD entry with SPI %.8x",
-			 ntohl(id->spi));
+		DBG1(DBG_KNL, "unable to update SAD entry with SPI %.8x%s",
+			 ntohl(id->spi), markstr);
 		goto failed;
 	}
 
@@ -2403,6 +2392,7 @@ METHOD(kernel_ipsec_t, add_policy, status_t,
 	policy_sa_t *assigned_sa, *current_sa;
 	enumerator_t *enumerator;
 	bool found = FALSE, update = TRUE;
+	char markstr[32] = "";
 
 	/* create a policy */
 	INIT(policy,
@@ -2411,6 +2401,7 @@ METHOD(kernel_ipsec_t, add_policy, status_t,
 		.direction = id->dir,
 		.reqid = data->sa->reqid,
 	);
+	format_mark(markstr, sizeof(markstr), id->mark);
 
 	/* find the policy, which matches EXACTLY */
 	this->mutex->lock(this->mutex);
@@ -2420,18 +2411,18 @@ METHOD(kernel_ipsec_t, add_policy, status_t,
 		if (current->reqid && data->sa->reqid &&
 			current->reqid != data->sa->reqid)
 		{
-			DBG1(DBG_CFG, "unable to install policy %R === %R %N (mark "
-				 "%u/0x%08x) for reqid %u, the same policy for reqid %u exists",
-				 id->src_ts, id->dst_ts, policy_dir_names, id->dir,
-				 id->mark.value, id->mark.mask, data->sa->reqid, current->reqid);
+			DBG1(DBG_CFG, "unable to install policy %R === %R %N%s for reqid "
+				 "%u, the same policy for reqid %u exists",
+				 id->src_ts, id->dst_ts, policy_dir_names, id->dir, markstr,
+				 data->sa->reqid, current->reqid);
 			policy_entry_destroy(this, policy);
 			this->mutex->unlock(this->mutex);
 			return INVALID_STATE;
 		}
 		/* use existing policy */
-		DBG2(DBG_KNL, "policy %R === %R %N  (mark %u/0x%08x) already exists, "
-			"increasing refcount", id->src_ts, id->dst_ts, policy_dir_names,
-			id->dir, id->mark.value, id->mark.mask);
+		DBG2(DBG_KNL, "policy %R === %R %N%s already exists, increasing "
+			 "refcount", id->src_ts, id->dst_ts, policy_dir_names, id->dir,
+			 markstr);
 		policy_entry_destroy(this, policy);
 		policy = current;
 		found = TRUE;
@@ -2489,15 +2480,14 @@ METHOD(kernel_ipsec_t, add_policy, status_t,
 		found = TRUE;
 	}
 
-	DBG2(DBG_KNL, "%s policy %R === %R %N  (mark %u/0x%08x)",
-		 found ? "updating" : "adding", id->src_ts, id->dst_ts,
-		 policy_dir_names, id->dir, id->mark.value, id->mark.mask);
+	DBG2(DBG_KNL, "%s policy %R === %R %N%s", found ? "updating" : "adding",
+		 id->src_ts, id->dst_ts, policy_dir_names, id->dir, markstr);
 
 	if (add_policy_internal(this, policy, assigned_sa, found) != SUCCESS)
 	{
-		DBG1(DBG_KNL, "unable to %s policy %R === %R %N",
+		DBG1(DBG_KNL, "unable to %s policy %R === %R %N%s",
 			 found ? "update" : "add", id->src_ts, id->dst_ts,
-			 policy_dir_names, id->dir);
+			 policy_dir_names, id->dir, markstr);
 		return FAILED;
 	}
 	return SUCCESS;
@@ -2512,12 +2502,13 @@ METHOD(kernel_ipsec_t, query_policy, status_t,
 	struct xfrm_userpolicy_id *policy_id;
 	struct xfrm_userpolicy_info *policy = NULL;
 	size_t len;
+	char markstr[32] = "";
 
 	memset(&request, 0, sizeof(request));
+	format_mark(markstr, sizeof(markstr), id->mark);
 
-	DBG2(DBG_KNL, "querying policy %R === %R %N  (mark %u/0x%08x)",
-		 id->src_ts, id->dst_ts, policy_dir_names, id->dir, id->mark.value,
-		 id->mark.mask);
+	DBG2(DBG_KNL, "querying policy %R === %R %N%s", id->src_ts, id->dst_ts,
+		 policy_dir_names, id->dir, markstr);
 
 	hdr = &request.hdr;
 	hdr->nlmsg_flags = NLM_F_REQUEST;
@@ -2564,8 +2555,8 @@ METHOD(kernel_ipsec_t, query_policy, status_t,
 
 	if (policy == NULL)
 	{
-		DBG2(DBG_KNL, "unable to query policy %R === %R %N", id->src_ts,
-			 id->dst_ts, policy_dir_names, id->dir);
+		DBG2(DBG_KNL, "unable to query policy %R === %R %N%s", id->src_ts,
+			 id->dst_ts, policy_dir_names, id->dir, markstr);
 		free(out);
 		return FAILED;
 	}
@@ -2602,10 +2593,12 @@ METHOD(kernel_ipsec_t, del_policy, status_t,
 		.mark = id->mark,
 		.cfg = *data->sa,
 	};
+	char markstr[32] = "";
 
-	DBG2(DBG_KNL, "deleting policy %R === %R %N  (mark %u/0x%08x)",
-		 id->src_ts, id->dst_ts, policy_dir_names, id->dir, id->mark.value,
-		 id->mark.mask);
+	format_mark(markstr, sizeof(markstr), id->mark);
+
+	DBG2(DBG_KNL, "deleting policy %R === %R %N%s", id->src_ts, id->dst_ts,
+		 policy_dir_names, id->dir, markstr);
 
 	/* create a policy */
 	memset(&policy, 0, sizeof(policy_entry_t));
@@ -2618,17 +2611,8 @@ METHOD(kernel_ipsec_t, del_policy, status_t,
 	current = this->policies->get(this->policies, &policy);
 	if (!current)
 	{
-		if (id->mark.value)
-		{
-			DBG1(DBG_KNL, "deleting policy %R === %R %N  (mark %u/0x%08x) "
-				 "failed, not found", id->src_ts, id->dst_ts,
-				 policy_dir_names, id->dir, id->mark.value, id->mark.mask);
-		}
-		else
-		{
-			DBG1(DBG_KNL, "deleting policy %R === %R %N failed, not found",
-				 id->src_ts, id->dst_ts, policy_dir_names, id->dir);
-		}
+		DBG1(DBG_KNL, "deleting policy %R === %R %N%s failed, not found",
+			 id->src_ts, id->dst_ts, policy_dir_names, id->dir, markstr);
 		this->mutex->unlock(this->mutex);
 		return NOT_FOUND;
 	}
@@ -2664,15 +2648,14 @@ METHOD(kernel_ipsec_t, del_policy, status_t,
 			return SUCCESS;
 		}
 
-		DBG2(DBG_KNL, "updating policy %R === %R %N  (mark %u/0x%08x)",
-			 id->src_ts, id->dst_ts, policy_dir_names, id->dir, id->mark.value,
-			 id->mark.mask);
+		DBG2(DBG_KNL, "updating policy %R === %R %N%s", id->src_ts, id->dst_ts,
+			 policy_dir_names, id->dir, markstr);
 
 		current->used_by->get_first(current->used_by, (void**)&mapping);
 		if (add_policy_internal(this, current, mapping, TRUE) != SUCCESS)
 		{
-			DBG1(DBG_KNL, "unable to update policy %R === %R %N",
-				 id->src_ts, id->dst_ts, policy_dir_names, id->dir);
+			DBG1(DBG_KNL, "unable to update policy %R === %R %N%s",
+				 id->src_ts, id->dst_ts, policy_dir_names, id->dir, markstr);
 			return FAILED;
 		}
 		return SUCCESS;
@@ -2703,8 +2686,8 @@ METHOD(kernel_ipsec_t, del_policy, status_t,
 									  route->src_ip, route->if_name) != SUCCESS)
 		{
 			DBG1(DBG_KNL, "error uninstalling route installed with policy "
-				 "%R === %R %N", id->src_ts, id->dst_ts, policy_dir_names,
-				 id->dir);
+				 "%R === %R %N%s", id->src_ts, id->dst_ts, policy_dir_names,
+				 id->dir, markstr);
 		}
 	}
 
@@ -2714,17 +2697,8 @@ METHOD(kernel_ipsec_t, del_policy, status_t,
 
 	if (this->socket_xfrm->send_ack(this->socket_xfrm, hdr) != SUCCESS)
 	{
-		if (id->mark.value)
-		{
-			DBG1(DBG_KNL, "unable to delete policy %R === %R %N  (mark "
-				 "%u/0x%08x)", id->src_ts, id->dst_ts, policy_dir_names,
-				 id->dir, id->mark.value, id->mark.mask);
-		}
-		else
-		{
-			DBG1(DBG_KNL, "unable to delete policy %R === %R %N",
-				 id->src_ts, id->dst_ts, policy_dir_names, id->dir);
-		}
+		DBG1(DBG_KNL, "unable to delete policy %R === %R %N%s", id->src_ts,
+			 id->dst_ts, policy_dir_names, id->dir, markstr);
 		return FAILED;
 	}
 	return SUCCESS;