From 3225290d778401ed9c977f4c86afa33bc1c9abd8 Mon Sep 17 00:00:00 2001 From: Pau Espin Pedrol Date: Thu, 29 Jul 2021 16:44:11 +0200 Subject: [PATCH] Move timer X2002 to tbf_fsm Related: OS#2709 Change-Id: I94b71c60ed49d51ebdf6d6b428056b4b94354676 --- src/bts.cpp | 6 +-- src/gprs_rlcmac_sched.cpp | 4 -- src/pdch.cpp | 2 - src/tbf.cpp | 77 +++++++----------------------------- src/tbf.h | 5 +-- src/tbf_dl.cpp | 8 ++-- src/tbf_dl.h | 2 +- src/tbf_fsm.c | 83 +++++++++++++++++++++++++++++++++++++++ src/tbf_fsm.h | 2 + tests/tbf/TbfTest.cpp | 11 ++++-- tests/tbf/TbfTest.err | 20 +++++++++- 11 files changed, 134 insertions(+), 86 deletions(-) diff --git a/src/bts.cpp b/src/bts.cpp index 729ff5d4..12a1b04b 100644 --- a/src/bts.cpp +++ b/src/bts.cpp @@ -655,11 +655,7 @@ int bts_rcv_imm_ass_cnf(struct gprs_rlcmac_bts *bts, const uint8_t *data, uint32 } LOGP(DRLCMAC, LOGL_DEBUG, "Got IMM.ASS confirm for TLLI=%08x\n", tlli); - - if (dl_tbf->m_wait_confirm) { - /* Transition to FLOW in gprs_rlcmac_tbf::handle_timeout() when timer expires */ - T_START(dl_tbf, T0, -2002, "assignment (AGCH)", true); - } + osmo_fsm_inst_dispatch(dl_tbf->state_fsm.fi, TBF_EV_ASSIGN_PCUIF_CNF, NULL); return 0; } diff --git a/src/gprs_rlcmac_sched.cpp b/src/gprs_rlcmac_sched.cpp index 18c07633..d73e55d8 100644 --- a/src/gprs_rlcmac_sched.cpp +++ b/src/gprs_rlcmac_sched.cpp @@ -308,10 +308,6 @@ static struct msgb *sched_select_downlink(struct gprs_rlcmac_bts *bts, struct gp && tbf->state_is_not(TBF_ST_FINISHED)) continue; - /* waiting for CCCH IMM.ASS confirm */ - if (tbf->m_wait_confirm) - continue; - /* If a GPRS (CS1-4) Dl block is required, skip EGPRS(_GSMK) tbfs: */ if (req_mcs_kind == GPRS && tbf->is_egprs_enabled()) continue; diff --git a/src/pdch.cpp b/src/pdch.cpp index 9477178d..439759fa 100644 --- a/src/pdch.cpp +++ b/src/pdch.cpp @@ -369,8 +369,6 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet, tbf_free(tbf); osmo_fsm_inst_dispatch(new_tbf->state_fsm.fi, TBF_EV_ASSIGN_ACK_PACCH, NULL); - /* stop pending assignment timer */ - new_tbf->t_stop(T0, "control acked (DL-TBF)"); tbf_assign_control_ts(new_tbf); return; diff --git a/src/tbf.cpp b/src/tbf.cpp index 74a44d9b..5efbe7f2 100644 --- a/src/tbf.cpp +++ b/src/tbf.cpp @@ -59,8 +59,6 @@ extern void *tall_pcu_ctx; unsigned int next_tbf_ctr_group_id = 0; /* Incrementing group id */ -static void tbf_timer_cb(void *_tbf); - const struct value_string gprs_rlcmac_tbf_ul_ack_state_names[] = { OSMO_VALUE_STRING(GPRS_RLCMAC_UL_ACK_NONE), OSMO_VALUE_STRING(GPRS_RLCMAC_UL_ACK_SEND_ACK), /* send acknowledge on next RTS */ @@ -76,7 +74,6 @@ static const struct value_string tbf_counters_names[] = { }; static const struct value_string tbf_timers_names[] = { - OSMO_VALUE_STRING(T0), OSMO_VALUE_STRING(T3141), OSMO_VALUE_STRING(T3191), OSMO_VALUE_STRING(T3193), @@ -422,7 +419,6 @@ bool gprs_rlcmac_tbf::timers_pending(enum tbf_timers t) if (t != T_MAX) return osmo_timer_pending(&Tarr[t]); - /* we don't start with T0 because it's internal timer which requires special handling */ for (i = T3141; i < T_MAX; i++) if (osmo_timer_pending(&Tarr[i])) return true; @@ -433,8 +429,7 @@ bool gprs_rlcmac_tbf::timers_pending(enum tbf_timers t) void gprs_rlcmac_tbf::stop_timers(const char *reason) { uint8_t i; - /* we start with T0 because timer reset does not require any special handling */ - for (i = T0; i < T_MAX; i++) + for (i = T3141; i < T_MAX; i++) t_stop((enum tbf_timers)i, reason); } @@ -502,9 +497,6 @@ void gprs_rlcmac_tbf::t_start(enum tbf_timers t, int T, const char *reason, bool Tarr[t].data = this; switch(t) { - case T0: - Tarr[t].cb = tbf_timer_cb; - break; case T3141: Tarr[t].cb = cb_T3141; break; @@ -594,7 +586,6 @@ void gprs_rlcmac_tbf::set_polling(uint32_t new_poll_fn, uint8_t ts, enum pdch_ul void gprs_rlcmac_tbf::poll_timeout(struct gprs_rlcmac_pdch *pdch, uint32_t poll_fn, enum pdch_ulc_tbf_poll_reason reason) { - uint16_t pgroup; gprs_rlcmac_ul_tbf *ul_tbf = as_ul_tbf(this); LOGPTBF(this, LOGL_NOTICE, "poll timeout for FN=%d, TS=%d (curr FN %d)\n", @@ -645,7 +636,8 @@ void gprs_rlcmac_tbf::poll_timeout(struct gprs_rlcmac_pdch *pdch, uint32_t poll_ /* Timeout waiting for CTRL ACK acking Pkt Cell Change Continue */ osmo_fsm_inst_dispatch(m_ms->nacc->fi, NACC_EV_TIMEOUT_CELL_CHG_CONTINUE, NULL); return; - } else if (direction == GPRS_RLCMAC_DL_TBF) { + } else if (reason == PDCH_ULC_POLL_DL_ACK) { + /* POLL Timeout expecting DL ACK/NACK: implies direction == GPRS_RLCMAC_DL_TBF */ gprs_rlcmac_dl_tbf *dl_tbf = as_dl_tbf(this); if (!(dl_tbf->state_fsm.state_flags & (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK))) { @@ -669,16 +661,7 @@ void gprs_rlcmac_tbf::poll_timeout(struct gprs_rlcmac_pdch *pdch, uint32_t poll_ return; } /* resend IMM.ASS on CCCH on timeout */ - if ((dl_tbf->state_fsm.state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH)) - && !(dl_tbf->state_fsm.state_flags & (1 << GPRS_RLCMAC_FLAG_DL_ACK))) { - LOGPTBF(dl_tbf, LOGL_DEBUG, "Re-send dowlink assignment on PCH (IMSI=%s)\n", - imsi()); - /* send immediate assignment */ - if ((pgroup = imsi2paging_group(imsi())) > 999) - LOGPTBF(dl_tbf, LOGL_ERROR, "IMSI to paging group failed! (%s)\n", imsi()); - bts_snd_dl_ass(dl_tbf->bts, dl_tbf, pgroup); - dl_tbf->m_wait_confirm = 1; - } + osmo_fsm_inst_dispatch(this->state_fsm.fi, TBF_EV_DL_ACKNACK_MISS, NULL); } else LOGPTBF(this, LOGL_ERROR, "Poll Timeout, but no event!\n"); } @@ -729,48 +712,6 @@ int gprs_rlcmac_tbf::setup(int8_t use_trx, bool single_slot) return 0; } -static void tbf_timer_cb(void *_tbf) -{ - struct gprs_rlcmac_tbf *tbf = (struct gprs_rlcmac_tbf *)_tbf; - tbf->handle_timeout(); -} - -void gprs_rlcmac_tbf::handle_timeout() -{ - int current_fn = bts_current_frame_number(bts); - - LOGPTBF(this, LOGL_DEBUG, "timer 0 expired. cur_fn=%d\n", current_fn); - - /* Finish waiting after IMM.ASS confirm timer for CCCH assignment (see timer X2002) */ - if ((state_fsm.state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH))) { - gprs_rlcmac_dl_tbf *dl_tbf = as_dl_tbf(this); - dl_tbf->m_wait_confirm = 0; - if (dl_tbf->state_is(TBF_ST_ASSIGN)) { - tbf_assign_control_ts(dl_tbf); - - if (!dl_tbf->upgrade_to_multislot) { - /* change state to FLOW, so scheduler - * will start transmission */ - osmo_fsm_inst_dispatch(dl_tbf->state_fsm.fi, TBF_EV_ASSIGN_READY_CCCH, NULL); - return; - } - - /* This tbf can be upgraded to use multiple DL - * timeslots and now that there is already one - * slot assigned send another DL assignment via - * PDCH. */ - - /* keep to flags */ - dl_tbf->state_fsm.state_flags &= GPRS_RLCMAC_FLAG_TO_MASK; - - dl_tbf->update(); - - dl_tbf->trigger_ass(dl_tbf); - } else - LOGPTBF(dl_tbf, LOGL_NOTICE, "Continue flow after IMM.ASS confirm\n"); - } -} - int gprs_rlcmac_tbf::establish_dl_tbf_on_pacch() { struct gprs_rlcmac_dl_tbf *new_tbf = NULL; @@ -977,6 +918,16 @@ bool tbf_is_control_ts(const struct gprs_rlcmac_tbf *tbf, uint8_t ts) return tbf->is_control_ts(ts); } +bool tbf_can_upgrade_to_multislot(const struct gprs_rlcmac_tbf *tbf) +{ + return tbf->upgrade_to_multislot; +} + +int tbf_update(struct gprs_rlcmac_tbf *tbf) +{ + return tbf->update(); +} + const char* tbf_rlcmac_diag(const struct gprs_rlcmac_tbf *tbf) { static char buf[256]; diff --git a/src/tbf.h b/src/tbf.h index 4218cf58..84c3d394 100644 --- a/src/tbf.h +++ b/src/tbf.h @@ -100,9 +100,6 @@ extern unsigned int next_tbf_ctr_group_id; #define LOGPTBF(tbf, level, fmt, args...) LOGP(DTBF, level, "%s " fmt, tbf_name(tbf), ## args) enum tbf_timers { - /* internal assign/reject timer */ - T0, - /* Wait contention resolution success on UL TBFs assigned over CCCH */ T3141, @@ -164,6 +161,8 @@ void tbf_poll_timeout(struct gprs_rlcmac_tbf *tbf, struct gprs_rlcmac_pdch *pdch void tbf_update_state_fsm_name(struct gprs_rlcmac_tbf *tbf); const char* tbf_rlcmac_diag(const struct gprs_rlcmac_tbf *tbf); bool tbf_is_control_ts(const struct gprs_rlcmac_tbf *tbf, uint8_t ts); +bool tbf_can_upgrade_to_multislot(const struct gprs_rlcmac_tbf *tbf); +int tbf_update(struct gprs_rlcmac_tbf *tbf); #ifdef __cplusplus } #endif diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp index 10492d90..bed7a08c 100644 --- a/src/tbf_dl.cpp +++ b/src/tbf_dl.cpp @@ -191,7 +191,6 @@ gprs_rlcmac_dl_tbf::~gprs_rlcmac_dl_tbf() gprs_rlcmac_dl_tbf::gprs_rlcmac_dl_tbf(struct gprs_rlcmac_bts *bts_, GprsMs *ms) : gprs_rlcmac_tbf(bts_, ms, GPRS_RLCMAC_DL_TBF), m_tx_counter(0), - m_wait_confirm(0), m_dl_ack_requested(false), m_last_dl_poll_fn(-1), m_last_dl_drained_fn(-1), @@ -622,7 +621,6 @@ void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf) if ((pgroup = imsi2paging_group(imsi())) > 999) LOGPTBFDL(this, LOGL_ERROR, "IMSI to paging group failed! (%s)\n", imsi()); bts_snd_dl_ass(bts, this, pgroup); - m_wait_confirm = 1; } } @@ -1170,7 +1168,6 @@ int gprs_rlcmac_dl_tbf::release() /* reset rlc states */ m_tx_counter = 0; - m_wait_confirm = 0; m_window.reset(); osmo_fsm_inst_dispatch(this->state_fsm.fi, TBF_EV_ASSIGN_DEL_CCCH, NULL); @@ -1464,3 +1461,8 @@ struct gprs_rlcmac_dl_tbf *as_dl_tbf(struct gprs_rlcmac_tbf *tbf) else return NULL; } + +void tbf_dl_trigger_ass(struct gprs_rlcmac_dl_tbf *tbf, struct gprs_rlcmac_tbf *old_tbf) +{ + return tbf->trigger_ass(old_tbf); +} diff --git a/src/tbf_dl.h b/src/tbf_dl.h index 97193276..ad1469ad 100644 --- a/src/tbf_dl.h +++ b/src/tbf_dl.h @@ -71,7 +71,6 @@ struct gprs_rlcmac_dl_tbf : public gprs_rlcmac_tbf { * variables are in both (dl and ul) structs and not outside union. */ int32_t m_tx_counter; /* count all transmitted blocks */ - uint8_t m_wait_confirm; /* wait for CCCH IMM.ASS cnf */ bool m_dl_ack_requested; int32_t m_last_dl_poll_fn; int32_t m_last_dl_drained_fn; @@ -153,6 +152,7 @@ int dl_tbf_handle(struct gprs_rlcmac_bts *bts, const uint8_t egprs_ms_class, const uint16_t delay_csec, const uint8_t *data, const uint16_t len); +void tbf_dl_trigger_ass(struct gprs_rlcmac_dl_tbf *tbf, struct gprs_rlcmac_tbf *old_tbf); #ifdef __cplusplus } #endif diff --git a/src/tbf_fsm.c b/src/tbf_fsm.c index 0dbf04c8..42c5118e 100644 --- a/src/tbf_fsm.c +++ b/src/tbf_fsm.c @@ -46,6 +46,8 @@ const struct value_string tbf_fsm_event_names[] = { { TBF_EV_ASSIGN_DEL_CCCH, "ASSIGN_DEL_CCCH" }, { TBF_EV_ASSIGN_ACK_PACCH, "ASSIGN_ACK_PACCH" }, { TBF_EV_ASSIGN_READY_CCCH, "ASSIGN_READY_CCCH" }, + { TBF_EV_ASSIGN_PCUIF_CNF, "ASSIGN_PCUIF_CNF" }, + { TBF_EV_DL_ACKNACK_MISS, "DL_ACKNACK_MISS" }, { TBF_EV_LAST_DL_DATA_SENT, "LAST_DL_DATA_SENT" }, { TBF_EV_LAST_UL_DATA_RECVD, "LAST_UL_DATA_RECVD" }, { TBF_EV_FINAL_ACK_RECVD, "FINAL_ACK_RECVD" }, @@ -136,12 +138,17 @@ static void st_assign_on_enter(struct osmo_fsm_inst *fi, uint32_t prev_state) "Starting timer X2001 [assignment (PACCH)] with %u sec. %u microsec\n", sec, micro); osmo_timer_schedule(&fi->timer, sec, micro); + } else if (tbf_direction(ctx->tbf) == GPRS_RLCMAC_DL_TBF) { + /* GPRS_RLCMAC_FLAG_CCCH is set, so here we submitted an DL Ass through PCUIF on CCCH */ } } static void st_assign(struct osmo_fsm_inst *fi, uint32_t event, void *data) { struct tbf_fsm_ctx *ctx = (struct tbf_fsm_ctx *)fi->priv; + unsigned long val; + unsigned int sec, micro; + switch (event) { case TBF_EV_ASSIGN_ADD_CCCH: mod_ass_type(ctx, GPRS_RLCMAC_FLAG_CCCH, true); @@ -160,6 +167,23 @@ static void st_assign(struct osmo_fsm_inst *fi, uint32_t event, void *data) } tbf_fsm_state_chg(fi, TBF_ST_FLOW); break; + case TBF_EV_ASSIGN_PCUIF_CNF: + /* BTS informs us it sent Imm Ass for DL TBF over CCCH. We now + * have to wait for X2002 to trigger (meaning MS is already + * listening on PDCH) in order to move to FLOW state and start + * transmitting data to it. When X2002 triggers (see cb timer + * end of the file) it will send TBF_EV_ASSIGN_READY_CCCH back + * to us here. */ + OSMO_ASSERT(tbf_direction(ctx->tbf) == GPRS_RLCMAC_DL_TBF); + fi->T = -2002; + val = osmo_tdef_get(the_pcu->T_defs, fi->T, OSMO_TDEF_MS, -1); + sec = val / 1000; + micro = (val % 1000) * 1000; + LOGPTBF(ctx->tbf, LOGL_DEBUG, + "Starting timer X2002 [assignment (AGCH)] with %u sec. %u microsec\n", + sec, micro); + osmo_timer_schedule(&fi->timer, sec, micro); + break; case TBF_EV_ASSIGN_READY_CCCH: /* change state to FLOW, so scheduler will start transmission */ tbf_fsm_state_chg(fi, TBF_ST_FLOW); @@ -172,7 +196,28 @@ static void st_assign(struct osmo_fsm_inst *fi, uint32_t event, void *data) static void st_flow(struct osmo_fsm_inst *fi, uint32_t event, void *data) { struct tbf_fsm_ctx *ctx = (struct tbf_fsm_ctx *)fi->priv; + switch (event) { + case TBF_EV_DL_ACKNACK_MISS: + /* DL TBF: we missed a DL ACK/NACK. If we started assignment + * over CCCH and never received any DL ACK/NACK yet, it means we + * don't even know if the MS successfuly received the Imm Ass on + * CCCH and hence is listening on PDCH. Let's better refrain + * from continuing and start assignment on CCCH again */ + if ((ctx->state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH)) + && !(ctx->state_flags & (1 << GPRS_RLCMAC_FLAG_DL_ACK))) { + struct GprsMs *ms = tbf_ms(ctx->tbf); + const char *imsi = ms_imsi(ms); + uint16_t pgroup; + LOGPTBF(ctx->tbf, LOGL_DEBUG, "Re-send dowlink assignment on PCH (IMSI=%s)\n", + imsi); + tbf_fsm_state_chg(fi, TBF_ST_ASSIGN); + /* send immediate assignment */ + if ((pgroup = imsi2paging_group(imsi)) > 999) + LOGPTBF(ctx->tbf, LOGL_ERROR, "IMSI to paging group failed! (%s)\n", imsi); + bts_snd_dl_ass(ms->bts, ctx->tbf, pgroup); + } + break; case TBF_EV_LAST_DL_DATA_SENT: case TBF_EV_LAST_UL_DATA_RECVD: /* All data has been sent or received, change state to FINISHED */ @@ -201,6 +246,8 @@ static void st_finished(struct osmo_fsm_inst *fi, uint32_t event, void *data) { struct tbf_fsm_ctx *ctx = (struct tbf_fsm_ctx *)fi->priv; switch (event) { + case TBF_EV_DL_ACKNACK_MISS: + break; case TBF_EV_FINAL_ACK_RECVD: /* We received Final Ack (DL ACK/NACK) from MS. move to WAIT_RELEASE, we wait there for release or re-use the TBF in @@ -267,10 +314,42 @@ static void tbf_fsm_cleanup(struct osmo_fsm_inst *fi, enum osmo_fsm_term_cause c */ } +static void handle_timeout_X2002(struct tbf_fsm_ctx *ctx) +{ + struct gprs_rlcmac_dl_tbf *dl_tbf = as_dl_tbf(ctx->tbf); + + if (ctx->fi->state == TBF_ST_ASSIGN) { + tbf_assign_control_ts(ctx->tbf); + + if (!tbf_can_upgrade_to_multislot(ctx->tbf)) { + /* change state to FLOW, so scheduler + * will start transmission */ + osmo_fsm_inst_dispatch(ctx->fi, TBF_EV_ASSIGN_READY_CCCH, NULL); + return; + } + + /* This tbf can be upgraded to use multiple DL + * timeslots and now that there is already one + * slot assigned send another DL assignment via + * PDCH. */ + + /* keep to flags */ + ctx->state_flags &= GPRS_RLCMAC_FLAG_TO_MASK; + + tbf_update(ctx->tbf); + + tbf_dl_trigger_ass(dl_tbf, ctx->tbf); + } else + LOGPTBF(ctx->tbf, LOGL_NOTICE, "Continue flow after IMM.ASS confirm\n"); +} + static int tbf_fsm_timer_cb(struct osmo_fsm_inst *fi) { struct tbf_fsm_ctx *ctx = (struct tbf_fsm_ctx *)fi->priv; switch (fi->T) { + case -2002: + handle_timeout_X2002(ctx); + break; case -2001: LOGPTBF(ctx->tbf, LOGL_NOTICE, "releasing due to PACCH assignment timeout.\n"); /* fall-through */ @@ -301,6 +380,7 @@ static struct osmo_fsm_state tbf_fsm_states[] = { X(TBF_EV_ASSIGN_ADD_CCCH) | X(TBF_EV_ASSIGN_ADD_PACCH) | X(TBF_EV_ASSIGN_ACK_PACCH) | + X(TBF_EV_ASSIGN_PCUIF_CNF) | X(TBF_EV_ASSIGN_READY_CCCH), .out_state_mask = X(TBF_ST_FLOW) | @@ -312,12 +392,14 @@ static struct osmo_fsm_state tbf_fsm_states[] = { }, [TBF_ST_FLOW] = { .in_event_mask = + X(TBF_EV_DL_ACKNACK_MISS) | X(TBF_EV_LAST_DL_DATA_SENT) | X(TBF_EV_LAST_UL_DATA_RECVD) | X(TBF_EV_FINAL_ACK_RECVD) | X(TBF_EV_MAX_N3101) | X(TBF_EV_MAX_N3105), .out_state_mask = + X(TBF_ST_ASSIGN) | X(TBF_ST_FINISHED) | X(TBF_ST_WAIT_RELEASE) | X(TBF_ST_RELEASING), @@ -326,6 +408,7 @@ static struct osmo_fsm_state tbf_fsm_states[] = { }, [TBF_ST_FINISHED] = { .in_event_mask = + X(TBF_EV_DL_ACKNACK_MISS) | X(TBF_EV_FINAL_ACK_RECVD) | X(TBF_EV_MAX_N3103) | X(TBF_EV_MAX_N3105), diff --git a/src/tbf_fsm.h b/src/tbf_fsm.h index 9d2919d3..2f63eef2 100644 --- a/src/tbf_fsm.h +++ b/src/tbf_fsm.h @@ -32,6 +32,8 @@ enum tbf_fsm_event { TBF_EV_ASSIGN_DEL_CCCH, /* An assignment previously sent over CCCH has been confirmed by MS */ TBF_EV_ASSIGN_ACK_PACCH, /* We received a CTRL ACK confirming assignment started on PACCH */ TBF_EV_ASSIGN_READY_CCCH, /* TBF Start Time timer triggered */ + TBF_EV_ASSIGN_PCUIF_CNF, /* Transmission of IMM.ASS for DL TBF to the MS confirmed by BTS over PCUIF */ + TBF_EV_DL_ACKNACK_MISS, /* DL TBF: We polled for DL ACK/NACK but we received none (POLL timeout) */ TBF_EV_LAST_DL_DATA_SENT, /* DL TBF sends RLCMAC block containing last DL avilable data buffered */ TBF_EV_LAST_UL_DATA_RECVD, /* UL TBF sends RLCMAC block containing last UL data (cv=0) */ TBF_EV_FINAL_ACK_RECVD, /* DL ACK/NACK with FINAL_ACK=1 received from MS */ diff --git a/tests/tbf/TbfTest.cpp b/tests/tbf/TbfTest.cpp index 1fcaead7..19611a70 100644 --- a/tests/tbf/TbfTest.cpp +++ b/tests/tbf/TbfTest.cpp @@ -219,7 +219,6 @@ static gprs_rlcmac_dl_tbf *create_dl_tbf(struct gprs_rlcmac_bts *bts, uint8_t ms osmo_fsm_inst_dispatch(dl_tbf->dl_ass_fsm.fi, TBF_DL_ASS_EV_SCHED_ASS, NULL); osmo_fsm_inst_dispatch(dl_tbf->state_fsm.fi, TBF_EV_ASSIGN_ADD_CCCH, NULL); osmo_fsm_inst_dispatch(dl_tbf->state_fsm.fi, TBF_EV_ASSIGN_ACK_PACCH, NULL); - dl_tbf->m_wait_confirm = 0; check_tbf(dl_tbf); *trx_no_ = trx_no; @@ -591,9 +590,13 @@ static void test_tbf_dl_llc_loss() OSMO_ASSERT(ms_dl_tbf(ms) != NULL); /* Here PCU would answer with data_cnf and trigger - * bts_rcv_imm_ass_cnf(), which would set up the timer X2002. In this - * test we go directly to T0 timeout to move it to FLOW state: */ - ms_dl_tbf(ms)->handle_timeout(); + * bts_rcv_imm_ass_cnf(), which would trigger TBF_EV_ASSIGN_PCUIF_CNF. + * That in turn would set up timer X2002. Finally, X2002 timeout + * moves it to FLOW state. We set X2002 timeout to 0 here to get + * immediate trigger through osmo_select_main() */ + OSMO_ASSERT(osmo_tdef_set(the_pcu->T_defs, -2002, 0, OSMO_TDEF_MS) == 0); + osmo_fsm_inst_dispatch(ms_dl_tbf(ms)->state_fsm.fi, TBF_EV_ASSIGN_PCUIF_CNF, NULL); + osmo_select_main(0); OSMO_ASSERT(ms_dl_tbf(ms)->state_is(TBF_ST_FLOW)); /* Get first BSN */ diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err index b66707a7..e5664ef2 100644 --- a/tests/tbf/TbfTest.err +++ b/tests/tbf/TbfTest.err @@ -1681,7 +1681,9 @@ TBF(DL-TFI_0){NULL}: state_chg to ASSIGN TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=ASSIGN) TX: START Immediate Assignment Downlink (PCH) - TRX=0 (0) TS=4 TA=0 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=ASSIGN) appending 19 bytes -TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=ASSIGN) timer 0 expired. cur_fn=2654167 +TBF(DL-TFI_0){ASSIGN}: Received Event ASSIGN_PCUIF_CNF +TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=ASSIGN) Starting timer X2002 [assignment (AGCH)] with 0 sec. 0 microsec +TBF(DL-TFI_0){ASSIGN}: Timeout of X2002 TBF(DL-TFI_0){ASSIGN}: Received Event ASSIGN_READY_CCCH TBF(DL-TFI_0){ASSIGN}: state_chg to FLOW TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=FLOW) downlink (V(A)==0 .. V(S)==0) mcs_mode_restrict=EGPRS @@ -2047,6 +2049,7 @@ PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654292): TBF(TFI=0 TLLI= TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) poll timeout for FN=2654292, TS=7 (curr FN 2654292) TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) N3105 0 => 1 (< MAX 8) +TBF(DL-TFI_0){FINISHED}: Received Event DL_ACKNACK_MISS PDCH(bts=0,trx=0,ts=7) Received RTS for PDCH: FN=2654296 block_nr=2 scheduling USF=0 for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW), expect answer on UL FN=2654301 PDCH(bts=0,trx=0,ts=7) FN=2654296 Scheduling data message at RTS for DL TFI=0 prio=5 mcs_mode_restrict=EGPRS_GMSK-only TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) downlink (V(A)==0 .. V(S)==1) mcs_mode_restrict=EGPRS_GMSK-only @@ -2107,6 +2110,7 @@ PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654309): TBF(TFI=0 TLLI= TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) poll timeout for FN=2654309, TS=7 (curr FN 2654348) TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FINISHED}: Received Event DL_ACKNACK_MISS PDCH(bts=0,trx=0,ts=7) Received RTS for PDCH: FN=2654348 block_nr=2 scheduling USF=0 for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW), expect answer on UL FN=2654353 UL_ASS_TBF(UL-TFI_1){SEND_ASS}: Received Event CREATE_RLCMAC_MSG PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654348 + 13 = 2654361 @@ -4283,10 +4287,12 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 112) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS PDCH(bts=0,trx=0,ts=4) Expiring FN=112 but previous FN=104 is still reserved! PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=104): TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=104, TS=4 (curr FN 112) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 2 => 3 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRRRRRRRRRRRRRRRRRRR"(BSN=24) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:25, lost=0, recv=25, skipped=0, bsn=0, info='RRRRRRRRRRRRRRRRRRRRRRRRR.......................................' @@ -4546,6 +4552,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 91) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRRRRRRRRRRRRRR"(BSN=19) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:20, lost=0, recv=20, skipped=0, bsn=0, info='RRRRRRRRRRRRRRRRRRRR............................................' @@ -4765,6 +4772,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 69) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRRRRRRRRR"(BSN=14) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:15, lost=0, recv=15, skipped=0, bsn=0, info='RRRRRRRRRRRRRRR.................................................' @@ -4968,6 +4976,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 60) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRRRRRRR"(BSN=12) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:13, lost=0, recv=13, skipped=0, bsn=0, info='RRRRRRRRRRRRR...................................................' @@ -5155,6 +5164,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 52) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRRRRR"(BSN=10) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:11, lost=0, recv=11, skipped=0, bsn=0, info='RRRRRRRRRRR.....................................................' @@ -5318,6 +5328,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 39) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRR"(BSN=7) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:8, lost=0, recv=8, skipped=0, bsn=0, info='RRRRRRRR........................................................' @@ -5490,6 +5501,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 34) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRRRRR"(BSN=10) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:11, lost=0, recv=10, skipped=1, bsn=0, info='xRRRRRRRRRR.....................................................' @@ -5653,6 +5665,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 30) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRRR"(BSN=8) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:9, lost=0, recv=9, skipped=0, bsn=0, info='RRRRRRRRR.......................................................' @@ -5805,6 +5818,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 26) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 1 => 2 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RRRRRRRR"(BSN=7) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:8, lost=0, recv=8, skipped=0, bsn=0, info='RRRRRRRR........................................................' @@ -6119,6 +6133,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=21): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=21, TS=4 (curr FN 63) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 0 => 1 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RR"(BSN=1) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:2, lost=0, recv=2, skipped=0, bsn=0, info='RR..............................................................' @@ -6213,6 +6228,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=21): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=21, TS=4 (curr FN 63) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 0 => 1 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RR"(BSN=1) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:2, lost=0, recv=2, skipped=0, bsn=0, info='RR..............................................................' @@ -6307,6 +6323,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 63) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 0 => 1 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RR"(BSN=1) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:2, lost=0, recv=2, skipped=0, bsn=0, info='RR..............................................................' @@ -6401,6 +6418,7 @@ PDCH(bts=0,trx=0,ts=4) Timeout for registered POLL (FN=17): TBF(TFI=0 TLLI=0xffe TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) poll timeout for FN=17, TS=4 (curr FN 63) TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) Timeout for polling PACKET DOWNLINK ACK: |Assignment was on PACCH|No downlink ACK received yet| TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) N3105 0 => 1 (< MAX 8) +TBF(DL-TFI_0){FLOW}: Received Event DL_ACKNACK_MISS TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) downlink acknowledge TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) ack: (BSN=0)"RR"(BSN=1) R=ACK I=NACK TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW EGPRS) DL analysis, range=0:2, lost=0, recv=2, skipped=0, bsn=0, info='RR..............................................................'