Expand RLCMAC diagnostics output
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.
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
}
}
-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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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;