tbf_ul_fsm: Avoid freeing tbf after 4 CV=0 retrans in acknowledged mode

The restriction to only to transmit last data block (CV=0) up to 4 times
only applies in Unacknowledged mode of operation, which we don't
support. Hence, simply comment it out so that it can be enabled if
unacknowledge mode is ever supported.

Related: OS#6208
Change-Id: Ie7cdb286b9c7255e3fbf9f936f103fab04acf96a

4 files changed, 64 insertions, 99 deletions

diff --git a/src/rlcmac/tbf_ul_fsm.c b/src/rlcmac/tbf_ul_fsm.c
index 3c041a6..e5a2f9a 100644
--- a/src/rlcmac/tbf_ul_fsm.c
+++ b/src/rlcmac/tbf_ul_fsm.c
@@ -233,18 +233,22 @@ static void st_finished(struct osmo_fsm_inst *fi, uint32_t event, void *data)
 		}
 		break;
 	case GPRS_RLCMAC_TBF_UL_EV_LAST_UL_DATA_SENT:
-		/* If LAST_UL_DATA_SENT is received in this state, it means the
-		 * UL TBF is retransmitting the block.
-		 * 9.3.3.3.2: The block with CV=0 shall not be retransmitted more than four times.
-		 */
+		/* If LAST_UL_DATA_SENT is received in this state, it means the UL TBF is retransmitting the block. */
 		ctx->last_data_block_retrans_attempts++;
 		LOGPFSML(ctx->fi, LOGL_INFO, "Data block with CV=0 retransmit attempts=%u\n", ctx->last_data_block_retrans_attempts);
 		arm_T3182_if_needed(ctx);
+		/* 9.3.2.4.2 (Acknowledged mode): When the mobile station has sent the RLC data block with CV = 0 and there are no
+		 * elements in the V(B) array set to the value Nacked, it shall start timer T3182 for this TBF [...and ...] shall
+		 * continue to send RLC data blocks on each assigned uplink data block */
+#if 0
+		/*  9.3.3.3.2 (Unacknowledged mode): The block with CV=0 shall not be retransmitted more than four times.
+		 * FIXME: Remove "if 0" when unacknowledged mode support is added. */
 		if (ctx->last_data_block_retrans_attempts == 4) {
 			LOGPFSML(ctx->fi, LOGL_NOTICE, "TBF establishment failure (Data block with CV=0 retransmit attempts=%u)\n",
 				 ctx->last_data_block_retrans_attempts);
 			gprs_rlcmac_ul_tbf_free(ctx->ul_tbf);
 		}
+#endif
 		break;
 	default:
 		OSMO_ASSERT(0);
diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c
index 35def30..046e7cc 100644
--- a/tests/rlcmac/rlcmac_prim_test.c
+++ b/tests/rlcmac/rlcmac_prim_test.c
@@ -826,7 +826,18 @@ static void test_ul_tbf_n3104_timeout(void)
 	cleanup_test();
 }
 
-static void test_ul_tbf_t3182_timeout(void)
+/* 9.3.2.4.2 (acked mode): When the mobile station has sent the RLC data block
+ * with CV = 0 and there are no elements in the V(B) array set to the value
+ * Nacked, it shall start timer T3182 for this TBF. The mobile station shall
+ * continue to send RLC data blocks on each assigned uplink data block,
+ * according to the algorithm defined in sub-clause 9.1.3.
+ * 9.3.3.3.2 (unacked mode): Upon each retransmission of the last block with
+ * CV=0, the mobile station shall restart timer T3182 for the TBF. The block
+ * with CV=0 shall not be retransmitted more than four times. If the medium
+ * access mode is dynamic allocation, the repetitions are transmitted when the
+ * mobile station is scheduled USFs.
+ */
+static void test_ul_tbf_t3182_timeout(bool acked_mode)
 {
 	struct osmo_gprs_rlcmac_prim *rlcmac_prim;
 	int rc;
@@ -873,6 +884,19 @@ static void test_ul_tbf_t3182_timeout(void)
 	rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim);
 	OSMO_ASSERT(rc == 0);
 
