[M] Change in libosmo-gprs[master]: rlcmac: tests: Account for T3180 existance in test_ul_tbf_t3166_timeout

16 Oct 2023

pespin has uploaded this change for review. (
https://gerrit.osmocom.org/c/libosmo-gprs/+/34772?usp=email )


Change subject: rlcmac: tests: Account for T3180 existance in test_ul_tbf_t3166_timeout
......................................................................

rlcmac: tests: Account for T3180 existance in test_ul_tbf_t3166_timeout

Test test_ul_tbf_t3166_timeout needs to be modified in order to avoid
triggering T3180 once it is implemented in a follow-up patch.
Both T3180 and T3166 are armed at the same time, so modify the scenario
to really scenify the case where T3166 matters: the MS keeps receiving USF
indications but the PCU doesn't see them and hence never sends a PKT UL
ACK/NACK.

Related: OS#6209
Change-Id: Ib84ccfd89773913703e0ab3e09d0ce9eb123e994
---
M tests/rlcmac/rlcmac_prim_test.c
M tests/rlcmac/rlcmac_prim_test.err
M tests/rlcmac/rlcmac_prim_test.ok
3 files changed, 99 insertions(+), 17 deletions(-)



  git pull ssh://gerrit.osmocom.org:29418/libosmo-gprs refs/changes/72/34772/1

diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c
index 93f59fc..fb179fd 100644
--- a/tests/rlcmac/rlcmac_prim_test.c
+++ b/tests/rlcmac/rlcmac_prim_test.c
@@ -750,7 +750,7 @@
 	rlcmac_prim->grr.unitdata_req.radio_prio = 1;
 	rc = osmo_gprs_rlcmac_prim_upper_down(rlcmac_prim);
 
-	for (i = 0; i < 4; i++) {
+	for (i = 0; i < 4; i++) { /* 4 packet access procedure attempts */
 		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);
@@ -761,8 +761,16 @@
 		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);
+		/* In 5 seconds, T3166 will trigger. T3180 has also been armed
+		* at 5s, so scenify PCU USF-polling the MS to avoid trigger T3180
+		* instead of T3166. Fir increase 2 of the 5 seconds: */
+		clock_override_add(2, 0);
+		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 Remaining 3 out of 5 seconds, T3166 timeout should trigger */
+		clock_override_add(3, 0);
 		clock_debug("Expect T3166 timeout");
 		osmo_select_main(0);
 	}
diff --git a/tests/rlcmac/rlcmac_prim_test.err b/tests/rlcmac/rlcmac_prim_test.err
index 9435c04..5027ca8 100644
--- a/tests/rlcmac/rlcmac_prim_test.err
+++ b/tests/rlcmac/rlcmac_prim_test.err
@@ -219,9 +219,25 @@
 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 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 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 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 (26): 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 00 00 23 42
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 
+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 01 02 1d 00 00 23
42 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 00 
+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) N3104 inc (2)
+DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
+DLGLOBAL INFO UL_TBF{FINISHED}: Timeout of T3166
+DLGLOBAL INFO UL_TBF{FINISHED}: T3166 timeout attempts=1
+DLGLOBAL INFO UL_TBF{FINISHED}: state_chg to NEW
 DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 (release)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request
 DLGLOBAL INFO Tx L1CTL-PDCH_REL.req
@@ -255,9 +271,20 @@
 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 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 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) 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 01 02 1d 00 00 23
42 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 00 
+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) N3104 inc (2)
+DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
+DLGLOBAL INFO UL_TBF{FINISHED}: Timeout of T3166
+DLGLOBAL INFO UL_TBF{FINISHED}: T3166 timeout attempts=2
+DLGLOBAL INFO UL_TBF{FINISHED}: state_chg to NEW
 DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 (release)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request
 DLGLOBAL INFO Tx L1CTL-PDCH_REL.req
@@ -291,9 +318,20 @@
 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 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 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) 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 01 02 1d 00 00 23
42 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 00 
+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) N3104 inc (2)
+DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
+DLGLOBAL INFO UL_TBF{FINISHED}: Timeout of T3166
+DLGLOBAL INFO UL_TBF{FINISHED}: T3166 timeout attempts=3
+DLGLOBAL INFO UL_TBF{FINISHED}: state_chg to NEW
 DLGLOBAL INFO UL_TBF{NEW}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 (release)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request
 DLGLOBAL INFO Tx L1CTL-PDCH_REL.req
@@ -327,13 +365,24 @@
 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 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 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) 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 01 02 1d 00 00 23
42 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 00 
+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) N3104 inc (2)
+DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
+DLGLOBAL INFO UL_TBF{FINISHED}: Timeout of T3166
+DLGLOBAL INFO UL_TBF{FINISHED}: T3166 timeout attempts=4
+DLGLOBAL NOTICE UL_TBF{FINISHED}: TBF establishment failure (T3166 timeout attempts=4)
 DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated
-DLGLOBAL INFO UL_TBF{FLOW}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 (release)
+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{FLOW}: Deallocated
+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
diff --git a/tests/rlcmac/rlcmac_prim_test.ok b/tests/rlcmac/rlcmac_prim_test.ok
index c4f014a..571f918 100644
--- a/tests/rlcmac/rlcmac_prim_test.ok
+++ b/tests/rlcmac/rlcmac_prim_test.ok
@@ -52,6 +52,8 @@
 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 ]
+sys={2.000000}, mono={2.000000}: clock_override_add
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[00 01
02 1d 00 00 23 42 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 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
@@ -60,6 +62,8 @@
 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_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 ]
+sys={7.000000}, mono={7.000000}: clock_override_add
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[00 01
02 1d 00 00 23 42 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 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
@@ -68,6 +72,8 @@
 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_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 ]
+sys={12.000000}, mono={12.000000}: clock_override_add
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[00 01
02 1d 00 00 23 42 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 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
@@ -76,6 +82,8 @@
 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_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 ]
+sys={17.000000}, mono={17.000000}: clock_override_add
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 data=[00 01
02 1d 00 00 23 42 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 00 ]
 sys={20.000000}, mono={20.000000}: clock_override_add
 sys={20.000000}, mono={20.000000}: Expect T3166 timeout
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00

-- 
To view, visit https://gerrit.osmocom.org/c/libosmo-gprs/+/34772?usp=email
To unsubscribe, or for help writing mail filters, visit
https://gerrit.osmocom.org/settings

Gerrit-Project: libosmo-gprs
Gerrit-Branch: master
Gerrit-Change-Id: Ib84ccfd89773913703e0ab3e09d0ce9eb123e994
Gerrit-Change-Number: 34772
Gerrit-PatchSet: 1
Gerrit-Owner: pespin &lt;pespin(a)sysmocom.de&gt;
Gerrit-MessageType: newchange



    

2025

2024

2023

2022

[M] Change in libosmo-gprs[master]: rlcmac: tests: Account for T3180 existance in test_ul_tbf_t3166_timeout