pespin has submitted this change. ( https://gerrit.osmocom.org/c/libosmo-gprs/+/31350 )
Change subject: rlcmac: Implement T3166 ......................................................................
rlcmac: Implement T3166
Change-Id: I58dd757cbb5d8279fdf7fbdfb6f38ec0119c6156 --- M include/osmocom/gprs/rlcmac/tbf_ul.h M include/osmocom/gprs/rlcmac/tbf_ul_fsm.h M src/rlcmac/rlcmac.c M src/rlcmac/tbf_ul.c M src/rlcmac/tbf_ul_fsm.c M tests/rlcmac/rlcmac_prim_test.c M tests/rlcmac/rlcmac_prim_test.err M tests/rlcmac/rlcmac_prim_test.ok 8 files changed, 288 insertions(+), 15 deletions(-)
Approvals: laforge: Looks good to me, but someone else must approve Jenkins Builder: Verified pespin: Looks good to me, approved
diff --git a/include/osmocom/gprs/rlcmac/tbf_ul.h b/include/osmocom/gprs/rlcmac/tbf_ul.h index 08075be..f1b7128 100644 --- a/include/osmocom/gprs/rlcmac/tbf_ul.h +++ b/include/osmocom/gprs/rlcmac/tbf_ul.h @@ -45,6 +45,8 @@ struct gprs_rlcmac_ul_tbf *gprs_rlcmac_ul_tbf_alloc(struct gprs_rlcmac_entity *gre); void gprs_rlcmac_ul_tbf_free(struct gprs_rlcmac_ul_tbf *ul_tbf);
+bool gprs_rlcmac_ul_tbf_in_contention_resolution(const struct gprs_rlcmac_ul_tbf *ul_tbf); + bool gprs_rlcmac_ul_tbf_data_rts(const struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi); bool gprs_rlcmac_ul_tbf_dummy_rts(const struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi);
diff --git a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h index 327acd7..6957992 100644 --- a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h +++ b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h @@ -28,6 +28,7 @@ GPRS_RLCMAC_TBF_UL_EV_UL_ASS_START, GPRS_RLCMAC_TBF_UL_EV_UL_ASS_COMPL, GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT, + GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS, GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT, GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD, }; diff --git a/src/rlcmac/rlcmac.c b/src/rlcmac/rlcmac.c index ac489d5..cff7c79 100644 --- a/src/rlcmac/rlcmac.c +++ b/src/rlcmac/rlcmac.c @@ -45,6 +45,7 @@ /* TS 44.060 Table 13.1.1 */ static struct osmo_tdef T_defs_rlcmac[] = { { .T=3164, .default_val=5, .desc="Wait for Uplink State Flag After Assignment (s)" }, + { .T=3166, .default_val=5, .desc="Wait for Packet Uplink ACK/NACK after sending of first data block (s)" }, { 0 } /* empty item at the end */ };
diff --git a/src/rlcmac/tbf_ul.c b/src/rlcmac/tbf_ul.c index a47a2b3..993f694 100644 --- a/src/rlcmac/tbf_ul.c +++ b/src/rlcmac/tbf_ul.c @@ -90,6 +90,28 @@ talloc_free(ul_tbf); }
+/* whether the UL TBF is in Contention Resolution state (false = already succeeded)*/ +bool gprs_rlcmac_ul_tbf_in_contention_resolution(const struct gprs_rlcmac_ul_tbf *ul_tbf) +{ + struct osmo_fsm_inst *fi = ul_tbf->state_fsm.fi; + switch (fi->state) { + case GPRS_RLCMAC_TBF_UL_ST_NEW: + case GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN: + return true; + case GPRS_RLCMAC_TBF_UL_ST_FLOW: + case GPRS_RLCMAC_TBF_UL_ST_FINISHED: + /* TS 44.60 7.1.3.3: For 2hase access, contention resolution is + * successful once we get out of GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN + * (when we receive a Pkt Ul Ass, see TS 44.60 7.1.3.3) */ + /* 1phase access: Check if either T3164 or T3166 are active: */ + return (ul_tbf->ul_ass_fsm.ass_type == GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE && + osmo_timer_pending(&fi->timer) && + (fi->T == 3164 || fi->T == 3166)); + default: + return false; + } +} + /* Used by the scheduler to find out whether an Uplink Dummy Control Block can be transmitted. If * true, it will potentially call gprs_rlcmac_ul_tbf_dummy_create() to generate a new dummy message to transmit. */ bool gprs_rlcmac_ul_tbf_dummy_rts(const struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi) @@ -171,6 +193,9 @@ int rc; rc = gprs_rlcmac_ul_tbf_update_window(ul_tbf, first_bsn, rbb);
+ if (gprs_rlcmac_ul_tbf_in_contention_resolution(ul_tbf)) + osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi, GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS, NULL); + if (final_ack) { LOGPTBFUL(ul_tbf, LOGL_DEBUG, "Final ACK received.\n"); rc = gprs_rlcmac_ul_tbf_handle_final_ack(ul_tbf); diff --git a/src/rlcmac/tbf_ul_fsm.c b/src/rlcmac/tbf_ul_fsm.c index 72f2994..19d352d 100644 --- a/src/rlcmac/tbf_ul_fsm.c +++ b/src/rlcmac/tbf_ul_fsm.c @@ -25,16 +25,18 @@
#include <osmocom/gprs/rlcmac/tbf_ul_fsm.h> #include <osmocom/gprs/rlcmac/tbf_ul.h> +#include <osmocom/gprs/rlcmac/rlc_window_ul.h> #include <osmocom/gprs/rlcmac/gre.h>
#define X(s) (1 << (s))
static const struct value_string tbf_ul_fsm_event_names[] = { - { GPRS_RLCMAC_TBF_UL_EV_UL_ASS_START, "UL_ASS_START" }, - { GPRS_RLCMAC_TBF_UL_EV_UL_ASS_COMPL, "UL_ASS_COMPL" }, - { GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT, "FIRST_UL_DATA_SENT" }, - { GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT, "LAST_UL_DATA_SENT" }, - { GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD, "FINAL_ACK_RECVD" }, + { GPRS_RLCMAC_TBF_UL_EV_UL_ASS_START, "UL_ASS_START" }, + { GPRS_RLCMAC_TBF_UL_EV_UL_ASS_COMPL, "UL_ASS_COMPL" }, + { GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT, "FIRST_UL_DATA_SENT" }, + { GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS, "CONTENTION_RESOLUTION_SUCCESS" }, + { GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT, "LAST_UL_DATA_SENT" }, + { GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD, "FINAL_ACK_RECVD" }, { 0, NULL } };
@@ -42,7 +44,7 @@ [GPRS_RLCMAC_TBF_UL_ST_NEW] = { }, [GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN] = { }, [GPRS_RLCMAC_TBF_UL_ST_FLOW] = { .T = 3164 }, - [GPRS_RLCMAC_TBF_UL_ST_FINISHED] = { }, + [GPRS_RLCMAC_TBF_UL_ST_FINISHED] = { .keep_timer = true }, /* keep FLOW state's T3164 / T3166 */ };
/* Transition to a state, using the T timer defined in tbf_fsm_timeouts. @@ -77,14 +79,29 @@ return gprs_rlcmac_prim_call_down_cb(rlcmac_prim); }
+static void reinit_pkt_acces_procedure(struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx) +{ + int rc; + /* TS 44.060 sub-clause 7.1.4. Reinitiate the packet access procedure: + * Move to NEW state, start Ass and wait for GPRS_RLCMAC_TBF_UL_ASS_EV_START */ + tbf_ul_fsm_state_chg(ctx->fi, GPRS_RLCMAC_TBF_UL_ST_NEW); + /* We always use 1phase for now... */ + rc = gprs_rlcmac_tbf_ul_ass_start(ctx->ul_tbf, GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE); + if (rc < 0) + gprs_rlcmac_ul_tbf_free(ctx->ul_tbf); +} + /* This one is triggered when packet access procedure fails, which can happen * either in WAIT_IMM_ASS (ImmAss timeout), FLOW (T3164) or FINISHED (T3164, T3166) */ static void st_new_on_enter(struct osmo_fsm_inst *fi, uint32_t prev_state) { struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv; + memset(&ctx->ul_tbf->cur_alloc, 0, sizeof(ctx->ul_tbf->cur_alloc)); ctx->ul_tbf->n3104 = 0;
+ /* Mark everything we transmitted so far as NACKed: */ + gprs_rlcmac_rlc_ul_window_mark_for_resend(ctx->ul_tbf->ulw); /* Make sure the lower layers realize this tbf_nr has no longer any assigned resource: */ configure_ul_tbf(ctx); } @@ -118,11 +135,26 @@ static void st_flow(struct osmo_fsm_inst *fi, uint32_t event, void *data) { struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv; + unsigned long val_sec; + switch (event) { case GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT: LOGPFSML(ctx->fi, LOGL_INFO, "First UL block sent, stop T3164\n"); OSMO_ASSERT(fi->T == 3164); osmo_timer_del(&fi->timer); + if (ctx->ul_tbf->ul_ass_fsm.ass_type == GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE) { + LOGPFSML(ctx->fi, LOGL_INFO, "First UL block sent (1 phase access), start T3166\n"); + fi->T = 3166; + val_sec = osmo_tdef_get(g_ctx->T_defs, fi->T, OSMO_TDEF_S, -1); + osmo_timer_schedule(&fi->timer, val_sec, 0); + } + break; + case GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS: + LOGPFSML(ctx->fi, LOGL_INFO, "Contention resolution succeeded, stop T3166\n"); + OSMO_ASSERT(ctx->ul_tbf->ul_ass_fsm.ass_type == GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE); + OSMO_ASSERT(fi->T == 3166); + osmo_timer_del(&fi->timer); + fi->T = 0; break; case GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT: tbf_ul_fsm_state_chg(fi, GPRS_RLCMAC_TBF_UL_ST_FINISHED); @@ -134,8 +166,15 @@
static void st_finished(struct osmo_fsm_inst *fi, uint32_t event, void *data) { - //struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv; + struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv; switch (event) { + case GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS: + LOGPFSML(ctx->fi, LOGL_INFO, "Contention resolution succeeded, stop T3166\n"); + OSMO_ASSERT(ctx->ul_tbf->ul_ass_fsm.ass_type == GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE); + OSMO_ASSERT(fi->T == 3166); + osmo_timer_del(&fi->timer); + fi->T = 0; + break; case GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD: break; default: @@ -165,6 +204,7 @@ [GPRS_RLCMAC_TBF_UL_ST_FLOW] = { .in_event_mask = X(GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT) | + X(GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS) | X(GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT), .out_state_mask = X(GPRS_RLCMAC_TBF_UL_ST_NEW) | @@ -174,9 +214,10 @@ }, [GPRS_RLCMAC_TBF_UL_ST_FINISHED] = { .in_event_mask = + X(GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS) | X(GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD), .out_state_mask = - X(GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN), + X(GPRS_RLCMAC_TBF_UL_ST_NEW), .name = "FINISHED", .action = st_finished, }, @@ -185,7 +226,6 @@ static int tbf_ul_fsm_timer_cb(struct osmo_fsm_inst *fi) { struct gprs_rlcmac_tbf_ul_fsm_ctx *ctx = (struct gprs_rlcmac_tbf_ul_fsm_ctx *)fi->priv; - int rc;
switch (fi->T) { case 3164: @@ -200,13 +240,23 @@ gprs_rlcmac_ul_tbf_free(ctx->ul_tbf); return 0; } - /* TS 44.060 sub-clause 7.1.4. Reinitiate the packet access procedure: - * Move to NEW state, start Ass and wait for GPRS_RLCMAC_TBF_UL_ASS_EV_START */ - tbf_ul_fsm_state_chg(fi, GPRS_RLCMAC_TBF_UL_ST_NEW); - /* We always use 1phase for now... */ - rc = gprs_rlcmac_tbf_ul_ass_start(ctx->ul_tbf, GPRS_RLCMAC_TBF_UL_ASS_TYPE_1PHASE); - if (rc < 0) + reinit_pkt_acces_procedure(ctx); + break; + case 3166: + ctx->pkt_acc_proc_attempts++; + LOGPFSML(ctx->fi, LOGL_INFO, "T3166 timeout attempts=%u\n", ctx->pkt_acc_proc_attempts); + OSMO_ASSERT(fi->state == GPRS_RLCMAC_TBF_UL_ST_FLOW || + fi->state == GPRS_RLCMAC_TBF_UL_ST_FINISHED); + if (ctx->pkt_acc_proc_attempts == 4) { + /* TS 44.060 7.1.4 "... expiry of timers T3166 ... the + * mobile station shall remain in packet idle mode and + * notify higher layer (TBF establishment failure)" */ + /* TODO: find out how to notify higher layers */ + LOGPFSML(ctx->fi, LOGL_NOTICE, "TBF establishment failure (T3166 timeout attempts=%u)\n", ctx->pkt_acc_proc_attempts); gprs_rlcmac_ul_tbf_free(ctx->ul_tbf); + return 0; + } + reinit_pkt_acces_procedure(ctx); break; default: OSMO_ASSERT(0); diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c index 75c18f8..09fa3c4 100644 --- a/tests/rlcmac/rlcmac_prim_test.c +++ b/tests/rlcmac/rlcmac_prim_test.c @@ -485,6 +485,45 @@ cleanup_test(); }
+static void test_ul_tbf_t3166_timeout(void) +{ + struct osmo_gprs_rlcmac_prim *rlcmac_prim; + int rc; + + printf("=== %s start ===\n", __func__); + prepare_test(); + uint32_t tlli = 0x2342; + uint8_t ts_nr = 7; + uint8_t usf = 0; + uint32_t rts_fn = 4; + unsigned int i; + + rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_grr_unitdata_req(tlli, pdu_llc_gmm_att_req, + sizeof(pdu_llc_gmm_att_req)); + rlcmac_prim->grr.unitdata_req.sapi = OSMO_GPRS_RLCMAC_LLC_SAPI_GMM; + rc = osmo_gprs_rlcmac_prim_upper_down(rlcmac_prim); + + for (i = 0; i < 4; i++) { + OSMO_ASSERT(sizeof(ccch_imm_ass_pkt_ul_tbf_normal) == GSM_MACBLOCK_LEN); + ccch_imm_ass_pkt_ul_tbf_normal[7] = last_rach_req_ra; /* Update RA to match */ + rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_l1ctl_ccch_data_ind(0, ccch_imm_ass_pkt_ul_tbf_normal); + rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim); + + /* Trigger transmission of LLC data (GMM Attach) (first part) */ + rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_l1ctl_pdch_rts_ind(ts_nr, rts_fn, usf); + rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim); + OSMO_ASSERT(rc == 0); + + /* increase time 5 seconds, timeout should trigger */ + clock_override_add(5, 0); + clock_debug("Expect T3166 timeout"); + osmo_select_main(0); + } + + printf("=== %s end ===\n", __func__); + cleanup_test(); +} + /* PCU allocates a DL TBF through PCH ImmAss for MS (when in packet-idle) */ static void test_dl_tbf_ccch_assign(void) { @@ -553,6 +592,7 @@
test_ul_tbf_attach(); test_ul_tbf_t3164_timeout(); + test_ul_tbf_t3166_timeout(); test_dl_tbf_ccch_assign();
talloc_free(tall_ctx); diff --git a/tests/rlcmac/rlcmac_prim_test.err b/tests/rlcmac/rlcmac_prim_test.err index 3346867..26deb79 100644 --- a/tests/rlcmac/rlcmac_prim_test.err +++ b/tests/rlcmac/rlcmac_prim_test.err @@ -27,6 +27,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166 DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 1, CS=CS-2 DLGLOBAL DEBUG -- Chunk with length 3 is less than remaining space (30): add length header to delimit LLC frame @@ -46,6 +47,8 @@ DLGLOBAL DEBUG - got ack for BSN=0 DLGLOBAL DEBUG - got ack for BSN=1 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) V(B): (V(A)=2)""(V(S)-1=1) A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid +DLGLOBAL INFO UL_TBF{FINISHED}: Received Event CONTENTION_RESOLUTION_SUCCESS +DLGLOBAL INFO UL_TBF{FINISHED}: Contention resolution succeeded, stop T3166 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Final ACK received. DLGLOBAL INFO UL_TBF{FINISHED}: Received Event FINAL_ACK_RECVD DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated @@ -127,6 +130,122 @@ DLGLOBAL NOTICE UL_TBF{FLOW}: TBF establishment failure (T3164 timeout attempts=4) DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated DLGLOBAL INFO UL_TBF{FLOW}: Deallocated +DLGLOBAL INFO Rx from upper layers: GRR-UNITDATA.request +DLGLOBAL INFO TLLI=0x00002342 not found, creating entity on the fly +DLGLOBAL INFO UL_TBF{NEW}: Allocated +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Allocated +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Received Event START +DLGLOBAL INFO UL_TBF{NEW}: Received Event UL_ASS_START +DLGLOBAL INFO UL_TBF{NEW}: state_chg to ASSIGN +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Send RACH.req ra=0x7a +DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS +DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: Received Event RX_CCCH_IMM_ASS +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss initial CS=CS-2 +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss DynamicAlloc (1phase access) ts_nr=7 usf=0 +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: state_chg to COMPLETED +DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL +DLGLOBAL INFO UL_TBF{ASSIGN}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x80 +DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW +DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 0, CS=CS-2 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Dequeue next LLC (len=33) +DLGLOBAL DEBUG -- Chunk with length 33 larger than space (30) left in block: copy only remaining space, and we are done +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN 0, CS-2): 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 0 BSN2 -1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 +DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166 +DLGLOBAL INFO UL_TBF{FLOW}: Timeout of T3166 +DLGLOBAL INFO UL_TBF{FLOW}: T3166 timeout attempts=1 +DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW +DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x00 +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Received Event START +DLGLOBAL INFO UL_TBF{NEW}: Received Event UL_ASS_START +DLGLOBAL INFO UL_TBF{NEW}: state_chg to ASSIGN +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Send RACH.req ra=0x7c +DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS +DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: Received Event RX_CCCH_IMM_ASS +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss initial CS=CS-2 +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss DynamicAlloc (1phase access) ts_nr=7 usf=0 +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: state_chg to COMPLETED +DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL +DLGLOBAL INFO UL_TBF{ASSIGN}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x80 +DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW +DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 0 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 0 BSN2 -1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 +DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166 +DLGLOBAL INFO UL_TBF{FLOW}: Timeout of T3166 +DLGLOBAL INFO UL_TBF{FLOW}: T3166 timeout attempts=2 +DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW +DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x00 +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Received Event START +DLGLOBAL INFO UL_TBF{NEW}: Received Event UL_ASS_START +DLGLOBAL INFO UL_TBF{NEW}: state_chg to ASSIGN +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Send RACH.req ra=0x79 +DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS +DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: Received Event RX_CCCH_IMM_ASS +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss initial CS=CS-2 +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss DynamicAlloc (1phase access) ts_nr=7 usf=0 +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: state_chg to COMPLETED +DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL +DLGLOBAL INFO UL_TBF{ASSIGN}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x80 +DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW +DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 0 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 0 BSN2 -1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 +DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166 +DLGLOBAL INFO UL_TBF{FLOW}: Timeout of T3166 +DLGLOBAL INFO UL_TBF{FLOW}: T3166 timeout attempts=3 +DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW +DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x00 +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Received Event START +DLGLOBAL INFO UL_TBF{NEW}: Received Event UL_ASS_START +DLGLOBAL INFO UL_TBF{NEW}: state_chg to ASSIGN +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Send RACH.req ra=0x7d +DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS +DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: Received Event RX_CCCH_IMM_ASS +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss initial CS=CS-2 +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: ImmAss DynamicAlloc (1phase access) ts_nr=7 usf=0 +DLGLOBAL INFO UL_TBF_ASS{WAIT_CCCH_IMM_ASS}: state_chg to COMPLETED +DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL +DLGLOBAL INFO UL_TBF{ASSIGN}: Send L1CTL-CF_UL_TBF.req ul_slotmask=0x80 +DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW +DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 0 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 0 BSN2 -1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 +DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164 +DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent (1 phase access), start T3166 +DLGLOBAL INFO UL_TBF{FLOW}: Timeout of T3166 +DLGLOBAL INFO UL_TBF{FLOW}: T3166 timeout attempts=4 +DLGLOBAL NOTICE UL_TBF{FLOW}: TBF establishment failure (T3166 timeout attempts=4) +DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated +DLGLOBAL INFO UL_TBF{FLOW}: Deallocated DLGLOBAL INFO Rx from upper layers: GMMRR-ASSIGN.request DLGLOBAL INFO GMMRR-ASSIGN.req: creating new entity TLLI=0x00000001 DLGLOBAL INFO Rx from lower layers: L1CTL-CCCH_DATA.indication diff --git a/tests/rlcmac/rlcmac_prim_test.ok b/tests/rlcmac/rlcmac_prim_test.ok index c419cb6..9c61988 100644 --- a/tests/rlcmac/rlcmac_prim_test.ok +++ b/tests/rlcmac/rlcmac_prim_test.ok @@ -27,6 +27,32 @@ sys={20.000000}, mono={20.000000}: clock_override_add sys={20.000000}, mono={20.000000}: Expect T3164 timeout === test_ul_tbf_t3164_timeout end === +=== test_ul_tbf_t3166_timeout start === +sys={0.000000}, mono={0.000000}: clock_override_set +test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7a +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x80 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 ] +sys={5.000000}, mono={5.000000}: clock_override_add +sys={5.000000}, mono={5.000000}: Expect T3166 timeout +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00 +test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7c +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x80 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 ] +sys={10.000000}, mono={10.000000}: clock_override_add +sys={10.000000}, mono={10.000000}: Expect T3166 timeout +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00 +test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x79 +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x80 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 ] +sys={15.000000}, mono={15.000000}: clock_override_add +sys={15.000000}, mono={15.000000}: Expect T3166 timeout +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00 +test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7d +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x80 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[3c 00 01 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 00 00 00 00 71 62 f2 24 6c 84 44 04 11 e5 10 00 00 ] +sys={20.000000}, mono={20.000000}: clock_override_add +sys={20.000000}, mono={20.000000}: Expect T3166 timeout +=== test_ul_tbf_t3166_timeout end === === test_dl_tbf_ccch_assign start === sys={0.000000}, mono={0.000000}: clock_override_set test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_DL_TBF.request dl_tbf_nr=0 dl_slotmask=0x80 dl_tfi=0
-
pespin