+	if (acked_mode) {
+		/* Make sure we don't apply the max-4-cv0-tx limit as with unacked mode: */
+		unsigned int i;
+		for (i = 0; i < 5; i++) {
+			rts_fn = fn_next_block(rts_fn);
+			printf("RTS %u: FN=%u\n", i, rts_fn);
+			/* Trigger transmission of LLC data (GMM Attach) (second 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 T3182 timeout");
@@ -882,8 +906,10 @@ static void test_ul_tbf_t3182_timeout(void)
 	cleanup_test();
 }
 
+#if 0
+/* FIXME: enable this whenever unacknowledged mode is supported. */
 /* 9.3.3.3.2: The block with CV=0 shall not be retransmitted more than four times. */
-static void test_ul_tbf_last_data_cv0_retrans_max(void)
+static void test_ul_tbf_unack_mode_last_data_cv0_retrans_max(void)
 {
 	struct osmo_gprs_rlcmac_prim *rlcmac_prim;
 	int rc;
@@ -943,6 +969,7 @@ static void test_ul_tbf_last_data_cv0_retrans_max(void)
 	printf("=== %s end ===\n", __func__);
 	cleanup_test();
 }
+#endif
 
 /* 9.3.1 Countdown procedure */
 static void test_ul_tbf_countdown_procedure(void)
@@ -1206,8 +1233,11 @@ int main(int argc, char *argv[])
 	test_ul_tbf_t3164_timeout();
 	test_ul_tbf_t3166_timeout();
 	test_ul_tbf_n3104_timeout();
-	test_ul_tbf_t3182_timeout();
-	test_ul_tbf_last_data_cv0_retrans_max();
+	test_ul_tbf_t3182_timeout(true);
+#if 0
+	test_ul_tbf_t3182_timeout(false);
+	test_ul_tbf_unack_mode_last_data_cv0_retrans_max();
+#endif
 	test_ul_tbf_countdown_procedure();
 	test_ul_tbf_request_another_ul_tbf();
 	test_dl_tbf_ccch_assign();
diff --git a/tests/rlcmac/rlcmac_prim_test.err b/tests/rlcmac/rlcmac_prim_test.err
index c76fe8f..19b289f 100644
--- a/tests/rlcmac/rlcmac_prim_test.err
+++ b/tests/rlcmac/rlcmac_prim_test.err
@@ -589,76 +589,6 @@ DLGLOBAL INFO UL_TBF{FLOW}: Received Event LAST_UL_DATA_SENT
 DLGLOBAL INFO UL_TBF{FLOW}: Last UL block sent (CV=0), start T3182
 DLGLOBAL INFO UL_TBF{FLOW}: state_chg to FINISHED
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
-DLGLOBAL INFO UL_TBF{FINISHED}: Timeout of T3182
-DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated
-DLGLOBAL INFO UL_TBF{FINISHED}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 (release)
-DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request
-DLGLOBAL INFO UL_TBF{FINISHED}: Deallocated
-DLGLOBAL INFO Tx L1CTL-PDCH_REL.req
-DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_RELEASE.request
-DLGLOBAL INFO DL_TBF_ASS{IDLE}: Deallocated
-DLGLOBAL INFO Rx from upper layers: GRR-UNITDATA.request
-DLGLOBAL INFO TLLI=0x00002342 not found, creating entity on the fly
-DLGLOBAL INFO DL_TBF_ASS{IDLE}: Allocated
-DLGLOBAL DEBUG GRE(00002342) Enqueueing LLC-PDU len=33 SAPI=GMM radio_prio=1
-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}: Requesting one-phase packet access using CCCH
-DLGLOBAL DEBUG Tx to lower layers: L1CTL-RACH.request
-DLGLOBAL INFO UL_TBF_ASS{IDLE}: state_chg to WAIT_CCCH_IMM_ASS
-DLGLOBAL DEBUG Rx from lower layers: L1CTL-CCCH_DATA.indication
-DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_ESTABLISH.request
-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 TFI=0 initCS=CS-2 cur_tn=7 cur_fn=0 start_fn=0
-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 TBF(UL:NR-0:TLLI-00002342) Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 ul_slotmask=0x80 tbf_starting_time(present=0 fn=0)
-DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request
-DLGLOBAL INFO UL_TBF{ASSIGN}: state_chg to FLOW
-DLGLOBAL INFO UL_TBF_ASS{COMPLETED}: state_chg to IDLE
-DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
-DLGLOBAL DEBUG Rx RTS.ind (fn=4, ts=7, usf=0)
-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 (26) 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, CV=15): 00 00 23 42 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 
-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 CV=15)
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 00 23 42 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 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 DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
-DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_DATA.indication
-DLGLOBAL INFO TS=7 FN=4 Rx Pkt UL ACK/NACK
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Got GPRS UL ACK bitmap: SSN: 1, BSN 0 to 1 - 1 (1 blocks), "R"
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) ack:  (BSN=0)"R"(BSN=0)  R=ACK I=NACK
-DLGLOBAL DEBUG - got ack for BSN=0
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) V(B): (V(A)=1)""(V(S)-1=0)  A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid
-DLGLOBAL INFO UL_TBF{FLOW}: Received Event RX_UL_ACK_NACK
-DLGLOBAL INFO UL_TBF{FLOW}: Contention resolution succeeded, stop T3166
-DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
-DLGLOBAL DEBUG Rx RTS.ind (fn=8, ts=7, usf=0)
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 1, CS=CS-2
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Entering Countdown procedure CV=0
-DLGLOBAL DEBUG -- Chunk with length 7 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 DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=1, CS-2, CV=0): 1d 11 e5 10 00 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 
-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 CV=0)
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 11 e5 10 00 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 00 
-DLGLOBAL INFO UL_TBF{FLOW}: Received Event LAST_UL_DATA_SENT
-DLGLOBAL INFO UL_TBF{FLOW}: Last UL block sent (CV=0), start T3182
-DLGLOBAL INFO UL_TBF{FLOW}: state_chg to FINISHED
-DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
 DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 DLGLOBAL DEBUG Rx RTS.ind (fn=13, ts=7, usf=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all blocks have been transmitted.
@@ -706,12 +636,24 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 1
 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT
 DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=4
 DLGLOBAL INFO UL_TBF{FINISHED}: Last UL block sent (CV=0), start T3182
-DLGLOBAL NOTICE UL_TBF{FINISHED}: TBF establishment failure (Data block with CV=0 retransmit attempts=4)
+DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
+DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG Rx RTS.ind (fn=30, ts=7, usf=0)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all blocks have been transmitted.
+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 CV=0)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 00 00 02 1d 11 e5 10 00 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 00 
+DLGLOBAL INFO UL_TBF{FINISHED}: Received Event LAST_UL_DATA_SENT
+DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=5
+DLGLOBAL INFO UL_TBF{FINISHED}: Last UL block sent (CV=0), start T3182
+DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
+DLGLOBAL INFO UL_TBF{FINISHED}: Timeout of T3182
 DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated
 DLGLOBAL INFO UL_TBF{FINISHED}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 (release)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request
 DLGLOBAL INFO UL_TBF{FINISHED}: Deallocated
-DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
 DLGLOBAL INFO Tx L1CTL-PDCH_REL.req
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_RELEASE.request
 DLGLOBAL INFO DL_TBF_ASS{IDLE}: Deallocated
diff --git a/tests/rlcmac/rlcmac_prim_test.ok b/tests/rlcmac/rlcmac_prim_test.ok
index dcaa816..f28262a 100644
--- a/tests/rlcmac/rlcmac_prim_test.ok
+++ b/tests/rlcmac/rlcmac_prim_test.ok
@@ -129,21 +129,6 @@ test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=
 test_rlcmac_prim_up_cb(): Rx GMMRR-LLC_TRANSMITTED.indication TLLI=0x00002342
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[3c 01 01 00 00 23 42 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 00 ]
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 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 00 ]
-sys={5.000000}, mono={5.000000}: clock_override_add
-sys={5.000000}, mono={5.000000}: Expect T3182 timeout
-test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
-=== test_ul_tbf_t3182_timeout end ===
-sys={5.027690}, mono={5.027690}: clock_override_add
-sys={5.027690}, mono={5.027690}: Expect defer_pkt_idle_timer timeout
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
-=== test_ul_tbf_last_data_cv0_retrans_max start ===
-sys={0.000000}, mono={0.000000}: clock_override_set
-test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x78
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_ESTABLISH.request
-test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x80
-test_rlcmac_prim_up_cb(): Rx GMMRR-LLC_TRANSMITTED.indication TLLI=0x00002342
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[3c 01 01 00 00 23 42 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 00 ]
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 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 00 ]
 RTS 0: FN=13
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=13 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 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 00 ]
 RTS 1: FN=17
@@ -151,11 +136,15 @@ test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=17 ts=7 data_len=34 da
 RTS 2: FN=21
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 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 00 ]
 RTS 3: FN=26
-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-PDCH_DATA.request fn=26 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 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 00 ]
-=== test_ul_tbf_last_data_cv0_retrans_max end ===
-sys={0.027690}, mono={0.027690}: clock_override_add
-sys={0.027690}, mono={0.027690}: Expect defer_pkt_idle_timer timeout
+RTS 4: FN=30
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=30 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 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 00 ]
+sys={5.000000}, mono={5.000000}: clock_override_add
+sys={5.000000}, mono={5.000000}: Expect T3182 timeout
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
+=== test_ul_tbf_t3182_timeout end ===
+sys={5.027690}, mono={5.027690}: clock_override_add
+sys={5.027690}, mono={5.027690}: Expect defer_pkt_idle_timer timeout
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 === test_ul_tbf_countdown_procedure start ===
 sys={0.000000}, mono={0.000000}: clock_override_set