rlcmac: Log RTS.ind

Change-Id: I678f2aaea419a0cb5dad58610784144538914cf5

2 files changed, 42 insertions, 0 deletions

diff --git a/src/rlcmac/rlcmac_prim.c b/src/rlcmac/rlcmac_prim.c
index 0e73ecd..f5c171a 100644
--- a/src/rlcmac/rlcmac_prim.c
+++ b/src/rlcmac/rlcmac_prim.c
@@ -565,6 +565,8 @@ static int rlcmac_prim_handle_l1ctl_pdch_rts_ind(struct osmo_gprs_rlcmac_prim *r
 		.usf = rlcmac_prim->l1ctl.pdch_rts_ind.usf,
 	};
 
+	LOGRLCMAC(LOGL_DEBUG, "Rx RTS.ind (fn=%u, ts=%u, usf=%u)\n", bi.fn, bi.ts, bi.usf);
+
 	rc = gprs_rlcmac_rcv_rts_block(&bi);
 	return rc;
 }
diff --git a/tests/rlcmac/rlcmac_prim_test.err b/tests/rlcmac/rlcmac_prim_test.err
index 41773b2..1fedbba 100644
--- a/tests/rlcmac/rlcmac_prim_test.err
+++ b/tests/rlcmac/rlcmac_prim_test.err
@@ -22,6 +22,7 @@ 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
@@ -36,6 +37,7 @@ 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_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 (26): add length header to delimit LLC frame
@@ -63,6 +65,7 @@ DLGLOBAL DEBUG UL_TBF{FINISHED}: Final ACK received
 DLGLOBAL INFO UL_TBF{FINISHED}: state_chg to RELEASING
 DLGLOBAL DEBUG Register POLL (TS=7 FN=21, reason=UL_ACK)
 DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG Rx RTS.ind (fn=21, ts=7, usf=0)
 DLGLOBAL DEBUG (ts=7,fn=21,usf=0) Tx Pkt Control Ack (UL ACK/NACK poll)
 DLGLOBAL DEBUG GRE(00002342) Tx Packet Control Ack
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
@@ -202,6 +205,7 @@ 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
@@ -240,6 +244,7 @@ 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) 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
@@ -275,6 +280,7 @@ 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) 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
@@ -310,6 +316,7 @@ 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) 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
@@ -358,6 +365,7 @@ 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=8, 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
@@ -372,6 +380,7 @@ 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_RTS.indication
+DLGLOBAL DEBUG Rx RTS.ind (fn=13, ts=7, usf=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 1, CS=CS-2
 DLGLOBAL DEBUG -- Chunk with length 7 is less than remaining space (26): add length header to delimit LLC frame
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0
@@ -385,6 +394,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 3c 01 02 1f 0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (2)
 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=17, ts=7, usf=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 2, CS=CS-2
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Entering Countdown procedure CV=0
 DLGLOBAL DEBUG -- Chunk with length 15 is less than remaining space (26): add length header to delimit LLC frame
@@ -400,6 +410,7 @@ DLGLOBAL INFO UL_TBF{FLOW}: state_chg to FINISHED
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (3)
 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=21, ts=7, usf=0)
 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)
@@ -409,6 +420,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (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=26, 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
@@ -417,6 +429,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 3c 01 02 1f 0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (5)
 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) Resending BSN 2
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 2 BSN2 -1)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs
@@ -427,6 +440,7 @@ DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=1
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (6)
 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=34, ts=7, usf=0)
 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)
@@ -436,6 +450,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (7)
 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=39, 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
@@ -444,6 +459,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 3c 01 02 1f 0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (8)
 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=43, ts=7, usf=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 2
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 2 BSN2 -1)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs
@@ -454,6 +470,7 @@ DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=2
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (9)
 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=47, ts=7, usf=0)
 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)
@@ -463,6 +480,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 3c 01 01 00 0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (10)
 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=52, 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
@@ -471,6 +489,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 3c 01 02 1f 0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (11)
 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=56, ts=7, usf=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Resending BSN 2
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 2 BSN2 -1)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying 1 RLC blocks, 1 BSNs
@@ -532,6 +551,7 @@ 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
@@ -554,6 +574,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) V(B): (V(A)=1)""(V(S)-1=0)  A=Acked N=
 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
@@ -600,6 +621,7 @@ 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
@@ -622,6 +644,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) V(B): (V(A)=1)""(V(S)-1=0)  A=Acked N=
 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
@@ -637,6 +660,7 @@ 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.
 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)
@@ -648,6 +672,7 @@ DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=1
 DLGLOBAL INFO UL_TBF{FINISHED}: Last UL block sent (CV=0), start T3182
 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=17, 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)
@@ -659,6 +684,7 @@ DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=2
 DLGLOBAL INFO UL_TBF{FINISHED}: Last UL block sent (CV=0), start T3182
 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=21, 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)
@@ -670,6 +696,7 @@ DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=3
 DLGLOBAL INFO UL_TBF{FINISHED}: Last UL block sent (CV=0), start T3182
 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=26, 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)
@@ -714,6 +741,7 @@ 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=200)
 DLGLOBAL DEBUG -- Chunk with length 200 larger than space (26) left in block: copy only remaining space, and we are done
@@ -736,6 +764,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) V(B): (V(A)=1)""(V(S)-1=0)  A=Acked N=
 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 -- Chunk with length 174 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=1, CS-2, CV=15): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 
