lynxis lazus has submitted this change. (
https://gerrit.osmocom.org/c/libosmocore/+/22294 )
Change subject: gprs_ns2: rework logging of Rx and Tx NS PDU
......................................................................
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
---
M include/osmocom/core/logging.h
M src/gb/gprs_ns2.c
M src/gb/gprs_ns2_internal.h
M src/gb/gprs_ns2_message.c
M src/gb/gprs_ns2_vc_fsm.c
M src/logging.c
M tests/logging/logging_vty_test.vty
7 files changed, 92 insertions(+), 70 deletions(-)
Approvals:
laforge: Looks good to me, approved
Jenkins Builder: Verified
diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h
index 01850c4..343f976 100644
--- a/include/osmocom/core/logging.h
+++ b/include/osmocom/core/logging.h
@@ -122,7 +122,9 @@
#define DLRSPRO -19 /*!< Osmocom Remote SIM Protocol */
#define DLNS -20 /*!< Osmocom NS layer */
#define DLBSSGP -21 /*!< Osmocom BSSGP layer */
-#define OSMO_NUM_DLIB 21 /*!< Number of logging sub-systems in libraries
*/
+#define DLNSDATA -22 /*!< Osmocom NS layer data pdus */
+#define DLNSSIGNAL -23 /*!< Osmocom NS layer signal pdus */
+#define OSMO_NUM_DLIB 23 /*!< Number of logging sub-systems in libraries
*/
/* Colors that can be used in log_info_cat.color */
#define OSMO_LOGCOLOR_NORMAL NULL
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)
diff --git a/tests/logging/logging_vty_test.vty
b/tests/logging/logging_vty_test.vty
index 82db2cc..91c2a48 100644
--- a/tests/logging/logging_vty_test.vty
+++ b/tests/logging/logging_vty_test.vty
@@ -54,7 +54,7 @@
logging print level (0|1)
logging print file (0|1|basename) [last]
logging set-log-mask MASK
- logging level
(aa|bb|ccc|dddd|eee|lglobal|llapd|linp|lmux|lmi|lmib|lsms|lctrl|lgtp|lstats|lgsup|loap|lss7|lsccp|lsua|lm3ua|lmgcp|ljibuf|lrspro|lns|lbssgp)
(debug|info|notice|error|fatal)
+ logging level
(aa|bb|ccc|dddd|eee|lglobal|llapd|linp|lmux|lmi|lmib|lsms|lctrl|lgtp|lstats|lgsup|loap|lss7|lsccp|lsua|lm3ua|lmgcp|ljibuf|lrspro|lns|lbssgp|lnsdata|lnssignal)
(debug|info|notice|error|fatal)
logging level set-all (debug|info|notice|error|fatal)
logging level force-all (debug|info|notice|error|fatal)
no logging level force-all
@@ -472,39 +472,41 @@
logging_vty_test# list
...
- logp
(aa|bb|ccc|dddd|eee|lglobal|llapd|linp|lmux|lmi|lmib|lsms|lctrl|lgtp|lstats|lgsup|loap|lss7|lsccp|lsua|lm3ua|lmgcp|ljibuf|lrspro|lns|lbssgp)
(debug|info|notice|error|fatal) .LOGMESSAGE
+ logp
(aa|bb|ccc|dddd|eee|lglobal|llapd|linp|lmux|lmi|lmib|lsms|lctrl|lgtp|lstats|lgsup|loap|lss7|lsccp|lsua|lm3ua|lmgcp|ljibuf|lrspro|lns|lbssgp|lnsdata|lnssignal)
(debug|info|notice|error|fatal) .LOGMESSAGE
...
logging_vty_test# logp?
logp Print a message on all log outputs; useful for placing markers in test
logs
logging_vty_test# logp ?
- aa Antropomorphic Armadillos (AA)
- bb Bidirectional Breadspread (BB)
- ccc Chaos Communication Congress (CCC)
- dddd Dehydrated Dribbling Duck Dunkers (DDDD)
- eee Exhaustive Entropy Extraction (EEE)
- lglobal Library-internal global log family
- llapd LAPD in libosmogsm
- linp A-bis Intput Subsystem
- lmux A-bis B-Subchannel TRAU Frame Multiplex
- lmi A-bis Input Driver for Signalling
- lmib A-bis Input Driver for B-Channels (voice)
- lsms Layer3 Short Message Service (SMS)
- lctrl Control Interface
- lgtp GPRS GTP library
- lstats Statistics messages and logging
- lgsup Generic Subscriber Update Protocol
- loap Osmocom Authentication Protocol
- lss7 libosmo-sigtran Signalling System 7
- lsccp libosmo-sigtran SCCP Implementation
- lsua libosmo-sigtran SCCP User Adaptation
- lm3ua libosmo-sigtran MTP3 User Adaptation
- lmgcp libosmo-mgcp Media Gateway Control Protocol
- ljibuf libosmo-netif Jitter Buffer
- lrspro Remote SIM protocol
- lns GPRS NS layer
- lbssgp GPRS BSSGP layer
+ aa Antropomorphic Armadillos (AA)
+ bb Bidirectional Breadspread (BB)
+ ccc Chaos Communication Congress (CCC)
+ dddd Dehydrated Dribbling Duck Dunkers (DDDD)
+ eee Exhaustive Entropy Extraction (EEE)
+ lglobal Library-internal global log family
+ llapd LAPD in libosmogsm
+ linp A-bis Intput Subsystem
+ lmux A-bis B-Subchannel TRAU Frame Multiplex
+ lmi A-bis Input Driver for Signalling
+ lmib A-bis Input Driver for B-Channels (voice)
+ lsms Layer3 Short Message Service (SMS)
+ lctrl Control Interface
+ lgtp GPRS GTP library
+ lstats Statistics messages and logging
+ lgsup Generic Subscriber Update Protocol
+ loap Osmocom Authentication Protocol
+ lss7 libosmo-sigtran Signalling System 7
+ lsccp libosmo-sigtran SCCP Implementation
+ lsua libosmo-sigtran SCCP User Adaptation
+ lm3ua libosmo-sigtran MTP3 User Adaptation
+ lmgcp libosmo-mgcp Media Gateway Control Protocol
+ ljibuf libosmo-netif Jitter Buffer
+ lrspro Remote SIM protocol
+ lns GPRS NS layer
+ lbssgp GPRS BSSGP layer
+ lnsdata GPRS NS layer data PDU
+ lnssignal GPRS NS layer signal PDU
logging_vty_test# logp lglobal ?
debug Log debug messages and higher levels
--
To view, visit https://gerrit.osmocom.org/c/libosmocore/+/22294
To unsubscribe, or for help writing mail filters, visit
https://gerrit.osmocom.org/settings
Gerrit-Project: libosmocore
Gerrit-Branch: master
Gerrit-Change-Id: I34b8fde2955ecc010d1dcd9512e1bba9211e2c0d
Gerrit-Change-Number: 22294
Gerrit-PatchSet: 16
Gerrit-Owner: lynxis lazus <[email protected]>
Gerrit-Reviewer: Jenkins Builder
Gerrit-Reviewer: daniel <[email protected]>
Gerrit-Reviewer: laforge <[email protected]>
Gerrit-Reviewer: lynxis lazus <[email protected]>
Gerrit-CC: pespin <[email protected]>
Gerrit-MessageType: merged
