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
diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp
index 4fc60e4..0bcb67b 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -58,8 +58,7 @@
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 @@
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 @@
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 @@
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 @@
}
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 @@
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 @@
/* 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 @@
/* 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 @@
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 @@
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 @@
* 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 @@
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, 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();
}