From a9da84ac9f59e1222156583480886ad859cbc261 Mon Sep 17 00:00:00 2001 From: Pau Espin Pedrol Date: Thu, 16 Feb 2023 18:28:34 +0100 Subject: [PATCH] rlcmac: Implement N3104 Related: OS#5500 Change-Id: Ia8c35aad7a537ab76447187847f8cee8c379352c --- include/osmocom/gprs/rlcmac/tbf_ul.h | 2 +- include/osmocom/gprs/rlcmac/tbf_ul_fsm.h | 1 + src/rlcmac/tbf_ul.c | 20 ++++ src/rlcmac/tbf_ul_fsm.c | 9 ++ tests/rlcmac/rlcmac_prim_test.c | 109 ++++++++++++++++++++ tests/rlcmac/rlcmac_prim_test.err | 124 +++++++++++++++++++++++ tests/rlcmac/rlcmac_prim_test.ok | 26 +++++ 7 files changed, 290 insertions(+), 1 deletion(-) diff --git a/include/osmocom/gprs/rlcmac/tbf_ul.h b/include/osmocom/gprs/rlcmac/tbf_ul.h index f1b7128..c187938 100644 --- a/include/osmocom/gprs/rlcmac/tbf_ul.h +++ b/include/osmocom/gprs/rlcmac/tbf_ul.h @@ -46,7 +46,7 @@ struct gprs_rlcmac_ul_tbf *gprs_rlcmac_ul_tbf_alloc(struct gprs_rlcmac_entity *g 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); - +unsigned int gprs_rlcmac_ul_tbf_n3104_max(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 6957992..8cadf69 100644 --- a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h +++ b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h @@ -28,6 +28,7 @@ enum tbf_ul_fsm_event { 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_N3104_MAX, 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/tbf_ul.c b/src/rlcmac/tbf_ul.c index ce7ac1f..d5067dc 100644 --- a/src/rlcmac/tbf_ul.c +++ b/src/rlcmac/tbf_ul.c @@ -112,6 +112,17 @@ bool gprs_rlcmac_ul_tbf_in_contention_resolution(const struct gprs_rlcmac_ul_tbf } } +unsigned int gprs_rlcmac_ul_tbf_n3104_max(const struct gprs_rlcmac_ul_tbf *ul_tbf) +{ + /* 3GPP TS 44.060 13.3: + * N3104_MAX = 3 * (BS_CV_MAX + 3) * number of uplink timeslots assigned */ + /* If we didn't receive SI13 yet, use maximum value bs_cv_max in range 0..15 */ + uint8_t bs_cv_max = g_ctx->si13_available ? + g_ctx->si13ro.u.PBCCH_Not_present.GPRS_Cell_Options.BS_CV_MAX : + 15; + return 3 * (bs_cv_max + 3) * ul_tbf->cur_alloc.num_ts; +} + /* 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) @@ -790,6 +801,15 @@ static struct msgb *create_ul_acked_block(struct gprs_rlcmac_ul_tbf *ul_tbf, if (ul_tbf->n3104 == 0) osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi, GPRS_RLCMAC_TBF_UL_EV_FIRST_UL_DATA_SENT, NULL); ul_tbf->n3104++; + if (gprs_rlcmac_ul_tbf_in_contention_resolution(ul_tbf)) { + unsigned int n3104_max = gprs_rlcmac_ul_tbf_n3104_max(ul_tbf); + if (ul_tbf->n3104 >= n3104_max) { + LOGPTBFUL(ul_tbf, LOGL_NOTICE, "N3104_MAX (%u) reached\n", n3104_max); + osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi, GPRS_RLCMAC_TBF_UL_EV_N3104_MAX, NULL); + } else { + LOGPTBFUL(ul_tbf, LOGL_DEBUG, "N3104 inc (%u)\n", ul_tbf->n3104); + } + } return msg; } diff --git a/src/rlcmac/tbf_ul_fsm.c b/src/rlcmac/tbf_ul_fsm.c index 19d352d..a84859d 100644 --- a/src/rlcmac/tbf_ul_fsm.c +++ b/src/rlcmac/tbf_ul_fsm.c @@ -34,6 +34,7 @@ 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_N3104_MAX, "N3104_MAX" }, { 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" }, @@ -149,6 +150,9 @@ static void st_flow(struct osmo_fsm_inst *fi, uint32_t event, void *data) osmo_timer_schedule(&fi->timer, val_sec, 0); } break; + case GPRS_RLCMAC_TBF_UL_EV_N3104_MAX: + reinit_pkt_acces_procedure(ctx); + 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); @@ -168,6 +172,9 @@ 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; switch (event) { + case GPRS_RLCMAC_TBF_UL_EV_N3104_MAX: + reinit_pkt_acces_procedure(ctx); + 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); @@ -204,6 +211,7 @@ static struct osmo_fsm_state tbf_ul_fsm_states[] = { [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_N3104_MAX) | X(GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS) | X(GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT), .out_state_mask = @@ -214,6 +222,7 @@ static struct osmo_fsm_state tbf_ul_fsm_states[] = { }, [GPRS_RLCMAC_TBF_UL_ST_FINISHED] = { .in_event_mask = + X(GPRS_RLCMAC_TBF_UL_EV_N3104_MAX) | X(GPRS_RLCMAC_TBF_UL_EV_CONTENTION_RESOLUTION_SUCCESS) | X(GPRS_RLCMAC_TBF_UL_EV_FINAL_ACK_RECVD), .out_state_mask = diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c index 09fa3c4..cc33c4c 100644 --- a/tests/rlcmac/rlcmac_prim_test.c +++ b/tests/rlcmac/rlcmac_prim_test.c @@ -24,6 +24,8 @@ #include #include #include +#include +#include #include #include @@ -293,6 +295,63 @@ static void ul_ack_nack_mark(Ack_Nack_Description_t *ack_desc, unsigned int idx, ack_desc->RECEIVED_BLOCK_BITMAP[sizeof(ack_desc->RECEIVED_BLOCK_BITMAP) - idx/8 - 1] &= ~(1 << (idx & 0x03)); } +static uint8_t *create_si13(uint8_t bs_cv_max /* 0..15 */) +{ + static uint8_t si13_buf[GSM_MACBLOCK_LEN]; + struct gsm48_system_information_type_13 *si13 = (struct gsm48_system_information_type_13 *)&si13_buf[0]; + struct osmo_gsm48_si13_info si13_info; + int ret; + + memset(si13, GSM_MACBLOCK_PADDING, GSM_MACBLOCK_LEN); + + si13->header.rr_protocol_discriminator = GSM48_PDISC_RR; + si13->header.skip_indicator = 0; + si13->header.system_information = GSM48_MT_RR_SYSINFO_13; + + si13_info = (struct osmo_gsm48_si13_info){ + .cell_opts = { + .nmo = GPRS_NMO_II, + .t3168 = 2000, + .t3192 = 1500, + .drx_timer_max = 3, + .bs_cv_max = bs_cv_max, + .ctrl_ack_type_use_block = 1, + .ext_info_present = true, + .ext_info = { + .egprs_supported = 1, + .use_egprs_p_ch_req = 1, + .bep_period = 5, + .pfc_supported = 0, + .dtm_supported = 0, + .bss_paging_coordination = 1, + .ccn_active = true, + }, + }, + .pwr_ctrl_pars = { + .alpha = 0, /* a = 0.0 */ + .t_avg_w = 16, + .t_avg_t = 16, + .pc_meas_chan = 0, /* downling measured on CCCH */ + .n_avg_i = 8, + }, + .bcch_change_mark = 1, /* Information about the other SIs */ + .si_change_field = 0, + .rac = 33, + .spgc_ccch_sup = 0, + .net_ctrl_ord = 1 /* NC1 */, + .prio_acc_thr = 6, + }; + + ret = osmo_gsm48_rest_octets_si13_encode(si13->rest_octets, &si13_info); + if (ret < 0) + return NULL; + + /* length is coded in bit 2 an up */ + si13->header.l2_plen = 0x01; + + return &si13_buf[0]; +} + static int test_rlcmac_prim_up_cb(struct osmo_gprs_rlcmac_prim *rlcmac_prim, void *user_data) { const char *pdu_name = osmo_gprs_rlcmac_prim_name(rlcmac_prim); @@ -524,6 +583,55 @@ static void test_ul_tbf_t3166_timeout(void) cleanup_test(); } +static void test_ul_tbf_n3104_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; + const unsigned int bs_cv_max = 0; + const unsigned int num_ts = 1; + const unsigned int n3104_max = 3 * (bs_cv_max + 3) * num_ts; + + /* Submit an SI13 with bs_cv_max=0: */ + rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_l1ctl_ccch_data_ind(0, create_si13(bs_cv_max)); + rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim); + OSMO_ASSERT(rc == 0); + + 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); + + 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); + OSMO_ASSERT(rc == 0); + + for (i = 0; i < n3104_max; i++) { + rts_fn = fn_next_block(rts_fn); + printf("RTS %u: FN=%u\n", i, rts_fn); + /* 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); + } + + /* After N3104 triggers, MS re-tries pkt access: */ + 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); + + 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) { @@ -593,6 +701,7 @@ int main(int argc, char *argv[]) test_ul_tbf_attach(); test_ul_tbf_t3164_timeout(); test_ul_tbf_t3166_timeout(); + test_ul_tbf_n3104_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 26deb79..cd154f1 100644 --- a/tests/rlcmac/rlcmac_prim_test.err +++ b/tests/rlcmac/rlcmac_prim_test.err @@ -28,6 +28,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c 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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) 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 @@ -40,6 +41,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN 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 1) DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (2) DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_DATA.indication DLGLOBAL INFO TS=7 FN=8 Rx Pkt UL ACK/NACK DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Got GPRS UL ACK bitmap: SSN: 1, BSN 0 to 2 - 1 (2 blocks), "RR" @@ -160,6 +162,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c 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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) 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 @@ -187,6 +190,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c 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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) 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 @@ -214,6 +218,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c 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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) 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 @@ -241,11 +246,130 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 00 01 01 c 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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) 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 lower layers: L1CTL-CCCH_DATA.indication +DLGLOBAL DEBUG Rx SI13 from lower layers +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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (1) +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 +DLGLOBAL DEBUG -- Final block, so we done. +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0 +DLGLOBAL INFO UL_TBF{FLOW}: Received Event LAST_UL_DATA_SENT +DLGLOBAL INFO UL_TBF{FLOW}: state_chg to FINISHED +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN 1, CS-2): 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (2) +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all blocks have been transmitted. +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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (3) +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (4) +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all blocks have been transmitted. +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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (5) +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (6) +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all blocks have been transmitted. +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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (7) +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 1 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 1 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 1) +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (8) +DLGLOBAL INFO Rx from lower layers: L1CTL-PDCH_RTS.indication +DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all blocks have been transmitted. +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 NOTICE TBF(UL:NR-0:TLLI-00002342) N3104_MAX (9) reached +DLGLOBAL INFO UL_TBF{FINISHED}: Received Event N3104_MAX +DLGLOBAL INFO UL_TBF{FINISHED}: 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=0x7b +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 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 9c61988..3db040a 100644 --- a/tests/rlcmac/rlcmac_prim_test.ok +++ b/tests/rlcmac/rlcmac_prim_test.ok @@ -53,6 +53,32 @@ test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 dat 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_ul_tbf_n3104_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 +RTS 0: FN=8 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 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 ] +RTS 1: FN=13 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=13 ts=7 data_len=34 data=[00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ] +RTS 2: FN=17 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=17 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 ] +RTS 3: FN=21 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=34 data=[00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ] +RTS 4: FN=26 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=26 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 ] +RTS 5: FN=30 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=30 ts=7 data_len=34 data=[00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ] +RTS 6: FN=34 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=34 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 ] +RTS 7: FN=39 +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=39 ts=7 data_len=34 data=[00 00 02 0d e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ] +RTS 8: FN=43 +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=0x7b +test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=43 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 ] +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x80 +=== test_ul_tbf_n3104_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