@@ -745,6 +774,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=1 CV=15)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 1, CS-2): 3c 00 03 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 
 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) Sending new block at BSN 2, CS=CS-2
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Entering Countdown procedure CV=4
 DLGLOBAL DEBUG -- Chunk with length 144 larger than space (30) left in block: copy only remaining space, and we are done
@@ -755,6 +785,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=2 CV=4)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 2, CS-2): 10 00 05 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 
 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=17, ts=7, usf=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 3, CS=CS-2
 DLGLOBAL DEBUG -- Chunk with length 114 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=3, CS-2, CV=3): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 
@@ -764,6 +795,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=3 CV=3)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 3, CS-2): 0c 00 07 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 
 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=21, ts=7, usf=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 4, CS=CS-2
 DLGLOBAL DEBUG -- Chunk with length 84 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=4, CS-2, CV=2): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 
@@ -773,6 +805,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=4 CV=2)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 4, CS-2): 08 00 09 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 
 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=26, ts=7, usf=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Sending new block at BSN 5, CS=CS-2
 DLGLOBAL DEBUG -- Chunk with length 54 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=5, CS-2, CV=1): ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 
@@ -782,6 +815,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=5 CV=1)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 5, CS-2): 04 00 0b ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 00 
 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) Sending new block at BSN 6, CS=CS-2
 DLGLOBAL DEBUG -- Chunk with length 24 is less than remaining space (30): add length header to delimit LLC frame
 DLGLOBAL DEBUG -- Final block, so we done.
@@ -824,6 +858,7 @@ 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) Entering Countdown procedure CV=0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Dequeue next LLC (len=14)
@@ -856,6 +891,7 @@ DLGLOBAL DEBUG Register POLL (TS=7 FN=17, reason=UL_ACK)
 DLGLOBAL INFO Rx from upper layers: GRR-UNITDATA.request
 DLGLOBAL DEBUG GRE(00002342) Enqueueing LLC-PDU len=14 SAPI=GMM radio_prio=1
 DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG Rx RTS.ind (fn=17, ts=7, usf=0)
 DLGLOBAL DEBUG (ts=7,fn=17,usf=0) Tx Pkt Resource Request (UL ACK/NACK poll)
 DLGLOBAL INFO UL_TBF{NEW}: Allocated
 DLGLOBAL INFO UL_TBF_ASS{IDLE}: Allocated
@@ -908,6 +944,7 @@ DLGLOBAL INFO DL_TBF{FLOW}: Received Event LAST_DL_DATA_RECVD
 DLGLOBAL INFO DL_TBF{FLOW}: state_chg to FINISHED
 DLGLOBAL DEBUG Register POLL (TS=7 FN=21, reason=DL_ACK)
 DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG Rx RTS.ind (fn=21, ts=7, usf=0)
 DLGLOBAL DEBUG (ts=7,fn=21,usf=0) Tx DL ACK/NACK FinalAck=1
 DLGLOBAL DEBUG TBF(DL:NR-0:TLLI-00000001) - SSN 1, V(N): "IIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIR" R=Received I=Invalid, FINAL_ACK=1
 DLGLOBAL INFO TBF(DL:NR-0:TLLI-00000001) Starting T3192 (0 ms)
@@ -949,6 +986,7 @@ DLGLOBAL DEBUG Register POLL (TS=7 FN=21, reason=DL_ACK)
 DLGLOBAL INFO Rx from upper layers: GRR-UNITDATA.request
 DLGLOBAL DEBUG GRE(00000001) Enqueueing LLC-PDU len=14 SAPI=GMM radio_prio=1
 DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG Rx RTS.ind (fn=21, ts=7, usf=0)
 DLGLOBAL DEBUG (ts=7,fn=21,usf=0) Tx DL ACK/NACK FinalAck=1
 DLGLOBAL INFO UL_TBF{NEW}: Allocated
 DLGLOBAL INFO UL_TBF_ASS{IDLE}: Allocated
@@ -967,6 +1005,7 @@ DLGLOBAL INFO UL_TBF_ASS{WAIT_PKT_UL_ASS}: state_chg to WAIT_TBF_STARTING_TIME2
 DLGLOBAL INFO TBF(UL:NR-0:TLLI-00000001) Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 ul_slotmask=0xc0 tbf_starting_time(present=1 fn=52)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request
 DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
+DLGLOBAL DEBUG Rx RTS.ind (fn=43, ts=7, usf=2)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) TS=7 FN=43 Waiting for tbf_starting_time=52
 DLGLOBAL DEBUG (ts=7,fn=43,usf=2) Tx Pkt Control Ack (UL ASS poll)
 DLGLOBAL INFO UL_TBF_ASS{WAIT_TBF_STARTING_TIME2}: Received Event CREATE_RLCMAC_MSG
@@ -974,6 +1013,7 @@ DLGLOBAL INFO UL_TBF_ASS{WAIT_TBF_STARTING_TIME2}: TS=7 FN=43 Tx Pkt Ctrl Ack
 DLGLOBAL DEBUG GRE(00000001) Tx Packet Control Ack
 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=52, ts=6, usf=1)
 DLGLOBAL INFO TBF(UL:NR-0:TLLI-00000001) TS=52 FN=6 TBF_STARTING_TIME reached
 DLGLOBAL INFO UL_TBF_ASS{WAIT_TBF_STARTING_TIME2}: Received Event TBF_STARTING_TIME
 DLGLOBAL INFO UL_TBF_ASS{WAIT_TBF_STARTING_TIME2}: state_chg to COMPLETED