TBF: add dedicated log categories

Previously all TBF-related events were logged as part of DRLCMAC which
is too broad to make it practically useful due to excessive amount of
log messages generated. Introduce dedicated log categories for
TBF-related events. Adjust test output as necessary.

Change-Id: I64d660e5971263d5c63d2ba95d50625c16a594aa
This commit is contained in:
Max 2018-01-19 18:22:25 +01:00
parent d81b3bf360
commit 0524e38d9e
8 changed files with 137182 additions and 5537 deletions

View File

@ -32,6 +32,9 @@ static const struct log_info_cat default_categories[] = {
{"DRLCMACUL", "\033[1;36m", "GPRS RLC/MAC layer Uplink (RLCMAC)", LOGL_NOTICE, 1},
{"DRLCMACSCHED", "\033[0;36m", "GPRS RLC/MAC layer Scheduling (RLCMAC)", LOGL_NOTICE, 1},
{"DRLCMACMEAS", "\033[1;31m", "GPRS RLC/MAC layer Measurements (RLCMAC)", LOGL_INFO, 1},
{"DTBF","\033[1;34m", "Temporary Block Flow (TBF)", LOGL_INFO , 1},
{"DTBFDL","\033[1;34m", "Temporary Block Flow (TBF) Downlink", LOGL_INFO , 1},
{"DTBFUL","\033[1;34m", "Temporary Block Flow (TBF) Uplink", LOGL_INFO , 1},
{"DNS","\033[1;34m", "GPRS Network Service Protocol (NS)", LOGL_INFO , 1},
{"DBSSGP","\033[1;34m", "GPRS BSS Gateway Protocol (BSSGP)", LOGL_INFO , 1},
{"DPCU", "\033[1;35m", "GPRS Packet Control Unit (PCU)", LOGL_NOTICE, 1},

View File

@ -37,6 +37,9 @@ enum {
DRLCMACUL,
DRLCMACSCHED,
DRLCMACMEAS,
DTBF,
DTBFDL,
DTBFUL,
DNS,
DBSSGP,
DPCU,

View File

@ -222,9 +222,8 @@ void gprs_rlcmac_tbf::assign_imsi(const char *imsi_)
GprsMs *old_ms;
if (!imsi_ || !m_ms) {
LOGP(DRLCMAC, LOGL_ERROR,
"%s failed to assign IMSI: missing IMSI or MS object\n",
name());
LOGPTBF(this, LOGL_ERROR,
"failed to assign IMSI: missing IMSI or MS object\n");
return;
}
@ -239,10 +238,10 @@ void gprs_rlcmac_tbf::assign_imsi(const char *imsi_)
* different IMSI */
OSMO_ASSERT(old_ms != m_ms);
LOGP(DRLCMAC, LOGL_INFO,
"%s the IMSI '%s' was already assigned to another "
LOGPTBF(this, LOGL_INFO,
"IMSI '%s' was already assigned to another "
"MS object: TLLI = 0x%08x, that IMSI will be removed\n",
name(), imsi_, old_ms->tlli());
imsi_, old_ms->tlli());
merge_and_clear_ms(old_ms);
}
@ -336,10 +335,8 @@ void gprs_rlcmac_tbf::merge_and_clear_ms(GprsMs *old_ms)
/* TODO: Use timer? */
if (old_ms->ul_tbf() && !old_ms->ul_tbf()->timers_pending(T_MAX)) {
if (old_ms->ul_tbf() == this) {
LOGP(DRLCMAC, LOGL_ERROR,
"%s is referred by the old MS "
"and will not be deleted\n",
name());
LOGPTBF(this, LOGL_ERROR,
"is referred by the old MS and will not be deleted\n");
set_ms(NULL);
} else {
tbf_free(old_ms->ul_tbf());
@ -347,10 +344,8 @@ void gprs_rlcmac_tbf::merge_and_clear_ms(GprsMs *old_ms)
}
if (old_ms->dl_tbf() && !old_ms->dl_tbf()->timers_pending(T_MAX)) {
if (old_ms->dl_tbf() == this) {
LOGP(DRLCMAC, LOGL_ERROR,
"%s is referred by the old MS "
"and will not be deleted\n",
name());
LOGPTBF(this, LOGL_ERROR,
"is referred by the old MS and will not be deleted\n");
set_ms(NULL);
} else {
tbf_free(old_ms->dl_tbf());
@ -397,7 +392,7 @@ gprs_rlcmac_ul_tbf *tbf_alloc_ul(struct gprs_rlcmac_bts *bts,
/* use multislot class of downlink TBF */
tbf = tbf_alloc_ul_tbf(bts, ms, use_trx, ms_class, egprs_ms_class, 0);
if (!tbf) {
LOGP(DRLCMAC, LOGL_NOTICE, "No PDCH resource\n");
LOGP(DTBF, LOGL_NOTICE, "No PDCH resource\n");
/* FIXME: send reject */
return NULL;
}
@ -482,7 +477,7 @@ void tbf_free(struct gprs_rlcmac_tbf *tbf)
rate_ctr_group_free(tbf->m_ctrs);
LOGP(DRLCMAC, LOGL_DEBUG, "********** %s-TBF ends here **********\n",
LOGP(DTBF, LOGL_DEBUG, "********** %s-TBF ends here **********\n",
(tbf->direction != GPRS_RLCMAC_UL_TBF) ? "DL" : "UL");
talloc_free(tbf);
}
@ -503,14 +498,14 @@ int gprs_rlcmac_tbf::update()
if (direction != GPRS_RLCMAC_DL_TBF)
return -EINVAL;
LOGP(DRLCMAC, LOGL_DEBUG, "********** DL-TBF update **********\n");
LOGP(DTBF, LOGL_DEBUG, "********** DL-TBF update **********\n");
tbf_unlink_pdch(this);
rc = bts_data->alloc_algorithm(bts_data, ms(), this,
bts_data->alloc_algorithm_curst, 0, -1);
/* if no resource */
if (rc < 0) {
LOGP(DRLCMAC, LOGL_ERROR, "No resource after update???\n");
LOGPTBF(this, LOGL_ERROR, "No resource after update???\n");
return -rc;
}
@ -606,7 +601,7 @@ void gprs_rlcmac_tbf::t_start(enum tbf_timers t, uint32_t sec, uint32_t microsec
const char *file, unsigned line)
{
if (t >= T_MAX) {
LOGPSRC(DRLCMAC, LOGL_ERROR, file, line, "%s attempting to start unknown timer %s [%s]\n",
LOGPSRC(DTBF, LOGL_ERROR, file, line, "%s attempting to start unknown timer %s [%s]\n",
tbf_name(this), get_value_string(tbf_timers_names, t), reason);
return;
}
@ -614,7 +609,7 @@ void gprs_rlcmac_tbf::t_start(enum tbf_timers t, uint32_t sec, uint32_t microsec
if (!force && osmo_timer_pending(&T[t]))
return;
LOGPSRC(DRLCMAC, LOGL_DEBUG, file, line, "%s %sstarting timer %s [%s] with %u sec. %u microsec.\n",
LOGPSRC(DTBF, LOGL_DEBUG, file, line, "%s %sstarting timer %s [%s] with %u sec. %u microsec.\n",
tbf_name(this), osmo_timer_pending(&T[t]) ? "re" : "",
get_value_string(tbf_timers_names, t), reason, sec, microsec);
@ -637,7 +632,7 @@ void gprs_rlcmac_tbf::t_start(enum tbf_timers t, uint32_t sec, uint32_t microsec
T[t].cb = cb_T3195;
break;
default:
LOGPSRC(DRLCMAC, LOGL_ERROR, file, line, "%s attempting to set callback for unknown timer %s [%s]\n",
LOGPSRC(DTBF, LOGL_ERROR, file, line, "%s attempting to set callback for unknown timer %s [%s]\n",
tbf_name(this), get_value_string(tbf_timers_names, t), reason);
}
@ -683,9 +678,9 @@ void gprs_rlcmac_tbf::set_polling(uint32_t new_poll_fn, uint8_t ts, enum gprs_rl
chan = "PACCH";
if ((state_flags & (1 << (GPRS_RLCMAC_FLAG_PACCH))) && (state_flags & (1 << (GPRS_RLCMAC_FLAG_CCCH))))
LOGP(DRLCMACDL, LOGL_ERROR,
"%s Attempt to schedule polling on %s (FN=%d, TS=%d) with both CCCH and PACCH flags set - FIXME!\n",
name(), chan, poll_fn, poll_ts);
LOGPTBFDL(this, LOGL_ERROR,
"Attempt to schedule polling on %s (FN=%d, TS=%d) with both CCCH and PACCH flags set - FIXME!\n",
chan, poll_fn, poll_ts);
/* schedule polling */
poll_state = GPRS_RLCMAC_POLL_SCHED;
@ -696,24 +691,24 @@ void gprs_rlcmac_tbf::set_polling(uint32_t new_poll_fn, uint8_t ts, enum gprs_rl
case GPRS_RLCMAC_POLL_UL_ASS:
ul_ass_state = GPRS_RLCMAC_UL_ASS_WAIT_ACK;
LOGP(DRLCMACDL, LOGL_INFO, "%s Scheduled UL Assignment polling on %s (FN=%d, TS=%d)\n",
name(), chan, poll_fn, poll_ts);
LOGPTBFDL(this, LOGL_INFO, "Scheduled UL Assignment polling on %s (FN=%d, TS=%d)\n",
chan, poll_fn, poll_ts);
break;
case GPRS_RLCMAC_POLL_DL_ASS:
dl_ass_state = GPRS_RLCMAC_DL_ASS_WAIT_ACK;
LOGP(DRLCMACDL, LOGL_INFO, "%s Scheduled DL Assignment polling on %s (FN=%d, TS=%d)\n",
name(), chan, poll_fn, poll_ts);
LOGPTBFDL(this, LOGL_INFO, "Scheduled DL Assignment polling on %s (FN=%d, TS=%d)\n",
chan, poll_fn, poll_ts);
break;
case GPRS_RLCMAC_POLL_UL_ACK:
ul_ack_state = GPRS_RLCMAC_UL_ACK_WAIT_ACK;
LOGP(DRLCMACUL, LOGL_DEBUG, "%s Scheduled UL Acknowledgement polling on %s (FN=%d, TS=%d)\n",
name(), chan, poll_fn, poll_ts);
LOGPTBFUL(this, LOGL_DEBUG, "Scheduled UL Acknowledgement polling on %s (FN=%d, TS=%d)\n",
chan, poll_fn, poll_ts);
break;
case GPRS_RLCMAC_POLL_DL_ACK:
LOGP(DRLCMACDL, LOGL_DEBUG, "%s Scheduled DL Acknowledgement polling on %s (FN=%d, TS=%d)\n",
name(), chan, poll_fn, poll_ts);
LOGPTBFDL(this, LOGL_DEBUG, "Scheduled DL Acknowledgement polling on %s (FN=%d, TS=%d)\n",
chan, poll_fn, poll_ts);
break;
}
}
@ -729,7 +724,7 @@ void gprs_rlcmac_tbf::poll_timeout()
m_n3101++;
if (m_n3101 == bts->bts_data()->n3101) {
LOGP(DRLCMAC, LOGL_NOTICE, " N3101 exceeded MAX (%u)\n", bts->bts_data()->n3101);
LOGPTBF(this, LOGL_NOTICE, "N3101 exceeded MAX (%u)\n", bts->bts_data()->n3101);
TBF_SET_STATE(this, GPRS_RLCMAC_RELEASING);
T_START(this, T3169, bts->bts_data()->t3169, 0, "MAX N3101 reached", false);
return;
@ -737,7 +732,7 @@ void gprs_rlcmac_tbf::poll_timeout()
if (ul_tbf && ul_tbf->handle_ctrl_ack()) {
if (!ul_tbf->ctrl_ack_to_toggle()) {
LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ACK\n");
LOGPTBF(this, LOGL_NOTICE, "Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ACK\n");
rlcmac_diag();
}
bts->rlc_ack_timedout();
@ -745,8 +740,7 @@ void gprs_rlcmac_tbf::poll_timeout()
if (state_is(GPRS_RLCMAC_FINISHED)) {
ul_tbf->m_n3103++;
if (ul_tbf->m_n3103 == ul_tbf->bts->bts_data()->n3103) {
LOGP(DRLCMAC, LOGL_NOTICE,
"- N3103 exceeded\n");
LOGPTBF(this, LOGL_NOTICE, "N3103 exceeded\n");
bts->pkt_ul_ack_nack_poll_failed();
TBF_SET_STATE(ul_tbf, GPRS_RLCMAC_RELEASING);
T_START(ul_tbf, T3169, ul_tbf->bts->bts_data()->t3169, 0, "MAX N3103 reached", false);
@ -758,18 +752,17 @@ void gprs_rlcmac_tbf::poll_timeout()
} else if (ul_ass_state == GPRS_RLCMAC_UL_ASS_WAIT_ACK) {
if (!(state_flags & (1 << GPRS_RLCMAC_FLAG_TO_UL_ASS))) {
LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling "
"PACKET CONTROL ACK for PACKET UPLINK "
"ASSIGNMENT.\n");
rlcmac_diag();
state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_UL_ASS);
LOGPTBF(this, LOGL_NOTICE,
"Timeout for polling PACKET CONTROL ACK for PACKET UPLINK ASSIGNMENT.\n");
rlcmac_diag();
state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_UL_ASS);
}
ul_ass_state = GPRS_RLCMAC_UL_ASS_NONE;
n3105++;
bts->rlc_ass_timedout();
bts->pua_poll_timedout();
if (n3105 == bts_data()->n3105) {
LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
LOGPTBF(this, LOGL_NOTICE, "N3105 exceeded\n");
TBF_SET_STATE(this, GPRS_RLCMAC_RELEASING);
T_START(this, T3195, bts_data()->t3195, 0, "MAX N3105 reached", true);
bts->rlc_ass_failed();
@ -780,9 +773,8 @@ void gprs_rlcmac_tbf::poll_timeout()
ul_ass_state = GPRS_RLCMAC_UL_ASS_SEND_ASS;
} else if (dl_ass_state == GPRS_RLCMAC_DL_ASS_WAIT_ACK) {
if (!(state_flags & (1 << GPRS_RLCMAC_FLAG_TO_DL_ASS))) {
LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling "
"PACKET CONTROL ACK for PACKET DOWNLINK "
"ASSIGNMENT.\n");
LOGPTBF(this, LOGL_NOTICE,
"Timeout for polling PACKET CONTROL ACK for PACKET DOWNLINK ASSIGNMENT.\n");
rlcmac_diag();
state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_DL_ASS);
}
@ -791,7 +783,7 @@ void gprs_rlcmac_tbf::poll_timeout()
bts->rlc_ass_timedout();
bts->pda_poll_timedout();
if (n3105 == bts->bts_data()->n3105) {
LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
LOGPTBF(this, LOGL_NOTICE, "N3105 exceeded\n");
TBF_SET_STATE(this, GPRS_RLCMAC_RELEASING);
T_START(this, T3195, bts_data()->t3195, 0, "MAX N3105 reached", true);
bts->rlc_ass_failed();
@ -804,8 +796,8 @@ void gprs_rlcmac_tbf::poll_timeout()
gprs_rlcmac_dl_tbf *dl_tbf = as_dl_tbf(this);
if (!(dl_tbf->state_flags & (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK))) {
LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling "
"PACKET DOWNLINK ACK.\n");
LOGPTBF(this, LOGL_NOTICE,
"Timeout for polling PACKET DOWNLINK ACK.\n");
dl_tbf->rlcmac_diag();
dl_tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK);
}
@ -817,7 +809,7 @@ void gprs_rlcmac_tbf::poll_timeout()
bts->pkt_dl_ack_nack_poll_timedout();
}
if (dl_tbf->n3105 == dl_tbf->bts->bts_data()->n3105) {
LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
LOGPTBF(this, LOGL_NOTICE, "N3105 exceeded\n");
TBF_SET_STATE(dl_tbf, GPRS_RLCMAC_RELEASING);
T_START(dl_tbf, T3195, dl_tbf->bts_data()->t3195, 0, "MAX N3105 reached", true);
bts->pkt_dl_ack_nack_poll_failed();
@ -834,7 +826,7 @@ void gprs_rlcmac_tbf::poll_timeout()
dl_tbf->m_wait_confirm = 1;
}
} else
LOGP(DRLCMAC, LOGL_ERROR, "- Poll Timeout, but no event!\n");
LOGPTBF(this, LOGL_ERROR, "Poll Timeout, but no event!\n");
}
static int setup_tbf(struct gprs_rlcmac_tbf *tbf,
@ -872,13 +864,13 @@ static int setup_tbf(struct gprs_rlcmac_tbf *tbf,
tbf->set_ms(ms);
LOGP(DRLCMAC, LOGL_INFO,
"Allocated %s: trx = %d, ul_slots = %02x, dl_slots = %02x\n",
tbf->name(), tbf->trx->trx_no, tbf->ul_slots(), tbf->dl_slots());
LOGPTBF(tbf, LOGL_INFO,
"Allocated: trx = %d, ul_slots = %02x, dl_slots = %02x\n",
tbf->trx->trx_no, tbf->ul_slots(), tbf->dl_slots());
tbf->m_ctrs = rate_ctr_group_alloc(tbf, &tbf_ctrg_desc, 0);
if (!tbf->m_ctrs) {
LOGP(DRLCMAC, LOGL_ERROR, "Couldn't allocate TBF counters\n");
LOGPTBF(tbf, LOGL_ERROR, "Couldn't allocate TBF counters\n");
return -1;
}
@ -923,14 +915,13 @@ struct gprs_rlcmac_ul_tbf *tbf_alloc_ul_tbf(struct gprs_rlcmac_bts *bts,
int rc;
if (egprs_ms_class == 0 && bts->egprs_enabled) {
LOGP(DRLCMAC, LOGL_NOTICE,
"Not accepting non-EGPRS phone in EGPRS-only mode\n");
LOGP(DTBF, LOGL_NOTICE, "Not accepting non-EGPRS phone in EGPRS-only mode\n");
bts->bts->tbf_failed_egprs_only();
return NULL;
}
LOGP(DRLCMAC, LOGL_DEBUG, "********** UL-TBF starts here **********\n");
LOGP(DRLCMAC, LOGL_INFO, "Allocating UL TBF: MS_CLASS=%d/%d\n",
LOGP(DTBF, LOGL_DEBUG, "********** UL-TBF starts here **********\n");
LOGP(DTBF, LOGL_INFO, "Allocating UL TBF: MS_CLASS=%d/%d\n",
ms_class, egprs_ms_class);
tbf = talloc(tall_pcu_ctx, struct gprs_rlcmac_ul_tbf);
@ -947,8 +938,8 @@ struct gprs_rlcmac_ul_tbf *tbf_alloc_ul_tbf(struct gprs_rlcmac_bts *bts,
if (egprs_ms_class > 0 && bts->egprs_enabled) {
tbf->enable_egprs();
setup_egprs_mode(bts, ms);
LOGP(DRLCMAC, LOGL_INFO, "Enabled EGPRS for %s, mode %s\n",
tbf->name(), GprsCodingScheme::modeName(ms->mode()));
LOGPTBF(tbf, LOGL_INFO, "Enabled EGPRS, mode %s\n",
GprsCodingScheme::modeName(ms->mode()));
}
rc = setup_tbf(tbf, ms, use_trx, ms_class, egprs_ms_class, single_slot);
@ -965,7 +956,7 @@ struct gprs_rlcmac_ul_tbf *tbf_alloc_ul_tbf(struct gprs_rlcmac_bts *bts,
tbf->m_ul_egprs_ctrs = rate_ctr_group_alloc(tbf, &tbf_ul_egprs_ctrg_desc, 0);
tbf->m_ul_gprs_ctrs = rate_ctr_group_alloc(tbf, &tbf_ul_gprs_ctrg_desc, 0);
if (!tbf->m_ul_egprs_ctrs || !tbf->m_ul_gprs_ctrs) {
LOGP(DRLCMAC, LOGL_ERROR, "Couldn't allocate TBF UL counters\n");
LOGPTBF(tbf, LOGL_ERROR, "Couldn't allocate TBF UL counters\n");
talloc_free(tbf);
return NULL;
}
@ -1014,16 +1005,15 @@ struct gprs_rlcmac_dl_tbf *tbf_alloc_dl_tbf(struct gprs_rlcmac_bts *bts,
if (egprs_ms_class == 0 && bts->egprs_enabled) {
if (ms_class > 0) {
LOGP(DRLCMAC, LOGL_NOTICE,
"Not accepting non-EGPRS phone in EGPRS-only mode\n");
LOGP(DTBF, LOGL_NOTICE, "Not accepting non-EGPRS phone in EGPRS-only mode\n");
bts->bts->tbf_failed_egprs_only();
return NULL;
}
egprs_ms_class = 1;
}
LOGP(DRLCMAC, LOGL_DEBUG, "********** DL-TBF starts here **********\n");
LOGP(DRLCMAC, LOGL_INFO, "Allocating DL TBF: MS_CLASS=%d/%d\n",
LOGP(DTBF, LOGL_DEBUG, "********** DL-TBF starts here **********\n");
LOGP(DTBF, LOGL_INFO, "Allocating DL TBF: MS_CLASS=%d/%d\n",
ms_class, egprs_ms_class);
tbf = talloc(tall_pcu_ctx, struct gprs_rlcmac_dl_tbf);
@ -1040,8 +1030,8 @@ struct gprs_rlcmac_dl_tbf *tbf_alloc_dl_tbf(struct gprs_rlcmac_bts *bts,
if (egprs_ms_class > 0 && bts->egprs_enabled) {
tbf->enable_egprs();
setup_egprs_mode(bts, ms);
LOGP(DRLCMAC, LOGL_INFO, "Enabled EGPRS for %s, mode %s\n",
tbf->name(), GprsCodingScheme::modeName(ms->mode()));
LOGPTBF(tbf, LOGL_INFO, "Enabled EGPRS, mode %s\n",
GprsCodingScheme::modeName(ms->mode()));
}
rc = setup_tbf(tbf, ms, use_trx, ms_class, 0, single_slot);
@ -1055,14 +1045,14 @@ struct gprs_rlcmac_dl_tbf *tbf_alloc_dl_tbf(struct gprs_rlcmac_bts *bts,
tbf->set_window_size();
tbf->m_dl_egprs_ctrs = rate_ctr_group_alloc(tbf, &tbf_dl_egprs_ctrg_desc, 0);
if (!tbf->m_dl_egprs_ctrs) {
LOGP(DRLCMAC, LOGL_ERROR, "Couldn't allocate EGPRS DL counters\n");
LOGPTBF(tbf, LOGL_ERROR, "Couldn't allocate EGPRS DL counters\n");
talloc_free(tbf);
return NULL;
}
} else {
tbf->m_dl_gprs_ctrs = rate_ctr_group_alloc(tbf, &tbf_dl_gprs_ctrg_desc, 0);
if (!tbf->m_dl_gprs_ctrs) {
LOGP(DRLCMAC, LOGL_ERROR, "Couldn't allocate GPRS DL counters\n");
LOGPTBF(tbf, LOGL_ERROR, "Couldn't allocate GPRS DL counters\n");
talloc_free(tbf);
return NULL;
}
@ -1132,17 +1122,17 @@ void gprs_rlcmac_tbf::handle_timeout()
int gprs_rlcmac_tbf::rlcmac_diag()
{
if ((state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH)))
LOGP(DRLCMAC, LOGL_NOTICE, "- Assignment was on CCCH\n");
LOGPTBF(this, LOGL_NOTICE, "Assignment was on CCCH\n");
if ((state_flags & (1 << GPRS_RLCMAC_FLAG_PACCH)))
LOGP(DRLCMAC, LOGL_NOTICE, "- Assignment was on PACCH\n");
LOGPTBF(this, LOGL_NOTICE, "Assignment was on PACCH\n");
if ((state_flags & (1 << GPRS_RLCMAC_FLAG_UL_DATA)))
LOGP(DRLCMAC, LOGL_NOTICE, "- Uplink data was received\n");
LOGPTBF(this, LOGL_NOTICE, "Uplink data was received\n");
else if (direction == GPRS_RLCMAC_UL_TBF)
LOGP(DRLCMAC, LOGL_NOTICE, "- No uplink data received yet\n");
LOGPTBF(this, LOGL_NOTICE, "No uplink data received yet\n");
if ((state_flags & (1 << GPRS_RLCMAC_FLAG_DL_ACK)))
LOGP(DRLCMAC, LOGL_NOTICE, "- Downlink ACK was received\n");
LOGPTBF(this, LOGL_NOTICE, "Downlink ACK was received\n");
else if (direction == GPRS_RLCMAC_DL_TBF)
LOGP(DRLCMAC, LOGL_NOTICE, "- No downlink ACK received yet\n");
LOGPTBF(this, LOGL_NOTICE, "No downlink ACK received yet\n");
return 0;
}
@ -1158,17 +1148,16 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
bool old_tfi_is_valid = is_tfi_assigned();
if (direction == GPRS_RLCMAC_DL_TBF && !is_control_ts(ts)) {
LOGP(DRLCMAC, LOGL_NOTICE, "Cannot poll for downlink "
"assigment, because MS cannot reply. (TS=%d, "
"first common TS=%d)\n", ts,
first_common_ts);
LOGPTBF(this, LOGL_NOTICE,
"Cannot poll for downlink assigment, because MS cannot reply. (TS=%d, first common TS=%d)\n",
ts, first_common_ts);
poll_ass_dl = 0;
}
if (poll_ass_dl) {
if (poll_state == GPRS_RLCMAC_POLL_SCHED &&
ul_ass_state == GPRS_RLCMAC_UL_ASS_WAIT_ACK)
{
LOGPTBFUL(this, LOGL_DEBUG,
LOGPTBF(this, LOGL_DEBUG,
"Polling is already scheduled, so we must wait for the uplink assignment...\n");
return NULL;
}
@ -1184,9 +1173,8 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
/* be sure to check first, if contention resolution is done,
* otherwise we cannot send the assignment yet */
if (!ul_tbf->m_contention_resolution_done) {
LOGP(DRLCMAC, LOGL_DEBUG, "Cannot assign DL TBF now, "
"because contention resolution is not "
"finished.\n");
LOGPTBF(this, LOGL_DEBUG,
"Cannot assign DL TBF now, because contention resolution is not finished.\n");
return NULL;
}
}
@ -1202,14 +1190,12 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
}
if (new_dl_tbf == as_dl_tbf(this))
LOGP(DRLCMAC, LOGL_DEBUG,
"New and old TBF are the same %s\n", name());
LOGPTBF(this, LOGL_DEBUG, "New and old TBF are the same.\n");
if (old_tfi_is_valid && !new_dl_tbf->is_tlli_valid()) {
LOGP(DRLCMACDL, LOGL_ERROR,
"The old TFI is not assigned and there is no "
"TLLI. Old TBF %s, new TBF %s\n",
name(), new_dl_tbf->name());
LOGPTBF(this, LOGL_ERROR,
"The old TFI is not assigned and there is no TLLI. New TBF %s\n",
new_dl_tbf->name());
dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
return NULL;
}
@ -1232,10 +1218,10 @@ 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(DTBF, LOGL_DEBUG, "+++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++\n");
encode_gsm_rlcmac_downlink(ass_vec, mac_control_block);
LOGPC(DCSN1, LOGL_NOTICE, "\n");
LOGP(DRLCMAC, LOGL_DEBUG, "------------------------- TX : Packet Downlink Assignment -------------------------\n");
LOGP(DTBF, LOGL_DEBUG, "------------------------- TX : Packet Downlink Assignment -------------------------\n");
bts->pkt_dl_assignemnt();
bitvec_pack(ass_vec, msgb_put(msg, 23));
bitvec_free(ass_vec);
@ -1329,10 +1315,10 @@ 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(DTBF, LOGL_DEBUG, "+++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++\n");
decode_gsm_rlcmac_downlink(ass_vec, mac_control_block);
LOGPC(DCSN1, LOGL_NOTICE, "\n");
LOGP(DRLCMAC, LOGL_DEBUG, "------------------------- TX : Packet Uplink Assignment -------------------------\n");
LOGP(DTBF, LOGL_DEBUG, "------------------------- TX : Packet Uplink Assignment -------------------------\n");
bts->pkt_ul_assignment();
bitvec_free(ass_vec);
talloc_free(mac_control_block);
@ -1373,7 +1359,7 @@ int gprs_rlcmac_tbf::establish_dl_tbf_on_pacch()
ms() ? ms()->egprs_ms_class() : 0, 0);
if (!new_tbf) {
LOGP(DRLCMAC, LOGL_NOTICE, "No PDCH resource\n");
LOGP(DTBF, LOGL_NOTICE, "No PDCH resource\n");
return -1;
}
@ -1536,7 +1522,7 @@ struct gprs_rlcmac_ul_tbf *handle_tbf_reject(struct gprs_rlcmac_bts *bts,
ul_tbf->m_ul_gprs_ctrs = rate_ctr_group_alloc(ul_tbf,
&tbf_ul_gprs_ctrg_desc, 0);
if (!ul_tbf->m_ctrs || !ul_tbf->m_ul_egprs_ctrs || !ul_tbf->m_ul_gprs_ctrs) {
LOGP(DRLCMAC, LOGL_ERROR, "Cound not allocate TBF UL rate counters\n");
LOGPTBF(ul_tbf, LOGL_ERROR, "Cound not allocate TBF UL rate counters\n");
talloc_free(ul_tbf);
return NULL;
}

View File

@ -143,9 +143,9 @@ enum tbf_egprs_ul_counters {
TBF_CTR_EGPRS_UL_MCS9,
};
#define LOGPTBF(tbf, level, fmt, args...) LOGP(DRLCMAC, level, "%s " fmt, tbf_name(tbf), ## args)
#define LOGPTBFUL(tbf, level, fmt, args...) LOGP(DRLCMACUL, level, "%s " fmt, tbf_name(tbf), ## args)
#define LOGPTBFDL(tbf, level, fmt, args...) LOGP(DRLCMACDL, level, "%s " fmt, tbf_name(tbf), ## args)
#define LOGPTBF(tbf, level, fmt, args...) LOGP(DTBF, level, "%s " fmt, tbf_name(tbf), ## args)
#define LOGPTBFUL(tbf, level, fmt, args...) LOGP(DTBFUL, level, "%s " fmt, tbf_name(tbf), ## args)
#define LOGPTBFDL(tbf, level, fmt, args...) LOGP(DTBFDL, level, "%s " fmt, tbf_name(tbf), ## args)
enum tbf_timers {
/* internal assign/reject timer */
@ -393,7 +393,7 @@ inline void gprs_rlcmac_tbf::set_assigned_on(uint8_t state_flag, bool check_ccch
inline void gprs_rlcmac_tbf::set_state(enum gprs_rlcmac_tbf_state new_state, const char *file, int line)
{
LOGPSRC(DRLCMAC, LOGL_DEBUG, file, line, "%s changes state from %s to %s\n",
LOGPSRC(DTBF, LOGL_DEBUG, file, line, "%s changes state from %s to %s\n",
tbf_name(this),
tbf_state_name[state], tbf_state_name[new_state]);
state = new_state;

View File

@ -147,7 +147,7 @@ static int tbf_new_dl_assignment(struct gprs_rlcmac_bts *bts,
dl_tbf = tbf_alloc_dl_tbf(bts, ms, use_trx, ms_class, egprs_ms_class, ss);
if (!dl_tbf) {
LOGP(DRLCMAC, LOGL_NOTICE, "No PDCH resource\n");
LOGP(DTBF, LOGL_NOTICE, "No PDCH resource\n");
return -EBUSY;
}
dl_tbf->update_ms(tlli, GPRS_RLCMAC_DL_TBF);
@ -197,19 +197,16 @@ int gprs_rlcmac_dl_tbf::handle(struct gprs_rlcmac_bts *bts,
if (ms_old && ms_old != ms) {
/* The TLLI has changed (RAU), so there are two MS
* objects for the same MS */
LOGP(DRLCMAC, LOGL_NOTICE,
"There is a new MS object for the same MS: "
"(0x%08x, '%s') -> (0x%08x, '%s')\n",
ms_old->tlli(), ms_old->imsi(),
ms->tlli(), ms->imsi());
LOGP(DTBF, LOGL_NOTICE,
"There is a new MS object for the same MS: (0x%08x, '%s') -> (0x%08x, '%s')\n",
ms_old->tlli(), ms_old->imsi(), ms->tlli(), ms->imsi());
GprsMs::Guard guard_old(ms_old);
if (!dl_tbf && ms_old->dl_tbf()) {
LOGP(DRLCMAC, LOGL_NOTICE,
"%s IMSI %s: "
"moving DL TBF to new MS object\n",
ms_old->dl_tbf()->name(), imsi);
LOGP(DTBF, LOGL_NOTICE,
"IMSI %s, old TBF %s: moving DL TBF to new MS object\n",
imsi, ms_old->dl_tbf()->name());
dl_tbf = ms_old->dl_tbf();
/* Move the DL TBF to the new MS */
dl_tbf->set_ms(ms);
@ -326,7 +323,7 @@ bool gprs_rlcmac_dl_tbf::restart_bsn_cycle()
* should never happen if MS works correctly.
*/
if (m_window.window_empty()) {
LOGP(DRLCMACDL, LOGL_DEBUG, "- MS acked all blocks\n");
LOGPTBFDL(this, LOGL_DEBUG, "MS acked all blocks\n");
return false;
}
@ -336,9 +333,8 @@ bool gprs_rlcmac_dl_tbf::restart_bsn_cycle()
/* At this point there should be at least one unacked block
* to be resent. If not, this is an software error. */
if (resend == 0) {
LOGP(DRLCMACDL, LOGL_ERROR, "Software error: "
"There are no unacknowledged blocks, but V(A) "
" != V(S). PLEASE FIX!\n");
LOGPTBFDL(this, LOGL_ERROR,
"FIXME: Software error: There are no unacknowledged blocks, but V(A) != V(S). PLEASE FIX!\n");
return false;
}
@ -377,15 +373,13 @@ int gprs_rlcmac_dl_tbf::take_next_bsn(uint32_t fn,
ms()->current_cs_dl(),
bts->bts_data()->dl_arq_type);
LOGP(DRLCMACDL, LOGL_DEBUG,
"- initial_cs_dl(%d) last_mcs(%d)"
" demanded_mcs(%d) cs_trans(%d)"
" arq_type(%d) bsn(%d)\n",
m_rlc.block(bsn)->cs_init.to_num(),
m_rlc.block(bsn)->cs_last.to_num(),
ms()->current_cs_dl().to_num(),
m_rlc.block(bsn)->cs_current_trans.to_num(),
bts->bts_data()->dl_arq_type, bsn);
LOGPTBFDL(this, LOGL_DEBUG,
"initial_cs_dl(%d) last_mcs(%d) demanded_mcs(%d) cs_trans(%d) arq_type(%d) bsn(%d)\n",
m_rlc.block(bsn)->cs_init.to_num(),
m_rlc.block(bsn)->cs_last.to_num(),
ms()->current_cs_dl().to_num(),
m_rlc.block(bsn)->cs_current_trans.to_num(),
bts->bts_data()->dl_arq_type, bsn);
/* TODO: Need to remove this check when MCS-8 -> MCS-6
* transistion is handled.
@ -401,21 +395,21 @@ int gprs_rlcmac_dl_tbf::take_next_bsn(uint32_t fn,
data_len2 = m_rlc.block(bsn)->len;
if (force_data_len > 0 && force_data_len != data_len2)
return -1;
LOGP(DRLCMACDL, LOGL_DEBUG, "- Resending BSN %d\n", bsn);
LOGPTBFDL(this, LOGL_DEBUG, "Resending BSN %d\n", bsn);
/* re-send block with negative aknowlegement */
m_window.m_v_b.mark_unacked(bsn);
bts->rlc_resent();
} else if (state_is(GPRS_RLCMAC_FINISHED)) {
LOGP(DRLCMACDL, LOGL_DEBUG, "- Restarting at BSN %d, "
"because all blocks have been transmitted.\n",
m_window.v_a());
LOGPTBFDL(this, LOGL_DEBUG,
"Restarting at BSN %d, because all blocks have been transmitted.\n",
m_window.v_a());
bts->rlc_restarted();
if (restart_bsn_cycle())
return take_next_bsn(fn, previous_bsn, may_combine);
} else if (dl_window_stalled()) {
LOGP(DRLCMACDL, LOGL_NOTICE, "- Restarting at BSN %d, "
"because the window is stalled.\n",
m_window.v_a());
LOGPTBFDL(this, LOGL_NOTICE,
"Restarting at BSN %d, because the window is stalled.\n",
m_window.v_a());
bts->rlc_stalled();
if (restart_bsn_cycle())
return take_next_bsn(fn, previous_bsn, may_combine);
@ -423,31 +417,31 @@ int gprs_rlcmac_dl_tbf::take_next_bsn(uint32_t fn,
GprsCodingScheme new_cs;
/* New blocks may be send */
new_cs = force_cs ? force_cs : current_cs();
LOGP(DRLCMACDL, LOGL_DEBUG,
"- Sending new block at BSN %d, CS=%s\n",
m_window.v_s(), new_cs.name());
LOGPTBFDL(this, LOGL_DEBUG,
"Sending new block at BSN %d, CS=%s\n",
m_window.v_s(), new_cs.name());
bsn = create_new_bsn(fn, new_cs);
} else if (!m_window.window_empty()) {
LOGP(DRLCMACDL, LOGL_DEBUG, "- Restarting at BSN %d, "
"because all blocks have been transmitted (FLOW).\n",
m_window.v_a());
LOGPTBFDL(this, LOGL_DEBUG,
"Restarting at BSN %d, because all blocks have been transmitted (FLOW).\n",
m_window.v_a());
bts->rlc_restarted();
if (restart_bsn_cycle())
return take_next_bsn(fn, previous_bsn, may_combine);
} else {
/* Nothing left to send, create dummy LLC commands */
LOGP(DRLCMACDL, LOGL_DEBUG,
"- Sending new dummy block at BSN %d, CS=%s\n",
m_window.v_s(), current_cs().name());
LOGPTBFDL(this, LOGL_DEBUG,
"Sending new dummy block at BSN %d, CS=%s\n",
m_window.v_s(), current_cs().name());
bsn = create_new_bsn(fn, current_cs());
/* Don't send a second block, so don't set cs_current_trans */
}
if (bsn < 0) {
/* we just send final block again */
LOGP(DRLCMACDL, LOGL_DEBUG,
"- Nothing else to send, Re-transmit final block!\n");
LOGPTBFDL(this, LOGL_DEBUG,
"Nothing else to send, Re-transmit final block!\n");
bsn = m_window.v_s_mod(-1);
bts->rlc_final_block_resent();
bts->rlc_resent();
@ -589,11 +583,9 @@ int gprs_rlcmac_dl_tbf::create_new_bsn(const uint32_t fn, GprsCodingScheme cs)
* arrive, so request a DL ack/nack now */
request_dl_ack();
LOGP(DRLCMACDL, LOGL_DEBUG,
"-- Empty chunk, "
"added LLC dummy command of size %d, "
"drained_since=%d\n",
m_llc.frame_length(), frames_since_last_drain(fn));
LOGPTBFDL(this, LOGL_DEBUG,
"Empty chunk, added LLC dummy command of size %d, drained_since=%d\n",
m_llc.frame_length(), frames_since_last_drain(fn));
}
is_final = llc_queue_size() == 0 && !keep_open(fn);
@ -621,9 +613,9 @@ int gprs_rlcmac_dl_tbf::create_new_bsn(const uint32_t fn, GprsCodingScheme cs)
schedule_next_frame();
} while (ar == Encoding::AR_COMPLETED_SPACE_LEFT);
LOGP(DRLCMACDL, LOGL_DEBUG, "data block (BSN %d, %s): %s\n",
bsn, rlc_data->cs_last.name(),
osmo_hexdump(rlc_data->block, block_data_len));
LOGPTBFDL(this, LOGL_DEBUG, "data block (BSN %d, %s): %s\n",
bsn, rlc_data->cs_last.name(),
osmo_hexdump(rlc_data->block, block_data_len));
/* raise send state and set ack state array */
m_window.m_v_b.mark_unacked(bsn);
m_window.increment_send();
@ -719,10 +711,8 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
spb = get_egprs_dl_spb(index);
LOGP(DRLCMACDL, LOGL_DEBUG, "- need_padding %d spb_status %d spb %d"
"(BSN1 %d BSN2 %d)\n",
need_padding,
spb_status, spb, index, index2);
LOGPTBFDL(this, LOGL_DEBUG, "need_padding %d spb_status %d spb %d (BSN1 %d BSN2 %d)\n",
need_padding, spb_status, spb, index, index2);
gprs_rlc_data_info_init_dl(&rlc, cs, need_padding, spb);
@ -741,7 +731,7 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
OSMO_ASSERT(rlc.num_data_blocks <= ARRAY_SIZE(rlc.block_info));
OSMO_ASSERT(rlc.num_data_blocks > 0);
LOGP(DRLCMACDL, LOGL_DEBUG, "- Copying %u RLC blocks, %u BSNs\n", rlc.num_data_blocks, num_bsns);
LOGPTBFDL(this, LOGL_DEBUG, "Copying %u RLC blocks, %u BSNs\n", rlc.num_data_blocks, num_bsns);
/* Copy block(s) to RLC message: the num_data_blocks cannot be more than 2 - see assert above */
for (data_block_idx = 0; data_block_idx < OSMO_MIN(rlc.num_data_blocks, 2);
@ -803,8 +793,8 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
rdbi->bsn = bsn;
is_final = is_final || rdbi->cv == 0;
LOGP(DRLCMACDL, LOGL_DEBUG, "- Copying data unit %d (BSN %d)\n",
data_block_idx, bsn);
LOGPTBFDL(this, LOGL_DEBUG, "Copying data unit %d (BSN %d)\n",
data_block_idx, bsn);
Encoding::rlc_copy_from_aligned_buffer(&rlc, data_block_idx,
msg_data, block_data);
@ -826,15 +816,15 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
if (m_tx_counter >= POLL_ACK_AFTER_FRAMES || m_dl_ack_requested ||
need_poll) {
if (m_dl_ack_requested) {
LOGP(DRLCMACDL, LOGL_DEBUG, "- Scheduling Ack/Nack "
"polling, because is was requested explicitly "
"(e.g. first final block sent).\n");
LOGPTBFDL(this, LOGL_DEBUG,
"Scheduling Ack/Nack polling, because is was requested explicitly "
"(e.g. first final block sent).\n");
} else if (need_poll) {
LOGP(DRLCMACDL, LOGL_DEBUG, "- Scheduling Ack/Nack "
"polling, because polling timed out.\n");
LOGPTBFDL(this, LOGL_DEBUG,
"Scheduling Ack/Nack polling, because polling timed out.\n");
} else {
LOGP(DRLCMACDL, LOGL_DEBUG, "- Scheduling Ack/Nack "
"polling, because %d blocks sent.\n",
LOGPTBFDL(this, LOGL_DEBUG,
"Scheduling Ack/Nack polling, because %d blocks sent.\n",
POLL_ACK_AFTER_FRAMES);
}
@ -858,18 +848,18 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
m_last_dl_poll_fn = poll_fn;
LOGP(DRLCMACDL, LOGL_INFO,
"%s Scheduled Ack/Nack polling on FN=%d, TS=%d\n",
name(), poll_fn, poll_ts);
LOGPTBFDL(this, LOGL_INFO,
"Scheduled Ack/Nack polling on FN=%d, TS=%d\n",
poll_fn, poll_ts);
}
}
Encoding::rlc_write_dl_data_header(&rlc, msg_data);
LOGP(DRLCMACDL, LOGL_DEBUG, "msg block (BSN %d, %s%s): %s\n",
index, cs.name(),
need_padding ? ", padded" : "",
msgb_hexdump(dl_msg));
LOGPTBFDL(this, LOGL_DEBUG, "msg block (BSN %d, %s%s): %s\n",
index, cs.name(),
need_padding ? ", padded" : "",
msgb_hexdump(dl_msg));
/* Increment TX-counter */
m_tx_counter++;
@ -953,10 +943,9 @@ int gprs_rlcmac_dl_tbf::analyse_errors(char *show_rbb, uint8_t ssn,
}
}
LOGP(DRLCMACDL, LOGL_DEBUG, "%s DL analysis, range=%d:%d, lost=%d, recv=%d, "
"skipped=%d, bsn=%d, info='%s'\n",
name(), m_window.v_a(), m_window.v_s(), lost, received,
skipped, bsn, info);
LOGPTBFDL(this, LOGL_DEBUG,
"DL analysis, range=%d:%d, lost=%d, recv=%d, skipped=%d, bsn=%d, info='%s'\n",
m_window.v_a(), m_window.v_s(), lost, received, skipped, bsn, info);
res->received_packets = received_packets;
res->lost_packets = lost_packets;
@ -990,9 +979,9 @@ int gprs_rlcmac_dl_tbf::update_window(unsigned first_bsn,
Decoding::extract_rbb(rbb, show_rbb);
/* show received array in debug */
LOGP(DRLCMACDL, LOGL_DEBUG, "- ack: (BSN=%d)\"%s\""
"(BSN=%d) R=ACK I=NACK\n", first_bsn,
show_rbb, m_window.mod_sns(behind_last_bsn - 1));
LOGPTBFDL(this, LOGL_DEBUG,
"ack: (BSN=%d)\"%s\"(BSN=%d) R=ACK I=NACK\n",
first_bsn, show_rbb, m_window.mod_sns(behind_last_bsn - 1));
error_rate = analyse_errors(show_rbb, behind_last_bsn, &ana_res);
@ -1014,11 +1003,9 @@ int gprs_rlcmac_dl_tbf::update_window(unsigned first_bsn,
/* show receive state array in debug (V(A)..V(S)-1) */
m_window.show_state(show_v_b);
LOGP(DRLCMACDL, LOGL_DEBUG, "- V(B): (V(A)=%d)\"%s\""
"(V(S)-1=%d) A=Acked N=Nacked U=Unacked "
"X=Resend-Unacked I=Invalid\n",
m_window.v_a(), show_v_b,
m_window.v_s_mod(-1));
LOGPTBFDL(this, LOGL_DEBUG,
"V(B): (V(A)=%d)\"%s\"(V(S)-1=%d) A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid\n",
m_window.v_a(), show_v_b, m_window.v_s_mod(-1));
return 0;
}
@ -1033,9 +1020,9 @@ int gprs_rlcmac_dl_tbf::update_window(const uint8_t ssn, const uint8_t *rbb)
Decoding::extract_rbb(rbb, show_rbb);
/* show received array in debug (bit 64..1) */
LOGP(DRLCMACDL, LOGL_DEBUG, "- ack: (BSN=%d)\"%s\""
"(BSN=%d) R=ACK I=NACK\n", m_window.mod_sns(ssn - 64),
show_rbb, m_window.mod_sns(ssn - 1));
LOGPTBFDL(this, LOGL_DEBUG,
"ack: (BSN=%d)\"%s\"(BSN=%d) R=ACK I=NACK\n",
m_window.mod_sns(ssn - 64), show_rbb, m_window.mod_sns(ssn - 1));
/* apply received array to receive state (SSN-64..SSN-1) */
/* calculate distance of ssn from V(S) */
@ -1072,16 +1059,13 @@ int gprs_rlcmac_dl_tbf::update_window(const uint8_t ssn, const uint8_t *rbb)
/* show receive state array in debug (V(A)..V(S)-1) */
m_window.show_state(show_v_b);
LOGP(DRLCMACDL, LOGL_DEBUG, "- V(B): (V(A)=%d)\"%s\""
"(V(S)-1=%d) A=Acked N=Nacked U=Unacked "
"X=Resend-Unacked I=Invalid\n",
m_window.v_a(), show_v_b,
m_window.v_s_mod(-1));
LOGPTBFDL(this, LOGL_DEBUG,
"V(B): (V(A)=%d)\"%s\"(V(S)-1=%d) A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid\n",
m_window.v_a(), show_v_b, m_window.v_s_mod(-1));
if (state_is(GPRS_RLCMAC_FINISHED) && m_window.window_empty()) {
LOGP(DRLCMACDL, LOGL_NOTICE, "Received acknowledge of "
"all blocks, but without final ack "
"inidcation (don't worry)\n");
LOGPTBFDL(this, LOGL_NOTICE,
"Received acknowledge of all blocks, but without final ack inidcation (don't worry)\n");
}
return 0;
}
@ -1164,12 +1148,11 @@ int gprs_rlcmac_dl_tbf::rcvd_dl_ack(bool final_ack, unsigned first_bsn,
rc = update_window(first_bsn, rbb);
if (final_ack) {
LOGP(DRLCMACDL, LOGL_DEBUG, "- Final ACK received.\n");
LOGPTBFDL(this, LOGL_DEBUG, "Final ACK received.\n");
rc = maybe_start_new_window();
} else if (state_is(GPRS_RLCMAC_FINISHED) && m_window.window_empty()) {
LOGP(DRLCMACDL, LOGL_NOTICE, "Received acknowledge of "
"all blocks, but without final ack "
"indication (don't worry)\n");
LOGPTBFDL(this, LOGL_NOTICE,
"Received acknowledge of all blocks, but without final ack indication (don't worry)\n");
}
return rc;
@ -1288,11 +1271,11 @@ enum egprs_rlc_dl_reseg_bsn_state
*block_data = &rlc_data->block[22];
break;
default:
LOGP(DRLCMACDL, LOGL_ERROR, "Software error: "
"--%s hit invalid condition. headerType(%d) "
" blockstatus(%d) cs(%s) PLEASE FIX!\n", name(),
cs_current_trans.headerTypeData(),
*block_status_dl, cs_init.name());
LOGPTBFDL(this, LOGL_ERROR,
"FIXME: Software error: hit invalid condition. "
"headerType(%d) blockstatus(%d) cs(%s) PLEASE FIX!\n",
cs_current_trans.headerTypeData(),
*block_status_dl, cs_init.name());
break;
}
@ -1369,8 +1352,8 @@ enum egprs_rlcmac_dl_spb gprs_rlcmac_dl_tbf::get_egprs_dl_spb(const int bsn)
void gprs_rlcmac_dl_tbf::set_window_size()
{
uint16_t ws = egprs_window_size(bts->bts_data(), dl_slots());
LOGP(DRLCMAC, LOGL_INFO, "%s: setting EGPRS DL window size to %u, base(%u) slots(%u) ws_pdch(%u)\n",
name(), ws, bts->bts_data()->ws_base, pcu_bitcount(dl_slots()), bts->bts_data()->ws_pdch);
LOGPTBFDL(this, LOGL_INFO, "setting EGPRS DL window size to %u, base(%u) slots(%u) ws_pdch(%u)\n",
ws, bts->bts_data()->ws_base, pcu_bitcount(dl_slots()), bts->bts_data()->ws_pdch);
m_window.set_ws(ws);
}

View File

@ -59,7 +59,7 @@ int gprs_rlcmac_ul_tbf::assemble_forward_llc(const gprs_rlc_data *_data)
int i, num_frames = 0;
uint32_t dummy_tlli;
LOGP(DRLCMACUL, LOGL_DEBUG, "- Assembling frames: (len=%d)\n", len);
LOGPTBFUL(this, LOGL_DEBUG, "Assembling frames: (len=%d)\n", len);
num_frames = Decoding::rlc_data_from_ul_data(
rdbi, cs, data, &(frames[0]), ARRAY_SIZE(frames),
@ -72,7 +72,7 @@ int gprs_rlcmac_ul_tbf::assemble_forward_llc(const gprs_rlc_data *_data)
if (frame->length) {
bts->rlc_ul_payload_bytes(frame->length);
LOGP(DRLCMACUL, LOGL_DEBUG, "-- Frame %d "
LOGPTBFUL(this, LOGL_DEBUG, "Frame %d "
"starts at offset %d, "
"length=%d, is_complete=%d\n",
i + 1, frame->offset, frame->length,
@ -174,7 +174,7 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
this->state_flags |= (1 << GPRS_RLCMAC_FLAG_UL_DATA);
LOGP(DRLCMACUL, LOGL_DEBUG, "UL DATA TFI=%d received (V(Q)=%d .. "
LOGPTBFUL(this, LOGL_DEBUG, "UL DATA TFI=%d received (V(Q)=%d .. "
"V(R)=%d)\n", rlc->tfi, this->m_window.v_q(),
this->m_window.v_r());
@ -203,34 +203,29 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
bool need_rlc_data = false;
struct gprs_rlc_data *block;
LOGP(DRLCMACUL, LOGL_DEBUG,
"%s: Got %s RLC data block: "
"CV=%d, BSN=%d, SPB=%d, "
"PI=%d, E=%d, TI=%d, bitoffs=%d\n",
name(), rlc->cs.name(),
rdbi->cv, rdbi->bsn, rdbi->spb,
rdbi->pi, rdbi->e, rdbi->ti,
rlc->data_offs_bits[block_idx]);
LOGPTBFUL(this, LOGL_DEBUG,
"Got %s RLC data block: CV=%d, BSN=%d, SPB=%d, PI=%d, E=%d, TI=%d, bitoffs=%d\n",
rlc->cs.name(),
rdbi->cv, rdbi->bsn, rdbi->spb,
rdbi->pi, rdbi->e, rdbi->ti,
rlc->data_offs_bits[block_idx]);
/* Check whether the block needs to be decoded */
if (!m_window.is_in_window(rdbi->bsn)) {
LOGP(DRLCMACUL, LOGL_DEBUG, "- BSN %d out of window "
"%d..%d (it's normal)\n", rdbi->bsn,
m_window.v_q(),
m_window.mod_sns(m_window.v_q() + ws - 1));
LOGPTBFUL(this, LOGL_DEBUG, "BSN %d out of window %d..%d (it's normal)\n",
rdbi->bsn,
m_window.v_q(), m_window.mod_sns(m_window.v_q() + ws - 1));
} else if (m_window.is_received(rdbi->bsn)) {
LOGP(DRLCMACUL, LOGL_DEBUG,
"- BSN %d already received\n", rdbi->bsn);
LOGPTBFUL(this, LOGL_DEBUG,
"BSN %d already received\n", rdbi->bsn);
} else {
need_rlc_data = true;
}
if (!is_tlli_valid()) {
if (!rdbi->ti) {
LOGP(DRLCMACUL, LOGL_NOTICE,
"%s: Missing TLLI within UL DATA.\n",
name());
LOGPTBFUL(this, LOGL_NOTICE, "Missing TLLI within UL DATA.\n");
continue;
}
need_rlc_data = true;
@ -241,9 +236,9 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
/* Store block and meta info to BSN buffer */
LOGP(DRLCMACUL, LOGL_DEBUG, "- BSN %d storing in window (%d..%d)\n",
rdbi->bsn, m_window.v_q(),
m_window.mod_sns(m_window.v_q() + ws - 1));
LOGPTBFUL(this, LOGL_DEBUG, "BSN %d storing in window (%d..%d)\n",
rdbi->bsn, m_window.v_q(),
m_window.mod_sns(m_window.v_q() + ws - 1));
block = m_rlc.block(rdbi->bsn);
OSMO_ASSERT(rdbi->data_len <= sizeof(block->block));
rlc_data = &(block->block[0]);
@ -264,9 +259,9 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
block_idx, data, rlc_data);
}
LOGP(DRLCMACUL, LOGL_DEBUG,
"%s: data_length=%d, data=%s\n",
name(), block->len, osmo_hexdump(rlc_data, block->len));
LOGPTBFUL(this, LOGL_DEBUG,
"data_length=%d, data=%s\n",
block->len, osmo_hexdump(rlc_data, block->len));
/* Get/Handle TLLI */
if (rdbi->ti) {
num_chunks = Decoding::rlc_data_from_ul_data(
@ -274,28 +269,27 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
if (num_chunks < 0) {
bts->decode_error();
LOGP(DRLCMACUL, LOGL_NOTICE,
"Failed to decode TLLI of %s UL DATA "
"TFI=%d.\n", rlc->cs.name(), rlc->tfi);
LOGPTBFUL(this, LOGL_NOTICE,
"Failed to decode TLLI of %s UL DATA TFI=%d.\n",
rlc->cs.name(), rlc->tfi);
m_window.invalidate_bsn(rdbi->bsn);
continue;
}
if (!this->is_tlli_valid()) {
if (!new_tlli) {
LOGP(DRLCMACUL, LOGL_NOTICE,
"%s: TLLI = 0 within UL DATA.\n",
name());
LOGPTBFUL(this, LOGL_NOTICE,
"TLLI = 0 within UL DATA.\n");
m_window.invalidate_bsn(rdbi->bsn);
continue;
}
LOGP(DRLCMACUL, LOGL_INFO,
"Decoded premier TLLI=0x%08x of "
"UL DATA TFI=%d.\n", tlli(), rlc->tfi);
LOGPTBFUL(this, LOGL_INFO,
"Decoded premier TLLI=0x%08x of UL DATA TFI=%d.\n",
tlli(), rlc->tfi);
set_tlli_from_ul(new_tlli);
} else if (new_tlli && new_tlli != tlli()) {
LOGP(DRLCMACUL, LOGL_NOTICE, "TLLI mismatch on UL "
"DATA TFI=%d. (Ignoring due to contention "
"resolution)\n", rlc->tfi);
LOGPTBFUL(this, LOGL_NOTICE,
"TLLI mismatch on UL DATA TFI=%d. (Ignoring due to contention resolution)\n",
rlc->tfi);
m_window.invalidate_bsn(rdbi->bsn);
continue;
}
@ -324,12 +318,11 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
const struct gprs_rlc_data_block_info *rdbi =
&block->block_info;
LOGP(DRLCMACUL, LOGL_DEBUG, "- No gaps in received block, "
"last block: BSN=%d CV=%d\n", rdbi->bsn,
rdbi->cv);
LOGPTBFUL(this, LOGL_DEBUG,
"No gaps in received block, last block: BSN=%d CV=%d\n",
rdbi->bsn, rdbi->cv);
if (rdbi->cv == 0) {
LOGP(DRLCMACUL, LOGL_DEBUG, "- Finished with UL "
"TBF\n");
LOGPTBFUL(this, LOGL_DEBUG, "Finished with UL TBF\n");
TBF_SET_STATE(this, GPRS_RLCMAC_FINISHED);
/* Reset N3103 counter. */
this->m_n3103 = 0;
@ -353,29 +346,29 @@ void gprs_rlcmac_ul_tbf::maybe_schedule_uplink_acknack(
(m_rx_counter % SEND_ACK_AFTER_FRAMES) == 0)
{
if (rlc->si) {
LOGP(DRLCMACUL, LOGL_NOTICE, "- Scheduling Ack/Nack, "
"because MS is stalled.\n");
LOGPTBFUL(this, LOGL_NOTICE,
"Scheduling Ack/Nack, because MS is stalled.\n");
}
if (have_ti) {
LOGP(DRLCMACUL, LOGL_DEBUG, "- Scheduling Ack/Nack, "
"because TLLI is included.\n");
LOGPTBFUL(this, LOGL_DEBUG,
"Scheduling Ack/Nack, because TLLI is included.\n");
}
if (state_is(GPRS_RLCMAC_FINISHED)) {
LOGP(DRLCMACUL, LOGL_DEBUG, "- Scheduling Ack/Nack, "
"because last block has CV==0.\n");
LOGPTBFUL(this, LOGL_DEBUG,
"Scheduling Ack/Nack, because last block has CV==0.\n");
}
if ((m_rx_counter % SEND_ACK_AFTER_FRAMES) == 0) {
LOGP(DRLCMACUL, LOGL_DEBUG, "- Scheduling Ack/Nack, "
"because %d frames received.\n",
SEND_ACK_AFTER_FRAMES);
LOGPTBFUL(this, LOGL_DEBUG,
"Scheduling Ack/Nack, because %d frames received.\n",
SEND_ACK_AFTER_FRAMES);
}
if (ul_ack_state == GPRS_RLCMAC_UL_ACK_NONE) {
/* trigger sending at next RTS */
ul_ack_state = GPRS_RLCMAC_UL_ACK_SEND_ACK;
} else {
/* already triggered */
LOGP(DRLCMACUL, LOGL_DEBUG, "- Sending Ack/Nack is "
"already triggered, don't schedule!\n");
LOGPTBFUL(this, LOGL_DEBUG,
"Sending Ack/Nack is already triggered, don't schedule!\n");
}
}
}
@ -419,21 +412,16 @@ egprs_rlc_ul_reseg_bsn_state gprs_rlcmac_ul_tbf::handle_egprs_ul_second_seg(
if (spb_status->block_status_ul &
EGPRS_RESEG_FIRST_SEG_RXD) {
LOGP(DRLCMACUL, LOGL_DEBUG,
"---%s: Second seg is received "
"first seg is already present "
"set the status to complete\n", name());
LOGPTBFUL(this, LOGL_DEBUG,
"Second seg is received first seg is already present set the status to complete\n");
spb_status->block_status_ul = EGPRS_RESEG_DEFAULT;
block->len += Decoding::rlc_copy_to_aligned_buffer(rlc,
block_idx, data, rlc_data + block->len);
block->block_info.data_len += rdbi->data_len;
} else if (spb_status->block_status_ul == EGPRS_RESEG_DEFAULT) {
LOGP(DRLCMACUL, LOGL_DEBUG,
"---%s: Second seg is received "
"first seg is not received "
"set the status to second seg received\n",
name());
LOGPTBFUL(this, LOGL_DEBUG,
"Second seg is received first seg is not received set the status to second seg received\n");
block->len = Decoding::rlc_copy_to_aligned_buffer(rlc,
block_idx, data,
@ -456,10 +444,8 @@ egprs_rlc_ul_reseg_bsn_state gprs_rlcmac_ul_tbf::handle_egprs_ul_first_seg(
bts->spb_uplink_first_segment();
if (spb_status->block_status_ul & EGPRS_RESEG_SECOND_SEG_RXD) {
LOGP(DRLCMACUL, LOGL_DEBUG,
"---%s: First seg is received "
"second seg is already present "
"set the status to complete\n", name());
LOGPTBFUL(this, LOGL_DEBUG,
"First seg is received second seg is already present set the status to complete\n");
block->len += Decoding::rlc_copy_to_aligned_buffer(rlc,
block_idx, data, rlc_data);
@ -467,11 +453,8 @@ egprs_rlc_ul_reseg_bsn_state gprs_rlcmac_ul_tbf::handle_egprs_ul_first_seg(
block->block_info.data_len = block->len;
spb_status->block_status_ul = EGPRS_RESEG_DEFAULT;
} else if (spb_status->block_status_ul == EGPRS_RESEG_DEFAULT) {
LOGP(DRLCMACUL, LOGL_DEBUG,
"---%s: First seg is received "
"second seg is not received "
"set the status to first seg "
"received\n", name());
LOGPTBFUL(this, LOGL_DEBUG,
"First seg is received second seg is not received set the status to first seg received\n");
spb_status->block_status_ul = EGPRS_RESEG_FIRST_SEG_RXD;
block->len = Decoding::rlc_copy_to_aligned_buffer(rlc,
@ -487,11 +470,9 @@ egprs_rlc_ul_reseg_bsn_state gprs_rlcmac_ul_tbf::handle_egprs_ul_spb(
{
const gprs_rlc_data_block_info *rdbi = &rlc->block_info[block_idx];
LOGP(DRLCMACUL, LOGL_DEBUG,
"--%s: Got SPB(%d) "
"cs(%s) data block with BSN (%d), "
"TFI(%d).\n", name(), rdbi->spb, rlc->cs.name(), rdbi->bsn,
rlc->tfi);
LOGPTBFUL(this, LOGL_DEBUG,
"Got SPB(%d) cs(%s) data block with BSN (%d), TFI(%d).\n",
rdbi->spb, rlc->cs.name(), rdbi->bsn, rlc->tfi);
egprs_rlc_ul_reseg_bsn_state assemble_status = EGPRS_RESEG_INVALID;
@ -503,10 +484,9 @@ egprs_rlc_ul_reseg_bsn_state gprs_rlcmac_ul_tbf::handle_egprs_ul_spb(
assemble_status = handle_egprs_ul_second_seg(rlc,
block, data, block_idx);
else {
LOGP(DRLCMACUL, LOGL_ERROR,
"--%s: spb(%d) Not supported SPB for this EGPRS "
"configuration\n",
name(), rdbi->spb);
LOGPTBFUL(this, LOGL_ERROR,
"spb(%d) Not supported SPB for this EGPRS configuration\n",
rdbi->spb);
}
/*
@ -517,23 +497,20 @@ egprs_rlc_ul_reseg_bsn_state gprs_rlcmac_ul_tbf::handle_egprs_ul_spb(
switch (GprsCodingScheme::Scheme(rlc->cs)) {
case GprsCodingScheme::MCS3 :
block->cs_last = GprsCodingScheme::MCS6;
LOGP(DRLCMACUL, LOGL_DEBUG,
"--%s: Upgrading to MCS6\n", name());
LOGPTBFUL(this, LOGL_DEBUG, "Upgrading to MCS6\n");
break;
case GprsCodingScheme::MCS2 :
block->cs_last = GprsCodingScheme::MCS5;
LOGP(DRLCMACUL, LOGL_DEBUG,
"--%s: Upgrading to MCS5\n", name());
LOGPTBFUL(this, LOGL_DEBUG, "Upgrading to MCS5\n");
break;
case GprsCodingScheme::MCS1 :
LOGP(DRLCMACUL, LOGL_DEBUG,
"--%s: Upgrading to MCS4\n", name());
LOGPTBFUL(this, LOGL_DEBUG, "Upgrading to MCS4\n");
block->cs_last = GprsCodingScheme::MCS4;
break;
default:
LOGP(DRLCMACUL, LOGL_ERROR,
"--%s: cs(%s) Error in Upgrading to higher MCS\n",
name(), rlc->cs.name());
LOGPTBFUL(this, LOGL_ERROR,
"cs(%s) Error in Upgrading to higher MCS\n",
rlc->cs.name());
break;
}
}
@ -609,7 +586,7 @@ void gprs_rlcmac_ul_tbf::update_coding_scheme_counter_ul(const GprsCodingScheme
void gprs_rlcmac_ul_tbf::set_window_size()
{
uint16_t ws = egprs_window_size(bts->bts_data(), ul_slots());
LOGP(DRLCMAC, LOGL_INFO, "%s: setting EGPRS UL window size to %u, base(%u) slots(%u) ws_pdch(%u)\n",
name(), ws, bts->bts_data()->ws_base, pcu_bitcount(ul_slots()), bts->bts_data()->ws_pdch);
LOGPTBFUL(this, LOGL_INFO, "setting EGPRS UL window size to %u, base(%u) slots(%u) ws_pdch(%u)\n",
ws, bts->bts_data()->ws_base, pcu_bitcount(ul_slots()), bts->bts_data()->ws_pdch);
m_window.set_ws(ws);
}

File diff suppressed because it is too large Load Diff

File diff suppressed because it is too large Load Diff