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/bts.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/bts.cpp')
-rw-r--r-- | src/bts.cpp | 80 |
1 files changed, 33 insertions, 47 deletions
diff --git a/src/bts.cpp b/src/bts.cpp index e17399ac..b2af7aac 100644 --- a/src/bts.cpp +++ b/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"); } } |