rlcmac: Several fixes and improvements to have 2phase access working

Some solutions are not meant to be final ones, but some small
workarounds to have the whole thing running until the lower layers are
fixed/improved.

Related: OS#5500
Change-Id: I94bd0de6917b004cba73d2fffc7cf69b3b5c305d

5 files changed, 85 insertions, 12 deletions

diff --git a/src/rlcmac/sched.c b/src/rlcmac/sched.c
index 8709f71..6af2b6a 100644
--- a/src/rlcmac/sched.c
+++ b/src/rlcmac/sched.c
@@ -222,7 +222,7 @@ static struct msgb *sched_select_ctrl_msg(const struct gprs_rlcmac_rts_block_ind
 	if (tbfs->poll_ul_ass) {
 		LOGRLCMAC(LOGL_DEBUG, "(ts=%u,fn=%u,usf=%u) Tx Pkt Control Ack (UL ASS poll)\n",
 			  bi->ts, bi->fn, bi->usf);
-		msg = gprs_rlcmac_gre_create_pkt_ctrl_ack(ul_tbf_as_tbf(tbfs->poll_ul_ass)->gre);
+		msg = gprs_rlcmac_tbf_ul_ass_create_rlcmac_msg(tbfs->poll_ul_ass, bi);
 		if (msg)
 			return msg;
 	}
diff --git a/src/rlcmac/tbf_ul_ass_fsm.c b/src/rlcmac/tbf_ul_ass_fsm.c
index 8244f8e..0f0f9ee 100644
--- a/src/rlcmac/tbf_ul_ass_fsm.c
+++ b/src/rlcmac/tbf_ul_ass_fsm.c
@@ -30,6 +30,7 @@
 #include <osmocom/gprs/rlcmac/types.h>
 #include <osmocom/gprs/rlcmac/tbf_ul_ass_fsm.h>
 #include <osmocom/gprs/rlcmac/tbf_ul.h>
+#include <osmocom/gprs/rlcmac/tbf_dl.h>
 #include <osmocom/gprs/rlcmac/gre.h>
 #include <osmocom/gprs/rlcmac/sched.h>
 #include <osmocom/gprs/rlcmac/csn1_defs.h>
@@ -392,9 +393,17 @@ static void st_wait_pkt_ul_ass(struct osmo_fsm_inst *fi, uint32_t event, void *d
 		/* If RRBP contains valid data, schedule a response (PKT CONTROL ACK or PKT RESOURCE REQ). */
 		if (d->dl_block->SP) {
 			uint32_t poll_fn = rrbp2fn(d->fn, d->dl_block->RRBP);
+			uint32_t next_blk = fn_next_block(fn_next_block(poll_fn));
 			gprs_rlcmac_pdch_ulc_reserve(g_rlcmac_ctx->sched.ulc[d->ts_nr], poll_fn,
 						GPRS_RLCMAC_PDCH_ULC_POLL_UL_ASS,
 						ul_tbf_as_tbf(ctx->ul_tbf));
+			/* We need to wait at least until sending the PKT CTRL
+			 * ACK (in the old CTRL TS) before completing the
+			 * assignment and using the new TS assignment. */
+			if (!ctx->tbf_starting_time_exists && fn_cmp(ctx->tbf_starting_time, next_blk) < 0) {
+				ctx->tbf_starting_time_exists = true;
+				ctx->tbf_starting_time = next_blk;
+			}
 		}
 
 		if (ctx->tbf_starting_time_exists &&
@@ -409,10 +418,21 @@ static void st_wait_pkt_ul_ass(struct osmo_fsm_inst *fi, uint32_t event, void *d
 	}
 }
 
+static void st_wait_tbf_starting_time2_on_enter(struct osmo_fsm_inst *fi, uint32_t prev_state)
+{
+	struct gprs_rlcmac_tbf_ul_ass_fsm_ctx *ctx = (struct gprs_rlcmac_tbf_ul_ass_fsm_ctx *)fi->priv;
+
+	/* Configure lower layers to submit an RTS tick starting at tbf_starting_time
+	 * and scheduler will send event GPRS_RLCMAC_TBF_UL_ASS_EV_TBF_STARTING_TIME to us. */
+	gprs_rlcmac_ul_tbf_submit_configure_req(ctx->ul_tbf, &ctx->phase2_alloc,
+						ctx->tbf_starting_time_exists, ctx->tbf_starting_time);
+}
+
 static void st_wait_tbf_starting_time2(struct osmo_fsm_inst *fi, uint32_t event, void *data)
 {
 	struct gprs_rlcmac_tbf_ul_ass_fsm_ctx *ctx = (struct gprs_rlcmac_tbf_ul_ass_fsm_ctx *)fi->priv;
 	struct tbf_ul_ass_ev_rx_pkt_ul_ass_ctx *d;
+	struct tbf_ul_ass_ev_create_rlcmac_msg_ctx *data_ctx;
 	int rc;
 
 	switch (event) {
@@ -425,9 +445,26 @@ static void st_wait_tbf_starting_time2(struct osmo_fsm_inst *fi, uint32_t event,
 		/* If RRBP contains valid data, schedule a response (PKT CONTROL ACK or PKT RESOURCE REQ). */
 		if (d->dl_block->SP) {
 			uint32_t poll_fn = rrbp2fn(d->fn, d->dl_block->RRBP);
+			uint32_t next_blk = fn_next_block(poll_fn);
+			/* FIXME: double fn_next_block() here is to delay
+			* release of old TS late enough so that the PKT CTRL ACK
+			* is transmitted. This is wrong since we basically lose
+			* the first TS in the new TBF, but otherwise lower layers
+			* may free the lchan while last burst of the last block is
+			* still not transmitted... IMHO lower layers need to be
+			* fixed to delay closing the lchan until all the
+			* blocks/bursts enqueued are transmitted... */
+			next_blk = fn_next_block(next_blk);
 			gprs_rlcmac_pdch_ulc_reserve(g_rlcmac_ctx->sched.ulc[d->ts_nr], poll_fn,
 						GPRS_RLCMAC_PDCH_ULC_POLL_UL_ASS,
 						ul_tbf_as_tbf(ctx->ul_tbf));
+			/* We need to wait at least until sending the PKT CTRL
+			 * ACK (in the old CTRL TS) before completing the
+			 * assignment and using the new TS assignment. */
+			if (!ctx->tbf_starting_time_exists && fn_cmp(ctx->tbf_starting_time, next_blk) < 0) {
+				ctx->tbf_starting_time_exists = true;
+				ctx->tbf_starting_time = next_blk;
+			}
 		}
 
 		if (ctx->tbf_starting_time_exists &&
@@ -440,6 +477,13 @@ static void st_wait_tbf_starting_time2(struct osmo_fsm_inst *fi, uint32_t event,
 	case GPRS_RLCMAC_TBF_UL_ASS_EV_TBF_STARTING_TIME:
 		tbf_ul_ass_fsm_state_chg(fi, GPRS_RLCMAC_TBF_UL_ASS_ST_COMPL);
 		break;
+	case GPRS_RLCMAC_TBF_UL_ASS_EV_CREATE_RLCMAC_MSG:
+		data_ctx = (struct tbf_ul_ass_ev_create_rlcmac_msg_ctx *)data;
+		LOGPFSML(fi, LOGL_INFO, "TS=%u FN=%u Tx Pkt Ctrl Ack\n", data_ctx->ts, data_ctx->fn);
+		data_ctx->msg = gprs_rlcmac_gre_create_pkt_ctrl_ack(ul_tbf_as_tbf(ctx->ul_tbf)->gre);
+		if (!data_ctx->msg)
+			return;
+		break;
 	default:
 		OSMO_ASSERT(0);
 	}
@@ -517,12 +561,14 @@ static struct osmo_fsm_state tbf_ul_ass_fsm_states[] = {
 	[GPRS_RLCMAC_TBF_UL_ASS_ST_WAIT_TBF_STARTING_TIME2] = {
 		.in_event_mask =
 			X(GPRS_RLCMAC_TBF_UL_ASS_EV_RX_PKT_UL_ASS) |
-			X(GPRS_RLCMAC_TBF_UL_ASS_EV_TBF_STARTING_TIME),
+			X(GPRS_RLCMAC_TBF_UL_ASS_EV_TBF_STARTING_TIME) |
+			X(GPRS_RLCMAC_TBF_UL_ASS_EV_CREATE_RLCMAC_MSG),
 		.out_state_mask =
 			X(GPRS_RLCMAC_TBF_UL_ASS_ST_SCHED_PKT_RES_REQ) |
 			X(GPRS_RLCMAC_TBF_UL_ASS_ST_WAIT_TBF_STARTING_TIME2) |
 			X(GPRS_RLCMAC_TBF_UL_ASS_ST_COMPL),
 		.name = "WAIT_TBF_STARTING_TIME2",
+		.onenter = st_wait_tbf_starting_time2_on_enter,
 		.action = st_wait_tbf_starting_time2,
 	},
 	[GPRS_RLCMAC_TBF_UL_ASS_ST_COMPL] = {
@@ -638,6 +684,10 @@ int gprs_rlcmac_tbf_ul_ass_start_from_dl_tbf_ack_nack(struct gprs_rlcmac_ul_tbf
 {
 	int rc;
 	ul_tbf->ul_ass_fsm.dl_tbf = dl_tbf;
+	/* FIXME: Ideally this should only be the TS where the PKT UL ASS was received... */
+	ul_tbf->ul_ass_fsm.phase1_alloc.num_ts = dl_tbf->cur_alloc.num_ts;
+	memcpy(&ul_tbf->ul_ass_fsm.phase1_alloc.ts[0], &dl_tbf->cur_alloc.ts[0],
+	       sizeof(ul_tbf->ul_ass_fsm.phase1_alloc.ts));
 	rc = osmo_fsm_inst_dispatch(ul_tbf->ul_ass_fsm.fi,
 				    GPRS_RLCMAC_TBF_UL_ASS_EV_START_FROM_DL_TBF,
 				    NULL);
@@ -666,11 +716,21 @@ void gprs_rlcmac_tbf_ul_ass_fn_tick(const struct gprs_rlcmac_ul_tbf *ul_tbf, uin
 {
 	int res;
 
-	OSMO_ASSERT(gprs_rlcmac_tbf_ul_ass_waiting_tbf_starting_time(ul_tbf));
 	OSMO_ASSERT(ul_tbf->ul_ass_fsm.tbf_starting_time_exists);
-	OSMO_ASSERT(ul_tbf->ul_ass_fsm.phase1_alloc.num_ts > 0);
-	if (!ul_tbf->ul_ass_fsm.phase1_alloc.ts[ts_nr].allocated)
-		return;
+	switch (ul_tbf->ul_ass_fsm.fi->state) {
+	case GPRS_RLCMAC_TBF_UL_ASS_ST_WAIT_TBF_STARTING_TIME1:
+		OSMO_ASSERT(ul_tbf->ul_ass_fsm.phase1_alloc.num_ts > 0);
+		if (!ul_tbf->ul_ass_fsm.phase1_alloc.ts[ts_nr].allocated)
+			return;
+		break;
+	case GPRS_RLCMAC_TBF_UL_ASS_ST_WAIT_TBF_STARTING_TIME2:
+		OSMO_ASSERT(ul_tbf->ul_ass_fsm.phase2_alloc.num_ts > 0);
+		if (!ul_tbf->ul_ass_fsm.phase2_alloc.ts[ts_nr].allocated)
+			return;
+		break;
+	default:
+		OSMO_ASSERT(0);
+	}
 	res = fn_cmp(fn, ul_tbf->ul_ass_fsm.tbf_starting_time);
 	if (res < 0) {/* fn BEFORE tbf_starting_time */
 		LOGPTBFUL(ul_tbf, LOGL_DEBUG, "TS=%" PRIu8 " FN=%u Waiting for tbf_starting_time=%u\n",
@@ -681,6 +741,7 @@ void gprs_rlcmac_tbf_ul_ass_fn_tick(const struct gprs_rlcmac_ul_tbf *ul_tbf, uin
 		LOGPTBFUL(ul_tbf, LOGL_ERROR, "TS=%" PRIu8 " FN=%u Received late tick for tbf_starting_time=%u!\n",
 			  ts_nr, fn, ul_tbf->ul_ass_fsm.tbf_starting_time);
 	/* fn == tbf_starting time */
+	LOGPTBFUL(ul_tbf, LOGL_INFO, "TS=%" PRIu8 " FN=%u TBF_STARTING_TIME reached\n", fn, ts_nr);
 	osmo_fsm_inst_dispatch(ul_tbf->ul_ass_fsm.fi, GPRS_RLCMAC_TBF_UL_ASS_EV_TBF_STARTING_TIME, NULL);
 }
 
diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c
index 6e317b1..35def30 100644
--- a/tests/rlcmac/rlcmac_prim_test.c
+++ b/tests/rlcmac/rlcmac_prim_test.c
@@ -1136,6 +1136,9 @@ static void test_dl_tbf_ccch_assign_requests_ul_tbf_pacch(void)
 	rts_fn = fn_next_block(rts_fn);
 	ts_nr = 6;
 
+	/* FIXME: see extra fn_next_block() in libosmo-gprs-rlcmac st_wait_tbf_starting_time2() */
+	rts_fn = fn_next_block(rts_fn);
+
 	/* Trigger transmission of LLC data (GMM Attach) (first part) */
 	rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_l1ctl_pdch_rts_ind(ts_nr, rts_fn, usf_li[ts_nr]);
 	rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim);
diff --git a/tests/rlcmac/rlcmac_prim_test.err b/tests/rlcmac/rlcmac_prim_test.err
index 0921266..95dc475 100644
--- a/tests/rlcmac/rlcmac_prim_test.err
+++ b/tests/rlcmac/rlcmac_prim_test.err
@@ -963,17 +963,25 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_DATA.indication
 DLGLOBAL INFO TS=7 FN=26 Rx Pkt UL ASS
 DLGLOBAL INFO UL_TBF_ASS{WAIT_PKT_UL_ASS}: Received Event RX_PKT_UL_ASS
 DLGLOBAL DEBUG Register POLL (TS=7 FN=43, reason=UL_ASS)
-DLGLOBAL INFO UL_TBF_ASS{WAIT_PKT_UL_ASS}: state_chg to COMPLETED
-DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL
-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=0 fn=0)
+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 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 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
+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 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
+DLGLOBAL INFO UL_TBF{ASSIGN}: Received Event UL_ASS_COMPL
+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=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 TBF(UL:NR-0:TLLI-00000001) Sending new block at BSN 0, CS=CS-2
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Entering Countdown procedure CV=0
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Dequeue next LLC (len=14)
diff --git a/tests/rlcmac/rlcmac_prim_test.ok b/tests/rlcmac/rlcmac_prim_test.ok
index d601794..0c66e24 100644
--- a/tests/rlcmac/rlcmac_prim_test.ok
+++ b/tests/rlcmac/rlcmac_prim_test.ok
@@ -204,8 +204,9 @@ test_rlcmac_prim_up_cb(): Rx GRR-UNITDATA.indication TLLI=0x00000001 ll=[43 c0 0
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=23 data=[40 08 10 20 00 00 00 00 00 00 00 30 00 00 00 00 00 03 2b 2b 2b 2b 2b ]
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0xc0
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=43 ts=7 data_len=23 data=[40 04 00 00 00 04 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b ]
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0xc0
 test_rlcmac_prim_up_cb(): Rx GMMRR-LLC_TRANSMITTED.indication TLLI=0x00000001
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=47 ts=6 data_len=34 data=[00 06 00 39 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ]
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=52 ts=6 data_len=34 data=[00 06 00 39 01 c0 00 08 01 01 d5 71 00 00 08 29 26 24 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ]
 === test_dl_tbf_ccch_assign_requests_ul_tbf_pacch end ===
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
 === test_ccch_pag_req1 start ===