gprs_ns2: rework logging of Rx and Tx NS PDU

Introduce 2 new logging sub systems for signal and unit data.
Unify log messages so all log messages look similiar.
Log also Rx PDUs. Ensure dropped Tx packets (BLOCK/RESET on SNS)
contain *Tx*.

Change-Id: I34b8fde2955ecc010d1dcd9512e1bba9211e2c0d

5 files changed, 59 insertions, 41 deletions

diff --git a/src/gb/gprs_ns2.c b/src/gb/gprs_ns2.c
index 3574f28c..507a5acd 100644
--- a/src/gb/gprs_ns2.c
+++ b/src/gb/gprs_ns2.c
@@ -1261,6 +1261,11 @@ int ns2_recv_vc(struct gprs_ns2_vc *nsvc,
 	if (msg->len < sizeof(struct gprs_ns_hdr))
 		return -EINVAL;
 
+	if (nsh->pdu_type != NS_PDUT_UNITDATA)
+		LOG_NS_RX_SIGNAL(nsvc, nsh->pdu_type);
+	else
+		LOG_NS_DATA(nsvc, "Rx", nsh->pdu_type, LOGL_INFO, "\n");
+
 	switch (nsh->pdu_type) {
 	case SNS_PDUT_CONFIG:
 		/* one additional byte ('end flag') before the TLV part starts */
diff --git a/src/gb/gprs_ns2_internal.h b/src/gb/gprs_ns2_internal.h
index b4d0a0d6..df51ff5e 100644
--- a/src/gb/gprs_ns2_internal.h
+++ b/src/gb/gprs_ns2_internal.h
@@ -5,6 +5,7 @@
 #include <stdbool.h>
 #include <stdint.h>
 
+#include <osmocom/core/logging.h>
 #include <osmocom/gprs/protocol/gsm_08_16.h>
 #include <osmocom/gprs/gprs_ns2.h>
 
@@ -14,18 +15,30 @@
 #define LOGBIND(bind, lvl, fmt, args ...) \
 	LOGP(DLNS, lvl, "BIND(%s) " fmt, (bind)->name, ## args)
 
-
-#define LOGNSVC(nsvc, lvl, fmt, args ...)					\
+#define LOGNSVC_SS(ss, nsvc, lvl, fmt, args ...)				\
 	do {									\
 		if ((nsvc)->nsvci_is_valid) {					\
-			LOGP(DLNS, lvl, "NSE(%05u)-NSVC(%05u) " fmt,		\
+			LOGP(ss, lvl, "NSE(%05u)-NSVC(%05u) " fmt,		\
 			     (nsvc)->nse->nsei, (nsvc)->nsvci, ## args);	\
 		} else { 							\
-			LOGP(DLNS, lvl, "NSE(%05u)-NSVC(none) " fmt, 		\
+			LOGP(ss, lvl, "NSE(%05u)-NSVC(none) " fmt, 		\
 			     (nsvc)->nse->nsei, ## args);			\
 		}								\
 	} while (0)
 
+#define LOGNSVC(nsvc, lvl, fmt, args ...)					\
+	LOGNSVC_SS(DLNS, nsvc, lvl, fmt, ## args)
+
+#define LOG_NS_SIGNAL(nsvc, direction, pdu_type, lvl, fmt, args ...)	\
+	LOGNSVC_SS(DLNSSIGNAL, nsvc, lvl, "%s %s" fmt, direction, get_value_string(gprs_ns_pdu_strings, pdu_type), ## args)
+
+#define LOG_NS_DATA(nsvc, direction, pdu_type, lvl, fmt, args ...)	\
+	LOGNSVC_SS(DLNSDATA, nsvc, lvl, "%s %s" fmt, direction, get_value_string(gprs_ns_pdu_strings, pdu_type), ## args)
+
+#define LOG_NS_RX_SIGNAL(nsvc, pdu_type) LOG_NS_SIGNAL(nsvc, "Rx", pdu_type, LOGL_INFO, "\n")
+#define LOG_NS_TX_SIGNAL(nsvc, pdu_type) LOG_NS_SIGNAL(nsvc, "Tx", pdu_type, LOGL_INFO, "\n")
+
+
 struct osmo_fsm_inst;
 struct tlv_parsed;
 struct vty;
diff --git a/src/gb/gprs_ns2_message.c b/src/gb/gprs_ns2_message.c
index 535d5bed..9fcd48ca 100644
--- a/src/gb/gprs_ns2_message.c
+++ b/src/gb/gprs_ns2_message.c
@@ -198,9 +198,9 @@ static int ns2_tx_simple(struct gprs_ns2_vc *nsvc, uint8_t pdu_type)
 
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
 	nsh = (struct gprs_ns_hdr *) msg->l2h;
-
 	nsh->pdu_type = pdu_type;
 
+	LOG_NS_TX_SIGNAL(nsvc, nsh->pdu_type);
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -223,8 +223,6 @@ int ns2_tx_block(struct gprs_ns2_vc *nsvc, uint8_t cause)
 	if (!msg)
 		return -ENOMEM;
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx NS BLOCK (cause=%s)\n", gprs_ns2_cause_str(cause));
-
 	rate_ctr_inc(&nsvc->ctrg->ctr[NS_CTR_BLOCKED]);
 
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
@@ -234,6 +232,7 @@ int ns2_tx_block(struct gprs_ns2_vc *nsvc, uint8_t cause)
 	msgb_tvlv_put(msg, NS_IE_CAUSE, 1, &cause);
 	msgb_tvlv_put(msg, NS_IE_VCI, 2, (uint8_t *) &nsvci);
 
+	LOG_NS_SIGNAL(nsvc, "Tx", nsh->pdu_type, LOGL_INFO, " cause=%s\n", gprs_ns2_cause_str(cause));
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -255,14 +254,13 @@ int ns2_tx_block_ack(struct gprs_ns2_vc *nsvc)
 	if (!msg)
 		return -ENOMEM;
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx NS BLOCK ACK\n");
-
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
 	nsh = (struct gprs_ns_hdr *) msg->l2h;
 	nsh->pdu_type = NS_PDUT_BLOCK_ACK;
 
 	msgb_tvlv_put(msg, NS_IE_VCI, 2, (uint8_t *) &nsvci);
 
+	LOG_NS_TX_SIGNAL(nsvc, nsh->pdu_type);
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -286,8 +284,6 @@ int ns2_tx_reset(struct gprs_ns2_vc *nsvc, uint8_t cause)
 	if (!msg)
 		return -ENOMEM;
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx NS RESET (cause=%s)\n", gprs_ns2_cause_str(cause));
-
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
 	nsh = (struct gprs_ns_hdr *) msg->l2h;
 	nsh->pdu_type = NS_PDUT_RESET;
@@ -296,6 +292,7 @@ int ns2_tx_reset(struct gprs_ns2_vc *nsvc, uint8_t cause)
 	msgb_tvlv_put(msg, NS_IE_VCI, 2, (uint8_t *) &nsvci);
 	msgb_tvlv_put(msg, NS_IE_NSEI, 2, (uint8_t *) &nsei);
 
+	LOG_NS_SIGNAL(nsvc, "Tx", nsh->pdu_type, LOGL_INFO, " cause=%s\n", gprs_ns2_cause_str(cause));
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -326,11 +323,10 @@ int ns2_tx_reset_ack(struct gprs_ns2_vc *nsvc)
 
 	nsh->pdu_type = NS_PDUT_RESET_ACK;
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx NS RESET ACK\n");
-
 	msgb_tvlv_put(msg, NS_IE_VCI, 2, (uint8_t *)&nsvci);
 	msgb_tvlv_put(msg, NS_IE_NSEI, 2, (uint8_t *)&nsei);
 
+	LOG_NS_TX_SIGNAL(nsvc, nsh->pdu_type);
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -344,8 +340,6 @@ int ns2_tx_unblock(struct gprs_ns2_vc *nsvc)
 
 	ERR_IF_NSVC_USES_SNS(nsvc, "transmit NS UNBLOCK");
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx NS UNBLOCK\n");
-
 	return ns2_tx_simple(nsvc, NS_PDUT_UNBLOCK);
 }
 
@@ -360,8 +354,6 @@ int ns2_tx_unblock_ack(struct gprs_ns2_vc *nsvc)
 
 	ERR_IF_NSVC_USES_SNS(nsvc, "transmit NS UNBLOCK ACK");
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx NS UNBLOCK_ACK\n");
-
 	return ns2_tx_simple(nsvc, NS_PDUT_UNBLOCK_ACK);
 }
 
@@ -372,7 +364,6 @@ int ns2_tx_alive(struct gprs_ns2_vc *nsvc)
 {
 	log_set_context(LOG_CTX_GB_NSE, nsvc->nse);
 	log_set_context(LOG_CTX_GB_NSVC, nsvc);
-	LOGNSVC(nsvc, LOGL_DEBUG, "Tx NS ALIVE\n");
 
 	return ns2_tx_simple(nsvc, NS_PDUT_ALIVE);
 }
@@ -384,7 +375,6 @@ int ns2_tx_alive_ack(struct gprs_ns2_vc *nsvc)
 {
 	log_set_context(LOG_CTX_GB_NSE, nsvc->nse);
 	log_set_context(LOG_CTX_GB_NSVC, nsvc);
-	LOGNSVC(nsvc, LOGL_DEBUG, "Tx NS ALIVE_ACK\n");
 
 	return ns2_tx_simple(nsvc, NS_PDUT_ALIVE_ACK);
 }
@@ -417,6 +407,7 @@ int ns2_tx_unit_data(struct gprs_ns2_vc *nsvc,
 	nsh->data[1] = bvci >> 8;
 	nsh->data[2] = bvci & 0xff;
 
+	LOG_NS_DATA(nsvc, "Tx", nsh->pdu_type, LOGL_INFO, "\n");
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -442,8 +433,6 @@ int ns2_tx_status(struct gprs_ns2_vc *nsvc, uint8_t cause,
 	if (!msg)
 		return -ENOMEM;
 
-	LOGNSVC(nsvc, LOGL_NOTICE, "Tx NS STATUS (cause=%s)\n", gprs_ns2_cause_str(cause));
-
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
 	nsh = (struct gprs_ns_hdr *) msg->l2h;
 	nsh->pdu_type = NS_PDUT_STATUS;
@@ -478,6 +467,7 @@ int ns2_tx_status(struct gprs_ns2_vc *nsvc, uint8_t cause,
 		break;
 	}
 
+	LOG_NS_SIGNAL(nsvc, "Tx", nsh->pdu_type, LOGL_INFO, " cause=%s\n", gprs_ns2_cause_str(cause));
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -515,8 +505,6 @@ int ns2_tx_sns_ack(struct gprs_ns2_vc *nsvc, uint8_t trans_id, uint8_t *cause,
 		return -EIO;
 	}
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx SNS-ACK (trans_id=%u, cause=%s, num_ip4=%u, num_ip6=%u)\n",
-		trans_id, cause ? gprs_ns2_cause_str(*cause) : "NULL", num_ip4_elems, num_ip6_elems);
 
 	nsei = osmo_htons(nsvc->nse->nsei);
 
@@ -541,6 +529,9 @@ int ns2_tx_sns_ack(struct gprs_ns2_vc *nsvc, uint8_t trans_id, uint8_t *cause,
 			      (const uint8_t *)ip6_elems);
 	}
 
+	LOG_NS_SIGNAL(nsvc, "Tx", nsh->pdu_type, LOGL_INFO,
+		      " (trans_id=%u, cause=%s, num_ip4=%u, num_ip6=%u)\n",
+		      trans_id, cause ? gprs_ns2_cause_str(*cause) : "NULL", num_ip4_elems, num_ip6_elems);
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -576,9 +567,6 @@ int ns2_tx_sns_config(struct gprs_ns2_vc *nsvc, bool end_flag,
 		return -EIO;
 	}
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx SNS-CONFIG (end_flag=%u, num_ip4=%u, num_ip6=%u)\n",
-		end_flag, num_ip4_elems, num_ip6_elems);
-
 	nsei = osmo_htons(nsvc->nse->nsei);
 
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
@@ -599,6 +587,9 @@ int ns2_tx_sns_config(struct gprs_ns2_vc *nsvc, bool end_flag,
 			      (const uint8_t *)ip6_elems);
 	}
 
+	LOG_NS_SIGNAL(nsvc, "Tx", nsh->pdu_type, LOGL_INFO,
+		      " (end_flag=%u, num_ip4=%u, num_ip6=%u)\n",
+		      end_flag, num_ip4_elems, num_ip6_elems);
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -627,9 +618,6 @@ int ns2_tx_sns_config_ack(struct gprs_ns2_vc *nsvc, uint8_t *cause)
 		return -EIO;
 	}
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx SNS-CONFIG-ACK (cause=%s)\n",
-		cause ? gprs_ns2_cause_str(*cause) : "NULL");
-
 	nsei = osmo_htons(nsvc->nse->nsei);
 
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
@@ -641,6 +629,9 @@ int ns2_tx_sns_config_ack(struct gprs_ns2_vc *nsvc, uint8_t *cause)
 	if (cause)
 		msgb_tvlv_put(msg, NS_IE_CAUSE, 1, cause);
 
+	LOGNSVC(nsvc, LOGL_INFO, "Tx SNS-CONFIG-ACK (cause=%s)\n",
+		cause ? gprs_ns2_cause_str(*cause) : "NULL");
+	LOG_NS_TX_SIGNAL(nsvc, nsh->pdu_type);
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -675,9 +666,6 @@ int ns2_tx_sns_size(struct gprs_ns2_vc *nsvc, bool reset_flag, uint16_t max_nr_n
 		return -EIO;
 	}
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx SNS-SIZE (reset=%u, max_nr_nsvc=%u, num_ip4=%u, num_ip6=%u)\n",
-		reset_flag, max_nr_nsvc, ip4_ep_nr, ip6_ep_nr);
-
 	nsei = osmo_htons(nsvc->nse->nsei);
 
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
@@ -693,6 +681,9 @@ int ns2_tx_sns_size(struct gprs_ns2_vc *nsvc, bool reset_flag, uint16_t max_nr_n
 	if (ip6_ep_nr >= 0)
 		msgb_tv16_put(msg, NS_IE_IPv6_EP_NR, ip6_ep_nr);
 
+	LOG_NS_SIGNAL(nsvc, "Tx", nsh->pdu_type, LOGL_INFO,
+		      " (reset=%u, max_nr_nsvc=%u, num_ip4=%u, num_ip6=%u)\n",
+		      reset_flag, max_nr_nsvc, ip4_ep_nr, ip6_ep_nr);
 	return ns_vc_tx(nsvc, msg);
 }
 
@@ -717,9 +708,6 @@ int ns2_tx_sns_size_ack(struct gprs_ns2_vc *nsvc, uint8_t *cause)
 		return -EIO;
 	}
 
-	LOGNSVC(nsvc, LOGL_INFO, "Tx SNS-SIZE-ACK (cause=%s)\n",
-		cause ? gprs_ns2_cause_str(*cause) : "NULL");
-
 	nsei = osmo_htons(nsvc->nse->nsei);
 
 	msg->l2h = msgb_put(msg, sizeof(*nsh));
@@ -731,7 +719,7 @@ int ns2_tx_sns_size_ack(struct gprs_ns2_vc *nsvc, uint8_t *cause)
 	if (cause)
 		msgb_tvlv_put(msg, NS_IE_CAUSE, 1, cause);
 
+	LOG_NS_SIGNAL(nsvc, "Tx", nsh->pdu_type, LOGL_INFO, " cause=%s\n",
+		      cause ? gprs_ns2_cause_str(*cause) : "NULL");
 	return ns_vc_tx(nsvc, msg);
 }
-
-
diff --git a/src/gb/gprs_ns2_vc_fsm.c b/src/gb/gprs_ns2_vc_fsm.c
index f4d88f48..c64f60d0 100644
--- a/src/gb/gprs_ns2_vc_fsm.c
+++ b/src/gb/gprs_ns2_vc_fsm.c
@@ -646,6 +646,8 @@ static void ns2_vc_fsm_allstate_action(struct osmo_fsm_inst *fi,
 		 * the msg, the upper layer has to do it.
 		 * Otherwise the msg must be freed.
 		 */
+
+		LOG_NS_DATA(priv->nsvc, "Rx", NS_PDUT_UNITDATA, LOGL_INFO, "\n");
 		switch (fi->state) {
 		case GPRS_NS2_ST_BLOCKED:
 			/* 7.2.1: the BLOCKED_ACK might be lost */
@@ -812,8 +814,7 @@ int ns2_vc_rx(struct gprs_ns2_vc *nsvc, struct msgb *msg, struct tlv_parsed *tp)
 			if (nsh->pdu_type == NS_PDUT_RESET)
 				ns2_tx_reset_ack(nsvc);
 
-			LOGNSVC(nsvc, LOGL_ERROR, "Rx %s with wrong NSEI=%05u. Ignoring PDU.\n",
-				get_value_string(gprs_ns_pdu_strings, nsh->pdu_type), nsei);
+			LOG_NS_SIGNAL(nsvc, "Rx", nsh->pdu_type, LOGL_ERROR, " with wrong NSEI=%05u. Ignoring PDU.\n", nsei);
 			goto out;
 		}
 	}
@@ -825,8 +826,7 @@ int ns2_vc_rx(struct gprs_ns2_vc *nsvc, struct msgb *msg, struct tlv_parsed *tp)
 			if (nsh->pdu_type == NS_PDUT_RESET)
 				ns2_tx_reset_ack(nsvc);
 
-			LOGNSVC(nsvc, LOGL_ERROR, "Rx %s with wrong NSVCI=%05u. Ignoring PDU.\n",
-				get_value_string(gprs_ns_pdu_strings, nsh->pdu_type), nsvci);
+			LOG_NS_SIGNAL(nsvc, "Rx", nsh->pdu_type, LOGL_ERROR, " with wrong NSVCI=%05u. Ignoring PDU.\n", nsvci);
 			goto out;
 		}
 	}
diff --git a/src/logging.c b/src/logging.c
index c2a0453f..4517afcd 100644
--- a/src/logging.c
+++ b/src/logging.c
@@ -277,6 +277,18 @@ static const struct log_info_cat internal_cat[OSMO_NUM_DLIB] = {
 		.enabled = 1, .loglevel = LOGL_NOTICE,
 		.color = "\033[38;5;59m",
 	},
+	[INT2IDX(DLNSDATA)] = {
+		.name = "DLNSDATA",
+		.description = "GPRS NS layer data PDU",
+		.enabled = 1, .loglevel = LOGL_NOTICE,
+		.color = "\033[38;5;61m",
+	},
+	[INT2IDX(DLNSSIGNAL)] = {
+		.name = "DLNSSIGNAL",
+		.description = "GPRS NS layer signal PDU",
+		.enabled = 1, .loglevel = LOGL_NOTICE,
+		.color = "\033[38;5;63m",
+	},
 };
 
 void assert_loginfo(const char *src)