Introduce LOGTBF* for consistent logging
When troubleshooting complex issues with TBF lifecycle, it's much easier to follow the logs which are consistently formatted. Add LOGTBF*() macro similar to struct-specific log routines we use in other Osmocom project and use it to log TBF-related messages in a unified way. Tweak test output accordingly. Related: OS#2407 Change-Id: I388249afefc32d2f6e5cb5e5abc6daf4dbd284ea
This commit is contained in:
parent
ea9968f685
commit
c21f007277
80
src/bts.cpp
80
src/bts.cpp
|
@ -338,15 +338,13 @@ int BTS::add_paging(uint8_t chan_needed, uint8_t *identity_lv)
|
|||
}
|
||||
/* mark first slot found, if none is marked already */
|
||||
if (ts == 8 && first_ts >= 0) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "- %s uses "
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "uses "
|
||||
"TRX=%d TS=%d, so we mark\n",
|
||||
tbf_name(tbf),
|
||||
tbf->trx->trx_no, first_ts);
|
||||
slot_mask[tbf->trx->trx_no] |= (1 << first_ts);
|
||||
} else
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "- %s uses "
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "uses "
|
||||
"already marked TRX=%d TS=%d\n",
|
||||
tbf_name(tbf),
|
||||
tbf->trx->trx_no, ts);
|
||||
}
|
||||
}
|
||||
|
@ -690,17 +688,13 @@ int BTS::rcv_rach(uint16_t ra, uint32_t Fn, int16_t qta, uint8_t is_11bit,
|
|||
tbf->set_state(GPRS_RLCMAC_FLOW);
|
||||
tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_CCCH);
|
||||
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 "
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "[UPLINK] START\n");
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "RX: [PCU <- BTS] RACH "
|
||||
"qbit-ta=%d ra=0x%02x, Fn=%d "
|
||||
" (%d,%d,%d)\n",
|
||||
tbf_name(tbf),
|
||||
qta, ra, Fn, (Fn / (26 * 51)) % 32,
|
||||
Fn % 51, Fn % 26);
|
||||
LOGP(DRLCMAC, LOGL_INFO, "%s TX: START Immediate "
|
||||
"Assignment Uplink (AGCH)\n",
|
||||
tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_INFO, "TX: START Immediate Assignment Uplink (AGCH)\n");
|
||||
trx_no = tbf->trx->trx_no;
|
||||
ts_no = tbf->first_ts;
|
||||
usf = tbf->m_usf[ts_no];
|
||||
|
@ -812,7 +806,7 @@ void BTS::snd_dl_ass(gprs_rlcmac_tbf *tbf, uint8_t poll, const char *imsi)
|
|||
int plen;
|
||||
unsigned int ts = tbf->first_ts;
|
||||
|
||||
LOGP(DRLCMAC, LOGL_INFO, "TX: START %s Immediate Assignment Downlink (PCH)\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_INFO, "TX: START Immediate Assignment Downlink (PCH)\n");
|
||||
bitvec *immediate_assignment = bitvec_alloc(22, tall_pcu_ctx); /* without plen */
|
||||
bitvec_unhex(immediate_assignment, "2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b");
|
||||
/* use request reference that has maximum distance to current time,
|
||||
|
@ -1004,21 +998,21 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet,
|
|||
}
|
||||
tbf->update_ms(tlli, GPRS_RLCMAC_UL_TBF);
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "RX: [PCU <- BTS] %s Packet Control Ack\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "RX: [PCU <- BTS] Packet Control Ack\n");
|
||||
tbf->poll_state = GPRS_RLCMAC_POLL_NONE;
|
||||
|
||||
/* check if this control ack belongs to packet uplink ack */
|
||||
ul_tbf = as_ul_tbf(tbf);
|
||||
if (ul_tbf && ul_tbf->handle_ctrl_ack()) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "TBF: [UPLINK] END %s\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "[UPLINK] END\n");
|
||||
if (ul_tbf->ctrl_ack_to_toggle())
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "Recovered uplink ack for UL %s\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_NOTICE, "Recovered uplink ack for UL\n");
|
||||
|
||||
tbf_free(tbf);
|
||||
return;
|
||||
}
|
||||
if (tbf->dl_ass_state == GPRS_RLCMAC_DL_ASS_WAIT_ACK) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "TBF: [UPLINK] DOWNLINK ASSIGNED %s\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "[UPLINK] DOWNLINK ASSIGNED\n");
|
||||
/* reset N3105 */
|
||||
tbf->n3105 = 0;
|
||||
tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
|
||||
|
@ -1035,10 +1029,9 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet,
|
|||
|
||||
if ((new_tbf->state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH))) {
|
||||
/* We now know that the PACCH really existed */
|
||||
LOGP(DRLCMAC, LOGL_INFO,
|
||||
LOGPTBF(new_tbf, LOGL_INFO,
|
||||
"The TBF has been confirmed on the PACCH, "
|
||||
"changed type from CCCH to PACCH for %s\n",
|
||||
tbf_name(new_tbf));
|
||||
"changed type from CCCH to PACCH\n");
|
||||
new_tbf->state_flags &= ~(1 << GPRS_RLCMAC_FLAG_CCCH);
|
||||
new_tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH);
|
||||
}
|
||||
|
@ -1049,14 +1042,13 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet,
|
|||
(1 << GPRS_RLCMAC_FLAG_TO_DL_ASS))) {
|
||||
new_tbf->state_flags &=
|
||||
~(1 << GPRS_RLCMAC_FLAG_TO_DL_ASS);
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "Recovered downlink "
|
||||
"assignment for %s\n", tbf_name(new_tbf));
|
||||
LOGPTBF(new_tbf, LOGL_NOTICE, "Recovered downlink assignment\n");
|
||||
}
|
||||
tbf_assign_control_ts(new_tbf);
|
||||
return;
|
||||
}
|
||||
if (tbf->ul_ass_state == GPRS_RLCMAC_UL_ASS_WAIT_ACK) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "TBF: [DOWNLINK] UPLINK ASSIGNED %s\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "[DOWNLINK] UPLINK ASSIGNED\n");
|
||||
/* reset N3105 */
|
||||
tbf->n3105 = 0;
|
||||
tbf->ul_ass_state = GPRS_RLCMAC_UL_ASS_NONE;
|
||||
|
@ -1076,8 +1068,7 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet,
|
|||
(1 << GPRS_RLCMAC_FLAG_TO_UL_ASS))) {
|
||||
new_tbf->state_flags &=
|
||||
~(1 << GPRS_RLCMAC_FLAG_TO_UL_ASS);
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "Recovered uplink "
|
||||
"assignment for UL %s\n", tbf_name(new_tbf));
|
||||
LOGPTBF(new_tbf, LOGL_NOTICE, "Recovered uplink assignment for UL\n");
|
||||
}
|
||||
tbf_assign_control_ts(new_tbf);
|
||||
/* there might be LLC packets waiting in the queue, but the DL
|
||||
|
@ -1142,7 +1133,7 @@ static void get_meas(struct pcu_l1_meas *meas,
|
|||
for (i = 0; i < OSMO_MIN(ARRAY_SIZE(qr->Slot), ARRAY_SIZE(meas->ts)); i++)
|
||||
{
|
||||
if (qr->Slot[i].Exist) {
|
||||
LOGP(DRLCMAC, LOGL_INFO,
|
||||
LOGP(DRLCMAC, LOGL_DEBUG,
|
||||
"Channel quality report: i_level[%d] = %d\n",
|
||||
i, qr->Slot[i].I_LEVEL_TN);
|
||||
meas->set_ms_i_level(i, -2 * qr->Slot[i].I_LEVEL_TN);
|
||||
|
@ -1195,9 +1186,9 @@ void gprs_rlcmac_pdch::rcv_control_dl_ack_nack(Packet_Downlink_Ack_Nack_t *ack_n
|
|||
}
|
||||
|
||||
if (tbf->handle_ack_nack())
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "Recovered downlink ack for %s\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_NOTICE, "Recovered downlink ack\n");
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "RX: [PCU <- BTS] %s Packet Downlink Ack/Nack\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_DEBUG, "RX: [PCU <- BTS] Packet Downlink Ack/Nack\n");
|
||||
|
||||
bits.data = bits_data;
|
||||
bits.data_len = sizeof(bits_data);
|
||||
|
@ -1259,11 +1250,10 @@ void gprs_rlcmac_pdch::rcv_control_egprs_dl_ack_nack(EGPRS_PD_AckNack_t *ack_nac
|
|||
}
|
||||
|
||||
if (tbf->handle_ack_nack())
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "Recovered EGPRS downlink ack for %s\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_NOTICE, "Recovered EGPRS downlink ack\n");
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG,
|
||||
"RX: [PCU <- BTS] %s EGPRS Packet Downlink Ack/Nack\n",
|
||||
tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_DEBUG,
|
||||
"RX: [PCU <- BTS] EGPRS Packet Downlink Ack/Nack\n");
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "EGPRS ACK/NACK: "
|
||||
"ut: %d, final: %d, bow: %d, eow: %d, ssn: %d, have_crbb: %d, "
|
||||
|
@ -1348,19 +1338,17 @@ void gprs_rlcmac_pdch::rcv_resource_request(Packet_Resource_Request_t *request,
|
|||
/* We got a RACH so the MS was in packet idle mode and thus
|
||||
* didn't have any active TBFs */
|
||||
if (ul_tbf) {
|
||||
LOGP(DRLCMACUL, LOGL_NOTICE, "Got RACH from "
|
||||
"TLLI=0x%08x while %s still "
|
||||
"exists. Killing pending UL TBF\n",
|
||||
tlli, tbf_name(ul_tbf));
|
||||
LOGPTBFUL(ul_tbf, LOGL_NOTICE,
|
||||
"Got RACH from TLLI=0x%08x while TBF still exists. Killing pending UL TBF\n",
|
||||
tlli);
|
||||
tbf_free(ul_tbf);
|
||||
ul_tbf = NULL;
|
||||
}
|
||||
|
||||
if (dl_tbf) {
|
||||
LOGP(DRLCMACUL, LOGL_NOTICE, "Got RACH from "
|
||||
"TLLI=0x%08x while %s still exists. "
|
||||
"Release pending DL TBF\n", tlli,
|
||||
tbf_name(dl_tbf));
|
||||
LOGPTBFUL(dl_tbf, LOGL_NOTICE,
|
||||
"Got RACH from TLLI=0x%08x while TBF still exists. Release pending DL TBF\n",
|
||||
tlli);
|
||||
tbf_free(dl_tbf);
|
||||
dl_tbf = NULL;
|
||||
}
|
||||
|
@ -1400,8 +1388,8 @@ void gprs_rlcmac_pdch::rcv_resource_request(Packet_Resource_Request_t *request,
|
|||
}
|
||||
|
||||
/* set control ts to current MS's TS, until assignment complete */
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "%s change control TS %d -> %d until assinment is complete.\n",
|
||||
tbf_name(ul_tbf), ul_tbf->control_ts, ts_no);
|
||||
LOGPTBF(ul_tbf, LOGL_DEBUG, "change control TS %d -> %d until assinment is complete.\n",
|
||||
ul_tbf->control_ts, ts_no);
|
||||
|
||||
ul_tbf->control_ts = ts_no;
|
||||
/* schedule uplink assignment */
|
||||
|
@ -1427,9 +1415,8 @@ void gprs_rlcmac_pdch::rcv_resource_request(Packet_Resource_Request_t *request,
|
|||
LOGP(DRLCMAC, LOGL_NOTICE, "PACKET RESSOURCE REQ unknown downlink TFI=%d\n", tfi);
|
||||
return;
|
||||
}
|
||||
LOGP(DRLCMAC, LOGL_ERROR,
|
||||
"RX: [PCU <- BTS] %s FIXME: Packet resource request\n",
|
||||
tbf_name(dl_tbf));
|
||||
LOGPTBFDL(dl_tbf, LOGL_ERROR,
|
||||
"RX: [PCU <- BTS] FIXME: Packet resource request\n");
|
||||
} else {
|
||||
struct gprs_rlcmac_ul_tbf *ul_tbf;
|
||||
int8_t tfi = request->ID.u.Global_TFI.u.UPLINK_TFI;
|
||||
|
@ -1438,9 +1425,8 @@ void gprs_rlcmac_pdch::rcv_resource_request(Packet_Resource_Request_t *request,
|
|||
LOGP(DRLCMAC, LOGL_NOTICE, "PACKET RESSOURCE REQ unknown uplink TFI=%d\n", tfi);
|
||||
return;
|
||||
}
|
||||
LOGP(DRLCMAC, LOGL_ERROR,
|
||||
"RX: [PCU <- BTS] %s FIXME: Packet resource request\n",
|
||||
tbf_name(ul_tbf));
|
||||
LOGPTBFUL(ul_tbf, LOGL_ERROR,
|
||||
"RX: [PCU <- BTS] %s FIXME: Packet resource request\n");
|
||||
}
|
||||
}
|
||||
|
||||
|
|
111
src/tbf.cpp
111
src/tbf.cpp
|
@ -446,21 +446,19 @@ void tbf_free(struct gprs_rlcmac_tbf *tbf)
|
|||
dl_tbf->cleanup();
|
||||
}
|
||||
|
||||
LOGP(DRLCMAC, LOGL_INFO, "%s free\n", tbf_name(tbf));
|
||||
LOGPTBF(tbf, LOGL_INFO, "free\n");
|
||||
if (tbf->ul_ass_state != GPRS_RLCMAC_UL_ASS_NONE)
|
||||
LOGP(DRLCMAC, LOGL_ERROR, "%s Software error: Pending uplink "
|
||||
LOGPTBF(tbf, LOGL_ERROR, "Software error: Pending uplink "
|
||||
"assignment in state %s. This may not happen, because the "
|
||||
"assignment message never gets transmitted. Please "
|
||||
"be sure not to free in this state. PLEASE FIX!\n",
|
||||
tbf_name(tbf),
|
||||
get_value_string(gprs_rlcmac_tbf_ul_ass_state_names,
|
||||
tbf->ul_ass_state));
|
||||
if (tbf->dl_ass_state != GPRS_RLCMAC_DL_ASS_NONE)
|
||||
LOGP(DRLCMAC, LOGL_ERROR, "%s Software error: Pending downlink "
|
||||
LOGPTBF(tbf, LOGL_ERROR, "Software error: Pending downlink "
|
||||
"assignment in state %s. This may not happen, because the "
|
||||
"assignment message never gets transmitted. Please "
|
||||
"be sure not to free in this state. PLEASE FIX!\n",
|
||||
tbf_name(tbf),
|
||||
get_value_string(gprs_rlcmac_tbf_dl_ass_state_names,
|
||||
tbf->dl_ass_state));
|
||||
tbf->stop_timer("freeing TBF");
|
||||
|
@ -473,7 +471,8 @@ void tbf_free(struct gprs_rlcmac_tbf *tbf)
|
|||
|
||||
rate_ctr_group_free(tbf->m_ctrs);
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "********** TBF ends here **********\n");
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "********** %s-TBF ends here **********\n",
|
||||
(tbf->direction != GPRS_RLCMAC_UL_TBF) ? "DL" : "UL");
|
||||
talloc_free(tbf);
|
||||
}
|
||||
|
||||
|
@ -482,11 +481,11 @@ int gprs_rlcmac_tbf::update()
|
|||
struct gprs_rlcmac_bts *bts_data = bts->bts_data();
|
||||
int rc;
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "********** TBF update **********\n");
|
||||
|
||||
if (direction != GPRS_RLCMAC_DL_TBF)
|
||||
return -EINVAL;
|
||||
|
||||
LOGP(DRLCMAC, 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);
|
||||
|
@ -508,10 +507,10 @@ int gprs_rlcmac_tbf::update()
|
|||
int tbf_assign_control_ts(struct gprs_rlcmac_tbf *tbf)
|
||||
{
|
||||
if (tbf->control_ts == 0xff)
|
||||
LOGP(DRLCMAC, LOGL_INFO, "- Setting Control TS %d\n",
|
||||
LOGPTBF(tbf, LOGL_INFO, "Setting Control TS %d\n",
|
||||
tbf->first_common_ts);
|
||||
else if (tbf->control_ts != tbf->first_common_ts)
|
||||
LOGP(DRLCMAC, LOGL_INFO, "- Changing Control TS %d\n",
|
||||
LOGPTBF(tbf, LOGL_INFO, "Changing Control TS %d\n",
|
||||
tbf->first_common_ts);
|
||||
tbf->control_ts = tbf->first_common_ts;
|
||||
|
||||
|
@ -556,8 +555,8 @@ void gprs_rlcmac_tbf::stop_t3191()
|
|||
void gprs_rlcmac_tbf::stop_timer(const char *reason)
|
||||
{
|
||||
if (osmo_timer_pending(&timer)) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "%s stopping timer T%u [%s]\n",
|
||||
tbf_name(this), T, reason);
|
||||
LOGPTBF(this, LOGL_DEBUG, "stopping timer T%u [%s]\n",
|
||||
T, reason);
|
||||
osmo_timer_del(&timer);
|
||||
}
|
||||
}
|
||||
|
@ -568,21 +567,19 @@ int gprs_rlcmac_tbf::check_polling(uint32_t fn, uint8_t ts,
|
|||
uint32_t new_poll_fn = next_fn(fn, 13);
|
||||
|
||||
if (!is_control_ts(ts)) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "Polling cannot be "
|
||||
LOGPTBF(this, LOGL_DEBUG, "Polling cannot be "
|
||||
"scheduled in this TS %d (first control TS %d)\n",
|
||||
ts, control_ts);
|
||||
return -EINVAL;
|
||||
}
|
||||
if (poll_state != GPRS_RLCMAC_POLL_NONE) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG,
|
||||
"Polling is already scheduled for %s\n",
|
||||
name());
|
||||
LOGPTBF(this, LOGL_DEBUG, "Polling is already scheduled\n");
|
||||
return -EBUSY;
|
||||
}
|
||||
if (bts->sba()->find(trx->trx_no, ts, next_fn(fn, 13))) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "%s: Polling is already scheduled "
|
||||
LOGPTBF(this, LOGL_DEBUG, "Polling is already scheduled "
|
||||
"for single block allocation at FN %d TS %d ...\n",
|
||||
name(), new_poll_fn, ts);
|
||||
new_poll_fn, ts);
|
||||
return -EBUSY;
|
||||
}
|
||||
|
||||
|
@ -642,8 +639,8 @@ void gprs_rlcmac_tbf::poll_timeout()
|
|||
{
|
||||
gprs_rlcmac_ul_tbf *ul_tbf = as_ul_tbf(this);
|
||||
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "%s poll timeout for FN=%d, TS=%d (curr FN %d)\n",
|
||||
tbf_name(this), poll_fn, poll_ts, bts->current_frame_number());
|
||||
LOGPTBF(this, LOGL_NOTICE, "poll timeout for FN=%d, TS=%d (curr FN %d)\n",
|
||||
poll_fn, poll_ts, bts->current_frame_number());
|
||||
|
||||
poll_state = GPRS_RLCMAC_POLL_NONE;
|
||||
|
||||
|
@ -739,9 +736,7 @@ void gprs_rlcmac_tbf::poll_timeout()
|
|||
/* resend IMM.ASS on CCCH on timeout */
|
||||
if ((dl_tbf->state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH))
|
||||
&& !(dl_tbf->state_flags & (1 << GPRS_RLCMAC_FLAG_DL_ACK))) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "Re-send dowlink assignment "
|
||||
"for %s on PCH (IMSI=%s)\n",
|
||||
tbf_name(dl_tbf),
|
||||
LOGPTBF(dl_tbf, LOGL_DEBUG, "Re-send dowlink assignment on PCH (IMSI=%s)\n",
|
||||
imsi());
|
||||
/* send immediate assignment */
|
||||
dl_tbf->bts->snd_dl_ass(dl_tbf, 0, imsi());
|
||||
|
@ -843,9 +838,9 @@ struct gprs_rlcmac_ul_tbf *tbf_alloc_ul_tbf(struct gprs_rlcmac_bts *bts,
|
|||
return NULL;
|
||||
}
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "********** TBF starts here **********\n");
|
||||
LOGP(DRLCMAC, LOGL_INFO, "Allocating %s TBF: MS_CLASS=%d/%d\n",
|
||||
"UL", ms_class, egprs_ms_class);
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "********** UL-TBF starts here **********\n");
|
||||
LOGP(DRLCMAC, 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);
|
||||
|
||||
|
@ -936,9 +931,9 @@ struct gprs_rlcmac_dl_tbf *tbf_alloc_dl_tbf(struct gprs_rlcmac_bts *bts,
|
|||
egprs_ms_class = 1;
|
||||
}
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "********** TBF starts here **********\n");
|
||||
LOGP(DRLCMAC, LOGL_INFO, "Allocating %s TBF: MS_CLASS=%d/%d\n",
|
||||
"DL", ms_class, egprs_ms_class);
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "********** DL-TBF starts here **********\n");
|
||||
LOGP(DRLCMAC, 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);
|
||||
|
||||
|
@ -1002,20 +997,19 @@ static void tbf_timer_cb(void *_tbf)
|
|||
|
||||
void gprs_rlcmac_tbf::handle_timeout()
|
||||
{
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "%s timer %u expired.\n",
|
||||
tbf_name(this), T);
|
||||
LOGPTBF(this, LOGL_DEBUG, "timer %u expired.\n", T);
|
||||
|
||||
switch (T) {
|
||||
case 0: /* assignment */
|
||||
if ((state_flags & (1 << GPRS_RLCMAC_FLAG_PACCH))) {
|
||||
if (state_is(GPRS_RLCMAC_ASSIGN)) {
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "%s releasing due to "
|
||||
"PACCH assignment timeout.\n", tbf_name(this));
|
||||
LOGPTBF(this, LOGL_NOTICE,
|
||||
"releasing due to PACCH assignment timeout.\n");
|
||||
tbf_free(this);
|
||||
return;
|
||||
} else
|
||||
LOGP(DRLCMAC, LOGL_ERROR, "Error: %s is not "
|
||||
"in assign state\n", tbf_name(this));
|
||||
LOGPTBF(this, LOGL_ERROR,
|
||||
"Error: TBF is not in assign state\n");
|
||||
}
|
||||
if ((state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH))) {
|
||||
gprs_rlcmac_dl_tbf *dl_tbf = as_dl_tbf(this);
|
||||
|
@ -1042,15 +1036,15 @@ void gprs_rlcmac_tbf::handle_timeout()
|
|||
|
||||
dl_tbf->trigger_ass(dl_tbf);
|
||||
} else
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "%s Continue flow after "
|
||||
"IMM.ASS confirm\n", tbf_name(dl_tbf));
|
||||
LOGPTBF(dl_tbf, LOGL_NOTICE,
|
||||
"Continue flow after IMM.ASS confirm\n");
|
||||
}
|
||||
break;
|
||||
case 3169:
|
||||
case 3191:
|
||||
case 3195:
|
||||
LOGP(DRLCMAC, LOGL_NOTICE, "%s T%d timeout during "
|
||||
"transsmission\n", tbf_name(this), T);
|
||||
LOGPTBF(this, LOGL_NOTICE, "T%d timeout during "
|
||||
"transsmission\n", T);
|
||||
rlcmac_diag();
|
||||
/* fall through */
|
||||
case 3193:
|
||||
|
@ -1105,9 +1099,8 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
|
|||
if (poll_state == GPRS_RLCMAC_POLL_SCHED &&
|
||||
ul_ass_state == GPRS_RLCMAC_UL_ASS_WAIT_ACK)
|
||||
{
|
||||
LOGP(DRLCMACUL, LOGL_DEBUG, "Polling is already "
|
||||
"scheduled for %s, so we must wait for the uplink "
|
||||
"assignment...\n", tbf_name(this));
|
||||
LOGPTBFUL(this, LOGL_DEBUG,
|
||||
"Polling is already scheduled, so we must wait for the uplink assignment...\n");
|
||||
return NULL;
|
||||
}
|
||||
rc = check_polling(fn, ts, &new_poll_fn, &rrbp);
|
||||
|
@ -1133,9 +1126,8 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
|
|||
new_dl_tbf = ms()->dl_tbf();
|
||||
|
||||
if (!new_dl_tbf) {
|
||||
LOGP(DRLCMACDL, LOGL_ERROR, "We have a schedule for downlink "
|
||||
"assignment at %s, but there is no downlink "
|
||||
"TBF\n", tbf_name(this));
|
||||
LOGPTBFDL(this, LOGL_ERROR,
|
||||
"We have a schedule for downlink assignment, but there is no downlink TBF\n");
|
||||
dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
|
||||
return NULL;
|
||||
}
|
||||
|
@ -1164,7 +1156,7 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts)
|
|||
}
|
||||
bitvec_unhex(ass_vec,
|
||||
"2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b");
|
||||
LOGP(DRLCMAC, LOGL_INFO, "%s start Packet Downlink Assignment (PACCH)\n", tbf_name(new_dl_tbf));
|
||||
LOGPTBF(new_dl_tbf, LOGL_INFO, "start Packet Downlink Assignment (PACCH)\n");
|
||||
RlcMacDownlink_t * mac_control_block = (RlcMacDownlink_t *)talloc_zero(tall_pcu_ctx, RlcMacDownlink_t);
|
||||
Encoding::write_packet_downlink_assignment(mac_control_block,
|
||||
old_tfi_is_valid, m_tfi, (direction == GPRS_RLCMAC_DL_TBF),
|
||||
|
@ -1233,9 +1225,8 @@ struct msgb *gprs_rlcmac_tbf::create_ul_ass(uint32_t fn, uint8_t ts)
|
|||
|
||||
if (poll_state == GPRS_RLCMAC_POLL_SCHED &&
|
||||
ul_ass_state == GPRS_RLCMAC_UL_ASS_WAIT_ACK) {
|
||||
LOGP(DRLCMACUL, LOGL_DEBUG, "Polling is already "
|
||||
"scheduled for %s, so we must wait for the uplink "
|
||||
"assignment...\n", tbf_name(this));
|
||||
LOGPTBFUL(this, LOGL_DEBUG,
|
||||
"Polling is already scheduled, so we must wait for the uplink assignment...\n");
|
||||
return NULL;
|
||||
}
|
||||
|
||||
|
@ -1246,9 +1237,8 @@ struct msgb *gprs_rlcmac_tbf::create_ul_ass(uint32_t fn, uint8_t ts)
|
|||
if (ms())
|
||||
new_tbf = ms()->ul_tbf();
|
||||
if (!new_tbf) {
|
||||
LOGP(DRLCMACUL, LOGL_ERROR, "We have a schedule for uplink "
|
||||
"assignment at downlink %s, but there is no uplink "
|
||||
"TBF\n", tbf_name(this));
|
||||
LOGPTBFUL(this, LOGL_ERROR,
|
||||
"We have a schedule for uplink assignment, but there is no uplink TBF\n");
|
||||
ul_ass_state = GPRS_RLCMAC_UL_ASS_NONE;
|
||||
return NULL;
|
||||
}
|
||||
|
@ -1256,7 +1246,7 @@ struct msgb *gprs_rlcmac_tbf::create_ul_ass(uint32_t fn, uint8_t ts)
|
|||
msg = msgb_alloc(23, "rlcmac_ul_ass");
|
||||
if (!msg)
|
||||
return NULL;
|
||||
LOGP(DRLCMAC, LOGL_INFO, "%ss start Packet Uplink Assignment (PACCH)\n", tbf_name(new_tbf));
|
||||
LOGPTBF(new_tbf, LOGL_INFO, "start Packet Uplink Assignment (PACCH)\n");
|
||||
bitvec *ass_vec = bitvec_alloc(23, tall_pcu_ctx);
|
||||
if (!ass_vec) {
|
||||
msgb_free(msg);
|
||||
|
@ -1318,8 +1308,7 @@ int gprs_rlcmac_tbf::establish_dl_tbf_on_pacch()
|
|||
return -1;
|
||||
}
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "%s Trigger downlink assignment on PACCH\n",
|
||||
tbf_name(this));
|
||||
LOGPTBF(this, LOGL_DEBUG, "Trigger downlink assignment on PACCH\n");
|
||||
new_tbf->trigger_ass(this);
|
||||
|
||||
return 0;
|
||||
|
@ -1346,18 +1335,14 @@ int gprs_rlcmac_tbf::set_tlli_from_ul(uint32_t new_tlli)
|
|||
}
|
||||
|
||||
if (dl_tbf && dl_tbf->ms() != ms()) {
|
||||
LOGP(DRLCMACUL, LOGL_NOTICE, "Got RACH from "
|
||||
"TLLI=0x%08x while %s still exists. "
|
||||
"Killing pending DL TBF\n", new_tlli,
|
||||
tbf_name(dl_tbf));
|
||||
LOGPTBFUL(dl_tbf, LOGL_NOTICE,
|
||||
"Got RACH from TLLI=0x%08x while TBF still exists: killing pending DL TBF\n", new_tlli);
|
||||
tbf_free(dl_tbf);
|
||||
dl_tbf = NULL;
|
||||
}
|
||||
if (ul_tbf && ul_tbf->ms() != ms()) {
|
||||
LOGP(DRLCMACUL, LOGL_NOTICE, "Got RACH from "
|
||||
"TLLI=0x%08x while %s still exists. "
|
||||
"Killing pending UL TBF\n", new_tlli,
|
||||
tbf_name(ul_tbf));
|
||||
LOGPTBFUL(ul_tbf, LOGL_NOTICE,
|
||||
"Got RACH from TLLI=0x%08x while TBF still exists: killing pending UL TBF\n", new_tlli);
|
||||
tbf_free(ul_tbf);
|
||||
ul_tbf = NULL;
|
||||
}
|
||||
|
|
|
@ -134,6 +134,10 @@ 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 GPRS_RLCMAC_FLAG_CCCH 0 /* assignment on CCCH */
|
||||
#define GPRS_RLCMAC_FLAG_PACCH 1 /* assignment on PACCH */
|
||||
#define GPRS_RLCMAC_FLAG_UL_DATA 2 /* uplink data received */
|
||||
|
|
|
@ -58,8 +58,7 @@ static void llc_timer_cb(void *_tbf)
|
|||
if (tbf->state_is_not(GPRS_RLCMAC_FLOW))
|
||||
return;
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG,
|
||||
"%s LLC receive timeout, requesting DL ACK\n", tbf_name(tbf));
|
||||
LOGPTBFDL(tbf, LOGL_DEBUG, "LLC receive timeout, requesting DL ACK\n");
|
||||
|
||||
tbf->request_dl_ack();
|
||||
}
|
||||
|
@ -87,7 +86,7 @@ int gprs_rlcmac_dl_tbf::append_data(const uint8_t ms_class,
|
|||
const uint16_t pdu_delay_csec,
|
||||
const uint8_t *data, const uint16_t len)
|
||||
{
|
||||
LOGP(DRLCMAC, LOGL_INFO, "%s append\n", tbf_name(this));
|
||||
LOGPTBFDL(this, LOGL_DEBUG, "appending %u bytes\n", len);
|
||||
gprs_llc_queue::MetaInfo info;
|
||||
struct msgb *llc_msg = msgb_alloc(len, "llc_pdu_queue");
|
||||
if (!llc_msg)
|
||||
|
@ -101,9 +100,7 @@ int gprs_rlcmac_dl_tbf::append_data(const uint8_t ms_class,
|
|||
start_llc_timer();
|
||||
|
||||
if (state_is(GPRS_RLCMAC_WAIT_RELEASE)) {
|
||||
LOGP(DRLCMAC, LOGL_DEBUG,
|
||||
"%s in WAIT RELEASE state "
|
||||
"(T3193), so reuse TBF\n", tbf_name(this));
|
||||
LOGPTBFDL(this, LOGL_DEBUG, "in WAIT RELEASE state (T3193), so reuse TBF\n");
|
||||
tbf_update_ms_class(this, ms_class);
|
||||
establish_dl_tbf_on_pacch();
|
||||
}
|
||||
|
@ -156,7 +153,7 @@ static int tbf_new_dl_assignment(struct gprs_rlcmac_bts *bts,
|
|||
dl_tbf->update_ms(tlli, GPRS_RLCMAC_DL_TBF);
|
||||
dl_tbf->ms()->set_ta(ta);
|
||||
|
||||
LOGP(DRLCMAC, LOGL_DEBUG, "%s [DOWNLINK] START\n", tbf_name(dl_tbf));
|
||||
LOGPTBFDL(dl_tbf, LOGL_DEBUG, "[DOWNLINK] START\n");
|
||||
|
||||
/* Store IMSI for later look-up and PCH retransmission */
|
||||
dl_tbf->assign_imsi(imsi);
|
||||
|
@ -305,10 +302,10 @@ drop_frame:
|
|||
}
|
||||
|
||||
if (frames) {
|
||||
LOGP(DRLCMACDL, LOGL_NOTICE, "%s Discarding LLC PDU "
|
||||
LOGPTBFDL(this, LOGL_NOTICE, "Discarding LLC PDU "
|
||||
"because lifetime limit reached, "
|
||||
"count=%u new_queue_size=%zu\n",
|
||||
tbf_name(this), frames, llc_queue_size());
|
||||
frames, llc_queue_size());
|
||||
if (frames > 0xff)
|
||||
frames = 0xff;
|
||||
if (octets > 0xffffff)
|
||||
|
@ -470,9 +467,8 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(uint32_t fn, uint8_t ts)
|
|||
int bsn, bsn2 = -1;
|
||||
bool may_combine;
|
||||
|
||||
LOGP(DRLCMACDL, LOGL_DEBUG, "%s downlink (V(A)==%d .. "
|
||||
"V(S)==%d)\n", tbf_name(this),
|
||||
m_window.v_a(), m_window.v_s());
|
||||
LOGPTBFDL(this, LOGL_DEBUG, "downlink (V(A)==%d .. V(S)==%d)\n",
|
||||
m_window.v_a(), m_window.v_s());
|
||||
|
||||
bsn = take_next_bsn(fn, -1, &may_combine);
|
||||
if (bsn < 0)
|
||||
|
@ -492,7 +488,7 @@ void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf)
|
|||
|
||||
/* check for downlink tbf: */
|
||||
if (old_tbf) {
|
||||
LOGP(DRLCMACDL, LOGL_DEBUG, "Send dowlink assignment on PACCH, because %s exists\n", tbf_name(old_tbf));
|
||||
LOGPTBFDL(this, LOGL_DEBUG, "Send dowlink assignment on PACCH, because %s exists\n", old_tbf->name());
|
||||
old_tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_SEND_ASS;
|
||||
old_tbf->was_releasing = old_tbf->state_is(GPRS_RLCMAC_WAIT_RELEASE);
|
||||
|
||||
|
@ -504,8 +500,8 @@ void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf)
|
|||
/* start timer */
|
||||
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());
|
||||
LOGPTBFDL(this, LOGL_DEBUG, "Send dowlink assignment on PCH, no TBF exist (IMSI=%s)\n",
|
||||
imsi());
|
||||
was_releasing = state_is(GPRS_RLCMAC_WAIT_RELEASE);
|
||||
|
||||
/* change state */
|
||||
|
@ -530,9 +526,7 @@ void gprs_rlcmac_dl_tbf::schedule_next_frame()
|
|||
if (!msg)
|
||||
return;
|
||||
|
||||
LOGP(DRLCMACDL, LOGL_INFO,
|
||||
"- Dequeue next LLC for %s (len=%d)\n",
|
||||
tbf_name(this), msg->len);
|
||||
LOGPTBFDL(this, LOGL_INFO, "Dequeue next LLC (len=%d)\n", msg->len);
|
||||
|
||||
m_llc.put_frame(msg->data, msg->len);
|
||||
bts->llc_frame_sched();
|
||||
|
@ -616,8 +610,7 @@ int gprs_rlcmac_dl_tbf::create_new_bsn(const uint32_t fn, GprsCodingScheme cs)
|
|||
if (ar == Encoding::AR_NEED_MORE_BLOCKS)
|
||||
break;
|
||||
|
||||
LOGP(DRLCMACDL, LOGL_INFO, "Complete DL frame for %s"
|
||||
"len=%d\n", tbf_name(this), m_llc.frame_length());
|
||||
LOGPTBFDL(this, LOGL_INFO, "Complete DL frame, len=%d\n", m_llc.frame_length());
|
||||
gprs_rlcmac_dl_bw(this, m_llc.frame_length());
|
||||
bts->llc_dl_bytes(m_llc.frame_length());
|
||||
m_llc.reset();
|
||||
|
@ -1058,8 +1051,7 @@ int gprs_rlcmac_dl_tbf::update_window(const uint8_t ssn, const uint8_t *rbb)
|
|||
* to previous TBF
|
||||
* FIXME: we should implement polling for
|
||||
* control ack!*/
|
||||
LOGP(DRLCMACDL, LOGL_NOTICE, "- ack range is out of "
|
||||
"V(A)..V(S) range %s Free TBF!\n", tbf_name(this));
|
||||
LOGPTBFDL(this, LOGL_NOTICE, "ack range is out of V(A)..V(S) range - Free TBF!\n");
|
||||
return 1; /* indicate to free TBF */
|
||||
}
|
||||
|
||||
|
@ -1172,7 +1164,7 @@ int gprs_rlcmac_dl_tbf::rcvd_dl_ack(uint8_t final_ack, unsigned first_bsn,
|
|||
struct bitvec *rbb)
|
||||
{
|
||||
int rc;
|
||||
LOGP(DRLCMACDL, LOGL_DEBUG, "%s downlink acknowledge\n", tbf_name(this));
|
||||
LOGPTBFDL(this, LOGL_DEBUG, "downlink acknowledge\n");
|
||||
|
||||
rc = update_window(first_bsn, rbb);
|
||||
|
||||
|
@ -1190,12 +1182,12 @@ int gprs_rlcmac_dl_tbf::rcvd_dl_ack(uint8_t final_ack, unsigned first_bsn,
|
|||
|
||||
int gprs_rlcmac_dl_tbf::rcvd_dl_ack(uint8_t final_ack, uint8_t ssn, uint8_t *rbb)
|
||||
{
|
||||
LOGP(DRLCMACDL, LOGL_DEBUG, "%s downlink acknowledge\n", tbf_name(this));
|
||||
LOGPTBFDL(this, LOGL_DEBUG, "downlink acknowledge\n");
|
||||
|
||||
if (!final_ack)
|
||||
return update_window(ssn, rbb);
|
||||
|
||||
LOGP(DRLCMACDL, LOGL_DEBUG, "- Final ACK received.\n");
|
||||
LOGPTBFDL(this, LOGL_DEBUG, "Final ACK received.\n");
|
||||
return maybe_start_new_window();
|
||||
}
|
||||
|
||||
|
|
|
@ -84,8 +84,7 @@ int gprs_rlcmac_ul_tbf::assemble_forward_llc(const gprs_rlc_data *_data)
|
|||
|
||||
if (frame->is_complete) {
|
||||
/* send frame to SGSN */
|
||||
LOGP(DRLCMACUL, LOGL_INFO, "%s complete UL frame len=%d\n",
|
||||
tbf_name(this) , m_llc.frame_length());
|
||||
LOGPTBFUL(this, LOGL_INFO, "complete UL frame len=%d\n", m_llc.frame_length());
|
||||
snd_ul_ud();
|
||||
bts->llc_ul_bytes(m_llc.frame_length());
|
||||
m_llc.reset();
|
||||
|
@ -128,9 +127,8 @@ struct msgb *gprs_rlcmac_ul_tbf::create_ul_ack(uint32_t fn, uint8_t ts)
|
|||
if (final) {
|
||||
if (poll_state == GPRS_RLCMAC_POLL_SCHED &&
|
||||
ul_ack_state == GPRS_RLCMAC_UL_ACK_WAIT_ACK) {
|
||||
LOGP(DRLCMACUL, LOGL_DEBUG, "Polling is already "
|
||||
"scheduled for %s, so we must wait for "
|
||||
"the final uplink ack...\n", tbf_name(this));
|
||||
LOGPTBFUL(this, LOGL_DEBUG,
|
||||
"Polling is already scheduled, so we must wait for the final uplink ack...\n");
|
||||
return NULL;
|
||||
}
|
||||
|
||||
|
|
File diff suppressed because it is too large
Load Diff
Loading…
Reference in New Issue