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
diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp
index 5a42aa0..9a0bf78 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -147,7 +147,7 @@
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 @@
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 @@
* 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 @@
/* 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 @@
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 @@
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 @@
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 @@
* 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
}
}
- 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 @@
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 @@
/* 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 @@
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 @@
/* 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 @@
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 @@
*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 @@
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);
}