From 6cf65d9d81d4c4d8863d06876b292679513d1fc8 Mon Sep 17 00:00:00 2001 From: Alexander Couzens Date: Mon, 18 Jan 2021 17:55:35 +0100 Subject: 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 --- src/gb/gprs_ns2.c | 5 +++++ src/gb/gprs_ns2_internal.h | 21 ++++++++++++++---- src/gb/gprs_ns2_message.c | 54 ++++++++++++++++++---------------------------- src/gb/gprs_ns2_vc_fsm.c | 8 +++---- src/logging.c | 12 +++++++++++ 5 files changed, 59 insertions(+), 41 deletions(-) (limited to 'src') 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 #include +#include #include #include @@ -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) -- cgit v1.2.3