From 7b9c8ea175147e5609d02f40b77c137b563013e9 Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Sat, 16 May 2020 17:54:16 +0300 Subject: log: Fix "Paging request failed" logging level "Paging request failed" message can be logged e.g. when we're already paging this subscriber which means we get hundreds of these messages in a perfectly normal situation. Let's demote this to INFO and adjust the wording. Change-Id: I97214796906ac599338e87b2b4b5465ab6b2447a --- src/osmo-bsc/osmo_bsc_bssap.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/osmo-bsc/osmo_bsc_bssap.c b/src/osmo-bsc/osmo_bsc_bssap.c index 6f5aaa801..ddebb6a7d 100644 --- a/src/osmo-bsc/osmo_bsc_bssap.c +++ b/src/osmo-bsc/osmo_bsc_bssap.c @@ -140,7 +140,7 @@ page_subscriber(struct bsc_msc_data *msc, struct gsm_bts *bts, ret = bsc_grace_paging_request(msc->network->bsc_data->rf_ctrl->policy, subscr, chan_needed, msc, bts); if (ret == 0) - LOGP(DMSC, LOGL_ERROR, "Paging request failed: BTS: %d IMSI: '%s' TMSI: '0x%x/%u' LAC: 0x%x\n", + LOGP(DMSC, LOGL_INFO, "Paging request failed or repeated paging: BTS: %d IMSI: '%s' TMSI: '0x%x/%u' LAC: 0x%x\n", bts->nr, mi_string, tmsi, tmsi, lac); /* the paging code has grabbed its own references */ -- cgit v1.2.3 From 62766a595d7d51f20a7de6fd2aa8686535101881 Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Sat, 16 May 2020 17:56:05 +0300 Subject: log: Adjust "new SIGTRAN connection" logging level The "new SIGTRAN connection" message is sent on every new transaction between an MS and MSC, i.e. A LOT during normal operation. Let's demote it to INFO and clarify that this is about SCCP connection instead of a generic SIGTRAN term. Change-Id: I711b70ae84aa98f43ea3f807ea5c8464b71ca6bb --- src/osmo-bsc/osmo_bsc_sigtran.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/osmo-bsc/osmo_bsc_sigtran.c b/src/osmo-bsc/osmo_bsc_sigtran.c index 3871682f0..d36c85dd9 100644 --- a/src/osmo-bsc/osmo_bsc_sigtran.c +++ b/src/osmo-bsc/osmo_bsc_sigtran.c @@ -304,7 +304,7 @@ enum bsc_con osmo_bsc_sigtran_new_conn(struct gsm_subscriber_connection *conn, s ss7 = osmo_ss7_instance_find(msc->a.cs7_instance); OSMO_ASSERT(ss7); - LOGP(DMSC, LOGL_NOTICE, "Initializing resources for new SIGTRAN connection to MSC: %s...\n", + LOGP(DMSC, LOGL_INFO, "Initializing resources for new SCCP connection to MSC: %s...\n", osmo_sccp_addr_name(ss7, &msc->a.msc_addr)); if (a_reset_conn_ready(msc) == false) { @@ -350,7 +350,7 @@ int osmo_bsc_sigtran_open_conn(struct gsm_subscriber_connection *conn, struct ms LOGP(DMSC, LOGL_DEBUG, "Allocated new connection id: %d\n", conn->sccp.conn_id); ss7 = osmo_ss7_instance_find(msc->a.cs7_instance); OSMO_ASSERT(ss7); - LOGP(DMSC, LOGL_NOTICE, "Opening new SIGTRAN connection (id=%i) to MSC: %s\n", conn_id, + LOGP(DMSC, LOGL_INFO, "Opening new SCCP connection (id=%i) to MSC: %s\n", conn_id, osmo_sccp_addr_name(ss7, &msc->a.msc_addr)); rc = osmo_sccp_tx_conn_req_msg(msc->a.sccp_user, conn_id, &msc->a.bsc_addr, -- cgit v1.2.3 From 56e151a589c465358cc6c2b205f707505e38c1d8 Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Sat, 16 May 2020 18:05:19 +0300 Subject: bssmap: Ignore repeated BSSMAP RESET ACK messages. We're sending multiple RESET messages to establish a conection with an MSC and MSC can (and often will) respond with multiple RESET ACK messages. We should not treat this as an ERROR as it used to be in the original code. Change-Id: I109d638d5167e24f0357e3541415b9e7269aa5d1 --- src/osmo-bsc/a_reset.c | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/osmo-bsc/a_reset.c b/src/osmo-bsc/a_reset.c index f990e630f..713be86fb 100644 --- a/src/osmo-bsc/a_reset.c +++ b/src/osmo-bsc/a_reset.c @@ -103,6 +103,9 @@ static void fsm_conn_cb(struct osmo_fsm_inst *fi, uint32_t event, void *data) case EV_N_CONNECT: reset_ctx->conn_loss_counter = 0; break; + case EV_RESET_ACK: + LOGPFSML(fi, LOGL_INFO, "Received a duplicated BSSMAP RESET ACK, ignoring\n"); + break; } } @@ -140,7 +143,7 @@ static struct osmo_fsm_state reset_fsm_states[] = { .onenter = fsm_disc_onenter_cb, }, [ST_CONN] = { - .in_event_mask = (1 << EV_N_DISCONNECT) | (1 << EV_N_CONNECT), + .in_event_mask = (1 << EV_N_DISCONNECT) | (1 << EV_N_CONNECT) | (1 << EV_RESET_ACK), .out_state_mask = (1 << ST_DISC) | (1 << ST_CONN), .name = "CONN", .action = fsm_conn_cb, -- cgit v1.2.3 From 66a607ce2ba623a50d0ecc729f2083e79d0f9b09 Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Sat, 16 May 2020 18:09:57 +0300 Subject: log: Demote "CHAN RQD: reason" to INFO The "CHAN RQD: reason" message is purely informational and is a part of normal operation. Nothing to NOTICE there. Let's demote this to INFO. Change-Id: I325f2beb3248ed8eb25d1d8494c3868c5be4b758 --- src/osmo-bsc/abis_rsl.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/osmo-bsc/abis_rsl.c b/src/osmo-bsc/abis_rsl.c index a5e5f5140..dd2ea3f20 100644 --- a/src/osmo-bsc/abis_rsl.c +++ b/src/osmo-bsc/abis_rsl.c @@ -1369,7 +1369,7 @@ static int rsl_rx_chan_rqd(struct msgb *msg) /* Determine channel request cause code */ chreq_reason = get_reason_by_chreq(rqd_ref->ra, bts->network->neci); - LOG_BTS(bts, DRSL, LOGL_NOTICE, "CHAN RQD: reason: %s (ra=0x%02x, neci=0x%02x, chreq_reason=0x%02x)\n", + LOG_BTS(bts, DRSL, LOGL_INFO, "CHAN RQD: reason: %s (ra=0x%02x, neci=0x%02x, chreq_reason=0x%02x)\n", get_value_string(gsm_chreq_descs, chreq_reason), rqd_ref->ra, bts->network->neci, chreq_reason); /* Handle PDCH related rach requests (in case of BSC-co-located-PCU */ -- cgit v1.2.3 From c73130d57298dec9dec2254c0275e7a381ab84c4 Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Mon, 11 May 2020 00:30:11 +0300 Subject: stats: Add counters and gauges for BORKEN lchans/TS Now we can monitor the situation with the BORKEN lchans and TS in our BTS's over time. Change-Id: I427bbe1613a0e92bff432a7d76592fe50f620ebe --- include/osmocom/bsc/gsm_data.h | 50 +++++++++++++++++++++++++++++++++++- src/osmo-bsc/bsc_vty.c | 5 ++-- src/osmo-bsc/gsm_data.c | 2 ++ src/osmo-bsc/lchan_fsm.c | 32 ++++++++++++++++++++++++ src/osmo-bsc/timeslot_fsm.c | 57 +++++++++++++++++++++++++++++++++++++++--- 5 files changed, 139 insertions(+), 7 deletions(-) diff --git a/include/osmocom/bsc/gsm_data.h b/include/osmocom/bsc/gsm_data.h index 17da79d43..aeeb58d71 100644 --- a/include/osmocom/bsc/gsm_data.h +++ b/include/osmocom/bsc/gsm_data.h @@ -1396,7 +1396,7 @@ static inline struct gsm_bts *conn_get_bts(struct gsm_subscriber_connection *con void conn_update_ms_power_class(struct gsm_subscriber_connection *conn, uint8_t power_class); void lchan_update_ms_power_ctrl_level(struct gsm_lchan *lchan, int ms_power_dbm); -enum { +enum bts_counter_id { BTS_CTR_CHREQ_TOTAL, BTS_CTR_CHREQ_NO_CHANNEL, BTS_CTR_CHAN_RF_FAIL, @@ -1417,6 +1417,28 @@ enum { BTS_CTR_RSL_UNKNOWN, BTS_CTR_RSL_IPA_NACK, BTS_CTR_MODE_MODIFY_NACK, + BTS_CTR_LCHAN_BORKEN_FROM_UNUSED, + BTS_CTR_LCHAN_BORKEN_FROM_WAIT_ACTIV_ACK, + BTS_CTR_LCHAN_BORKEN_FROM_WAIT_RF_RELEASE_ACK, + BTS_CTR_LCHAN_BORKEN_FROM_BORKEN, + BTS_CTR_LCHAN_BORKEN_FROM_UNKNOWN, + BTS_CTR_LCHAN_BORKEN_EV_CHAN_ACTIV_ACK, + BTS_CTR_LCHAN_BORKEN_EV_CHAN_ACTIV_NACK, + BTS_CTR_LCHAN_BORKEN_EV_RF_CHAN_REL_ACK, + BTS_CTR_LCHAN_BORKEN_EV_VTY, + BTS_CTR_LCHAN_BORKEN_EV_CLEANUP, + BTS_CTR_TS_BORKEN_FROM_NOT_INITIALIZED, + BTS_CTR_TS_BORKEN_FROM_UNUSED, + BTS_CTR_TS_BORKEN_FROM_WAIT_PDCH_ACT, + BTS_CTR_TS_BORKEN_FROM_PDCH, + BTS_CTR_TS_BORKEN_FROM_WAIT_PDCH_DEACT, + BTS_CTR_TS_BORKEN_FROM_IN_USE, + BTS_CTR_TS_BORKEN_FROM_BORKEN, + BTS_CTR_TS_BORKEN_FROM_UNKNOWN, + BTS_CTR_TS_BORKEN_EV_LCHAN_REQUESTED, + BTS_CTR_TS_BORKEN_EV_LCHAN_UNUSED, + BTS_CTR_TS_BORKEN_EV_PDCH_ACT_ACK, + BTS_CTR_TS_BORKEN_EV_CLEANUP, }; static const struct rate_ctr_desc bts_ctr_description[] = { @@ -1441,6 +1463,30 @@ static const struct rate_ctr_desc bts_ctr_description[] = { [BTS_CTR_RSL_UNKNOWN] = {"rsl:unknown", "Number of unknown/unsupported RSL messages received from BTS"}, [BTS_CTR_RSL_IPA_NACK] = {"rsl:ipa_nack", "Number of IPA (RTP/dyn-PDCH) related NACKs received from BTS"}, [BTS_CTR_MODE_MODIFY_NACK] = {"chan:mode_modify_nack", "Number of Channel Mode Modify NACKs received from BTS"}, + + /* lchan/TS BORKEN state counters */ + [BTS_CTR_LCHAN_BORKEN_FROM_UNUSED] = {"lchan_borken:from_state:unused", "Transitions from lchan UNUSED state to BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_FROM_WAIT_ACTIV_ACK] = {"lchan_borken:from_state:wait_activ_ack", "Transitions from lchan WAIT_ACTIV_ACK state to BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_FROM_WAIT_RF_RELEASE_ACK] = {"lchan_borken:from_state:wait_rf_release_ack", "Transitions from lchan WAIT_RF_RELEASE_ACK state to BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_FROM_BORKEN] = {"lchan_borken:from_state:borken", "Transitions from lchan BORKEN state to BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_FROM_UNKNOWN] = {"lchan_borken:from_state:unknown", "Transitions from an unknown lchan state to BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_EV_CHAN_ACTIV_ACK] = {"lchan_borken:event:chan_activ_ack", "CHAN_ACTIV_ACK received in the lchan BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_EV_CHAN_ACTIV_NACK] = {"lchan_borken:event:chan_activ_nack", "CHAN_ACTIV_NACK received in the lchan BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_EV_RF_CHAN_REL_ACK] = {"lchan_borken:event:rf_chan_rel_ack", "RF_CHAN_REL_ACK received in the lchan BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_EV_VTY] = {"lchan_borken:event:vty", "VTY commands received in the lchan BORKEN state"}, + [BTS_CTR_LCHAN_BORKEN_EV_CLEANUP] = {"lchan_borken:event:cleanup", "lchan in a BORKEN state is cleaned up (BTS shuts down?)"}, + [BTS_CTR_TS_BORKEN_FROM_NOT_INITIALIZED] = {"ts_borken:from_state:not_initialized", "Transitions from TS NOT_INITIALIZED state to BORKEN state"}, + [BTS_CTR_TS_BORKEN_FROM_UNUSED] = {"ts_borken:from_state:unused", "Transitions from TS UNUSED state to BORKEN state"}, + [BTS_CTR_TS_BORKEN_FROM_WAIT_PDCH_ACT] = {"ts_borken:from_state:wait_pdch_act", "Transitions from TS WAIT_PDCH_ACT state to BORKEN state"}, + [BTS_CTR_TS_BORKEN_FROM_PDCH] = {"ts_borken:from_state:pdch", "Transitions from TS PDCH state to BORKEN state"}, + [BTS_CTR_TS_BORKEN_FROM_WAIT_PDCH_DEACT] = {"ts_borken:from_state:wait_pdch_deact", "Transitions from TS WAIT_PDCH_DEACT state to BORKEN state"}, + [BTS_CTR_TS_BORKEN_FROM_IN_USE] = {"ts_borken:from_state:in_use", "Transitions from TS IN_USE state to BORKEN state"}, + [BTS_CTR_TS_BORKEN_FROM_BORKEN] = {"ts_borken:from_state:borken", "Transitions from TS BORKEN state to BORKEN state"}, + [BTS_CTR_TS_BORKEN_FROM_UNKNOWN] = {"ts_borken:from_state:unknown", "Transitions from an unknown TS state to BORKEN state"}, + [BTS_CTR_TS_BORKEN_EV_LCHAN_REQUESTED] = {"ts_borken:event:lchan_requested", "LCHAN_REQUESTED received in the TS BORKEN state"}, + [BTS_CTR_TS_BORKEN_EV_LCHAN_UNUSED] = {"ts_borken:event:lchan_unused", "LCHAN_UNUSED received in the TS BORKEN state"}, + [BTS_CTR_TS_BORKEN_EV_PDCH_ACT_ACK] = {"ts_borken:event:pdch_act_ack", "PDCH_ACT_ACK received in the TS BORKEN state"}, + [BTS_CTR_TS_BORKEN_EV_CLEANUP] = {"ts_borken:event:cleanup", "TS in a BORKEN state is cleaned up (BTS shuts down?)"}, }; static const struct rate_ctr_group_desc bts_ctrg_desc = { @@ -1474,6 +1520,8 @@ enum { BTS_STAT_RACH_ACCESS, BTS_STAT_OML_CONNECTED, BTS_STAT_RSL_CONNECTED, + BTS_STAT_LCHAN_BORKEN, + BTS_STAT_TS_BORKEN, }; enum { diff --git a/src/osmo-bsc/bsc_vty.c b/src/osmo-bsc/bsc_vty.c index 30f685faa..d699cf7ba 100644 --- a/src/osmo-bsc/bsc_vty.c +++ b/src/osmo-bsc/bsc_vty.c @@ -5018,9 +5018,10 @@ DEFUN_HIDDEN(lchan_set_borken, lchan_set_borken_cmd, return CMD_WARNING; } } else { - if (lchan->fi->state == LCHAN_ST_BORKEN) + if (lchan->fi->state == LCHAN_ST_BORKEN) { + rate_ctr_inc(&lchan->ts->trx->bts->bts_ctrs->ctr[BTS_CTR_LCHAN_BORKEN_EV_VTY]); osmo_fsm_inst_state_chg(lchan->fi, LCHAN_ST_UNUSED, 0, 0); - else { + } else { vty_out(vty, "%% lchan is in state %s, only lchans that are in state %s may be moved to state %s manually%s", osmo_fsm_state_name(lchan->fi->fsm, lchan->fi->state), diff --git a/src/osmo-bsc/gsm_data.c b/src/osmo-bsc/gsm_data.c index 2847f388f..c34f06cb1 100644 --- a/src/osmo-bsc/gsm_data.c +++ b/src/osmo-bsc/gsm_data.c @@ -392,6 +392,8 @@ static const struct osmo_stat_item_desc bts_stat_desc[] = { { "rach_access", "RACH slots with access bursts in them", "%", 16, 0 }, { "oml_connected", "Number of OML links connected", "", 16, 0 }, { "rsl_connected", "Number of RSL links connected", "", 16, 0 }, + { "lchan_borken", "Number of lchans in the BORKEN state", "", 16, 0 }, + { "ts_borken", "Number of timeslots in the BORKEN state", "", 16, 0 }, }; static const struct osmo_stat_item_group_desc bts_statg_desc = { diff --git a/src/osmo-bsc/lchan_fsm.c b/src/osmo-bsc/lchan_fsm.c index fc8cd3fd8..ad37e9e07 100644 --- a/src/osmo-bsc/lchan_fsm.c +++ b/src/osmo-bsc/lchan_fsm.c @@ -1071,6 +1071,28 @@ static void lchan_fsm_wait_rf_release_ack(struct osmo_fsm_inst *fi, uint32_t eve static void lchan_fsm_borken_onenter(struct osmo_fsm_inst *fi, uint32_t prev_state) { struct gsm_lchan *lchan = lchan_fi_lchan(fi); + enum bts_counter_id ctr; + switch (prev_state) { + case LCHAN_ST_UNUSED: + ctr = BTS_CTR_LCHAN_BORKEN_FROM_UNUSED; + break; + case LCHAN_ST_WAIT_ACTIV_ACK: + ctr = BTS_CTR_LCHAN_BORKEN_FROM_WAIT_ACTIV_ACK; + break; + case LCHAN_ST_WAIT_RF_RELEASE_ACK: + ctr = BTS_CTR_LCHAN_BORKEN_FROM_WAIT_RF_RELEASE_ACK; + break; + case LCHAN_ST_BORKEN: + ctr = BTS_CTR_LCHAN_BORKEN_FROM_BORKEN; + break; + default: + ctr = BTS_CTR_LCHAN_BORKEN_FROM_UNKNOWN; + } + rate_ctr_inc(&lchan->ts->trx->bts->bts_ctrs->ctr[ctr]); + if (prev_state != LCHAN_ST_BORKEN) + osmo_stat_item_inc(lchan->ts->trx->bts->bts_statg->items[BTS_STAT_LCHAN_BORKEN], 1); + + /* The actual action besides all the beancounting above */ lchan_reset(lchan); } @@ -1081,6 +1103,8 @@ static void lchan_fsm_borken(struct osmo_fsm_inst *fi, uint32_t event, void *dat case LCHAN_EV_RSL_CHAN_ACTIV_ACK: /* A late Chan Activ ACK? Release. */ + rate_ctr_inc(&lchan->ts->trx->bts->bts_ctrs->ctr[BTS_CTR_LCHAN_BORKEN_EV_CHAN_ACTIV_ACK]); + osmo_stat_item_dec(lchan->ts->trx->bts->bts_statg->items[BTS_STAT_LCHAN_BORKEN], 1); lchan->release.in_error = true; lchan->release.rsl_error_cause = RSL_ERR_INTERWORKING; lchan_fsm_state_chg(LCHAN_ST_WAIT_RF_RELEASE_ACK); @@ -1088,11 +1112,15 @@ static void lchan_fsm_borken(struct osmo_fsm_inst *fi, uint32_t event, void *dat case LCHAN_EV_RSL_CHAN_ACTIV_NACK: /* A late Chan Activ NACK? Ok then, unused. */ + rate_ctr_inc(&lchan->ts->trx->bts->bts_ctrs->ctr[BTS_CTR_LCHAN_BORKEN_EV_CHAN_ACTIV_NACK]); + osmo_stat_item_dec(lchan->ts->trx->bts->bts_statg->items[BTS_STAT_LCHAN_BORKEN], 1); lchan_fsm_state_chg(LCHAN_ST_UNUSED); return; case LCHAN_EV_RSL_RF_CHAN_REL_ACK: /* A late Release ACK? */ + rate_ctr_inc(&lchan->ts->trx->bts->bts_ctrs->ctr[BTS_CTR_LCHAN_BORKEN_EV_RF_CHAN_REL_ACK]); + osmo_stat_item_dec(lchan->ts->trx->bts->bts_statg->items[BTS_STAT_LCHAN_BORKEN], 1); lchan->release.in_error = true; lchan->release.rsl_error_cause = RSL_ERR_INTERWORKING; lchan_fsm_state_chg(LCHAN_ST_WAIT_AFTER_ERROR); @@ -1384,6 +1412,10 @@ exit_release_handler: void lchan_fsm_cleanup(struct osmo_fsm_inst *fi, enum osmo_fsm_term_cause cause) { struct gsm_lchan *lchan = lchan_fi_lchan(fi); + if (lchan->fi->state == LCHAN_ST_BORKEN) { + rate_ctr_inc(&lchan->ts->trx->bts->bts_ctrs->ctr[BTS_CTR_LCHAN_BORKEN_EV_CLEANUP]); + osmo_stat_item_dec(lchan->ts->trx->bts->bts_statg->items[BTS_STAT_LCHAN_BORKEN], 1); + } lchan_reset(lchan); if (lchan->last_error) { talloc_free(lchan->last_error); diff --git a/src/osmo-bsc/timeslot_fsm.c b/src/osmo-bsc/timeslot_fsm.c index f8adfb6c7..5bf182ea2 100644 --- a/src/osmo-bsc/timeslot_fsm.c +++ b/src/osmo-bsc/timeslot_fsm.c @@ -654,6 +654,40 @@ static void ts_fsm_in_use(struct osmo_fsm_inst *fi, uint32_t event, void *data) } } +static void ts_fsm_borken_onenter(struct osmo_fsm_inst *fi, uint32_t prev_state) +{ + struct gsm_bts_trx_ts *ts = ts_fi_ts(fi); + enum bts_counter_id ctr; + switch (prev_state) { + case TS_ST_NOT_INITIALIZED: + ctr = BTS_CTR_TS_BORKEN_FROM_NOT_INITIALIZED; + break; + case TS_ST_UNUSED: + ctr = BTS_CTR_TS_BORKEN_FROM_UNUSED; + break; + case TS_ST_WAIT_PDCH_ACT: + ctr = BTS_CTR_TS_BORKEN_FROM_WAIT_PDCH_ACT; + break; + case TS_ST_PDCH: + ctr = BTS_CTR_TS_BORKEN_FROM_PDCH; + break; + case TS_ST_WAIT_PDCH_DEACT: + ctr = BTS_CTR_TS_BORKEN_FROM_WAIT_PDCH_DEACT; + break; + case TS_ST_IN_USE: + ctr = BTS_CTR_TS_BORKEN_FROM_IN_USE; + break; + case TS_ST_BORKEN: + ctr = BTS_CTR_TS_BORKEN_FROM_BORKEN; + break; + default: + ctr = BTS_CTR_TS_BORKEN_FROM_UNKNOWN; + } + rate_ctr_inc(&ts->trx->bts->bts_ctrs->ctr[ctr]); + if (prev_state != LCHAN_ST_BORKEN) + osmo_stat_item_inc(ts->trx->bts->bts_statg->items[BTS_STAT_TS_BORKEN], 1); +} + static void ts_fsm_borken(struct osmo_fsm_inst *fi, uint32_t event, void *data) { switch (event) { @@ -669,10 +703,14 @@ static void ts_fsm_borken(struct osmo_fsm_inst *fi, uint32_t event, void *data) } case TS_EV_PDCH_ACT_ACK: - /* Late PDCH activation ACK is not a crime. - * Just go into the PDCH mode as normal. */ - osmo_fsm_inst_state_chg(fi, TS_ST_PDCH, 0, 0); - return; + { + struct gsm_bts_trx_ts *ts = ts_fi_ts(fi); + /* Late PDCH activation ACK is not a crime. + * Just go into the PDCH mode as normal. */ + osmo_stat_item_dec(ts->trx->bts->bts_statg->items[BTS_STAT_TS_BORKEN], 1); + osmo_fsm_inst_state_chg(fi, TS_ST_PDCH, 0, 0); + return; + } default: OSMO_ASSERT(false); @@ -725,6 +763,15 @@ static void ts_fsm_allstate(struct osmo_fsm_inst *fi, uint32_t event, void *data } } +static void ts_fsm_cleanup(struct osmo_fsm_inst *fi, enum osmo_fsm_term_cause cause) +{ + struct gsm_bts_trx_ts *ts = ts_fi_ts(fi); + if (ts->fi->state == TS_ST_BORKEN) { + rate_ctr_inc(&ts->trx->bts->bts_ctrs->ctr[BTS_CTR_TS_BORKEN_EV_CLEANUP]); + osmo_stat_item_dec(ts->trx->bts->bts_statg->items[BTS_STAT_TS_BORKEN], 1); + } +} + #define S(x) (1 << (x)) static const struct osmo_fsm_state ts_fsm_states[] = { @@ -822,6 +869,7 @@ static const struct osmo_fsm_state ts_fsm_states[] = { }, [TS_ST_BORKEN] = { .name = "BORKEN", + .onenter = ts_fsm_borken_onenter, .action = ts_fsm_borken, .in_event_mask = 0 | S(TS_EV_LCHAN_REQUESTED) @@ -862,6 +910,7 @@ static struct osmo_fsm ts_fsm = { | S(TS_EV_RSL_DOWN) , .allstate_action = ts_fsm_allstate, + .cleanup = ts_fsm_cleanup, }; /* Return true if any lchans are waiting for this timeslot to become a specific PCHAN. If target_pchan is -- cgit v1.2.3 From 6b16ef8c290fe4d6e53862a4bdfda60a928f2afb Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Wed, 13 May 2020 00:47:03 +0300 Subject: bssap: Handle BSSMAP CONFUSION message. We decode the mesage and print it to the log files at ERROR log level. We also count it in the BSSMAP message counters. There is not much else we could do about it. Change-Id: Ib4cd94f185f751b2384842222678ff671ac413c4 --- include/osmocom/bsc/bsc_msc_data.h | 1 + src/osmo-bsc/osmo_bsc_bssap.c | 64 ++++++++++++++++++++++++++++++++++++++ src/osmo-bsc/osmo_bsc_msc.c | 1 + 3 files changed, 66 insertions(+) diff --git a/include/osmocom/bsc/bsc_msc_data.h b/include/osmocom/bsc/bsc_msc_data.h index 74a6f3ce2..fc816b4fd 100644 --- a/include/osmocom/bsc/bsc_msc_data.h +++ b/include/osmocom/bsc/bsc_msc_data.h @@ -69,6 +69,7 @@ enum { MSC_CTR_BSSMAP_RX_DT1_LCLS_CONNECT_CTRL, MSC_CTR_BSSMAP_RX_DT1_HANDOVER_CMD, MSC_CTR_BSSMAP_RX_DT1_CLASSMARK_RQST, + MSC_CTR_BSSMAP_RX_DT1_CONFUSION, MSC_CTR_BSSMAP_RX_DT1_UNKNOWN, MSC_CTR_BSSMAP_RX_DT1_DTAP, MSC_CTR_BSSMAP_RX_DT1_DTAP_ERROR, diff --git a/src/osmo-bsc/osmo_bsc_bssap.c b/src/osmo-bsc/osmo_bsc_bssap.c index 6f5aaa801..edc313b66 100644 --- a/src/osmo-bsc/osmo_bsc_bssap.c +++ b/src/osmo-bsc/osmo_bsc_bssap.c @@ -1006,6 +1006,66 @@ reject: return -EINVAL; } +/* Handle Confusion message, MSC indicating an error to us: + * + * See 3GPP TS 48.008 ยง3.2.1.45 + */ +static int bssmap_handle_confusion(struct gsm_subscriber_connection *conn, + struct msgb *msg, unsigned int length) +{ + struct tlv_parsed tp; + int diag_len; + enum gsm0808_cause cause; + enum gsm0808_cause_class cause_class; + struct gsm0808_diagnostics *diag; + + osmo_bssap_tlv_parse(&tp, msg->l4h + 1, length - 1); + + /* Check for the Cause and Diagnostic mandatory elements */ + if (!TLVP_PRESENT(&tp, GSM0808_IE_CAUSE) || !TLVP_PRESENT(&tp, GSM0808_IE_DIAGNOSTIC)) { + LOGPFSML(conn->fi, LOGL_ERROR, + "Received Confusion message," + " but either Cause or Diagnostic mandatory IE is not present: %s\n", + osmo_hexdump(msg->l4h, length)); + return -EINVAL; + } + + diag_len = TLVP_LEN(&tp, GSM0808_IE_DIAGNOSTIC); + if (diag_len < 5) { + LOGPFSML(conn->fi, LOGL_ERROR, + "Received Confusion message with short Diagnostic length: %d (expected > 5)\n", + diag_len); + return -EINVAL; + } + + cause = gsm0808_get_cause(&tp); + cause_class = gsm0808_cause_class(cause); + LOGPFSML(conn->fi, LOGL_ERROR, + "Received Confusion message: Cause %d/0x%x (%s)", + cause, cause, gsm0808_cause_name(cause)); + LOGPFSML(conn->fi, LOGL_ERROR, + "Received Confusion message: Cause class %d/0x%x (%s)", + cause_class, cause_class, gsm0808_cause_class_name(cause_class)); + + diag = (struct gsm0808_diagnostics *)TLVP_VAL(&tp, GSM0808_IE_DIAGNOSTIC); + /* octet location */ + LOGPFSML(conn->fi, LOGL_ERROR, + " Confusion Diagnostics error octet location %d (%s)\n", + diag->error_pointer_octet, + gsm0808_diagnostics_octet_location_str(diag->error_pointer_octet)); + /* bit location */ + LOGPFSML(conn->fi, LOGL_ERROR, + " Confusion Diagnostics error bit location: %d (%s)\n", + diag->error_pointer_bit, + gsm0808_diagnostics_bit_location_str(diag->error_pointer_bit)); + /* received message dump */ + LOGPFSML(conn->fi, LOGL_ERROR, + " Confusion Diagnostics message that provoked the error: %s\n", + osmo_hexdump(diag->msg, diag_len-2)); + + return 0; +} + static int bssmap_rcvmsg_udt(struct bsc_msc_data *msc, struct msgb *msg, unsigned int length) { @@ -1082,6 +1142,10 @@ static int bssmap_rcvmsg_dt1(struct gsm_subscriber_connection *conn, rate_ctr_inc(&ctrs[MSC_CTR_BSSMAP_RX_DT1_CLASSMARK_RQST]); ret = gsm48_send_rr_classmark_enquiry(conn->lchan); break; + case BSS_MAP_MSG_CONFUSION: + rate_ctr_inc(&ctrs[MSC_CTR_BSSMAP_RX_DT1_CONFUSION]); + ret = bssmap_handle_confusion(conn, msg, length); + break; default: rate_ctr_inc(&ctrs[MSC_CTR_BSSMAP_RX_DT1_UNKNOWN]); LOGP(DMSC, LOGL_NOTICE, "Unimplemented msg type: %s\n", diff --git a/src/osmo-bsc/osmo_bsc_msc.c b/src/osmo-bsc/osmo_bsc_msc.c index db3ffe4e7..e58ff7faf 100644 --- a/src/osmo-bsc/osmo_bsc_msc.c +++ b/src/osmo-bsc/osmo_bsc_msc.c @@ -55,6 +55,7 @@ static const struct rate_ctr_desc msc_ctr_description[] = { [MSC_CTR_BSSMAP_RX_DT1_LCLS_CONNECT_CTRL] = {"bssmap:rx:dt1:lcls_connect_ctrl:cmd", "Number of received BSSMAP DT1 LCLS CONNECT CTRL messages"}, [MSC_CTR_BSSMAP_RX_DT1_HANDOVER_CMD] = {"bssmap:rx:dt1:handover:cmd", "Number of received BSSMAP DT1 HANDOVER CMD messages"}, [MSC_CTR_BSSMAP_RX_DT1_CLASSMARK_RQST] = {"bssmap:rx:dt1:classmark:rqst", "Number of received BSSMAP DT1 CLASSMARK RQST messages"}, + [MSC_CTR_BSSMAP_RX_DT1_CONFUSION] = {"bssmap:rx:dt1:confusion", "Number of received BSSMAP DT1 CONFUSION messages"}, [MSC_CTR_BSSMAP_RX_DT1_UNKNOWN] = {"bssmap:rx:dt1:err_unknown", "Number of received BSSMAP unknown DT1 messages"}, [MSC_CTR_BSSMAP_RX_DT1_DTAP] = {"bssmap:rx:dt1:dtap:good", "Number of received BSSMAP DTAP messages"}, [MSC_CTR_BSSMAP_RX_DT1_DTAP_ERROR] = {"bssmap:rx:dt1:dtap:error", "Number of received BSSMAP DTAP messages with errors"}, -- cgit v1.2.3 From ccbba5955814f04bb003844a1eea7a251c0e41f4 Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Sat, 16 May 2020 18:49:59 +0300 Subject: stats: Add a BTS/BSC counter PAGING_NON_ACTIVE. Otherwise we're missing an important part of the callflow and the counters of responded/expired paging requests don't add up to attempted paging number. Change-Id: I1755be40d29980b75353cb4b8087d1ce0d92854a --- include/osmocom/bsc/gsm_data.h | 4 ++++ src/osmo-bsc/gsm_08_08.c | 2 ++ 2 files changed, 6 insertions(+) diff --git a/include/osmocom/bsc/gsm_data.h b/include/osmocom/bsc/gsm_data.h index aeeb58d71..264df8ee0 100644 --- a/include/osmocom/bsc/gsm_data.h +++ b/include/osmocom/bsc/gsm_data.h @@ -1412,6 +1412,7 @@ enum bts_counter_id { BTS_CTR_PAGING_ALREADY, BTS_CTR_PAGING_RESPONDED, BTS_CTR_PAGING_EXPIRED, + BTS_CTR_PAGING_NON_ACTIVE, BTS_CTR_CHAN_ACT_TOTAL, BTS_CTR_CHAN_ACT_NACK, BTS_CTR_RSL_UNKNOWN, @@ -1458,6 +1459,7 @@ static const struct rate_ctr_desc bts_ctr_description[] = { [BTS_CTR_PAGING_ALREADY] = {"paging:already", "Paging attempts ignored as subscriber was already being paged."}, [BTS_CTR_PAGING_RESPONDED] = {"paging:responded", "Paging attempts with successful paging response."}, [BTS_CTR_PAGING_EXPIRED] = {"paging:expired", "Paging Request expired because of timeout T3113."}, + [BTS_CTR_PAGING_NON_ACTIVE] = {"paging:non_active", "Non active subscriber responded to paging."}, [BTS_CTR_CHAN_ACT_TOTAL] = {"chan_act:total", "Total number of Channel Activations."}, [BTS_CTR_CHAN_ACT_NACK] = {"chan_act:nack", "Number of Channel Activations that the BTS NACKed"}, [BTS_CTR_RSL_UNKNOWN] = {"rsl:unknown", "Number of unknown/unsupported RSL messages received from BTS"}, @@ -1554,6 +1556,7 @@ enum { BSC_CTR_PAGING_ATTEMPTED, BSC_CTR_PAGING_DETACHED, BSC_CTR_PAGING_RESPONDED, + BSC_CTR_PAGING_NON_ACTIVE, BSC_CTR_UNKNOWN_UNIT_ID, }; @@ -1598,6 +1601,7 @@ static const struct rate_ctr_desc bsc_ctr_description[] = { [BSC_CTR_PAGING_ATTEMPTED] = {"paging:attempted", "Paging attempts for a subscriber."}, [BSC_CTR_PAGING_DETACHED] = {"paging:detached", "Paging request send failures because no responsible BTS was found."}, [BSC_CTR_PAGING_RESPONDED] = {"paging:responded", "Paging attempts with successful response."}, + [BSC_CTR_PAGING_NON_ACTIVE] = {"paging:non_active", "Paging response for non active subscriber."}, [BSC_CTR_UNKNOWN_UNIT_ID] = {"abis:unknown_unit_id", "Connection attempts from unknown IPA CCM Unit ID."}, }; diff --git a/src/osmo-bsc/gsm_08_08.c b/src/osmo-bsc/gsm_08_08.c index 4f9c69eb6..d48c9f72c 100644 --- a/src/osmo-bsc/gsm_08_08.c +++ b/src/osmo-bsc/gsm_08_08.c @@ -388,6 +388,8 @@ static int handle_page_resp(struct gsm_subscriber_connection *conn, struct msgb if (!subscr) { LOGP(DMSC, LOGL_ERROR, "Non active subscriber got paged.\n"); + rate_ctr_inc(&conn->lchan->ts->trx->bts->bts_ctrs->ctr[BTS_CTR_PAGING_NON_ACTIVE]); + rate_ctr_inc(&conn->network->bsc_ctrs->ctr[BSC_CTR_PAGING_NON_ACTIVE]); return -1; } -- cgit v1.2.3