diff options
author | Max <msuraev@sysmocom.de> | 2017-12-15 17:36:45 +0100 |
---|---|---|
committer | Max <msuraev@sysmocom.de> | 2017-12-20 14:14:40 +0000 |
commit | c21f007277713b15d9a48d0bcc6f28aa51b4f908 (patch) | |
tree | 775a15826b9aff9ddf11005057633d15cf4b8fbd /src/tbf.cpp | |
parent | ea9968f6854cbfe79506efedc43a953a7c38cdd6 (diff) |
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
Diffstat (limited to 'src/tbf.cpp')
-rw-r--r-- | src/tbf.cpp | 111 |
1 files changed, 48 insertions, 63 deletions
diff --git a/src/tbf.cpp b/src/tbf.cpp index c139af7b..18059ace 100644 --- a/src/tbf.cpp +++ b/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; } |