From 2399b1dbfc33b15f64781e611923bc0866f7ccd1 Mon Sep 17 00:00:00 2001 From: Max Date: Fri, 12 Jan 2018 15:48:12 +0100 Subject: TBF: log source of state transitions We use the same approach for osmo_fsm: when state transition happens, it's not very useful to always log the transition function itself, it's much more useful to see where the actual transition comes from. Change-Id: I348ba89bdda2b44c7019e9c893c764ee08c80bec Related: OS#1759 --- src/bts.cpp | 6 +++--- src/tbf.cpp | 18 +++++++++--------- src/tbf.h | 15 +++++++++------ src/tbf_dl.cpp | 10 +++++----- src/tbf_ul.cpp | 2 +- tests/tbf/TbfTest.cpp | 2 +- 6 files changed, 28 insertions(+), 25 deletions(-) diff --git a/src/bts.cpp b/src/bts.cpp index 14c05f2f..873af737 100644 --- a/src/bts.cpp +++ b/src/bts.cpp @@ -759,7 +759,7 @@ int BTS::rcv_rach(uint16_t ra, uint32_t Fn, int16_t qta, bool is_11bit, failure = true; } else { tbf->set_ta(ta); - tbf->set_state(GPRS_RLCMAC_FLOW); + TBF_SET_STATE(tbf, GPRS_RLCMAC_FLOW); tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_CCCH); T_START(tbf, T3169, m_bts.t3169, 0, "RACH (new UL-TBF)", true); LOGPTBF(tbf, LOGL_DEBUG, "[UPLINK] START\n"); @@ -1045,7 +1045,7 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet, "changed type from CCCH to PACCH\n"); new_tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH); } - new_tbf->set_state(GPRS_RLCMAC_FLOW); + TBF_SET_STATE(new_tbf, GPRS_RLCMAC_FLOW); /* stop pending assignment timer */ new_tbf->t_stop(T0, "control acked (DL-TBF)"); if (new_tbf->check_n_clear(GPRS_RLCMAC_FLAG_TO_DL_ASS)) @@ -1070,7 +1070,7 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet, tbf->direction == new_tbf->direction) tbf_free(tbf); - new_tbf->set_state(GPRS_RLCMAC_FLOW); + TBF_SET_STATE(new_tbf, GPRS_RLCMAC_FLOW); if (new_tbf->check_n_clear(GPRS_RLCMAC_FLAG_TO_UL_ASS)) LOGPTBF(new_tbf, LOGL_NOTICE, "Recovered uplink assignment for UL\n"); diff --git a/src/tbf.cpp b/src/tbf.cpp index 4878a079..a1e4392a 100644 --- a/src/tbf.cpp +++ b/src/tbf.cpp @@ -402,7 +402,7 @@ gprs_rlcmac_ul_tbf *tbf_alloc_ul(struct gprs_rlcmac_bts *bts, return NULL; } tbf->m_contention_resolution_done = 1; - tbf->set_assigned_on(GPRS_RLCMAC_FLAG_PACCH, false); + TBF_SET_ASS_ON(tbf, GPRS_RLCMAC_FLAG_PACCH, false); T_START(tbf, T3169, bts->t3169, 0, "allocation (UL-TBF)", true); tbf->update_ms(tlli, GPRS_RLCMAC_UL_TBF); OSMO_ASSERT(tbf->ms()); @@ -730,7 +730,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); - set_state(GPRS_RLCMAC_RELEASING); + TBF_SET_STATE(this, GPRS_RLCMAC_RELEASING); T_START(this, T3169, bts->bts_data()->t3169, 0, "MAX N3101 reached", false); return; } @@ -748,7 +748,7 @@ void gprs_rlcmac_tbf::poll_timeout() LOGP(DRLCMAC, LOGL_NOTICE, "- N3103 exceeded\n"); bts->pkt_ul_ack_nack_poll_failed(); - ul_tbf->set_state(GPRS_RLCMAC_RELEASING); + TBF_SET_STATE(ul_tbf, GPRS_RLCMAC_RELEASING); T_START(ul_tbf, T3169, ul_tbf->bts->bts_data()->t3169, 0, "MAX N3103 reached", false); return; } @@ -770,7 +770,7 @@ void gprs_rlcmac_tbf::poll_timeout() bts->pua_poll_timedout(); if (n3105 == bts_data()->n3105) { LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n"); - set_state(GPRS_RLCMAC_RELEASING); + TBF_SET_STATE(this, GPRS_RLCMAC_RELEASING); T_START(this, T3195, bts_data()->t3195, 0, "MAX N3105 reached", true); bts->rlc_ass_failed(); bts->pua_poll_failed(); @@ -792,7 +792,7 @@ void gprs_rlcmac_tbf::poll_timeout() bts->pda_poll_timedout(); if (n3105 == bts->bts_data()->n3105) { LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n"); - set_state(GPRS_RLCMAC_RELEASING); + TBF_SET_STATE(this, GPRS_RLCMAC_RELEASING); T_START(this, T3195, bts_data()->t3195, 0, "MAX N3105 reached", true); bts->rlc_ass_failed(); bts->pda_poll_failed(); @@ -818,7 +818,7 @@ void gprs_rlcmac_tbf::poll_timeout() } if (dl_tbf->n3105 == dl_tbf->bts->bts_data()->n3105) { LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n"); - dl_tbf->set_state(GPRS_RLCMAC_RELEASING); + 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(); bts->rlc_ack_failed(); @@ -1109,7 +1109,7 @@ void gprs_rlcmac_tbf::handle_timeout() if (!dl_tbf->upgrade_to_multislot) { /* change state to FLOW, so scheduler * will start transmission */ - dl_tbf->set_state(GPRS_RLCMAC_FLOW); + TBF_SET_STATE(dl_tbf, GPRS_RLCMAC_FLOW); return; } @@ -1245,7 +1245,7 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts) set_polling(new_poll_fn, ts, GPRS_RLCMAC_POLL_DL_ASS); } else { dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE; - new_dl_tbf->set_state(GPRS_RLCMAC_FLOW); + TBF_SET_STATE(new_dl_tbf, GPRS_RLCMAC_FLOW); tbf_assign_control_ts(new_dl_tbf); /* stop pending assignment timer */ new_dl_tbf->t_stop(T0, "assignment (DL-TBF)"); @@ -1523,7 +1523,7 @@ struct gprs_rlcmac_ul_tbf *handle_tbf_reject(struct gprs_rlcmac_bts *bts, llist_add(&ul_tbf->list(), &bts->bts->ul_tbfs()); ul_tbf->bts->tbf_ul_created(); - ul_tbf->set_assigned_on(GPRS_RLCMAC_FLAG_PACCH, false); + TBF_SET_ASS_ON(ul_tbf, GPRS_RLCMAC_FLAG_PACCH, false); ul_tbf->set_ms(ms); ul_tbf->update_ms(tlli, GPRS_RLCMAC_UL_TBF); diff --git a/src/tbf.h b/src/tbf.h index 6c9946e5..bf6ce4cd 100644 --- a/src/tbf.h +++ b/src/tbf.h @@ -180,6 +180,9 @@ enum tbf_timers { #define T_START(tbf, t, sec, usec, r, f) tbf->t_start(t, sec, usec, r, f, __FILE__, __LINE__) +#define TBF_SET_STATE(t, st) do { t->set_state(st, __FILE__, __LINE__); } while(0) +#define TBF_SET_ASS_ON(t, fl, chk) do { t->set_assigned_on(fl, chk, __FILE__, __LINE__); } while(0) + struct gprs_rlcmac_tbf { gprs_rlcmac_tbf(BTS *bts_, gprs_rlcmac_tbf_direction dir); @@ -188,9 +191,9 @@ struct gprs_rlcmac_tbf { bool state_is(enum gprs_rlcmac_tbf_state rhs) const; bool state_is_not(enum gprs_rlcmac_tbf_state rhs) const; - void set_state(enum gprs_rlcmac_tbf_state new_state); + void set_state(enum gprs_rlcmac_tbf_state new_state, const char *file, int line); bool check_n_clear(uint8_t state_flag); - void set_assigned_on(uint8_t state_flag, bool check_ccch); + void set_assigned_on(uint8_t state_flag, bool check_ccch, const char *file, int line); const char *state_name() const; const char *name() const; @@ -378,9 +381,9 @@ inline const char *gprs_rlcmac_tbf::state_name() const } /* Set assignment state and corrsponding flags */ -inline void gprs_rlcmac_tbf::set_assigned_on(uint8_t state_flag, bool check_ccch) +inline void gprs_rlcmac_tbf::set_assigned_on(uint8_t state_flag, bool check_ccch, const char *file, int line) { - set_state(GPRS_RLCMAC_ASSIGN); + set_state(GPRS_RLCMAC_ASSIGN, file, line); if (check_ccch) { if (!(state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH))) state_flags |= (1 << state_flag); @@ -388,9 +391,9 @@ inline void gprs_rlcmac_tbf::set_assigned_on(uint8_t state_flag, bool check_ccch state_flags |= (1 << state_flag); } -inline void gprs_rlcmac_tbf::set_state(enum gprs_rlcmac_tbf_state new_state) +inline void gprs_rlcmac_tbf::set_state(enum gprs_rlcmac_tbf_state new_state, const char *file, int line) { - LOGP(DRLCMAC, LOGL_DEBUG, "%s changes state from %s to %s\n", + LOGPSRC(DRLCMAC, 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 6b8eda79..5a42aa0d 100644 --- a/src/tbf_dl.cpp +++ b/src/tbf_dl.cpp @@ -493,7 +493,7 @@ void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf) old_tbf->was_releasing = old_tbf->state_is(GPRS_RLCMAC_WAIT_RELEASE); /* change state */ - set_assigned_on(GPRS_RLCMAC_FLAG_PACCH, true); + TBF_SET_ASS_ON(this, GPRS_RLCMAC_FLAG_PACCH, true); /* start timer */ T_START(this, T0, T_ASS_PACCH_SEC, 0, "assignment (PACCH)", true); @@ -503,7 +503,7 @@ void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf) was_releasing = state_is(GPRS_RLCMAC_WAIT_RELEASE); /* change state */ - set_assigned_on(GPRS_RLCMAC_FLAG_CCCH, false); + TBF_SET_ASS_ON(this, GPRS_RLCMAC_FLAG_CCCH, false); /* send immediate assignment */ bts->snd_dl_ass(this, 0, imsi()); @@ -614,7 +614,7 @@ int gprs_rlcmac_dl_tbf::create_new_bsn(const uint32_t fn, GprsCodingScheme cs) if (is_final) { request_dl_ack(); - set_state(GPRS_RLCMAC_FINISHED); + TBF_SET_STATE(this, GPRS_RLCMAC_FINISHED); } /* dequeue next LLC frame, if any */ @@ -1109,7 +1109,7 @@ int gprs_rlcmac_dl_tbf::release() /* report all outstanding packets as received */ gprs_rlcmac_received_lost(this, received, 0); - set_state(GPRS_RLCMAC_WAIT_RELEASE); + TBF_SET_STATE(this, GPRS_RLCMAC_WAIT_RELEASE); /* start T3193 */ T_START(this, T3193, bts_data()->t3193_msec / 1000, (bts_data()->t3193_msec % 1000) * 1000, @@ -1143,7 +1143,7 @@ int gprs_rlcmac_dl_tbf::abort() * (partly) encoded in chunk 1 of block V(A). (optional) */ } - set_state(GPRS_RLCMAC_RELEASING); + TBF_SET_STATE(this, GPRS_RLCMAC_RELEASING); /* reset rlc states */ m_window.reset(); diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp index 83ac08f4..eaf9c939 100644 --- a/src/tbf_ul.cpp +++ b/src/tbf_ul.cpp @@ -330,7 +330,7 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged( if (rdbi->cv == 0) { LOGP(DRLCMACUL, LOGL_DEBUG, "- Finished with UL " "TBF\n"); - set_state(GPRS_RLCMAC_FINISHED); + TBF_SET_STATE(this, GPRS_RLCMAC_FINISHED); /* Reset N3103 counter. */ this->m_n3103 = 0; } diff --git a/tests/tbf/TbfTest.cpp b/tests/tbf/TbfTest.cpp index ac15b2cc..9e21c73e 100644 --- a/tests/tbf/TbfTest.cpp +++ b/tests/tbf/TbfTest.cpp @@ -176,7 +176,7 @@ static gprs_rlcmac_dl_tbf *create_dl_tbf(BTS *the_bts, uint8_t ms_class, /* "Establish" the DL TBF */ dl_tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_SEND_ASS; - dl_tbf->set_state(GPRS_RLCMAC_FLOW); + TBF_SET_STATE(dl_tbf, GPRS_RLCMAC_FLOW); dl_tbf->m_wait_confirm = 0; check_tbf(dl_tbf); -- cgit v1.2.3