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
diff --git a/src/gb/gprs_ns2.c b/src/gb/gprs_ns2.c
index 3574f28..507a5ac 100644
--- a/src/gb/gprs_ns2.c
+++ b/src/gb/gprs_ns2.c
@@ -1261,6 +1261,11 @@
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 b4d0a0d..df51ff5 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 535d5be..9fcd48c 100644
--- a/src/gb/gprs_ns2_message.c
+++ b/src/gb/gprs_ns2_message.c
@@ -198,9 +198,9 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
{
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 @@
{
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 @@
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 @@
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 @@
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 @@
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 @@
(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 @@
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 @@
(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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 f4d88f4..c64f60d 100644
--- a/src/gb/gprs_ns2_vc_fsm.c
+++ b/src/gb/gprs_ns2_vc_fsm.c
@@ -646,6 +646,8 @@
* 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 @@
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 @@
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 c2a0453..4517afc 100644
--- a/src/logging.c
+++ b/src/logging.c
@@ -277,6 +277,18 @@
.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)