[PATCH 1/3] logging: Implement subsecond resolution of extended timestamps
Currently when using 'logging print extended-timestamp 1', the subsecond part (milliseconds) of the printed timestamp is always 0. This makes it difficult to correlate log entries with PCAP file entries if there are many of them per second. This patch changes _output in logging.c to use gettimeofday() instead of time() when extended timestamps are enabled and replaces the '000' by the milliseconds computed from tv_usec. Sponsored-by: On-Waves ehf --- src/logging.c | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/src/logging.c b/src/logging.c index c007a45..20b0596 100644 --- a/src/logging.c +++ b/src/logging.c @@ -38,6 +38,7 @@ #include <strings.h> #endif #include <time.h> +#include <sys/time.h> #include <errno.h> #include <osmocom/core/talloc.h> @@ -254,11 +255,13 @@ static void _output(struct log_target *target, unsigned int subsys, if (!cont) { if (target->print_ext_timestamp) { struct tm tm; - time_t timep = time(NULL); - localtime_r(&timep, &tm); - ret = snprintf(buf + offset, rem, "%04d%02d%02d%02d%02d%02d000 ", + struct timeval tv; + gettimeofday(&tv, NULL); + localtime_r(&tv.tv_sec, &tm); + ret = snprintf(buf + offset, rem, "%04d%02d%02d%02d%02d%02d%03d ", tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, - tm.tm_hour, tm.tm_min, tm.tm_sec); + tm.tm_hour, tm.tm_min, tm.tm_sec, + (int)(tv.tv_usec / 1000)); if (ret < 0) goto err; OSMO_SNPRINTF_RET(ret, rem, offset, len); -- 1.9.1
Currently each incoming PtP BSSGP STATUS message is handled as 'not yet implemented' and a BSSGP STATUS message (cause BSSGP_CAUSE_PROTO_ERR_UNSPEC) is sent back to the peer. This will cause endless messages loops if both peers use this BSSGP stack implementation. This does not apply to signalling messages. This commit changes the implementation of bssgp_rx_ptp() to just do logging in this case. Sponsored-by: On-Waves ehf --- src/gb/gprs_bssgp.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/gb/gprs_bssgp.c b/src/gb/gprs_bssgp.c index 851d01c..8708340 100644 --- a/src/gb/gprs_bssgp.c +++ b/src/gb/gprs_bssgp.c @@ -845,7 +845,9 @@ static int bssgp_rx_ptp(struct msgb *msg, struct tlv_parsed *tp, break; case BSSGP_PDUT_STATUS: /* Some exception has occurred */ + DEBUGP(DBSSGP, "BSSGP BVCI=%u Rx PTP BVC STATUS\n", bctx->bvci); /* FIXME: send NM_STATUS.ind to NM */ + break; case BSSGP_PDUT_DOWNLOAD_BSS_PFC: case BSSGP_PDUT_CREATE_BSS_PFC_ACK: case BSSGP_PDUT_CREATE_BSS_PFC_NACK: -- 1.9.1
Currently incoming BSSGP STATUS messages are just logged and no other action is taken. This makes it impossible for higher layers to react to failures which are indicated by corresponding STATUS messages unless a timeout is triggered as a result of that failure later on. This commit adds a bssgp_rx_status() function and calls it on incoming STATUS messages. That function logs a message, increments the new BSSGP_CTR_STATUS counter if the bctx context exists and invokes an NM_STATUS status indication. The latter will allow the application to handle failures immediately. Since all STATUS messages should be handled, the function is already called in bssgp_rcvmsg and the message is no longer handled in (and will not reach) bssgp_rx_sign and bssgp_rx_ptp. Ticket: OW#1414 Sponsored-by: On-Waves ehf --- include/osmocom/gprs/gprs_bssgp.h | 2 + src/gb/gprs_bssgp.c | 78 +++++++++++++++++++++++++++++++-------- tests/gb/gprs_bssgp_test.c | 35 ++++++++++++++++++ tests/gb/gprs_bssgp_test.ok | 4 ++ 4 files changed, 103 insertions(+), 16 deletions(-) diff --git a/include/osmocom/gprs/gprs_bssgp.h b/include/osmocom/gprs/gprs_bssgp.h index f229253..e24b563 100644 --- a/include/osmocom/gprs/gprs_bssgp.h +++ b/include/osmocom/gprs/gprs_bssgp.h @@ -33,6 +33,7 @@ enum bssgp_prim { PRIM_NM_BVC_RESET, PRIM_NM_BVC_BLOCK, PRIM_NM_BVC_UNBLOCK, + PRIM_NM_STATUS, }; struct osmo_bssgp_prim { @@ -117,6 +118,7 @@ enum bssgp_ctr { BSSGP_CTR_BYTES_OUT, BSSGP_CTR_BLOCKED, BSSGP_CTR_DISCARDED, + BSSGP_CTR_STATUS, }; diff --git a/src/gb/gprs_bssgp.c b/src/gb/gprs_bssgp.c index 8708340..2f23290 100644 --- a/src/gb/gprs_bssgp.c +++ b/src/gb/gprs_bssgp.c @@ -46,6 +46,7 @@ static const struct rate_ctr_desc bssgp_ctr_description[] = { { "bytes.out", "Bytes at BSSGP Level (Out)" }, { "blocked", "BVC Blocking count" }, { "discarded", "BVC LLC Discarded count" }, + { "status", "BVC Status count" }, }; static const struct rate_ctr_group_desc bssgp_ctrg_desc = { @@ -516,6 +517,46 @@ static int bssgp_rx_llc_disc(struct msgb *msg, struct tlv_parsed *tp, return bssgp_prim_cb(&nmp.oph, NULL); } +int bssgp_rx_status(struct msgb *msg, struct tlv_parsed *tp, + uint16_t bvci, struct bssgp_bvc_ctx *bctx) +{ + struct osmo_bssgp_prim nmp; + enum gprs_bssgp_cause cause; + + if (!TLVP_PRESENT(tp, BSSGP_IE_CAUSE)) { + LOGP(DBSSGP, LOGL_ERROR, "BSSGP BVCI=%u Rx STATUS " + "missing mandatory IE\n", bvci); + cause = BSSGP_CAUSE_PROTO_ERR_UNSPEC; + } else { + cause = *TLVP_VAL(tp, BSSGP_IE_CAUSE); + } + + LOGP(DBSSGP, LOGL_NOTICE, "BSSGP BVCI=%u Rx BVC STATUS, cause=%s\n", + bvci, bssgp_cause_str(cause)); + + if (cause == BSSGP_CAUSE_BVCI_BLOCKED || cause == BSSGP_CAUSE_UNKNOWN_BVCI) { + if (!TLVP_PRESENT(tp, BSSGP_IE_BVCI)) + LOGP(DBSSGP, LOGL_ERROR, + "BSSGP BVCI=%u Rx STATUS cause=%s " + "missing conditional BVCI IE\n", + bvci, bssgp_cause_str(cause)); + } + + if (bctx) + rate_ctr_inc(&bctx->ctrg->ctr[BSSGP_CTR_STATUS]); + + /* send NM_STATUS to NM */ + memset(&nmp, 0, sizeof(nmp)); + nmp.nsei = msgb_nsei(msg); + nmp.bvci = bvci; + nmp.tp = tp; + osmo_prim_init(&nmp.oph, SAP_BSSGP_NM, PRIM_NM_STATUS, + PRIM_OP_INDICATION, msg); + + return bssgp_prim_cb(&nmp.oph, NULL); +} + + /* One element (msgb) in a BSSGP Flow Control queue */ struct bssgp_fc_queue_element { /* linked list of queue elements */ @@ -807,10 +848,12 @@ static int bssgp_rx_ptp(struct msgb *msg, struct tlv_parsed *tp, uint8_t pdu_type = bgph->pdu_type; int rc = 0; + OSMO_ASSERT(pdu_type != BSSGP_PDUT_STATUS); + /* If traffic is received on a BVC that is marked as blocked, the * received PDU shall not be accepted and a STATUS PDU (Cause value: * BVC Blocked) shall be sent to the peer entity on the signalling BVC */ - if (bctx->state & BVC_S_BLOCKED && pdu_type != BSSGP_PDUT_STATUS) { + if (bctx->state & BVC_S_BLOCKED) { uint16_t bvci = msgb_bvci(msg); return bssgp_tx_status(BSSGP_CAUSE_BVCI_BLOCKED, &bvci, msg); } @@ -844,9 +887,7 @@ static int bssgp_rx_ptp(struct msgb *msg, struct tlv_parsed *tp, /* FIXME: Send FLOW_CONTROL_MS_ACK */ break; case BSSGP_PDUT_STATUS: - /* Some exception has occurred */ - DEBUGP(DBSSGP, "BSSGP BVCI=%u Rx PTP BVC STATUS\n", bctx->bvci); - /* FIXME: send NM_STATUS.ind to NM */ + /* This is already handled in bssgp_rcvmsg() */ break; case BSSGP_PDUT_DOWNLOAD_BSS_PFC: case BSSGP_PDUT_CREATE_BSS_PFC_ACK: @@ -943,9 +984,7 @@ static int bssgp_rx_sign(struct msgb *msg, struct tlv_parsed *tp, rc = bssgp_rx_bvc_reset(msg, tp, ns_bvci); break; case BSSGP_PDUT_STATUS: - /* Some exception has occurred */ - DEBUGP(DBSSGP, "BSSGP BVCI=%u Rx BVC STATUS\n", bvci); - /* FIXME: send NM_STATUS.ind to NM */ + /* This is already handled in bssgp_rcvmsg() */ break; /* those only exist in the SGSN -> BSS direction */ case BSSGP_PDUT_PAGING_PS: @@ -1006,15 +1045,6 @@ int bssgp_rcvmsg(struct msgb *msg) /* look-up or create the BTS context for this BVC */ bctx = btsctx_by_bvci_nsei(bvci, msgb_nsei(msg)); - /* Only a RESET PDU can create a new BVC context, - * otherwise it must be registered if a BVCI is given */ - if (!bctx && bvci != BVCI_SIGNALLING && - pdu_type != BSSGP_PDUT_BVC_RESET) { - LOGP(DBSSGP, LOGL_NOTICE, "NSEI=%u/BVCI=%u Rejecting PDU " - "type %u for unknown BVCI\n", msgb_nsei(msg), bvci, - pdu_type); - return bssgp_tx_status(BSSGP_CAUSE_UNKNOWN_BVCI, &bvci, msg); - } if (bctx) { log_set_context(GPRS_CTX_BVC, bctx); @@ -1023,6 +1053,22 @@ int bssgp_rcvmsg(struct msgb *msg) msgb_bssgp_len(msg)); } + /* Always handle STATUS PDUs, even if they contain an invalid BVCI or + * are otherwise unexpected */ + if (pdu_type == BSSGP_PDUT_STATUS) + /* Some exception has occurred */ + return bssgp_rx_status(msg, &tp, bvci, bctx); + + /* Only a RESET PDU can create a new BVC context, otherwise it must be + * registered if a BVCI is given. */ + if (!bctx && bvci != BVCI_SIGNALLING && + pdu_type != BSSGP_PDUT_BVC_RESET) { + LOGP(DBSSGP, LOGL_NOTICE, "NSEI=%u/BVCI=%u Rejecting PDU " + "type %u for unknown BVCI\n", msgb_nsei(msg), bvci, + pdu_type); + return bssgp_tx_status(BSSGP_CAUSE_UNKNOWN_BVCI, &bvci, msg); + } + if (ns_bvci == BVCI_SIGNALLING) rc = bssgp_rx_sign(msg, &tp, bctx); else if (ns_bvci == BVCI_PTM) diff --git a/tests/gb/gprs_bssgp_test.c b/tests/gb/gprs_bssgp_test.c index a247326..3d1384b 100644 --- a/tests/gb/gprs_bssgp_test.c +++ b/tests/gb/gprs_bssgp_test.c @@ -125,6 +125,40 @@ static void test_bssgp_suspend_resume(void) printf("----- %s END\n", __func__); } +static void send_bssgp_status(enum gprs_bssgp_cause cause, uint16_t *bvci) +{ + struct msgb *msg = bssgp_msgb_alloc(); + uint8_t cause_ = cause; + + msgb_v_put(msg, BSSGP_PDUT_STATUS); + msgb_tvlv_put(msg, BSSGP_IE_CAUSE, 1, &cause_); + if (bvci) { + uint16_t bvci_ = htons(*bvci); + msgb_tvlv_put(msg, BSSGP_IE_BVCI, 2, (uint8_t *) &bvci_); + } + + msgb_bssgp_send_and_free(msg); +} + +static void test_bssgp_status(void) +{ + uint16_t bvci; + + printf("----- %s START\n", __func__); + + send_bssgp_status(BSSGP_CAUSE_PROTO_ERR_UNSPEC, NULL); + OSMO_ASSERT(last_oph.primitive == PRIM_NM_STATUS); + + /* Enforce prim != PRIM_NM_STATUS */ + last_oph.primitive = PRIM_NM_LLC_DISCARDED; + + bvci = 1234; + send_bssgp_status(BSSGP_CAUSE_UNKNOWN_BVCI, &bvci); + OSMO_ASSERT(last_oph.primitive == PRIM_NM_STATUS); + + printf("----- %s END\n", __func__); +} + static struct log_info info = {}; int main(int argc, char **argv) @@ -146,6 +180,7 @@ int main(int argc, char **argv) printf("===== BSSGP test START\n"); test_bssgp_suspend_resume(); + test_bssgp_status(); printf("===== BSSGP test END\n\n"); exit(EXIT_SUCCESS); diff --git a/tests/gb/gprs_bssgp_test.ok b/tests/gb/gprs_bssgp_test.ok index c9ec83d..0392e6a 100644 --- a/tests/gb/gprs_bssgp_test.ok +++ b/tests/gb/gprs_bssgp_test.ok @@ -3,5 +3,9 @@ BSSGP primitive, SAP 16777219, prim = 3, op = 0, msg = 0b 1f 84 f0 12 34 56 1b 86 0f f1 80 20 37 00 BSSGP primitive, SAP 16777219, prim = 4, op = 0, msg = 0e 1f 84 f0 12 34 56 1b 86 0f f1 80 20 37 00 1d 81 01 ----- test_bssgp_suspend_resume END +----- test_bssgp_status START +BSSGP primitive, SAP 16777221, prim = 11, op = 2, msg = 41 07 81 27 +BSSGP primitive, SAP 16777221, prim = 11, op = 2, msg = 41 07 81 05 04 82 04 d2 +----- test_bssgp_status END ===== BSSGP test END -- 1.9.1
participants (1)
-
Jacob Erlbeck