VIRT-PHY: Separate logging of L1 Control and L1 Data

L1 Data is quite verbose, while control is typically limited, so let's
make sure we log them as separate sub-systems

Change-Id: Idebc371a63508c593855486ff01b2ba6e8c2cfd1

6 files changed, 37 insertions, 7 deletions

diff --git a/src/host/virt_phy/include/virtphy/logging.h b/src/host/virt_phy/include/virtphy/logging.h
index c98986c6..b22db992 100644
--- a/src/host/virt_phy/include/virtphy/logging.h
+++ b/src/host/virt_phy/include/virtphy/logging.h
@@ -5,6 +5,7 @@
 /* L1CTL related messages */
 enum virtphy_log_cat {
 	DL1C,
+	DL1P,
 	DVIRPHY,
 	DMAIN
 };
diff --git a/src/host/virt_phy/src/l1ctl_sap.c b/src/host/virt_phy/src/l1ctl_sap.c
index 6bd63c97..d8960425 100644
--- a/src/host/virt_phy/src/l1ctl_sap.c
+++ b/src/host/virt_phy/src/l1ctl_sap.c
@@ -70,7 +70,6 @@ void l1ctl_sap_rx_from_l23_inst_cb(struct l1ctl_sock_client *lsc, struct msgb *m
 	if (!msg)
 		return;
 
-	DEBUGPMS(DL1C, ms, "Message incoming from layer 2: %s\n", osmo_hexdump(msg->data, msg->len));
 	l1ctl_sap_handler(ms, msg);
 }
 
@@ -146,6 +145,20 @@ struct msgb *l1ctl_create_l2_msg(int msg_type, uint32_t fn, uint16_t snr, uint16
 	return msg;
 }
 
