fixeria has submitted this change. ( https://gerrit.osmocom.org/c/osmocom-bb/+/28744 ) Change subject: trxcon: make l1sched logging configurable, use trxcon->fi as prefix ...................................................................... trxcon: make l1sched logging configurable, use trxcon->fi as prefix This change makes it possible to configure l1sched related logging: * l1sched_logging_init() allows to configure logging categories for common and data messages (by default, DLGLOBAL is used); * struct l1sched_cfg allows to configure a logging prefix to be used in l1sched messges (by default, 'l1sched[0x%p] is used)'. Let's use osmo_fsm_inst_name(trxcon->fi) as the logging prefix. Change-Id: I26da1a506b02502a3a6a887533c35fb09c13c429 Related: OS#5599, OS#3761 --- M src/host/trxcon/include/osmocom/bb/l1sched/Makefile.am M src/host/trxcon/include/osmocom/bb/l1sched/l1sched.h A src/host/trxcon/include/osmocom/bb/l1sched/logging.h M src/host/trxcon/include/osmocom/bb/trxcon/trxcon.h M src/host/trxcon/src/sched_clck.c M src/host/trxcon/src/sched_lchan_common.c M src/host/trxcon/src/sched_lchan_pdtch.c M src/host/trxcon/src/sched_lchan_rach.c M src/host/trxcon/src/sched_lchan_sch.c M src/host/trxcon/src/sched_lchan_tchf.c M src/host/trxcon/src/sched_lchan_tchh.c M src/host/trxcon/src/sched_lchan_xcch.c M src/host/trxcon/src/sched_mframe.c M src/host/trxcon/src/sched_prim.c M src/host/trxcon/src/sched_trx.c M src/host/trxcon/src/trxcon.c 16 files changed, 253 insertions(+), 201 deletions(-) Approvals: pespin: Looks good to me, but someone else must approve fixeria: Looks good to me, approved Jenkins Builder: Verified diff --git a/src/host/trxcon/include/osmocom/bb/l1sched/Makefile.am b/src/host/trxcon/include/osmocom/bb/l1sched/Makefile.am index 295cc6b..76f54a7 100644 --- a/src/host/trxcon/include/osmocom/bb/l1sched/Makefile.am +++ b/src/host/trxcon/include/osmocom/bb/l1sched/Makefile.am @@ -1,3 +1,4 @@ noinst_HEADERS = \ l1sched.h \ + logging.h \ $(NULL) diff --git a/src/host/trxcon/include/osmocom/bb/l1sched/l1sched.h b/src/host/trxcon/include/osmocom/bb/l1sched/l1sched.h index 2969410..3c28f45 100644 --- a/src/host/trxcon/include/osmocom/bb/l1sched/l1sched.h +++ b/src/host/trxcon/include/osmocom/bb/l1sched/l1sched.h @@ -346,6 +346,12 @@ uint8_t offset; }; +/*! Scheduler configuration */ +struct l1sched_cfg { + /*! Logging context (used as prefix for messages) */ + const char *log_prefix; +}; + /*! One scheduler instance */ struct l1sched_state { /*! Clock state */ @@ -366,6 +372,8 @@ struct l1sched_ts *ts[TRX_TS_COUNT]; /*! BSIC value learned from SCH bursts */ uint8_t bsic; + /*! Logging context (used as prefix for messages) */ + const char *log_prefix; /*! Some private data */ void *priv; }; @@ -375,7 +383,9 @@ enum gsm_phys_chan_config config, int tn); /* Scheduler management functions */ -struct l1sched_state *l1sched_alloc(void *ctx, uint32_t fn_advance, void *priv); +void l1sched_logging_init(int log_cat_common, int log_cat_data); +struct l1sched_state *l1sched_alloc(void *ctx, const struct l1sched_cfg *cfg, + uint32_t fn_advance, void *priv); void l1sched_reset(struct l1sched_state *sched, bool reset_clock); void l1sched_free(struct l1sched_state *sched); diff --git a/src/host/trxcon/include/osmocom/bb/l1sched/logging.h b/src/host/trxcon/include/osmocom/bb/l1sched/logging.h new file mode 100644 index 0000000..fb1c018 --- /dev/null +++ b/src/host/trxcon/include/osmocom/bb/l1sched/logging.h @@ -0,0 +1,34 @@ +#pragma once + +extern int l1sched_log_cat_common; +extern int l1sched_log_cat_data; + +/* Messages using l1sched_state as the context */ +#define LOGP_SCHED_CAT(sched, cat, level, fmt, args...) \ + LOGP(l1sched_log_cat_##cat, level, "%s" fmt, \ + (sched)->log_prefix, ## args) + +/* Common messages using l1sched_state as the context */ +#define LOGP_SCHEDC(sched, level, fmt, args...) \ + LOGP_SCHED_CAT(sched, common, level, fmt, ## args) + +/* Data messages using l1sched_state as the context */ +#define LOGP_SCHEDD(sched, level, fmt, args...) \ + LOGP_SCHED_CAT(sched, common, level, fmt, ## args) + + +#define LOGP_LCHAN_NAME_ARGS(lchan) \ + (lchan)->ts->index, l1sched_lchan_desc[(lchan)->type].name + +/* Messages using l1sched_lchan_state as the context */ +#define LOGP_LCHAN_CAT(lchan, cat, level, fmt, args...) \ + LOGP_SCHED_CAT((lchan)->ts->sched, cat, level, "TS%u-%s " fmt, \ + LOGP_LCHAN_NAME_ARGS(lchan), ## args) + +/* Common messages using l1sched_lchan_state as the context */ +#define LOGP_LCHANC(lchan, level, fmt, args...) \ + LOGP_LCHAN_CAT(lchan, common, level, fmt, ## args) + +/* Data messages using l1sched_lchan_state as the context */ +#define LOGP_LCHAND(lchan, level, fmt, args...) \ + LOGP_LCHAN_CAT(lchan, data, level, fmt, ## args) diff --git a/src/host/trxcon/include/osmocom/bb/trxcon/trxcon.h b/src/host/trxcon/include/osmocom/bb/trxcon/trxcon.h index 2c28f80..12ad017 100644 --- a/src/host/trxcon/include/osmocom/bb/trxcon/trxcon.h +++ b/src/host/trxcon/include/osmocom/bb/trxcon/trxcon.h @@ -22,6 +22,9 @@ struct trxcon_inst { struct osmo_fsm_inst *fi; + /* Logging context for sched and l1c */ + const char *log_prefix; + /* The L1 scheduler */ struct l1sched_state *sched; /* L1/L2 interfaces */ diff --git a/src/host/trxcon/src/sched_clck.c b/src/host/trxcon/src/sched_clck.c index 27e8eb9..a3d75fc 100644 --- a/src/host/trxcon/src/sched_clck.c +++ b/src/host/trxcon/src/sched_clck.c @@ -30,13 +30,14 @@ #include <inttypes.h> #include <string.h> +#include <osmocom/core/logging.h> #include <osmocom/core/talloc.h> #include <osmocom/core/msgb.h> #include <osmocom/core/timer.h> #include <osmocom/core/timer_compat.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> #define MAX_FN_SKEW 50 #define TRX_LOSS_FRAMES 400 @@ -50,7 +51,7 @@ /* Check if transceiver is still alive */ if (sched->fn_counter_lost++ == TRX_LOSS_FRAMES) { - LOGP(DSCH, LOGL_DEBUG, "No more clock from transceiver\n"); + LOGP_SCHEDC(sched, LOGL_DEBUG, "No more clock from transceiver\n"); sched->clck_state = L1SCHED_CLCK_ST_WAIT; return; @@ -65,8 +66,8 @@ /* If someone played with clock, or if the process stalled */ if (elapsed_us > GSM_TDMA_FN_DURATION_uS * MAX_FN_SKEW || elapsed_us < 0) { - LOGP(DSCH, LOGL_NOTICE, "PC clock skew: " - "elapsed uS %" PRId64 "\n", elapsed_us); + LOGP_SCHEDC(sched, LOGL_NOTICE, "PC clock skew: " + "elapsed uS %" PRId64 "\n", elapsed_us); sched->clck_state = L1SCHED_CLCK_ST_WAIT; @@ -123,13 +124,13 @@ if (sched->clck_state == L1SCHED_CLCK_ST_WAIT) { l1sched_clck_correct(sched, &tv_now, fn); - LOGP(DSCH, LOGL_DEBUG, "Initial clock received: fn=%u\n", fn); + LOGP_SCHEDC(sched, LOGL_DEBUG, "Initial clock received: fn=%u\n", fn); sched->clck_state = L1SCHED_CLCK_ST_OK; return 0; } - LOGP(DSCH, LOGL_NOTICE, "Clock indication: fn=%u\n", fn); + LOGP_SCHEDC(sched, LOGL_NOTICE, "Clock indication: fn=%u\n", fn); osmo_timer_del(&sched->clock_timer); @@ -143,15 +144,15 @@ /* Check for max clock skew */ if (elapsed_fn > MAX_FN_SKEW || elapsed_fn < -MAX_FN_SKEW) { - LOGP(DSCH, LOGL_NOTICE, "GSM clock skew: old fn=%u, " - "new fn=%u\n", sched->fn_counter_proc, fn); + LOGP_SCHEDC(sched, LOGL_NOTICE, "GSM clock skew: old fn=%u, " + "new fn=%u\n", sched->fn_counter_proc, fn); l1sched_clck_correct(sched, &tv_now, fn); return 0; } - LOGP(DSCH, LOGL_INFO, "GSM clock jitter: %" PRId64 "\n", - elapsed_fn * GSM_TDMA_FN_DURATION_uS - elapsed_us); + LOGP_SCHEDC(sched, LOGL_INFO, "GSM clock jitter: %" PRId64 "\n", + elapsed_fn * GSM_TDMA_FN_DURATION_uS - elapsed_us); /* Too many frames have been processed already */ if (elapsed_fn < 0) { diff --git a/src/host/trxcon/src/sched_lchan_common.c b/src/host/trxcon/src/sched_lchan_common.c index 5d5ef6d..6fe5b2e 100644 --- a/src/host/trxcon/src/sched_lchan_common.c +++ b/src/host/trxcon/src/sched_lchan_common.c @@ -36,7 +36,7 @@ #include <osmocom/gsm/protocol/gsm_08_58.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> /* GSM 05.02 Chapter 5.2.3 Normal Burst (NB) */ const uint8_t l1sched_nb_training_bits[8][26] = { @@ -122,10 +122,10 @@ /* FIXME: AMR is not implemented yet */ return 0; case GSM48_CMODE_SIGN: - LOGP(DSCH, LOGL_ERROR, "BFI is not allowed in signalling mode\n"); + LOGP_LCHAND(lchan, LOGL_ERROR, "BFI is not allowed in signalling mode\n"); return 0; default: - LOGP(DSCH, LOGL_ERROR, "Invalid TCH mode: %u\n", lchan->tch_mode); + LOGP_LCHAND(lchan, LOGL_ERROR, "Invalid TCH mode: %u\n", lchan->tch_mode); return 0; } } diff --git a/src/host/trxcon/src/sched_lchan_pdtch.c b/src/host/trxcon/src/sched_lchan_pdtch.c index 9cad53a..0ef4573 100644 --- a/src/host/trxcon/src/sched_lchan_pdtch.c +++ b/src/host/trxcon/src/sched_lchan_pdtch.c @@ -31,25 +31,22 @@ #include <osmocom/coding/gsm0503_coding.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> int rx_pdtch_fn(struct l1sched_lchan_state *lchan, uint32_t fn, uint8_t bid, const sbit_t *bits, const struct l1sched_meas_set *meas) { - const struct l1sched_lchan_desc *lchan_desc; uint8_t l2[GPRS_L2_MAX_LEN], *mask; int n_errors, n_bits_total, rc; sbit_t *buffer, *offset; size_t l2_len; /* Set up pointers */ - lchan_desc = &l1sched_lchan_desc[lchan->type]; mask = &lchan->rx_burst_mask; buffer = lchan->rx_bursts; - LOGP(DSCHD, LOGL_DEBUG, "Packet data received on %s: " - "fn=%u ts=%u bid=%u\n", lchan_desc->name, fn, lchan->ts->index, bid); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Packet data received: fn=%u bid=%u\n", fn, bid); /* Align to the first burst of a block */ if (*mask == 0x00 && bid != 0) @@ -75,12 +72,11 @@ /* Check for complete set of bursts */ if ((*mask & 0xf) != 0xf) { - LOGP(DSCHD, LOGL_ERROR, "Received incomplete (%s) data frame at " - "fn=%u (%u/%u) for %s\n", - l1sched_burst_mask2str(mask, 4), lchan->meas_avg.fn, - lchan->meas_avg.fn % lchan->ts->mf_layout->period, - lchan->ts->mf_layout->period, - lchan_desc->name); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Received incomplete (%s) packet data at fn=%u (%u/%u)\n", + l1sched_burst_mask2str(mask, 4), lchan->meas_avg.fn, + lchan->meas_avg.fn % lchan->ts->mf_layout->period, + lchan->ts->mf_layout->period); /* NOTE: do not abort here, give it a try. Maybe we're lucky ;) */ } @@ -91,8 +87,9 @@ rc = gsm0503_pdtch_decode(l2, buffer, NULL, &n_errors, &n_bits_total); if (rc < 0) { - LOGP(DSCHD, LOGL_ERROR, "Received bad %s frame (rc=%d, ber=%d/%d) at fn=%u\n", - lchan_desc->name, rc, n_errors, n_bits_total, lchan->meas_avg.fn); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Received bad frame (rc=%d, ber=%d/%d) at fn=%u\n", + rc, n_errors, n_bits_total, lchan->meas_avg.fn); } /* Determine L2 length */ @@ -108,14 +105,12 @@ int tx_pdtch_fn(struct l1sched_lchan_state *lchan, struct l1sched_burst_req *br) { - const struct l1sched_lchan_desc *lchan_desc; ubit_t *buffer, *offset; const uint8_t *tsc; uint8_t *mask; int rc; /* Set up pointers */ - lchan_desc = &l1sched_lchan_desc[lchan->type]; mask = &lchan->tx_burst_mask; buffer = lchan->tx_bursts; @@ -131,9 +126,9 @@ rc = gsm0503_pdtch_encode(buffer, lchan->prim->payload, lchan->prim->payload_len); if (rc < 0) { - LOGP(DSCHD, LOGL_ERROR, "Failed to encode L2 payload (len=%zu): %s\n", - lchan->prim->payload_len, osmo_hexdump(lchan->prim->payload, - lchan->prim->payload_len)); + LOGP_LCHAND(lchan, LOGL_ERROR, "Failed to encode L2 payload (len=%zu): %s\n", + lchan->prim->payload_len, osmo_hexdump(lchan->prim->payload, + lchan->prim->payload_len)); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -159,8 +154,7 @@ memset(br->burst + 145, 0, 3); /* TB */ br->burst_len = GSM_BURST_LEN; - LOGP(DSCHD, LOGL_DEBUG, "Scheduled %s fn=%u ts=%u burst=%u\n", - lchan_desc->name, br->fn, lchan->ts->index, br->bid); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Scheduled at fn=%u burst=%u\n", br->fn, br->bid); /* If we have sent the last (4/4) burst */ if ((*mask & 0x0f) == 0x0f) { diff --git a/src/host/trxcon/src/sched_lchan_rach.c b/src/host/trxcon/src/sched_lchan_rach.c index e5944c6..e7422b2 100644 --- a/src/host/trxcon/src/sched_lchan_rach.c +++ b/src/host/trxcon/src/sched_lchan_rach.c @@ -31,7 +31,7 @@ #include <osmocom/coding/gsm0503_coding.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> /* 3GPP TS 05.02, section 5.2.7 "Access burst (AB)" */ #define RACH_EXT_TAIL_BITS_LEN 8 @@ -88,8 +88,9 @@ if (L1SCHED_PRIM_IS_RACH11(lchan->prim)) { /* Check requested synch. sequence */ if (rach->synch_seq >= RACH_SYNCH_SEQ_NUM) { - LOGP(DSCHD, LOGL_ERROR, "Unknown RACH synch. sequence=0x%02x\n", - rach->synch_seq); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Unknown RACH synch. sequence=0x%02x\n", + rach->synch_seq); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -99,8 +100,9 @@ /* Encode extended (11-bit) payload */ rc = gsm0503_rach_ext_encode(payload, rach->ra, bsic, true); if (rc) { - LOGP(DSCHD, LOGL_ERROR, "Could not encode extended RACH burst " - "(ra=%u bsic=%u)\n", rach->ra, bsic); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Could not encode extended RACH burst (ra=%u bsic=%u)\n", + rach->ra, bsic); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -112,16 +114,18 @@ /* Encode regular (8-bit) payload */ rc = gsm0503_rach_ext_encode(payload, rach->ra, bsic, false); if (rc) { - LOGP(DSCHD, LOGL_ERROR, "Could not encode RACH burst " - "(ra=%u bsic=%u)\n", rach->ra, bsic); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Could not encode RACH burst (ra=%u bsic=%u)\n", + rach->ra, bsic); /* Forget this primitive */ l1sched_prim_drop(lchan); return rc; } } else { - LOGP(DSCHD, LOGL_ERROR, "Primitive has unexpected " - "type=0x%02x\n", lchan->prim->type); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Primitive has unexpected type=0x%02x\n", + lchan->prim->type); l1sched_prim_drop(lchan); return -EINVAL; } @@ -143,10 +147,9 @@ memset(burst_ptr, 0, br->burst + GSM_BURST_LEN - burst_ptr); br->burst_len = GSM_BURST_LEN; - LOGP(DSCHD, LOGL_NOTICE, "Scheduled %s RACH (%s) on fn=%u, tn=%u, lchan=%s\n", - L1SCHED_PRIM_IS_RACH11(lchan->prim) ? "extended (11-bit)" : "regular (8-bit)", - get_value_string(rach_synch_seq_names, rach->synch_seq), br->fn, - lchan->ts->index, l1sched_lchan_desc[lchan->type].name); + LOGP_LCHAND(lchan, LOGL_NOTICE, "Scheduled %s RACH (%s) at fn=%u\n", + L1SCHED_PRIM_IS_RACH11(lchan->prim) ? "extended (11-bit)" : "regular (8-bit)", + get_value_string(rach_synch_seq_names, rach->synch_seq), br->fn); /* Confirm RACH request */ l1sched_handle_data_cnf(lchan, br->fn, L1SCHED_DT_OTHER); diff --git a/src/host/trxcon/src/sched_lchan_sch.c b/src/host/trxcon/src/sched_lchan_sch.c index 235e64c..c61e134 100644 --- a/src/host/trxcon/src/sched_lchan_sch.c +++ b/src/host/trxcon/src/sched_lchan_sch.c @@ -33,7 +33,7 @@ #include <osmocom/coding/gsm0503_coding.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> static void decode_sb(struct gsm_time *time, uint8_t *bsic, uint8_t *sb_info) { @@ -78,20 +78,21 @@ /* Attempt to decode */ rc = gsm0503_sch_decode(sb_info, payload); if (rc) { - LOGP(DSCHD, LOGL_ERROR, "Received bad SCH burst at fn=%u\n", fn); + LOGP_LCHAND(lchan, LOGL_ERROR, "Received bad SCH burst at fn=%u\n", fn); return rc; } /* Decode BSIC and TDMA frame number */ decode_sb(&time, &bsic, sb_info); - LOGP(DSCHD, LOGL_DEBUG, "Received SCH: bsic=%u, fn=%u, sched_fn=%u\n", + LOGP_LCHAND(lchan, LOGL_DEBUG, "Received SCH: bsic=%u, fn=%u, sched_fn=%u\n", bsic, time.fn, lchan->ts->sched->fn_counter_proc); /* Check if decoded frame number matches */ if (time.fn != fn) { - LOGP(DSCHD, LOGL_ERROR, "Decoded fn=%u does not match " - "fn=%u provided by scheduler\n", time.fn, fn); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Decoded fn=%u does not match fn=%u provided by scheduler\n", + time.fn, fn); return -EINVAL; } diff --git a/src/host/trxcon/src/sched_lchan_tchf.c b/src/host/trxcon/src/sched_lchan_tchf.c index 8349193..1a1b93d 100644 --- a/src/host/trxcon/src/sched_lchan_tchf.c +++ b/src/host/trxcon/src/sched_lchan_tchf.c @@ -33,25 +33,22 @@ #include <osmocom/codec/codec.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> int rx_tchf_fn(struct l1sched_lchan_state *lchan, uint32_t fn, uint8_t bid, const sbit_t *bits, const struct l1sched_meas_set *meas) { - const struct l1sched_lchan_desc *lchan_desc; int n_errors = -1, n_bits_total, rc; sbit_t *buffer, *offset; uint8_t l2[128], *mask; size_t l2_len; /* Set up pointers */ - lchan_desc = &l1sched_lchan_desc[lchan->type]; mask = &lchan->rx_burst_mask; buffer = lchan->rx_bursts; - LOGP(DSCHD, LOGL_DEBUG, "Traffic received on %s: fn=%u ts=%u bid=%u\n", - lchan_desc->name, fn, lchan->ts->index, bid); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Traffic received: fn=%u bid=%u\n", fn, bid); /* Align to the first burst of a block */ if (*mask == 0x00 && bid != 0) @@ -77,12 +74,11 @@ /* Check for complete set of bursts */ if ((*mask & 0xff) != 0xff) { - LOGP(DSCHD, LOGL_ERROR, "Received incomplete (%s) traffic frame at " - "fn=%u (%u/%u) for %s\n", - l1sched_burst_mask2str(mask, 8), lchan->meas_avg.fn, - lchan->meas_avg.fn % lchan->ts->mf_layout->period, - lchan->ts->mf_layout->period, - lchan_desc->name); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Received incomplete (%s) traffic frame at fn=%u (%u/%u)\n", + l1sched_burst_mask2str(mask, 8), lchan->meas_avg.fn, + lchan->meas_avg.fn % lchan->ts->mf_layout->period, + lchan->ts->mf_layout->period); /* NOTE: do not abort here, give it a try. Maybe we're lucky ;) */ } @@ -105,10 +101,10 @@ * TODO: AMR requires a dedicated loop, * which will be implemented later... */ - LOGP(DSCHD, LOGL_ERROR, "AMR isn't supported yet\n"); + LOGP_LCHAND(lchan, LOGL_ERROR, "AMR isn't supported yet\n"); return -ENOTSUP; default: - LOGP(DSCHD, LOGL_ERROR, "Invalid TCH mode: %u\n", lchan->tch_mode); + LOGP_LCHAND(lchan, LOGL_ERROR, "Invalid TCH mode: %u\n", lchan->tch_mode); return -EINVAL; } @@ -117,8 +113,9 @@ /* Check decoding result */ if (rc < 4) { - LOGP(DSCHD, LOGL_ERROR, "Received bad %s frame (rc=%d, ber=%d/%d) at fn=%u\n", - lchan_desc->name, rc, n_errors, n_bits_total, lchan->meas_avg.fn); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Received bad frame (rc=%d, ber=%d/%d) at fn=%u\n", + rc, n_errors, n_bits_total, lchan->meas_avg.fn); /* Send BFI */ goto bfi; @@ -171,7 +168,6 @@ int tx_tchf_fn(struct l1sched_lchan_state *lchan, struct l1sched_burst_req *br) { - const struct l1sched_lchan_desc *lchan_desc; ubit_t *buffer, *offset; const uint8_t *tsc; uint8_t *mask; @@ -179,7 +175,6 @@ int rc; /* Set up pointers */ - lchan_desc = &l1sched_lchan_desc[lchan->type]; mask = &lchan->tx_burst_mask; buffer = lchan->tx_bursts; @@ -205,16 +200,17 @@ * TODO: AMR requires a dedicated loop, * which will be implemented later... */ - LOGP(DSCHD, LOGL_ERROR, "AMR isn't supported yet, " - "dropping frame...\n"); + LOGP_LCHAND(lchan, LOGL_ERROR, + "AMR isn't supported yet, dropping frame...\n"); /* Forget this primitive */ l1sched_prim_drop(lchan); return -ENOTSUP; default: - LOGP(DSCHD, LOGL_ERROR, "Invalid TCH mode: %u, " - "dropping frame...\n", lchan->tch_mode); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Invalid TCH mode: %u, dropping frame...\n", + lchan->tch_mode); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -226,9 +222,9 @@ if (lchan->prim->payload_len == GSM_MACBLOCK_LEN) { l2_len = GSM_MACBLOCK_LEN; /* FACCH */ } else if (lchan->prim->payload_len != l2_len) { - LOGP(DSCHD, LOGL_ERROR, "Primitive has odd length %zu " - "(expected %zu for TCH or %u for FACCH), so dropping...\n", - lchan->prim->payload_len, l2_len, GSM_MACBLOCK_LEN); + LOGP_LCHAND(lchan, LOGL_ERROR, "Primitive has odd length %zu " + "(expected %zu for TCH or %u for FACCH), so dropping...\n", + lchan->prim->payload_len, l2_len, GSM_MACBLOCK_LEN); l1sched_prim_drop(lchan); return -EINVAL; @@ -240,9 +236,9 @@ /* Encode payload */ rc = gsm0503_tch_fr_encode(buffer, lchan->prim->payload, l2_len, 1); if (rc) { - LOGP(DSCHD, LOGL_ERROR, "Failed to encode L2 payload (len=%zu): %s\n", - lchan->prim->payload_len, osmo_hexdump(lchan->prim->payload, - lchan->prim->payload_len)); + LOGP_LCHAND(lchan, LOGL_ERROR, "Failed to encode L2 payload (len=%zu): %s\n", + lchan->prim->payload_len, osmo_hexdump(lchan->prim->payload, + lchan->prim->payload_len)); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -268,8 +264,7 @@ memset(br->burst + 145, 0, 3); /* TB */ br->burst_len = GSM_BURST_LEN; - LOGP(DSCHD, LOGL_DEBUG, "Scheduled %s fn=%u ts=%u burst=%u\n", - lchan_desc->name, br->fn, lchan->ts->index, br->bid); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Scheduled fn=%u burst=%u\n", br->fn, br->bid); /* If we have sent the last (4/4) burst */ if (*mask == 0x0f) { diff --git a/src/host/trxcon/src/sched_lchan_tchh.c b/src/host/trxcon/src/sched_lchan_tchh.c index de9c047..b0bc566 100644 --- a/src/host/trxcon/src/sched_lchan_tchh.c +++ b/src/host/trxcon/src/sched_lchan_tchh.c @@ -36,7 +36,7 @@ #include <osmocom/codec/codec.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> static const uint8_t tch_h0_traffic_block_map[3][4] = { /* B0(0,2,4,6), B1(4,6,8,10), B2(8,10,0,2) */ @@ -182,10 +182,11 @@ BLOCK_FIRST_FN(tch_h1_traffic_block_map); } - LOGP(DSCHD, LOGL_ERROR, "Failed to calculate TDMA " - "frame number of the first burst of %s block, " - "using the current fn=%u\n", facch ? - "FACCH/H" : "TCH/H", last_fn); +#if 0 + LOGP_LCHAND(lchan, LOGL_ERROR, + "Failed to calculate TDMA frame number of the first burst of %s block, " + "using the current fn=%u\n", facch ? "FACCH/H" : "TCH/H", last_fn); +#endif /* Couldn't calculate the first fn, return the last */ return last_fn; @@ -195,19 +196,16 @@ uint32_t fn, uint8_t bid, const sbit_t *bits, const struct l1sched_meas_set *meas) { - const struct l1sched_lchan_desc *lchan_desc; int n_errors = -1, n_bits_total, rc; sbit_t *buffer, *offset; uint8_t l2[128], *mask; size_t l2_len; /* Set up pointers */ - lchan_desc = &l1sched_lchan_desc[lchan->type]; mask = &lchan->rx_burst_mask; buffer = lchan->rx_bursts; - LOGP(DSCHD, LOGL_DEBUG, "Traffic received on %s: fn=%u ts=%u bid=%u\n", - lchan_desc->name, fn, lchan->ts->index, bid); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Traffic received: fn=%u bid=%u\n", fn, bid); if (*mask == 0x00) { /* Align to the first burst */ @@ -268,10 +266,10 @@ * TODO: AMR requires a dedicated loop, * which will be implemented later... */ - LOGP(DSCHD, LOGL_ERROR, "AMR isn't supported yet\n"); + LOGP_LCHAND(lchan, LOGL_ERROR, "AMR isn't supported yet\n"); return -ENOTSUP; default: - LOGP(DSCHD, LOGL_ERROR, "Invalid TCH mode: %u\n", lchan->tch_mode); + LOGP_LCHAND(lchan, LOGL_ERROR, "Invalid TCH mode: %u\n", lchan->tch_mode); return -EINVAL; } @@ -287,8 +285,9 @@ /* Calculate AVG of the measurements (assuming 4 bursts) */ l1sched_lchan_meas_avg(lchan, 4); - LOGP(DSCHD, LOGL_ERROR, "Received bad %s frame (rc=%d, ber=%d/%d) at fn=%u\n", - lchan_desc->name, rc, n_errors, n_bits_total, lchan->meas_avg.fn); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Received bad frame (rc=%d, ber=%d/%d) at fn=%u\n", + rc, n_errors, n_bits_total, lchan->meas_avg.fn); /* Send BFI */ goto bfi; @@ -360,7 +359,6 @@ int tx_tchh_fn(struct l1sched_lchan_state *lchan, struct l1sched_burst_req *br) { - const struct l1sched_lchan_desc *lchan_desc; ubit_t *buffer, *offset; const uint8_t *tsc; uint8_t *mask; @@ -368,7 +366,6 @@ int rc; /* Set up pointers */ - lchan_desc = &l1sched_lchan_desc[lchan->type]; mask = &lchan->tx_burst_mask; buffer = lchan->tx_bursts; @@ -409,15 +406,16 @@ * TODO: AMR requires a dedicated loop, * which will be implemented later... */ - LOGP(DSCHD, LOGL_ERROR, "AMR isn't supported yet, " - "dropping frame...\n"); + LOGP_LCHAND(lchan, LOGL_ERROR, + "AMR isn't supported yet, dropping frame...\n"); /* Forget this primitive */ l1sched_prim_drop(lchan); return -ENOTSUP; default: - LOGP(DSCHD, LOGL_ERROR, "Invalid TCH mode: %u, " - "dropping frame...\n", lchan->tch_mode); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Invalid TCH mode: %u, dropping frame...\n", + lchan->tch_mode); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -428,9 +426,9 @@ if (L1SCHED_PRIM_IS_FACCH(lchan->prim)) { l2_len = GSM_MACBLOCK_LEN; /* FACCH */ } else if (lchan->prim->payload_len != l2_len) { - LOGP(DSCHD, LOGL_ERROR, "Primitive has odd length %zu " - "(expected %zu for TCH or %u for FACCH), so dropping...\n", - lchan->prim->payload_len, l2_len, GSM_MACBLOCK_LEN); + LOGP_LCHAND(lchan, LOGL_ERROR, "Primitive has odd length %zu " + "(expected %zu for TCH or %u for FACCH), so dropping...\n", + lchan->prim->payload_len, l2_len, GSM_MACBLOCK_LEN); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -440,9 +438,9 @@ /* Encode the payload */ rc = gsm0503_tch_hr_encode(buffer, lchan->prim->payload, l2_len); if (rc) { - LOGP(DSCHD, LOGL_ERROR, "Failed to encode L2 payload (len=%zu): %s\n", - lchan->prim->payload_len, osmo_hexdump(lchan->prim->payload, - lchan->prim->payload_len)); + LOGP_LCHAND(lchan, LOGL_ERROR, "Failed to encode L2 payload (len=%zu): %s\n", + lchan->prim->payload_len, osmo_hexdump(lchan->prim->payload, + lchan->prim->payload_len)); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -471,8 +469,7 @@ memset(br->burst + 145, 0, 3); /* TB */ br->burst_len = GSM_BURST_LEN; - LOGP(DSCHD, LOGL_DEBUG, "Scheduled %s fn=%u ts=%u burst=%u\n", - lchan_desc->name, br->fn, lchan->ts->index, br->bid); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Scheduled fn=%u burst=%u\n", br->fn, br->bid); /* In case of a FACCH/H frame, one block less */ if (lchan->ul_facch_blocks) diff --git a/src/host/trxcon/src/sched_lchan_xcch.c b/src/host/trxcon/src/sched_lchan_xcch.c index e677764..0d24866 100644 --- a/src/host/trxcon/src/sched_lchan_xcch.c +++ b/src/host/trxcon/src/sched_lchan_xcch.c @@ -31,24 +31,21 @@ #include <osmocom/coding/gsm0503_coding.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> int rx_data_fn(struct l1sched_lchan_state *lchan, uint32_t fn, uint8_t bid, const sbit_t *bits, const struct l1sched_meas_set *meas) { - const struct l1sched_lchan_desc *lchan_desc; uint8_t l2[GSM_MACBLOCK_LEN], *mask; int n_errors, n_bits_total, rc; sbit_t *buffer, *offset; /* Set up pointers */ - lchan_desc = &l1sched_lchan_desc[lchan->type]; mask = &lchan->rx_burst_mask; buffer = lchan->rx_bursts; - LOGP(DSCHD, LOGL_DEBUG, "Data received on %s: fn=%u ts=%u bid=%u\n", - lchan_desc->name, fn, lchan->ts->index, bid); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Data received: fn=%u bid=%u\n", fn, bid); /* Align to the first burst of a block */ if (*mask == 0x00 && bid != 0) @@ -74,12 +71,11 @@ /* Check for complete set of bursts */ if ((*mask & 0xf) != 0xf) { - LOGP(DSCHD, LOGL_ERROR, "Received incomplete (%s) data frame at " - "fn=%u (%u/%u) for %s\n", - l1sched_burst_mask2str(mask, 4), lchan->meas_avg.fn, - lchan->meas_avg.fn % lchan->ts->mf_layout->period, - lchan->ts->mf_layout->period, - lchan_desc->name); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Received incomplete (%s) data frame at fn=%u (%u/%u)\n", + l1sched_burst_mask2str(mask, 4), lchan->meas_avg.fn, + lchan->meas_avg.fn % lchan->ts->mf_layout->period, + lchan->ts->mf_layout->period); /* NOTE: xCCH has an insane amount of redundancy for error * correction, so even just 2 valid bursts might be enough * to reconstruct some L2 frames. This is why we do not @@ -92,8 +88,9 @@ /* Attempt to decode */ rc = gsm0503_xcch_decode(l2, buffer, &n_errors, &n_bits_total); if (rc) { - LOGP(DSCHD, LOGL_ERROR, "Received bad %s frame (rc=%d, ber=%d/%d) at fn=%u\n", - lchan_desc->name, rc, n_errors, n_bits_total, lchan->meas_avg.fn); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Received bad frame (rc=%d, ber=%d/%d) at fn=%u\n", + rc, n_errors, n_bits_total, lchan->meas_avg.fn); } /* Send a L2 frame to the higher layers */ @@ -105,14 +102,12 @@ int tx_data_fn(struct l1sched_lchan_state *lchan, struct l1sched_burst_req *br) { - const struct l1sched_lchan_desc *lchan_desc; ubit_t *buffer, *offset; const uint8_t *tsc; uint8_t *mask; int rc; /* Set up pointers */ - lchan_desc = &l1sched_lchan_desc[lchan->type]; mask = &lchan->tx_burst_mask; buffer = lchan->tx_bursts; @@ -126,8 +121,9 @@ /* Check the prim payload length */ if (lchan->prim->payload_len != GSM_MACBLOCK_LEN) { - LOGP(DSCHD, LOGL_ERROR, "Primitive has odd length %zu (expected %u), " - "so dropping...\n", lchan->prim->payload_len, GSM_MACBLOCK_LEN); + LOGP_LCHAND(lchan, LOGL_ERROR, + "Primitive has odd length %zu (expected %u), so dropping...\n", + lchan->prim->payload_len, GSM_MACBLOCK_LEN); l1sched_prim_drop(lchan); return -EINVAL; @@ -136,9 +132,9 @@ /* Encode payload */ rc = gsm0503_xcch_encode(buffer, lchan->prim->payload); if (rc) { - LOGP(DSCHD, LOGL_ERROR, "Failed to encode L2 payload (len=%zu): %s\n", - lchan->prim->payload_len, osmo_hexdump(lchan->prim->payload, - lchan->prim->payload_len)); + LOGP_LCHAND(lchan, LOGL_ERROR, "Failed to encode L2 payload (len=%zu): %s\n", + lchan->prim->payload_len, osmo_hexdump(lchan->prim->payload, + lchan->prim->payload_len)); /* Forget this primitive */ l1sched_prim_drop(lchan); @@ -164,8 +160,7 @@ memset(br->burst + 145, 0, 3); /* TB */ br->burst_len = GSM_BURST_LEN; - LOGP(DSCHD, LOGL_DEBUG, "Scheduled %s fn=%u ts=%u burst=%u\n", - lchan_desc->name, br->fn, lchan->ts->index, br->bid); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Scheduled fn=%u burst=%u\n", br->fn, br->bid); /* If we have sent the last (4/4) burst */ if ((*mask & 0x0f) == 0x0f) { diff --git a/src/host/trxcon/src/sched_mframe.c b/src/host/trxcon/src/sched_mframe.c index e8aa439..90b7763 100644 --- a/src/host/trxcon/src/sched_mframe.c +++ b/src/host/trxcon/src/sched_mframe.c @@ -26,6 +26,7 @@ #include <osmocom/gsm/gsm_utils.h> #include <osmocom/bb/l1sched/l1sched.h> +#include <osmocom/bb/l1sched/logging.h> /* Non-combined CCCH */ static const struct l1sched_tdma_frame frame_bcch[51] = { diff --git a/src/host/trxcon/src/sched_prim.c b/src/host/trxcon/src/sched_prim.c index 0b1b0df..33d48de 100644 --- a/src/host/trxcon/src/sched_prim.c +++ b/src/host/trxcon/src/sched_prim.c @@ -31,7 +31,7 @@ #include <osmocom/gsm/protocol/gsm_04_08.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> /** * Initializes a new primitive by allocating memory @@ -54,17 +54,16 @@ /* Determine lchan type */ lchan_type = l1sched_chan_nr2lchan_type(chan_nr, link_id); if (!lchan_type) { - LOGP(DSCH, LOGL_ERROR, "Couldn't determine lchan type " - "for chan_nr=%02x and link_id=%02x\n", chan_nr, link_id); + /* TODO: use proper logging context */ + LOGP(DLGLOBAL, LOGL_ERROR, "Couldn't determine lchan type " + "for chan_nr=%02x and link_id=%02x\n", chan_nr, link_id); return NULL; } /* Allocate a new primitive */ prim = talloc_zero_size(ctx, sizeof(*prim) + pl_len); - if (prim == NULL) { - LOGP(DSCH, LOGL_ERROR, "Failed to allocate memory\n"); + if (prim == NULL) return NULL; - } /* Init primitive header */ prim->payload_len = pl_len; @@ -100,7 +99,7 @@ /* Check whether required timeslot is allocated and configured */ ts = sched->ts[tn]; if (ts == NULL || ts->mf_layout == NULL) { - LOGP(DSCH, LOGL_ERROR, "Timeslot %u isn't configured\n", tn); + LOGP_SCHEDC(sched, LOGL_ERROR, "Timeslot %u isn't configured\n", tn); return NULL; } @@ -196,15 +195,15 @@ /* Inform about the cache usage count */ if (cached && lchan->sacch.mr_cache_usage > 5) { - LOGP(DSCHD, LOGL_NOTICE, "SACCH MR cache usage count=%u > 5 " - "on lchan=%s => ancient measurements, please fix!\n", - lchan->sacch.mr_cache_usage, - l1sched_lchan_desc[lchan->type].name); + LOGP_LCHAND(lchan, LOGL_NOTICE, + "SACCH MR cache usage count=%u > 5 " + "=> ancient measurements, please fix!\n", + lchan->sacch.mr_cache_usage); } - LOGP(DSCHD, LOGL_NOTICE, "Using a %s Measurement Report " - "on lchan=%s\n", (cached ? "cached" : "dummy"), - l1sched_lchan_desc[lchan->type].name); + LOGP_LCHAND(lchan, LOGL_NOTICE, + "Using a %s Measurement Report\n", + cached ? "cached" : "dummy"); return prim; } @@ -271,11 +270,9 @@ break; /* something else was found */ } - LOGP(DSCHD, LOGL_DEBUG, "SACCH MR selection on lchan=%s: " - "mr_tx_last=%d prim_mr=%p prim_nmr=%p\n", - l1sched_lchan_desc[lchan->type].name, - lchan->sacch.mr_tx_last, - prim_mr, prim_nmr); + LOGP_LCHAND(lchan, LOGL_DEBUG, + "SACCH MR selection: mr_tx_last=%d prim_mr=%p prim_nmr=%p\n", + lchan->sacch.mr_tx_last, prim_mr, prim_nmr); /* Prioritize non-MR prim if possible */ if (mr_now && prim_mr) @@ -299,16 +296,14 @@ prim->payload, GSM_MACBLOCK_LEN); lchan->sacch.mr_cache_usage = 0; - LOGP(DSCHD, LOGL_DEBUG, "SACCH MR cache has been updated " - "for lchan=%s\n", l1sched_lchan_desc[lchan->type].name); + LOGP_LCHAND(lchan, LOGL_DEBUG, "SACCH MR cache has been updated\n"); } /* Update the MR transmission state */ lchan->sacch.mr_tx_last = PRIM_IS_MR(prim); - LOGP(DSCHD, LOGL_DEBUG, "SACCH decision on lchan=%s: %s\n", - l1sched_lchan_desc[lchan->type].name, PRIM_IS_MR(prim) ? - "Measurement Report" : "data frame"); + LOGP_LCHAND(lchan, LOGL_DEBUG, "SACCH decision: %s\n", + PRIM_IS_MR(prim) ? "Measurement Report" : "data frame"); return prim; } @@ -592,8 +587,7 @@ /* Assign the current prim */ lchan->prim = prim; - LOGP(DSCHD, LOGL_DEBUG, "Transmitting a dummy / silence frame " - "on lchan=%s\n", l1sched_lchan_desc[chan].name); + LOGP_LCHAND(lchan, LOGL_DEBUG, "Transmitting a dummy / silence frame\n"); return 0; } diff --git a/src/host/trxcon/src/sched_trx.c b/src/host/trxcon/src/sched_trx.c index 443c23d..d44c1ba 100644 --- a/src/host/trxcon/src/sched_trx.c +++ b/src/host/trxcon/src/sched_trx.c @@ -33,7 +33,11 @@ #include <osmocom/core/linuxlist.h> #include <osmocom/bb/l1sched/l1sched.h> -#include <osmocom/bb/trxcon/logging.h> +#include <osmocom/bb/l1sched/logging.h> + +/* Logging categories to be used for common/data messages */ +int l1sched_log_cat_common = DLGLOBAL; +int l1sched_log_cat_data = DLGLOBAL; static int l1sched_cfg_pchan_comb_req(struct l1sched_state *sched, uint8_t tn, enum gsm_phys_chan_config pchan) @@ -150,12 +154,17 @@ l1sched_handle_burst_req(sched, &br[tn]); } -struct l1sched_state *l1sched_alloc(void *ctx, uint32_t fn_advance, void *priv) +void l1sched_logging_init(int log_cat_common, int log_cat_data) +{ + l1sched_log_cat_common = log_cat_common; + l1sched_log_cat_data = log_cat_data; +} + +struct l1sched_state *l1sched_alloc(void *ctx, const struct l1sched_cfg *cfg, + uint32_t fn_advance, void *priv) { struct l1sched_state *sched; - LOGP(DSCH, LOGL_NOTICE, "Init scheduler\n"); - sched = talloc(ctx, struct l1sched_state); if (!sched) return NULL; @@ -167,6 +176,11 @@ .priv = priv, }; + if (cfg->log_prefix == NULL) + sched->log_prefix = talloc_asprintf(sched, "l1sched[0x%p]: ", sched); + else + sched->log_prefix = talloc_strdup(sched, cfg->log_prefix); + return sched; } @@ -177,7 +191,7 @@ if (sched == NULL) return; - LOGP(DSCH, LOGL_NOTICE, "Shutdown scheduler\n"); + LOGP_SCHEDC(sched, LOGL_NOTICE, "Shutdown scheduler\n"); /* Free all potentially allocated timeslots */ for (tn = 0; tn < ARRAY_SIZE(sched->ts); tn++) @@ -194,8 +208,8 @@ if (sched == NULL) return; - LOGP(DSCH, LOGL_NOTICE, "Reset scheduler %s\n", - reset_clock ? "and clock counter" : ""); + LOGP_SCHEDC(sched, LOGL_NOTICE, "Reset scheduler %s\n", + reset_clock ? "and clock counter" : ""); /* Free all potentially allocated timeslots */ for (tn = 0; tn < ARRAY_SIZE(sched->ts); tn++) @@ -210,11 +224,11 @@ { /* Make sure that ts isn't allocated yet */ if (sched->ts[tn] != NULL) { - LOGP(DSCH, LOGL_ERROR, "Timeslot #%u already allocated\n", tn); + LOGP_SCHEDC(sched, LOGL_ERROR, "Timeslot #%u already allocated\n", tn); return NULL; } - LOGP(DSCH, LOGL_NOTICE, "Add a new TDMA timeslot #%u\n", tn); + LOGP_SCHEDC(sched, LOGL_NOTICE, "Add a new TDMA timeslot #%u\n", tn); sched->ts[tn] = talloc_zero(sched, struct l1sched_ts); sched->ts[tn]->sched = sched; @@ -233,7 +247,7 @@ if (ts == NULL) return; - LOGP(DSCH, LOGL_NOTICE, "Delete TDMA timeslot #%u\n", tn); + LOGP_SCHEDC(sched, LOGL_NOTICE, "Delete TDMA timeslot #%u\n", tn); /* Deactivate all logical channels */ l1sched_deactivate_all_lchans(ts); @@ -284,8 +298,9 @@ if (ts->mf_layout->chan_config != config) return -EINVAL; - LOGP(DSCH, LOGL_NOTICE, "(Re)configure TDMA timeslot #%u as %s\n", - tn, ts->mf_layout->name); + LOGP_SCHEDC(sched, LOGL_NOTICE, + "(Re)configure TDMA timeslot #%u as %s\n", + tn, ts->mf_layout->name); /* Init queue primitives for TX */ INIT_LLIST_HEAD(&ts->tx_prims); @@ -405,7 +420,7 @@ /* Prevent NULL-pointer deference */ if (ts == NULL) { - LOGP(DSCH, LOGL_ERROR, "Timeslot isn't configured\n"); + LOGP_SCHEDC(ts->sched, LOGL_ERROR, "Timeslot isn't configured\n"); return -EINVAL; } @@ -437,13 +452,11 @@ return -EINVAL; if (lchan->active) { - LOGP(DSCH, LOGL_ERROR, "Logical channel %s already activated " - "on ts=%d\n", l1sched_lchan_desc[chan].name, ts->index); + LOGP_LCHANC(lchan, LOGL_ERROR, "is already activated\n"); return -EINVAL; } - LOGP(DSCH, LOGL_NOTICE, "Activating lchan=%s " - "on ts=%d\n", l1sched_lchan_desc[chan].name, ts->index); + LOGP_LCHANC(lchan, LOGL_NOTICE, "activating\n"); /* Conditionally allocate memory for bursts */ if (lchan_desc->rx_fn && lchan_desc->burst_buf_size > 0) { @@ -473,12 +486,12 @@ /* Print some TDMA statistics for Downlink */ if (l1sched_lchan_desc[lchan->type].rx_fn && lchan->active) { - LOGP(DSCH, LOGL_DEBUG, "TDMA statistics for lchan=%s on ts=%u: " - "%lu DL frames have been processed, " - "%lu lost (compensated), last fn=%u\n", - l1sched_lchan_desc[lchan->type].name, lchan->ts->index, - lchan->tdma.num_proc, lchan->tdma.num_lost, - lchan->tdma.last_proc); + LOGP_LCHANC(lchan, LOGL_DEBUG, "TDMA statistics: " + "%lu DL frames have been processed, " + "%lu lost (compensated), last fn=%u\n", + lchan->tdma.num_proc, + lchan->tdma.num_lost, + lchan->tdma.last_proc); } /* Reset internal state variables */ @@ -526,13 +539,11 @@ return -EINVAL; if (!lchan->active) { - LOGP(DSCH, LOGL_ERROR, "Logical channel %s already deactivated " - "on ts=%d\n", l1sched_lchan_desc[chan].name, ts->index); + LOGP_LCHANC(lchan, LOGL_ERROR, "is already deactivated\n"); return -EINVAL; } - LOGP(DSCH, LOGL_DEBUG, "Deactivating lchan=%s " - "on ts=%d\n", l1sched_lchan_desc[chan].name, ts->index); + LOGP_LCHANC(lchan, LOGL_DEBUG, "deactivating\n"); /* Reset internal state, free memory */ l1sched_reset_lchan(lchan); @@ -547,8 +558,9 @@ { struct l1sched_lchan_state *lchan; - LOGP(DSCH, LOGL_DEBUG, "Deactivating all logical channels " - "on ts=%d\n", ts->index); + LOGP_SCHEDC(ts->sched, LOGL_DEBUG, + "Deactivating all logical channels on ts=%d\n", + ts->index); llist_for_each_entry(lchan, &ts->lchans, list) { /* Omit inactive channels */ @@ -660,22 +672,23 @@ if (elapsed < 0) { /* This burst has already been substituted by a dummy burst (all bits set to zero), * so better drop it. Otherwise we risk to get undefined behavior in handler(). */ - LOGP(DSCHD, LOGL_ERROR, "(%s) Rx burst with fn=%u older than the last " - "processed fn=%u (see OS#4658) => dropping\n", - l1sched_lchan_desc[lchan->type].name, - fn, lchan->tdma.last_proc); + LOGP_LCHAND(lchan, LOGL_ERROR, "Rx burst with fn=%u older than the last " + "processed fn=%u (see OS#4658) => dropping\n", + fn, lchan->tdma.last_proc); return -EALREADY; } /* Check how many frames we (potentially) need to compensate */ if (elapsed > mf->period) { - LOGP(DSCHD, LOGL_NOTICE, "Too many (>%u) contiguous TDMA frames elapsed (%d) " - "since the last processed fn=%u (current %u)\n", - mf->period, elapsed, lchan->tdma.last_proc, fn); + LOGP_LCHANC(lchan, LOGL_NOTICE, + "Too many (>%u) contiguous TDMA frames elapsed (%d) " + "since the last processed fn=%u (current %u)\n", + mf->period, elapsed, lchan->tdma.last_proc, fn); return -EIO; } else if (elapsed == 0) { - LOGP(DSCHD, LOGL_ERROR, "No TDMA frames elapsed since the last processed " - "fn=%u, must be a bug?\n", lchan->tdma.last_proc); + LOGP_LCHANC(lchan, LOGL_ERROR, + "No TDMA frames elapsed since the last processed " + "fn=%u, must be a bug?\n", lchan->tdma.last_proc); return -EIO; } @@ -692,8 +705,9 @@ if (fp->dl_chan != lchan->type) continue; - LOGP(DSCHD, LOGL_NOTICE, "Substituting lost TDMA frame %u on %s\n", - fake_meas.fn, l1sched_lchan_desc[lchan->type].name); + LOGP_LCHANC(lchan, LOGL_NOTICE, + "Substituting lost TDMA frame fn=%u\n", + fake_meas.fn); handler(lchan, fake_meas.fn, fp->dl_bid, bits, &fake_meas); @@ -722,8 +736,8 @@ /* Check whether required timeslot is allocated and configured */ ts = sched->ts[tn]; if (ts == NULL || ts->mf_layout == NULL) { - LOGP(DSCHD, LOGL_DEBUG, "TDMA timeslot #%u isn't configured, " - "ignoring burst...\n", tn); + LOGP_SCHEDD(sched, LOGL_DEBUG, + "Timeslot #%u isn't configured, ignoring burst...\n", tn); return -EINVAL; } @@ -770,8 +784,9 @@ * As a consequence, subst_frame_loss() will be unable to compensate * one (potentionally lost) Downlink burst. On practice, it would * happen once in 4615 * 10e-6 * (2 ^ 32 - 1) seconds or ~6 years. */ - LOGP(DSCHD, LOGL_NOTICE, "Too many TDMA frames have been processed. " - "Are you running trxcon for more than 6 years?!?\n"); + LOGP_LCHAND(lchan, LOGL_NOTICE, + "Too many TDMA frames have been processed. " + "Are you running trxcon for more than 6 years?!?\n"); lchan->tdma.num_proc = 1; } diff --git a/src/host/trxcon/src/trxcon.c b/src/host/trxcon/src/trxcon.c index df411c3..86d4c49 100644 --- a/src/host/trxcon/src/trxcon.c +++ b/src/host/trxcon/src/trxcon.c @@ -333,6 +333,9 @@ trxcon, LOGL_DEBUG, NULL); OSMO_ASSERT(trxcon->fi != NULL); + /* Logging context to be used by both l1ctl and l1sched modules */ + trxcon->log_prefix = talloc_asprintf(trxcon, "%s: ", osmo_fsm_inst_name(trxcon->fi)); + /* Init transceiver interface */ trxcon->trx = trx_if_open(trxcon, app_data.trx_bind_ip, @@ -344,7 +347,11 @@ } /* Init scheduler */ - trxcon->sched = l1sched_alloc(trxcon, app_data.trx_fn_advance, trxcon); + const struct l1sched_cfg sched_cfg = { + .log_prefix = trxcon->log_prefix, + }; + + trxcon->sched = l1sched_alloc(trxcon, &sched_cfg, app_data.trx_fn_advance, trxcon); if (trxcon->sched == NULL) { trxcon_inst_free(trxcon); return NULL; @@ -530,6 +537,7 @@ /* Init logging system */ trx_log_init(tall_trxcon_ctx, app_data.debug_mask); + l1sched_logging_init(DSCH, DSCHD); /* Configure pretty logging */ log_set_print_extended_timestamp(osmo_stderr_target, 1); -- To view, visit https://gerrit.osmocom.org/c/osmocom-bb/+/28744 To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings Gerrit-Project: osmocom-bb Gerrit-Branch: master Gerrit-Change-Id: I26da1a506b02502a3a6a887533c35fb09c13c429 Gerrit-Change-Number: 28744 Gerrit-PatchSet: 5 Gerrit-Owner: fixeria &lt;vyanitskiy(a)sysmocom.de&gt; Gerrit-Reviewer: Jenkins Builder Gerrit-Reviewer: fixeria &lt;vyanitskiy(a)sysmocom.de&gt; Gerrit-Reviewer: pespin &lt;pespin(a)sysmocom.de&gt; Gerrit-CC: laforge &lt;laforge(a)osmocom.org&gt; Gerrit-MessageType: merged