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 <pes...@sysmocom.de>
Gerrit-MessageType: newchange