+static bool is_l1ctl_control(uint8_t msg_type)
+{
+	switch (msg_type) {
+	case L1CTL_DATA_REQ:
+	case L1CTL_DATA_CONF:
+	case L1CTL_TRAFFIC_REQ:
+	case L1CTL_TRAFFIC_CONF:
+	case L1CTL_TRAFFIC_IND:
+		return false;
+	default:
+		return true;
+	}
+}
+
 /**
  * @brief General handler for incoming L1CTL messages from layer 2/3.
  *
@@ -154,6 +167,7 @@ struct msgb *l1ctl_create_l2_msg(int msg_type, uint32_t fn, uint16_t snr, uint16
 void l1ctl_sap_handler(struct l1_model_ms *ms, struct msgb *msg)
 {
 	struct l1ctl_hdr *l1h;
+	int log_subsys;
 
 	if (!msg)
 		return;
@@ -165,6 +179,13 @@ void l1ctl_sap_handler(struct l1_model_ms *ms, struct msgb *msg)
 		goto exit_msgbfree;
 	}
 
+	if (is_l1ctl_control(l1h->msg_type))
+		log_subsys = DL1C;
+	else
+		log_subsys = DL1P;
+
+	DEBUGPMS(log_subsys, ms, "Message incoming from layer 2: %s\n", osmo_hexdump(msg->data, msg->len));
+
 	switch (l1h->msg_type) {
 	case L1CTL_FBSB_REQ:
 		l1ctl_rx_fbsb_req(ms, msg);
diff --git a/src/host/virt_phy/src/logging.c b/src/host/virt_phy/src/logging.c
index 7fb2c238..feb50817 100644
--- a/src/host/virt_phy/src/logging.c
+++ b/src/host/virt_phy/src/logging.c
@@ -64,7 +64,15 @@ static const struct log_info_cat default_categories[] = {
 		.description = "Layer 1 Control",
 		.color = "\033[1;31m",
 		.enabled = 1,
-		.loglevel = LOGL_DEBUG, },
+		.loglevel = LOGL_DEBUG,
+	},
+	[DL1P] = {
+		.name = "DL1P",
+		.description = "Layer 1 Data",
+		.color = "\033[1;31m",
+		.enabled = 1,
+		.loglevel = LOGL_DEBUG,
+	},
 	[DVIRPHY] = {
 		.name = "DVIRPHY",
 		.description = "Virtual Layer 1 Interface",
diff --git a/src/host/virt_phy/src/virt_prim_data.c b/src/host/virt_phy/src/virt_prim_data.c
index e03d0974..cf34e7ae 100644
--- a/src/host/virt_phy/src/virt_prim_data.c
+++ b/src/host/virt_phy/src/virt_prim_data.c
@@ -71,7 +71,7 @@ void l1ctl_rx_data_req(struct l1_model_ms *ms, struct msgb *msg)
 	                                ul->chan_nr, ul->link_id);
 
 	rsl_dec_chan_nr(ul->chan_nr, &rsl_chantype, &subslot, &timeslot);
-	DEBUGPMS(DL1C, ms,
+	DEBUGPMS(DL1P, ms,
 	       "Received and handled from l23 - L1CTL_DATA_REQ (link_id=0x%02x, ul=%p, ul->payload=%p, data_ind=%p, data_ind->data=%p l3h=%p)\n",
 	       ul->link_id, ul, ul->payload, data_ind, data_ind->data,
 	       msg->l3h);
@@ -107,7 +107,7 @@ void l1ctl_tx_data_ind(struct l1_model_ms *ms, struct msgb *msg, uint16_t arfcn,
 
 	memcpy(l1di->data, msgb_data(msg), msgb_length(msg));
 
-	DEBUGPMS(DL1C, ms, "Sending signaling-data to l23.\n");
+	DEBUGPMS(DL1P, ms, "Sending signaling-data to l23.\n");
 	l1ctl_sap_tx_to_l23_inst(ms, l1ctl_msg);
 }
 
diff --git a/src/host/virt_phy/src/virt_prim_traffic.c b/src/host/virt_phy/src/virt_prim_traffic.c
index 04f6749e..46ba9f17 100644
--- a/src/host/virt_phy/src/virt_prim_traffic.c
+++ b/src/host/virt_phy/src/virt_prim_traffic.c
@@ -69,7 +69,7 @@ void l1ctl_rx_traffic_req(struct l1_model_ms *ms, struct msgb *msg)
 	uint32_t fn_sched = sched_fn_ul(ms->state.current_time, ul->chan_nr, ul->link_id);
 
 	rsl_dec_chan_nr(ul->chan_nr, &rsl_chantype, &subslot, &timeslot);
-	DEBUGPMS(DL1C, ms, "Received and handled from l23 - L1CTL_TRAFFIC_REQ\n");
+	DEBUGPMS(DL1P, ms, "Received and handled from l23 - L1CTL_TRAFFIC_REQ\n");
 
 	msg->l2h = tr->data;
 
@@ -102,7 +102,7 @@ void l1ctl_tx_traffic_ind(struct l1_model_ms *ms, struct msgb *msg, uint16_t arf
 	/* TODO: traffic decoding and decryption */
 
 	memcpy(l1ti->data, msgb_data(msg), msgb_length(msg));
-	DEBUGPMS(DL1C, ms, "Sending to l23 - L1CTL_TRAFFIC_IND\n");
+	DEBUGPMS(DL1P, ms, "Sending to l23 - L1CTL_TRAFFIC_IND\n");
 	l1ctl_sap_tx_to_l23_inst(ms, l1ctl_msg);
 }
 
diff --git a/src/host/virt_phy/src/virtphy.c b/src/host/virt_phy/src/virtphy.c
index 78a45f00..481cdc14 100644
--- a/src/host/virt_phy/src/virtphy.c
+++ b/src/host/virt_phy/src/virtphy.c
@@ -37,7 +37,7 @@
 #include <virtphy/logging.h>
 #include <virtphy/virt_l1_sched.h>
 
-#define DEFAULT_LOG_MASK "DL1C,1:DVIRPHY,1:DMAIN,1"
+#define DEFAULT_LOG_MASK "DL1C,1:DL1P,1:DVIRPHY,1:DMAIN,1"
 
 /* this exists once in the program, and contains the state that we
  * only keep once:  L1CTL server socket, GSMTAP/VirtUM socket */