This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.
lynxis lazus gerrit-no-reply at lists.osmocom.orglynxis 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 <lynxis at fe80.eu> Gerrit-Reviewer: Jenkins Builder Gerrit-Reviewer: daniel <dwillmann at sysmocom.de> Gerrit-Reviewer: laforge <laforge at osmocom.org> Gerrit-Reviewer: lynxis lazus <lynxis at fe80.eu> Gerrit-CC: pespin <pespin at sysmocom.de> Gerrit-MessageType: merged -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20210324/c2b0d6eb/attachment.htm>