cellular-infrastructure
/
osmo-pcu
mirror of https://gerrit.osmocom.org/osmo-pcu
9
0
Fork 1
Code Issues Releases Wiki Activity

TBF: expand timer logging 

* log timer values
* log start/stop cause
* update test output as necessary

This simplifies debugging issues with TBF timers.

Related: OS#2407
Change-Id: Ib8e537416af9bec5d447356286f44e9e8bbf1b7a
This commit is contained in:
Max 2017-12-01 17:40:20 +01:00 committed by Harald Welte
parent b4d368b576
commit cea806e5b9
6 changed files with 342 additions and 341 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
src/bts.cpp
View File

@ -548,7 +548,7 @@ int BTS::rcv_imm_ass_cnf(const uint8_t *data, uint32_t fn)
LOGP(DRLCMAC, LOGL_DEBUG, "Got IMM.ASS confirm for TLLI=%08x\n", tlli);
if (dl_tbf->m_wait_confirm)
tbf_timer_start(dl_tbf, 0, Tassign_agch);
tbf_timer_start(dl_tbf, 0, Tassign_agch, "assignment (AGCH)");
return 0;
}
@ -681,7 +681,7 @@ int BTS::rcv_rach(uint16_t ra, uint32_t Fn, int16_t qta, uint8_t is_11bit,
tbf->set_ta(ta);
tbf->set_state(GPRS_RLCMAC_FLOW);
tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_CCCH);
tbf_timer_start(tbf, 3169, m_bts.t3169, 0);
tbf_timer_start(tbf, 3169, m_bts.t3169, 0, "RACH (new UL-TBF)");
LOGP(DRLCMAC, LOGL_DEBUG, "%s [UPLINK] START\n",
tbf_name(tbf));
LOGP(DRLCMAC, LOGL_DEBUG, "%s RX: [PCU <- BTS] RACH "
@ -1036,7 +1036,7 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet,
}
new_tbf->set_state(GPRS_RLCMAC_FLOW);
/* stop pending assignment timer */
new_tbf->stop_timer();
new_tbf->stop_timer("control acked (DL-TBF)");
if ((new_tbf->state_flags &
(1 << GPRS_RLCMAC_FLAG_TO_DL_ASS))) {
new_tbf->state_flags &=

33
src/tbf.cpp
View File

@ -394,7 +394,7 @@ gprs_rlcmac_ul_tbf *tbf_alloc_ul(struct gprs_rlcmac_bts *bts,
tbf->m_contention_resolution_done = 1;
tbf->set_state(GPRS_RLCMAC_ASSIGN);
tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH);
tbf_timer_start(tbf, 3169, bts->t3169, 0);
tbf_timer_start(tbf, 3169, bts->t3169, 0, "allocation (UL-TBF)");
tbf->update_ms(tlli, GPRS_RLCMAC_UL_TBF);
OSMO_ASSERT(tbf->ms());
@ -464,7 +464,7 @@ void tbf_free(struct gprs_rlcmac_tbf *tbf)
tbf_name(tbf),
get_value_string(gprs_rlcmac_tbf_dl_ass_state_names,
tbf->dl_ass_state));
tbf->stop_timer();
tbf->stop_timer("freeing TBF");
/* TODO: Could/Should generate bssgp_tx_llc_discarded */
tbf_unlink_pdch(tbf);
llist_del(&tbf->list());
@ -529,13 +529,14 @@ const char *gprs_rlcmac_tbf::tbf_state_name[] = {
};
void tbf_timer_start(struct gprs_rlcmac_tbf *tbf, unsigned int T,
unsigned int seconds, unsigned int microseconds)
unsigned int seconds, unsigned int microseconds, const char *reason)
{
LOGPC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG, "%s %sstarting timer %u.",
tbf_name(tbf), osmo_timer_pending(&tbf->timer) ? "re" : "", T);
LOGPC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG,
"%s %sstarting timer T%u [%s] with %u sec. %u microsec.",
tbf_name(tbf), osmo_timer_pending(&tbf->timer) ? "re" : "", T, reason, seconds, microseconds);
if (T != tbf->T && osmo_timer_pending(&tbf->timer))
LOGPC(DRLCMAC, LOGL_ERROR, " while old timer %u pending", tbf->T);
LOGPC(DRLCMAC, LOGL_ERROR, " while old timer T%u pending", tbf->T);
LOGPC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG, "\n");
@ -551,14 +552,14 @@ void tbf_timer_start(struct gprs_rlcmac_tbf *tbf, unsigned int T,
void gprs_rlcmac_tbf::stop_t3191()
{
return stop_timer();
return stop_timer("T3191");
}
void gprs_rlcmac_tbf::stop_timer()
void gprs_rlcmac_tbf::stop_timer(const char *reason)
{
if (osmo_timer_pending(&timer)) {
LOGP(DRLCMAC, LOGL_DEBUG, "%s stopping timer %u.\n",
tbf_name(this), T);
LOGP(DRLCMAC, LOGL_DEBUG, "%s stopping timer T%u [%s]\n",
tbf_name(this), T, reason);
osmo_timer_del(&timer);
}
}
@ -662,7 +663,7 @@ void gprs_rlcmac_tbf::poll_timeout()
"- N3103 exceeded\n");
bts->pkt_ul_ack_nack_poll_failed();
ul_tbf->set_state(GPRS_RLCMAC_RELEASING);
tbf_timer_start(ul_tbf, 3169, ul_tbf->bts->bts_data()->t3169, 0);
tbf_timer_start(ul_tbf, 3169, ul_tbf->bts->bts_data()->t3169, 0, "MAX N3103 reached");
return;
}
/* reschedule UL ack */
@ -684,7 +685,7 @@ void gprs_rlcmac_tbf::poll_timeout()
if (n3105 == bts_data()->n3105) {
LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
set_state(GPRS_RLCMAC_RELEASING);
tbf_timer_start(this, 3195, bts_data()->t3195, 0);
tbf_timer_start(this, 3195, bts_data()->t3195, 0, "MAX N3105 reached");
bts->rlc_ass_failed();
bts->pua_poll_failed();
return;
@ -706,7 +707,7 @@ void gprs_rlcmac_tbf::poll_timeout()
if (n3105 == bts->bts_data()->n3105) {
LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
set_state(GPRS_RLCMAC_RELEASING);
tbf_timer_start(this, 3195, bts_data()->t3195, 0);
tbf_timer_start(this, 3195, bts_data()->t3195, 0, "MAX N3105 reached");
bts->rlc_ass_failed();
bts->pda_poll_failed();
return;
@ -732,7 +733,7 @@ void gprs_rlcmac_tbf::poll_timeout()
if (dl_tbf->n3105 == dl_tbf->bts->bts_data()->n3105) {
LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
dl_tbf->set_state(GPRS_RLCMAC_RELEASING);
tbf_timer_start(dl_tbf, 3195, dl_tbf->bts_data()->t3195, 0);
tbf_timer_start(dl_tbf, 3195, dl_tbf->bts_data()->t3195, 0, "MAX N3105 reached");
bts->pkt_dl_ack_nack_poll_failed();
bts->rlc_ack_failed();
return;
@ -1192,7 +1193,7 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
new_dl_tbf->set_state(GPRS_RLCMAC_FLOW);
tbf_assign_control_ts(new_dl_tbf);
/* stop pending assignment timer */
new_dl_tbf->stop_timer();
new_dl_tbf->stop_timer("assignment (DL-TBF)");
}
@ -1222,7 +1223,7 @@ struct msgb *gprs_rlcmac_tbf::create_packet_access_reject()
/* Start Tmr only if it is UL TBF */
if (direction == GPRS_RLCMAC_UL_TBF)
tbf_timer_start(this, 0, Treject_pacch);
tbf_timer_start(this, 0, Treject_pacch, "reject (PACCH)");
return msg;

4
src/tbf.h
View File

@ -174,7 +174,7 @@ struct gprs_rlcmac_tbf {
int update();
void handle_timeout();
void stop_timer();
void stop_timer(const char *reason);
void stop_t3191();
int establish_dl_tbf_on_pacch();
@ -330,7 +330,7 @@ struct gprs_rlcmac_ul_tbf *handle_tbf_reject(struct gprs_rlcmac_bts *bts,
int tbf_assign_control_ts(struct gprs_rlcmac_tbf *tbf);
void tbf_timer_start(struct gprs_rlcmac_tbf *tbf, unsigned int T,
unsigned int seconds, unsigned int microseconds);
unsigned int seconds, unsigned int microseconds, const char *reason);
inline bool gprs_rlcmac_tbf::state_is(enum gprs_rlcmac_tbf_state rhs) const
{

8
src/tbf_dl.cpp
View File

@ -488,7 +488,7 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(uint32_t fn, uint8_t ts)
void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf)
{
/* stop pending timer */
stop_timer();
stop_timer("assignment (DL-TBF)");
/* check for downlink tbf: */
if (old_tbf) {
@ -502,7 +502,7 @@ void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf)
state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH);
/* start timer */
tbf_timer_start(this, 0, Tassign_pacch);
tbf_timer_start(this, 0, Tassign_pacch, "assignment (PACCH)");
} else {
LOGP(DRLCMACDL, LOGL_DEBUG, "Send dowlink assignment for %s on PCH, no TBF exist (IMSI=%s)\n",
tbf_name(this), imsi());
@ -861,7 +861,7 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
m_tx_counter = 0;
/* start timer whenever we send the final block */
if (is_final)
tbf_timer_start(this, 3191, bts_data()->t3191, 0);
tbf_timer_start(this, 3191, bts_data()->t3191, 0, "final block (DL-TBF)");
clear_poll_timeout_flag();
@ -1126,7 +1126,7 @@ int gprs_rlcmac_dl_tbf::release()
/* start T3193 */
tbf_timer_start(this, 3193,
bts_data()->t3193_msec / 1000,
(bts_data()->t3193_msec % 1000) * 1000);
(bts_data()->t3193_msec % 1000) * 1000, "release (DL-TBF)");
/* reset rlc states */
m_tx_counter = 0;

2
src/tbf_ul.cpp
View File

@ -193,7 +193,7 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
unsigned int block_idx;
/* restart T3169 */
tbf_timer_start(this, 3169, bts_data()->t3169, 0);
tbf_timer_start(this, 3169, bts_data()->t3169, 0, "acked (data)");
/* Increment RX-counter */
this->m_rx_counter++;

630
tests/tbf/TbfTest.err
View File

File diff suppressed because it is too large Load Diff