diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/gprs_debug.cpp | 3 | ||||
| -rw-r--r-- | src/gprs_debug.h | 3 | ||||
| -rw-r--r-- | src/tbf.cpp | 176 | ||||
| -rw-r--r-- | src/tbf.h | 8 | ||||
| -rw-r--r-- | src/tbf_dl.cpp | 191 | ||||
| -rw-r--r-- | src/tbf_ul.cpp | 161 |
6 files changed, 247 insertions, 295 deletions
diff --git a/src/gprs_debug.cpp b/src/gprs_debug.cpp index 283962fc..f1ae6ad6 100644 --- a/src/gprs_debug.cpp +++ b/src/gprs_debug.cpp @@ -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}, diff --git a/src/gprs_debug.h b/src/gprs_debug.h index 747465ba..4c57633f 100644 --- a/src/gprs_debug.h +++ b/src/gprs_debug.h @@ -37,6 +37,9 @@ enum { DRLCMACUL, DRLCMACSCHED, DRLCMACMEAS, + DTBF, + DTBFDL, + DTBFUL, DNS, DBSSGP, DPCU, diff --git a/src/tbf.cpp b/src/tbf.cpp index a1e4392a..699f960f 100644 --- a/src/tbf.cpp +++ b/src/tbf.cpp @@ -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; } @@ -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; diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp index 5a42aa0d..9a0bf78c 100644 --- a/src/tbf_dl.cpp +++ b/src/tbf_dl.cpp @@ -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); } diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp index eaf9c939..ba048e54 100644 --- a/src/tbf_ul.cpp +++ b/src/tbf_ul.cpp @@ -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); } |