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
This commit is contained in:
Vadim Yanitskiy 2022-07-22 07:21:11 +07:00
parent 4a4bc0ed6e
commit 8f9e9806e6
16 changed files with 253 additions and 201 deletions

View File

@ -1,3 +1,4 @@
noinst_HEADERS = \
l1sched.h \
logging.h \
$(NULL)

View File

@ -346,6 +346,12 @@ struct l1sched_ts_prim_rach {
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_state {
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 @@ const struct l1sched_tdma_multiframe *l1sched_mframe_layout(
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);

View File

@ -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)

View File

@ -22,6 +22,9 @@ enum trxcon_fsm_events {
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 */

View File

@ -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 @@ static void l1sched_clck_tick(void *data)
/* 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 @@ static void l1sched_clck_tick(void *data)
/* 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 @@ int l1sched_clck_handle(struct l1sched_state *sched, uint32_t fn)
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 @@ int l1sched_clck_handle(struct l1sched_state *sched, uint32_t fn)
/* 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) {

View File

@ -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 @@ size_t l1sched_bad_frame_ind(uint8_t *l2, struct l1sched_lchan_state *lchan)
/* 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;
}
}

View File

@ -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 @@ int rx_pdtch_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ int rx_pdtch_fn(struct l1sched_lchan_state *lchan,
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 rx_pdtch_fn(struct l1sched_lchan_state *lchan,
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 @@ int tx_pdtch_fn(struct l1sched_lchan_state *lchan,
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 @@ send_burst:
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) {

View File

@ -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 @@ int tx_rach_fn(struct l1sched_lchan_state *lchan,
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 @@ int tx_rach_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ int tx_rach_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ int tx_rach_fn(struct l1sched_lchan_state *lchan,
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);

View File

@ -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 @@ int rx_sch_fn(struct l1sched_lchan_state *lchan,
/* 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;
}

View File

@ -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 @@ int rx_tchf_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ int rx_tchf_fn(struct l1sched_lchan_state *lchan,
* 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 @@ int rx_tchf_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ bfi:
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 tx_tchf_fn(struct l1sched_lchan_state *lchan,
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 @@ int tx_tchf_fn(struct l1sched_lchan_state *lchan,
* 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 @@ int tx_tchf_fn(struct l1sched_lchan_state *lchan,
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 @@ int tx_tchf_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ send_burst:
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) {

View File

@ -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 @@ uint32_t l1sched_tchh_block_dl_first_fn(enum l1sched_lchan_type chan,
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 @@ int rx_tchh_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);
if (*mask == 0x00) {
/* Align to the first burst */
@ -268,10 +266,10 @@ int rx_tchh_fn(struct l1sched_lchan_state *lchan,
* 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 @@ int rx_tchh_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ bfi:
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 tx_tchh_fn(struct l1sched_lchan_state *lchan,
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 @@ int tx_tchh_fn(struct l1sched_lchan_state *lchan,
* 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 @@ int tx_tchh_fn(struct l1sched_lchan_state *lchan,
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 @@ int tx_tchh_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ send_burst:
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)

View File

@ -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 @@ int rx_data_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ int rx_data_fn(struct l1sched_lchan_state *lchan,
/* 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 rx_data_fn(struct l1sched_lchan_state *lchan,
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 @@ int tx_data_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ int tx_data_fn(struct l1sched_lchan_state *lchan,
/* 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 @@ send_burst:
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) {

View File

@ -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] = {

View File

@ -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 @@ static struct l1sched_ts_prim *prim_alloc(void *ctx, size_t pl_len,
/* 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 @@ struct l1sched_ts_prim *l1sched_prim_push(struct l1sched_state *sched,
/* 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 @@ static struct l1sched_ts_prim *prim_compose_mr(struct l1sched_lchan_state *lchan
/* 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 @@ static struct l1sched_ts_prim *prim_dequeue_sacch(struct llist_head *queue,
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 @@ static struct l1sched_ts_prim *prim_dequeue_sacch(struct llist_head *queue,
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 @@ int l1sched_prim_dummy(struct l1sched_lchan_state *lchan)
/* 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;
}

View File

@ -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 @@ static void sched_frame_clck_cb(struct l1sched_state *sched)
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 @@ struct l1sched_state *l1sched_alloc(void *ctx, uint32_t fn_advance, void *priv)
.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 @@ void l1sched_free(struct l1sched_state *sched)
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 @@ void l1sched_reset(struct l1sched_state *sched, bool reset_clock)
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 @@ struct l1sched_ts *l1sched_add_ts(struct l1sched_state *sched, int tn)
{
/* 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 @@ void l1sched_del_ts(struct l1sched_state *sched, int tn)
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 @@ int l1sched_configure_ts(struct l1sched_state *sched, int tn,
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 @@ int l1sched_set_lchans(struct l1sched_ts *ts, uint8_t chan_nr,
/* 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 @@ int l1sched_activate_lchan(struct l1sched_ts *ts, enum l1sched_lchan_type chan)
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 @@ static void l1sched_reset_lchan(struct l1sched_lchan_state *lchan)
/* 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 @@ int l1sched_deactivate_lchan(struct l1sched_ts *ts, enum l1sched_lchan_type chan
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 @@ void l1sched_deactivate_all_lchans(struct l1sched_ts *ts)
{
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 @@ static int subst_frame_loss(struct l1sched_lchan_state *lchan,
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 @@ static int subst_frame_loss(struct l1sched_lchan_state *lchan,
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 @@ int l1sched_handle_rx_burst(struct l1sched_state *sched, uint8_t tn,
/* 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 @@ int l1sched_handle_rx_burst(struct l1sched_state *sched, uint8_t tn,
* 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;
}

View File

@ -333,6 +333,9 @@ struct trxcon_inst *trxcon_inst_alloc(void *ctx)
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 @@ struct trxcon_inst *trxcon_inst_alloc(void *ctx)
}
/* 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 @@ int main(int argc, char **argv)
/* 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);