From faed7381f241c9de43536ae6114ee8dfcc9a638f Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Sun, 17 May 2020 21:18:40 +0300 Subject: Fix crash in bsc_patch_mm_info() osmo-bsc has crashed with the following backtrace: 0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51 1 0x00007f0bc49b38db in __GI_abort () at abort.c:100 2 0x00007f0bc581ba30 in osmo_panic () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12 3 0x00005648ceeced69 in conn_get_bts (conn=) at ../../include/osmocom/bsc/gsm_data.h:1392 4 0x00005648cef37164 in conn_get_bts (conn=0x5648cf769e80) at osmo_bsc_filter.c:87 5 bsc_patch_mm_info (conn=conn@entry=0x5648cf769e80, data=, length=) at osmo_bsc_filter.c:48 6 0x00005648cef371b6 in bsc_scan_msc_msg (conn=conn@entry=0x5648cf769e80, msg=msg@entry=0x5648cf77ead0) at osmo_bsc_filter.c:159 7 0x00005648cef33988 in dtap_rcvmsg (msg=0x5648cf72b2f0, length=40, conn=0x5648cf769e80) at osmo_bsc_bssap.c:1215 8 bsc_handle_dt (conn=conn@entry=0x5648cf769e80, msg=0x5648cf72b2f0, len=40) at osmo_bsc_bssap.c:1299 9 0x00005648cef3b2b7 in handle_data_from_msc (msg=, conn=0x5648cf769e80) at osmo_bsc_sigtran.c:152 10 sccp_sap_up (oph=0x5648cf72b378, _scu=) at osmo_bsc_sigtran.c:267 11 0x00007f0bc5813c03 in _osmo_fsm_inst_dispatch () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12 12 0x00007f0bc51a8935 in sccp_scoc_rx_from_scrc (inst=inst@entry=0x5648cf6a8d60, xua=xua@entry=0x5648cf720150) at sccp_scoc.c:1695 13 0x00007f0bc51a62f3 in scrc_rx_mtp_xfer_ind_xua (inst=inst@entry=0x5648cf6a8d60, xua=xua@entry=0x5648cf720150) at sccp_scrc.c:459 14 0x00007f0bc51a9545 in mtp_user_prim_cb (oph=0x5648cf7681f8, ctx=0x5648cf6a8d60) at sccp_user.c:182 15 0x00007f0bc51a09c6 in m3ua_rx_xfer (xua=0x5648cf764a80, asp=0x5648cf45f540) at m3ua.c:586 16 m3ua_rx_msg (asp=asp@entry=0x5648cf45f540, msg=msg@entry=0x5648cf71e880) at m3ua.c:739 17 0x00007f0bc51b0763 in xua_cli_read_cb (conn=0x5648cf441ed0) at osmo_ss7.c:1761 18 0x00007f0bc55fab53 in osmo_stream_cli_read (cli=0x5648cf441ed0) at stream.c:232 19 osmo_stream_cli_fd_cb (ofd=, what=1) at stream.c:321 20 0x00007f0bc580edcf in ?? () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12 21 0x00007f0bc580f526 in osmo_select_main_ctx () from /usr/lib/x86_64-linux-gnu/libosmocore.so.12 22 0x00005648ceecfb2f in main (argc=, argv=) at osmo_bsc_main.c:953 Apparently, there is no lchan allocated at this moment, so conn_get_bts() crashes. But we only use it to get to "network" which we can do much easier and safer by doing conn->network. Change-Id: Id3f7b3efba60c0f050c1be98e5e539f1dab4cd57 --- src/osmo-bsc/osmo_bsc_filter.c | 3 +-- tests/bsc/bsc_test.c | 11 ++--------- 2 files changed, 3 insertions(+), 11 deletions(-) diff --git a/src/osmo-bsc/osmo_bsc_filter.c b/src/osmo-bsc/osmo_bsc_filter.c index 332ba6b83..3b72aeeb9 100644 --- a/src/osmo-bsc/osmo_bsc_filter.c +++ b/src/osmo-bsc/osmo_bsc_filter.c @@ -45,7 +45,6 @@ static int bsc_patch_mm_info(struct gsm_subscriber_connection *conn, { struct tlv_parsed tp; int parse_res; - struct gsm_bts *bts = conn_get_bts(conn); int tzunits; uint8_t tzbsd = 0; uint8_t dst = 0; @@ -58,7 +57,7 @@ static int bsc_patch_mm_info(struct gsm_subscriber_connection *conn, return 0; /* Is TZ patching enabled? */ - struct gsm_tz *tz = &bts->network->tz; + struct gsm_tz *tz = &conn->network->tz; if (!tz->override) return 0; diff --git a/tests/bsc/bsc_test.c b/tests/bsc/bsc_test.c index 6079ec500..5d8711838 100644 --- a/tests/bsc/bsc_test.c +++ b/tests/bsc/bsc_test.c @@ -123,16 +123,9 @@ static void test_scan(void) int i; struct gsm_network *net = gsm_network_init(ctx); - struct gsm_bts *bts = gsm_bts_alloc(net, 0); - struct bsc_msc_data *msc; - struct gsm_subscriber_connection *conn; + struct gsm_subscriber_connection *conn = talloc_zero(net, struct gsm_subscriber_connection); - msc = talloc_zero(net, struct bsc_msc_data); - conn = talloc_zero(net, struct gsm_subscriber_connection); - - bts->network = net; - conn->sccp.msc = msc; - conn->lchan = &bts->c0->ts[1].lchan[0]; + conn->network = net; /* start testing with proper messages */ printf("Testing BTS<->MSC message scan.\n"); -- cgit v1.2.3 From 2a04564efab8b514697bc102ee36205a10d3dcd9 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 DEBUG. 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 d6465bad8973e9b1a663e14d0e8dfc9f745229bf Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Sun, 17 May 2020 01:48:34 +0300 Subject: log: Demote "SAPI=%u ESTABLISH CONFIRM" message from ERROR to DEBUG. Not sure why this specific message is ERROR while similar ones around are DEBUG. So let's fix this disparity by demoting this message level. Change-Id: I655d4555f037def354aacbc5f089794f5fe811ed --- 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 dd2ea3f20..4a1d31476 100644 --- a/src/osmo-bsc/abis_rsl.c +++ b/src/osmo-bsc/abis_rsl.c @@ -1687,7 +1687,7 @@ static int abis_rsl_rx_rll(struct msgb *msg) } break; case RSL_MT_EST_CONF: - LOG_LCHAN(msg->lchan, LOGL_ERROR, "SAPI=%u ESTABLISH CONFIRM\n", sapi); + LOG_LCHAN(msg->lchan, LOGL_DEBUG, "SAPI=%u ESTABLISH CONFIRM\n", sapi); msg->lchan->sapis[sapi] = LCHAN_SAPI_NET; rll_indication(msg->lchan, rllh->link_id, BSC_RLLR_IND_EST_CONF); -- cgit v1.2.3 From 2c2bdb0d7313967c34526bbb0f109b648885e9b6 Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Mon, 18 May 2020 00:01:45 +0300 Subject: borken: Recover from more TS borken states. Change-Id: Ic87c325a73690ede1b81b4d33bac65a1a4beea2d --- src/osmo-bsc/timeslot_fsm.c | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-) diff --git a/src/osmo-bsc/timeslot_fsm.c b/src/osmo-bsc/timeslot_fsm.c index f8adfb6c7..84ffb7f54 100644 --- a/src/osmo-bsc/timeslot_fsm.c +++ b/src/osmo-bsc/timeslot_fsm.c @@ -669,9 +669,17 @@ 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); + case TS_EV_PDCH_ACT_NACK: + /* Late PDCH activation ACK/NACK is not a crime. + * Just process them as normal. */ + ts_fsm_wait_pdch_act(fi, event, data); + return; + + case TS_EV_PDCH_DEACT_ACK: + case TS_EV_PDCH_DEACT_NACK: + /* Late PDCH deactivation ACK/NACK is also not a crime. + * Just process them as normal. */ + ts_fsm_wait_pdch_deact(fi, event, data); return; default: @@ -827,8 +835,13 @@ static const struct osmo_fsm_state ts_fsm_states[] = { | S(TS_EV_LCHAN_REQUESTED) | S(TS_EV_LCHAN_UNUSED) | S(TS_EV_PDCH_ACT_ACK) + | S(TS_EV_PDCH_ACT_NACK) + | S(TS_EV_PDCH_DEACT_ACK) + | S(TS_EV_PDCH_DEACT_NACK) , .out_state_mask = 0 + | S(TS_ST_IN_USE) + | S(TS_ST_UNUSED) | S(TS_ST_NOT_INITIALIZED) | S(TS_ST_PDCH) , -- cgit v1.2.3 From 73cc1d8b78feb0f6b1f5a2c9cac8cadf741ebb34 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 | 48 +++++++++++++++++++++++++++- 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 | 72 +++++++++++++++++++++++++++++++++++++----- 5 files changed, 148 insertions(+), 11 deletions(-) diff --git a/include/osmocom/bsc/gsm_data.h b/include/osmocom/bsc/gsm_data.h index 17da79d43..e63b9637b 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,27 @@ 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_PDCH_ACT_ACK_NACK, + BTS_CTR_TS_BORKEN_EV_PDCH_DEACT_ACK_NACK, + BTS_CTR_TS_BORKEN_EV_CLEANUP, }; static const struct rate_ctr_desc bts_ctr_description[] = { @@ -1441,6 +1462,29 @@ 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_PDCH_ACT_ACK_NACK] = {"ts_borken:event:pdch_act_ack_nack", "PDCH_ACT_ACK/NACK received in the TS BORKEN state"}, + [BTS_CTR_TS_BORKEN_EV_PDCH_DEACT_ACK_NACK] = {"ts_borken:event:pdch_deact_ack_nack", "PDCH_DEACT_ACK/NACK 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 +1518,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 84ffb7f54..a72833f82 100644 --- a/src/osmo-bsc/timeslot_fsm.c +++ b/src/osmo-bsc/timeslot_fsm.c @@ -654,6 +654,39 @@ 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]); + 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) { @@ -670,17 +703,29 @@ static void ts_fsm_borken(struct osmo_fsm_inst *fi, uint32_t event, void *data) case TS_EV_PDCH_ACT_ACK: case TS_EV_PDCH_ACT_NACK: - /* Late PDCH activation ACK/NACK is not a crime. - * Just process them as normal. */ - ts_fsm_wait_pdch_act(fi, event, data); - return; + { + struct gsm_bts_trx_ts *ts = ts_fi_ts(fi); + struct gsm_bts *bts = ts->trx->bts; + /* Late PDCH activation ACK/NACK is not a crime. + * Just process them as normal. */ + rate_ctr_inc(&bts->bts_ctrs->ctr[BTS_CTR_TS_BORKEN_EV_PDCH_ACT_ACK_NACK]); + osmo_stat_item_dec(bts->bts_statg->items[BTS_STAT_TS_BORKEN], 1); + ts_fsm_wait_pdch_act(fi, event, data); + return; + } case TS_EV_PDCH_DEACT_ACK: case TS_EV_PDCH_DEACT_NACK: - /* Late PDCH deactivation ACK/NACK is also not a crime. - * Just process them as normal. */ - ts_fsm_wait_pdch_deact(fi, event, data); - return; + { + struct gsm_bts_trx_ts *ts = ts_fi_ts(fi); + struct gsm_bts *bts = ts->trx->bts; + /* Late PDCH deactivation ACK/NACK is also not a crime. + * Just process them as normal. */ + rate_ctr_inc(&bts->bts_ctrs->ctr[BTS_CTR_TS_BORKEN_EV_PDCH_DEACT_ACK_NACK]); + osmo_stat_item_dec(bts->bts_statg->items[BTS_STAT_TS_BORKEN], 1); + ts_fsm_wait_pdch_deact(fi, event, data); + return; + } default: OSMO_ASSERT(false); @@ -733,6 +778,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[] = { @@ -830,6 +884,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) @@ -875,6 +930,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 ef5ee6407244bee70a13cc3563080675f8e97166 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 e63b9637b..41c65fc9b 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, @@ -1457,6 +1458,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"}, @@ -1552,6 +1554,7 @@ enum { BSC_CTR_PAGING_ATTEMPTED, BSC_CTR_PAGING_DETACHED, BSC_CTR_PAGING_RESPONDED, + BSC_CTR_PAGING_NON_ACTIVE, BSC_CTR_UNKNOWN_UNIT_ID, }; @@ -1596,6 +1599,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 From 25b9d6ade10714f7a20430ed2874bf646a747c30 Mon Sep 17 00:00:00 2001 From: Alexander Chemeris Date: Sun, 17 May 2020 00:55:01 +0300 Subject: stats: Correctly count lchans under BORKEN/NOT_INITIALIZED TS. lchans under a BORKEN/NOT_INITIALIZED TS should be counted as used just as BORKEN lchans under a normal TS. Change-Id: Ic3dbc6b176d5dcff7ed2589bb875abf93e9f7ab0 --- src/osmo-bsc/chan_alloc.c | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/osmo-bsc/chan_alloc.c b/src/osmo-bsc/chan_alloc.c index 27c49cd0e..eeb6b0a1b 100644 --- a/src/osmo-bsc/chan_alloc.c +++ b/src/osmo-bsc/chan_alloc.c @@ -87,6 +87,14 @@ void bts_chan_load(struct pchan_load *cl, const struct gsm_bts *bts) pl->total++; + /* lchans under a BORKEN/NOT_INITIALIZED TS should + * be counted as used just as BORKEN lchans under + * a normal TS */ + if (!ts_is_usable(ts)) { + pl->used++; + continue; + } + switch (lchan->fi->state) { case LCHAN_ST_UNUSED: break; -- cgit v1.2.3 From 4d7bdc2b83beb71e155bf1158c6bb91c149d0474 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. Requires: libosmocore.git Change-Id If8afd2d096fb66c6c2f255a08fc1129de3d09cec Change-Id: Ib4cd94f185f751b2384842222678ff671ac413c4 --- TODO-RELEASE | 3 ++ include/osmocom/bsc/bsc_msc_data.h | 1 + src/osmo-bsc/osmo_bsc_bssap.c | 64 ++++++++++++++++++++++++++++++++++++++ src/osmo-bsc/osmo_bsc_msc.c | 1 + 4 files changed, 69 insertions(+) diff --git a/TODO-RELEASE b/TODO-RELEASE index dde4b72f2..e2fa427b3 100644 --- a/TODO-RELEASE +++ b/TODO-RELEASE @@ -8,3 +8,6 @@ # If any interfaces have been removed or changed since the last public release: c:r:0. #library what description / commit summary line manual needs common chapter cs7-config.adoc from osmo-gsm-manuals > 0.3.0 +libosmocore struct gsm0808_diagnostics Depends on libosmocore > 1.3.0 +libosmocore gsm0808_diagnostics_octet_location_str() Depends on libosmocore > 1.3.0 +libosmocore gsm0808_diagnostics_bit_location_str() Depends on libosmocore > 1.3.0 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 ddebb6a7d..0d6127258 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