pespin has uploaded this change for review. ( https://gerrit.osmocom.org/c/libosmo-gprs/+/31347 )
Change subject: rlcmac: Implement T3164 ......................................................................
rlcmac: Implement T3164
Change-Id: I1a3d7b552b36b84d84ca27572ce313265810fd3d --- 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, 218 insertions(+), 9 deletions(-)
git pull ssh://gerrit.osmocom.org:29418/libosmo-gprs refs/changes/47/31347/1
diff --git a/include/osmocom/gprs/rlcmac/tbf_ul.h b/include/osmocom/gprs/rlcmac/tbf_ul.h index f9c5a7f..08075be 100644 --- a/include/osmocom/gprs/rlcmac/tbf_ul.h +++ b/include/osmocom/gprs/rlcmac/tbf_ul.h @@ -26,6 +26,8 @@ /* Currently selected LLC frame to be scheduled/transmitted */ struct msgb *llc_tx_msg; int32_t last_ul_drained_fn; + /* count all transmitted data blocks */ + unsigned int n3104;
/* Holds state of all generated in-transit RLC blocks */ struct gprs_rlcmac_rlc_block_store *blkst; diff --git a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h index 1d7ff88..10115ae 100644 --- a/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h +++ b/include/osmocom/gprs/rlcmac/tbf_ul_fsm.h @@ -20,11 +20,14 @@ struct gprs_rlcmac_tbf *tbf; struct gprs_rlcmac_ul_tbf *ul_tbf; }; + /* Number of packet access procedure timeouts (T3164) */ + unsigned int T3164_attempts; };
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_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 c6c23e6..ac489d5 100644 --- a/src/rlcmac/rlcmac.c +++ b/src/rlcmac/rlcmac.c @@ -42,7 +42,9 @@
struct gprs_rlcmac_ctx *g_ctx;
+/* 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)" }, { 0 } /* empty item at the end */ };
diff --git a/src/rlcmac/tbf_ul.c b/src/rlcmac/tbf_ul.c index 4a6f9ce..a47a2b3 100644 --- a/src/rlcmac/tbf_ul.c +++ b/src/rlcmac/tbf_ul.c @@ -761,6 +761,9 @@ need_padding ? ", padded" : "", msgb_hexdump(msg));
+ 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++; return msg; }
diff --git a/src/rlcmac/tbf_ul_fsm.c b/src/rlcmac/tbf_ul_fsm.c index 3cff899..bc00ef2 100644 --- a/src/rlcmac/tbf_ul_fsm.c +++ b/src/rlcmac/tbf_ul_fsm.c @@ -30,8 +30,9 @@ #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_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" }, { 0, NULL } @@ -40,7 +41,7 @@ static const struct osmo_tdef_state_timeout tbf_ul_fsm_timeouts[32] = { [GPRS_RLCMAC_TBF_UL_ST_NEW] = { }, [GPRS_RLCMAC_TBF_UL_ST_WAIT_ASSIGN] = { }, - [GPRS_RLCMAC_TBF_UL_ST_FLOW] = { }, + [GPRS_RLCMAC_TBF_UL_ST_FLOW] = { .T = 3164 }, [GPRS_RLCMAC_TBF_UL_ST_FINISHED] = { }, };
@@ -104,8 +105,13 @@
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; + 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_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); + break; case GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT: tbf_ul_fsm_state_chg(fi, GPRS_RLCMAC_TBF_UL_ST_FINISHED); break; @@ -145,8 +151,10 @@ }, [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_LAST_UL_DATA_SENT), .out_state_mask = + X(GPRS_RLCMAC_TBF_UL_ST_NEW) | X(GPRS_RLCMAC_TBF_UL_ST_FINISHED), .name = "FLOW", .action = st_flow, @@ -164,13 +172,29 @@ 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 -2001: - LOGPTBFUL(ctx->ul_tbf, LOGL_NOTICE, "releasing due to PACCH assignment timeout.\n"); - /* fall-through */ - case 3169: - case 3195: - gprs_rlcmac_ul_tbf_free(ctx->ul_tbf); + case 3164: + ctx->T3164_attempts++; + LOGPFSML(ctx->fi, LOGL_INFO, "T3164 timeout attempts=%u\n", ctx->T3164_attempts); + OSMO_ASSERT(fi->state == GPRS_RLCMAC_TBF_UL_ST_FLOW); + if (ctx->T3164_attempts == 4) { + /* TS 44.060 7.1.4 "... the packet access procedure has already been attempted four time ..." + * mobile station shall notify higher layers (TBF establishment failure) */ + /* TODO: find out how to notify higher layers */ + gprs_rlcmac_ul_tbf_free(ctx->ul_tbf); + return 0; + } + /* TODO: TS 44.060 sub-clause 7.1.4. Reinitiate the packet + * access procedure unless the packet access procedure has + * already been attempted four times */ + /* 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) + gprs_rlcmac_ul_tbf_free(ctx->ul_tbf); break; default: OSMO_ASSERT(0); diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c index 658ddb3..75c18f8 100644 --- a/tests/rlcmac/rlcmac_prim_test.c +++ b/tests/rlcmac/rlcmac_prim_test.c @@ -21,6 +21,9 @@ #include <osmocom/core/utils.h> #include <osmocom/core/msgb.h> #include <osmocom/core/fsm.h> +#include <osmocom/core/timer.h> +#include <osmocom/core/timer_compat.h> +#include <osmocom/core/select.h>
#include <osmocom/gprs/rlcmac/rlcmac.h> #include <osmocom/gprs/rlcmac/csn1_defs.h> @@ -181,6 +184,44 @@ 0x2b, 0x2b, 0x2b, 0x2b };
+#define clock_debug(fmt, args...) \ + do { \ + struct timespec ts; \ + struct timeval tv; \ + osmo_clock_gettime(CLOCK_MONOTONIC, &ts); \ + osmo_gettimeofday(&tv, NULL); \ + fprintf(stdout, "sys={%lu.%06lu}, mono={%lu.%06lu}: " fmt "\n", \ + tv.tv_sec, tv.tv_usec, ts.tv_sec, ts.tv_nsec/1000, ##args); \ + } while (0) + +static void clock_override_enable(bool enable) +{ + osmo_gettimeofday_override = enable; + osmo_clock_override_enable(CLOCK_MONOTONIC, enable); +} + +static void clock_override_set(long sec, long usec) +{ + struct timespec *mono; + osmo_gettimeofday_override_time.tv_sec = sec; + osmo_gettimeofday_override_time.tv_usec = usec; + mono = osmo_clock_override_gettimespec(CLOCK_MONOTONIC); + mono->tv_sec = sec; + mono->tv_nsec = usec*1000; + + clock_debug("clock_override_set"); +} + +static void clock_override_add_debug(long sec, long usec, bool dbg) +{ + osmo_gettimeofday_override_add(sec, usec); + osmo_clock_override_add(CLOCK_MONOTONIC, sec, usec*1000); + if (dbg) + clock_debug("clock_override_add"); +} +#define clock_override_add(sec, usec) clock_override_add_debug(sec, usec, true) + + static inline unsigned fn2bn(unsigned fn) { return (fn % 52) / 4; @@ -346,6 +387,8 @@ void prepare_test(void) { int rc; + clock_override_set(0, 0); + rc = osmo_gprs_rlcmac_init(OSMO_GPRS_RLCMAC_LOCATION_MS); OSMO_ASSERT(rc == 0);
@@ -409,6 +452,39 @@ cleanup_test(); }
+static void test_ul_tbf_t3164_timeout(void) +{ + struct osmo_gprs_rlcmac_prim *rlcmac_prim; + int rc; + unsigned int i; + + printf("=== %s start ===\n", __func__); + prepare_test(); + uint32_t tlli = 0x2342; + + 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); + + OSMO_ASSERT(sizeof(ccch_imm_ass_pkt_ul_tbf_normal) == GSM_MACBLOCK_LEN); + + for (i = 0; i < 4; i++) { + 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); + + /* increase time 5 seconds, timeout should trigger */ + clock_override_add(5, 0); + clock_debug("Expect T3164 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) { @@ -473,7 +549,10 @@ log_set_print_level(osmo_stderr_target, 1); log_set_use_color(osmo_stderr_target, 0);
+ clock_override_enable(true); + test_ul_tbf_attach(); + test_ul_tbf_t3164_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 8f7283d..922b802 100644 --- a/tests/rlcmac/rlcmac_prim_test.err +++ b/tests/rlcmac/rlcmac_prim_test.err @@ -25,6 +25,8 @@ 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 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 @@ -48,6 +50,79 @@ DLGLOBAL INFO UL_TBF{FINISHED}: Received Event FINAL_ACK_RECVD DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated DLGLOBAL INFO UL_TBF{FINISHED}: 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=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 UL_TBF{FLOW}: Timeout of T3164 +DLGLOBAL INFO UL_TBF{FLOW}: T3164 timeout attempts=1 +DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW +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{FLOW}: Timeout of T3164 +DLGLOBAL INFO UL_TBF{FLOW}: T3164 timeout attempts=2 +DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW +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 UL_TBF{FLOW}: Timeout of T3164 +DLGLOBAL INFO UL_TBF{FLOW}: T3164 timeout attempts=3 +DLGLOBAL INFO UL_TBF{FLOW}: state_chg to NEW +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=0x78 +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{FLOW}: Timeout of T3164 +DLGLOBAL INFO UL_TBF{FLOW}: T3164 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 7792932..52243e5 100644 --- a/tests/rlcmac/rlcmac_prim_test.ok +++ b/tests/rlcmac/rlcmac_prim_test.ok @@ -1,10 +1,31 @@ === test_ul_tbf_attach start === +sys={0.000000}, mono={0.000000}: clock_override_set test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7e 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 ] test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 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 ] === test_ul_tbf_attach end === +=== test_ul_tbf_t3164_timeout start === +sys={0.000000}, mono={0.000000}: clock_override_set +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 +sys={5.000000}, mono={5.000000}: clock_override_add +sys={5.000000}, mono={5.000000}: Expect T3164 timeout +test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7b +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x80 +sys={10.000000}, mono={10.000000}: clock_override_add +sys={10.000000}, mono={10.000000}: Expect T3164 timeout +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 +sys={15.000000}, mono={15.000000}: clock_override_add +sys={15.000000}, mono={15.000000}: Expect T3164 timeout +test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x78 +test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x80 +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_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 test_rlcmac_prim_up_cb(): Rx GRR-UNITDATA.indication TLLI=0x00000001 ll=[43 c0 01 2b 2b 2b ] test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=23 data=[40 14 00 00 00 00 00 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b ]