aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorMax <msuraev@sysmocom.de>2016-02-25 17:31:31 +0100
committerMax <msuraev@sysmocom.de>2016-02-26 12:43:35 +0100
commitbf1cb08a48f2237ba493a5573246c8af7ed3768e (patch)
treef0a86728d47a7e39434a6ce461c25d57eba133d8
parent9d5ed08767be0ecdb144a1a15345e9705c23d8cc (diff)
Expand RLCMAC diagnostics outputmax/pacchtest
When smth bad happens (e. g. we hit timeout in RLCMAC) on TBF - obtain corresponding MS object and print extended information about it and its TBFs to aid troubleshooting. Diagnostic function should not change state hence make it const with no return value.
-rw-r--r--src/bts.cpp2
-rw-r--r--src/tbf.cpp93
-rw-r--r--src/tbf.h2
-rw-r--r--src/tbf_dl.cpp3
-rw-r--r--src/tbf_ul.cpp2
5 files changed, 89 insertions, 13 deletions
diff --git a/src/bts.cpp b/src/bts.cpp
index 715fb51..75766f1 100644
--- a/src/bts.cpp
+++ b/src/bts.cpp
@@ -1254,7 +1254,7 @@ int gprs_rlcmac_pdch::rcv_control_block(
bitvec *rlc_block, uint32_t fn)
{
RlcMacUplink_t * ul_control_block = (RlcMacUplink_t *)talloc_zero(tall_pcu_ctx, RlcMacUplink_t);
- LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ RX : Uplink Control Block on FN = %d ++++++++++++++\n", fn);
decode_gsm_rlcmac_uplink(rlc_block, ul_control_block);
LOGPC(DCSN1, LOGL_NOTICE, "\n");
LOGP(DRLCMAC, LOGL_DEBUG, "------------------------- RX : Uplink Control Block -------------------------\n");
diff --git a/src/tbf.cpp b/src/tbf.cpp
index 69b9e3a..c044f31 100644
--- a/src/tbf.cpp
+++ b/src/tbf.cpp
@@ -490,7 +490,7 @@ void gprs_rlcmac_tbf::poll_timeout()
if (!(state_flags & (1 << GPRS_RLCMAC_FLAG_TO_UL_ACK))) {
LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling "
"PACKET CONTROL ACK for PACKET UPLINK ACK\n");
- rlcmac_diag();
+ rlcmac_diag("POLL TIMEOUT for PACKET CONTROL ACK for PACKET UPLINK ACK");
state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_UL_ACK);
}
ul_ack_state = GPRS_RLCMAC_UL_ACK_NONE;
@@ -514,7 +514,7 @@ void gprs_rlcmac_tbf::poll_timeout()
LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling "
"PACKET CONTROL ACK for PACKET UPLINK "
"ASSIGNMENT.\n");
- rlcmac_diag();
+ rlcmac_diag("POLL TIMEOUT for PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT");
state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_UL_ASS);
}
ul_ass_state = GPRS_RLCMAC_UL_ASS_NONE;
@@ -534,7 +534,7 @@ void gprs_rlcmac_tbf::poll_timeout()
LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling "
"PACKET CONTROL ACK for PACKET DOWNLINK "
"ASSIGNMENT.\n");
- rlcmac_diag();
+ rlcmac_diag("POLL TIMEOUT for PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT");
state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_DL_ASS);
}
dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
@@ -555,7 +555,7 @@ void gprs_rlcmac_tbf::poll_timeout()
if (!(dl_tbf->state_flags & (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK))) {
LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling "
"PACKET DOWNLINK ACK.\n");
- dl_tbf->rlcmac_diag();
+ dl_tbf->rlcmac_diag("POLL TIMEOUT for PACKET DOWNLINK ACK");
dl_tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK);
}
dl_tbf->n3105++;
@@ -872,7 +872,7 @@ void gprs_rlcmac_tbf::handle_timeout()
case 3195:
LOGP(DRLCMAC, LOGL_NOTICE, "%s T%d timeout during "
"transsmission\n", tbf_name(this), T);
- rlcmac_diag();
+ rlcmac_diag("TRANSMISSION TIMEOUT");
/* fall through */
case 3193:
LOGP(DRLCMAC, LOGL_DEBUG,
@@ -887,8 +887,33 @@ void gprs_rlcmac_tbf::handle_timeout()
}
}
-int gprs_rlcmac_tbf::rlcmac_diag()
+static inline void print_tbf_diag(const struct gprs_rlcmac_tbf * t, bool uplink)
{
+ const char * d = uplink ? "UL" : "DL";
+
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS %s %s\n", d, t->name());
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS %s TBF 1st TS = %d, 1st common TS = %d, ctrl TS = %d\n",
+ d, t->first_ts, t->first_common_ts, t->control_ts);
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS %s TBF TSC = %d, DL: "OSMO_BIT_SPEC", UL: "OSMO_BIT_SPEC", mslot upgradeable: %d\n",
+ d, t->tsc(), OSMO_BIT_PRINT(t->dl_slots()), OSMO_BIT_PRINT(t->ul_slots()), t->upgrade_to_multislot);
+
+ unsigned i;
+ for (i = 0; i < 8; i++)
+ if (t->pdch[i])
+ if (t->pdch[i]->is_enabled())
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS %s PDCH[%d] USF = %d, last RTS FN = %d, TSC = %d, TS = %d\n",
+ d, i, t->pdch[i]->assigned_usf(), t->pdch[i]->last_rts_fn, t->pdch[i]->tsc, t->pdch[i]->ts_no);
+
+ if (GPRS_RLCMAC_POLL_SCHED == t->poll_state)
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS %s TBF poll. scheduled: FN = %d, TS = %d\n", d, t->poll_fn, t->poll_ts);
+ else
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS %s TBF no polling\n", d);
+}
+
+void gprs_rlcmac_tbf::rlcmac_diag(const char * context) const
+{
+ GprsMs * m = ms();
+ LOGP(DRLCMAC, LOGL_NOTICE, "- RLCMAC diag. report for %s:\n", context);
if ((state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH)))
LOGP(DRLCMAC, LOGL_NOTICE, "- Assignment was on CCCH\n");
if ((state_flags & (1 << GPRS_RLCMAC_FLAG_PACCH)))
@@ -902,7 +927,57 @@ int gprs_rlcmac_tbf::rlcmac_diag()
else if (direction == GPRS_RLCMAC_DL_TBF)
LOGP(DRLCMAC, LOGL_NOTICE, "- No downlink ACK received yet\n");
- return 0;
+ if (is_tfi_assigned())
+ LOGP(DRLCMAC, LOGL_NOTICE, "- TBF's TFI = %d\n", tfi());
+ else
+ LOGP(DRLCMAC, LOGL_NOTICE, "- No TFI is assigned to this TBF yet\n");
+
+ if (is_tlli_valid())
+ LOGP(DRLCMAC, LOGL_NOTICE, "- TBF's TLLI = 0x%x\n", tlli());
+ else
+ LOGP(DRLCMAC, LOGL_NOTICE, "- No TLLI is assigned to this TBF yet\n");
+
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS IMSI = %s, GPRS class = %d, EGPRS class = %d, TA = %d, TLLI = 0x%x\n",
+ m->imsi(), m->ms_class(), m->egprs_ms_class(), m->ta(), m->tlli());
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS 1st common TS = %d, current PACCH = %d\n",
+ m->first_common_ts(), m->current_pacch_slots());
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS DL: "OSMO_BIT_SPEC" (RSRVD: "OSMO_BIT_SPEC"), UL: "OSMO_BIT_SPEC" (RSRVD: "OSMO_BIT_SPEC")\n",
+ OSMO_BIT_PRINT(m->dl_slots()), OSMO_BIT_PRINT(m->reserved_dl_slots()), OSMO_BIT_PRINT(m->ul_slots()), OSMO_BIT_PRINT(m->reserved_ul_slots()));
+
+ if (m->is_idle())
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS id idle\n");
+ if (m->need_dl_tbf())
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS needs DL TBF\n");
+
+ if (m->dl_tbf()) {
+ struct gprs_rlcmac_dl_tbf * dl = m->dl_tbf();
+ print_tbf_diag(dl, false);
+
+ if (m->dl_tbf()->need_control_ts())
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS DL TBF needs ctrl TS\n");
+
+ if (m->dl_tbf()->have_data())
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS DL TBF have data\n");
+ } else
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS have no DL TBF\n");
+
+ if (m->ul_tbf()) {
+ struct gprs_rlcmac_ul_tbf * ul = m->ul_tbf();
+ print_tbf_diag(ul, true);
+
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS UL TBF USF: %d %d %d %d %d %d %d %d\n",
+ m->ul_tbf()->m_usf[0],
+ m->ul_tbf()->m_usf[1],
+ m->ul_tbf()->m_usf[2],
+ m->ul_tbf()->m_usf[3],
+ m->ul_tbf()->m_usf[4],
+ m->ul_tbf()->m_usf[5],
+ m->ul_tbf()->m_usf[6],
+ m->ul_tbf()->m_usf[7]);
+ } else
+ LOGP(DRLCMAC, LOGL_NOTICE, "- MS have no UL TBF\n");
+
+ LOGP(DRLCMAC, LOGL_NOTICE, "- RLCMAC diag. report complete\n\n");
}
struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
@@ -992,7 +1067,7 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
new_dl_tbf, poll_ass_dl, rrbp,
bts_data()->alpha, bts_data()->gamma, -1, 0,
is_egprs_enabled());
- LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ TX : Packet Downlink Assignment on FN = %d, TS = %d +++++\n", fn, ts);
encode_gsm_rlcmac_downlink(ass_vec, mac_control_block);
LOGPC(DCSN1, LOGL_NOTICE, "\n");
LOGP(DRLCMAC, LOGL_DEBUG, "------------------------- TX : Packet Downlink Assignment -------------------------\n");
@@ -1067,7 +1142,7 @@ struct msgb *gprs_rlcmac_tbf::create_ul_ass(uint32_t fn, uint8_t ts)
bts_data()->gamma, -1, is_egprs_enabled());
bitvec_pack(ass_vec, msgb_put(msg, 23));
RlcMacDownlink_t * mac_control_block = (RlcMacDownlink_t *)talloc_zero(tall_pcu_ctx, RlcMacDownlink_t);
- LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++\n");
+ LOGP(DRLCMAC, LOGL_DEBUG, "+++++++++++++++++++++++++ TX : Packet Uplink Assignment on FN = %d, TS = %d +++++\n", fn, ts);
decode_gsm_rlcmac_downlink(ass_vec, mac_control_block);
LOGPC(DCSN1, LOGL_NOTICE, "\n");
LOGP(DRLCMAC, LOGL_DEBUG, "------------------------- TX : Packet Uplink Assignment -------------------------\n");
diff --git a/src/tbf.h b/src/tbf.h
index ad8ad4c..b556e0c 100644
--- a/src/tbf.h
+++ b/src/tbf.h
@@ -112,7 +112,7 @@ struct gprs_rlcmac_tbf {
uint8_t tsc() const;
- int rlcmac_diag();
+ void rlcmac_diag(const char * context) const;
int update();
void handle_timeout();
diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp
index 7540d1b..0321ad1 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -706,9 +706,8 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
rc = check_polling(fn, ts, &new_poll_fn, &rrbp);
if (rc >= 0) {
set_polling(new_poll_fn, ts);
+ LOGP(DRLCMACDL, LOGL_DEBUG, "DL TBF polling scheduled in TS = %d, FN = %d\n", ts, new_poll_fn);
- LOGP(DRLCMACDL, LOGL_DEBUG, "Polling scheduled in this "
- "TS %d\n", ts);
m_tx_counter = 0;
/* start timer whenever we send the final block */
if (is_final)
diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp
index 9e763f4..c5f6f1e 100644
--- a/src/tbf_ul.cpp
+++ b/src/tbf_ul.cpp
@@ -129,6 +129,8 @@ struct msgb *gprs_rlcmac_ul_tbf::create_ul_ack(uint32_t fn, uint8_t ts)
if (final) {
set_polling(new_poll_fn, ts);
+ LOGP(DRLCMACUL, LOGL_DEBUG, "UL TBF polling scheduled in TS = %d, FN = %d\n", ts, new_poll_fn);
+
/* waiting for final acknowledge */
ul_ack_state = GPRS_RLCMAC_UL_ACK_WAIT_ACK;
m_final_ack_sent = 1;