rlcmac: Implement UL TBF Countdown procedure

The Countdown procedure (decreasing CV field in UL RLCMAC data blocks)
is defined in TS 44.060 9.3.1.

It is implemented by means of counting/calculating the amount of RLC/MAC
blocks to be transmitted based on the LLC frames in the several LLC
queues, without actually generating the RLC/MAC blocks. The blocks
cannot be generated ahead of time because that wouldn't allow recreating
them in case Tx UL CS changes, or if a higher priority LLC frames
arrives.
The functions calculating the required amount of RLC/MAC blocks are
coded so that they early return to avoid spending more time than
necessary counting blocks (< BS_CV_MAX).
An extra heuristic optimization to be used when LLC queues are long is left
documented as a TODO, in order to test further the general non-optimized
path for now. Once the counting is proved to work reliably, that and
other heuristic optimizations ca be implemented, like keeping and
decreasing CV cached counter while no Tx CS change occurs or no new LLC
frames are enqueued.

Change-Id: If043c86a0c2b89d0ac0b8174de39fbcb22bed8cb

include/osmocom/gprs/rlcmac/llc_queue.h

@@ -54,6 +54,8 @@ int gprs_rlcmac_llc_queue_enqueue(struct gprs_rlcmac_llc_queue *q, uint8_t *ll_p
 struct msgb *gprs_rlcmac_llc_queue_dequeue(struct gprs_rlcmac_llc_queue *q);
 uint8_t gprs_rlcmac_llc_queue_highest_radio_prio_pending(struct gprs_rlcmac_llc_queue *q);
 
+void gprs_rlcmac_llc_queue_merge_prepend(struct gprs_rlcmac_llc_queue *q, struct gprs_rlcmac_llc_queue *old_q);
+
 static inline size_t gprs_rlcmac_llc_queue_size(const struct gprs_rlcmac_llc_queue *q)
 {
 	return q->queue_size;

include/osmocom/gprs/rlcmac/rlcmac_enc.h

@@ -29,7 +29,7 @@ enum gpr_rlcmac_append_result gprs_rlcmac_enc_append_ul_data(
 				struct gprs_rlcmac_rlc_block_info *rdbi,
 				enum gprs_rlcmac_coding_scheme cs,
 				struct msgb *llc_msg, int *offset, int *num_chunks,
-				uint8_t *data_block, bool is_final, int *count_payload);
+				uint8_t *data_block, int *count_payload);
 
 void gprs_rlcmac_rlc_data_to_ul_append_egprs_li_padding(const struct gprs_rlcmac_rlc_block_info *rdbi,
 							int *offset, int *num_chunks, uint8_t *data_block);

include/osmocom/gprs/rlcmac/tbf_ul.h

@@ -40,6 +40,13 @@ struct gprs_rlcmac_ul_tbf {
 
 	/* (M)CS used to transmit uplink blocks, assigned by PCU: */
 	enum gprs_rlcmac_coding_scheme tx_cs;
+
+	/* Whether the UL TBF entered the countdown procedure (TS 44.060 9.3.1)*/
+	struct {
+		bool active;
+		uint8_t cv;
+		struct gprs_rlcmac_llc_queue *llc_queue;
+	} countdown_proc;
 };
 
 struct gprs_rlcmac_ul_tbf *gprs_rlcmac_ul_tbf_alloc(struct gprs_rlcmac_entity *gre);

src/rlcmac/llc_queue.c

@@ -227,3 +227,31 @@ uint8_t gprs_rlcmac_llc_queue_highest_radio_prio_pending(struct gprs_rlcmac_llc_
 	OSMO_ASSERT(prioq);
 	return prioq->radio_prio;
 }
+
+/* Merge old_q messages into q, prepending them. old_q must be freed by the caller. */
+void gprs_rlcmac_llc_queue_merge_prepend(struct gprs_rlcmac_llc_queue *q, struct gprs_rlcmac_llc_queue *old_q)
+{
+	unsigned int i, j;
+
+	/* Nothing to do: */
+	if (old_q->queue_size == 0)
+		return;
+
+	for (i = 0; i < ARRAY_SIZE(old_q->pq); i++) {
+		for (j = 0; j < ARRAY_SIZE(old_q->pq[i]); j++) {
+			struct llist_head *old_pq = &old_q->pq[i][j].queue;
+			struct llist_head *pq = &q->pq[i][j].queue;
+			struct llist_head *it;
+
+			/* Remove from old_pq and prepend to pq: */
+			while ((it = old_pq->next) != old_pq)
+				llist_move(it, pq);
+		}
+	}
+
+	q->queue_size += old_q->queue_size;
+	q->queue_octets += old_q->queue_octets;
+
+	old_q->queue_size = 0;
+	old_q->queue_octets = 0;
+}

src/rlcmac/rlcmac_enc.c

@@ -67,12 +67,13 @@ enum gpr_rlcmac_append_result gprs_rlcmac_enc_append_ul_data(
 				struct gprs_rlcmac_rlc_block_info *rdbi,
 				enum gprs_rlcmac_coding_scheme cs,
 				struct msgb *llc_msg, int *offset, int *num_chunks,
-				uint8_t *data_block, bool is_final, int *count_payload)
+				uint8_t *data_block, int *count_payload)
 {
 	int chunk;
 	int space;
 	struct gprs_rlcmac_rlc_li_field *li;
 	uint8_t *delimiter, *data, *e_pointer;
+	const bool is_final = rdbi->cv == 0;
 
 	data = data_block + *offset;
 	delimiter = data_block + *num_chunks;
@@ -117,7 +118,6 @@ enum gpr_rlcmac_append_result gprs_rlcmac_enc_append_ul_data(
 			*count_payload = space;
 		*offset = rdbi->data_len;
 		(*num_chunks)++;
-		rdbi->cv = 0;
 		return GPRS_RLCMAC_AR_COMPLETED_BLOCK_FILLED;
 	}
 	/* if chunk would fit exactly in space left */
@@ -191,7 +191,6 @@ enum gpr_rlcmac_append_result gprs_rlcmac_enc_append_ul_data(
 	/* if we don't have more LLC frames */
 	if (is_final) {
 		LOGRLCMAC(LOGL_DEBUG, "-- Final block, so we done.\n");
-		rdbi->cv = 0;
 		return GPRS_RLCMAC_AR_COMPLETED_BLOCK_FILLED;
 	}
 	/* we have no space left */

src/rlcmac/tbf_ul.c

@@ -72,6 +72,13 @@ void gprs_rlcmac_ul_tbf_free(struct gprs_rlcmac_ul_tbf *ul_tbf)
 	if (!ul_tbf)
 		return;
 
+	if (ul_tbf->countdown_proc.llc_queue) {
+		gprs_rlcmac_llc_queue_merge_prepend(ul_tbf->tbf.gre->llc_queue,
+						    ul_tbf->countdown_proc.llc_queue);
+		gprs_rlcmac_llc_queue_free(ul_tbf->countdown_proc.llc_queue);
+		ul_tbf->countdown_proc.llc_queue = NULL;
+	}
+
 	if (ul_tbf->tbf.gre->ul_tbf == ul_tbf)
 		ul_tbf->tbf.gre->ul_tbf = NULL;
 
@@ -146,7 +153,7 @@ bool gprs_rlcmac_ul_tbf_can_request_new_ul_tbf(const struct gprs_rlcmac_ul_tbf *
 		return false;
 
 	/* the mobile station has new data to transmit */
-	if (!gprs_rlcmac_ul_tbf_have_data(ul_tbf))
+	if (!gprs_rlcmac_entity_have_tx_data_queued(ul_tbf->tbf.gre))
 		return false;
 
 	/* "the mobile station has no other ongoing downlink TBFs */
@@ -312,8 +319,12 @@ free_ret:
 
 bool gprs_rlcmac_ul_tbf_have_data(const struct gprs_rlcmac_ul_tbf *ul_tbf)
 {
-	return (ul_tbf->llc_tx_msg && msgb_length(ul_tbf->llc_tx_msg) > 0) ||
-	       gprs_rlcmac_entity_have_tx_data_queued(ul_tbf->tbf.gre);
+	if (ul_tbf->llc_tx_msg && msgb_length(ul_tbf->llc_tx_msg) > 0)
+		return true;
+	if (ul_tbf->countdown_proc.active)
+		return gprs_rlcmac_llc_queue_size(ul_tbf->countdown_proc.llc_queue) > 0;
+	else
+		return gprs_rlcmac_entity_have_tx_data_queued(ul_tbf->tbf.gre);
 }
 
 bool gprs_rlcmac_ul_tbf_shall_keep_open(const struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi)
@@ -331,13 +342,20 @@ bool gprs_rlcmac_ul_tbf_shall_keep_open(const struct gprs_rlcmac_ul_tbf *ul_tbf,
 void gprs_rlcmac_ul_tbf_schedule_next_llc_frame(struct gprs_rlcmac_ul_tbf *ul_tbf)
 {
 	struct osmo_gprs_rlcmac_prim *rlcmac_prim_tx;
+	struct gprs_rlcmac_llc_queue *llc_queue;
 
 	if (ul_tbf->llc_tx_msg && msgb_length(ul_tbf->llc_tx_msg))
 		return;
 
 	msgb_free(ul_tbf->llc_tx_msg);
+
+	if (ul_tbf->countdown_proc.active)
+		llc_queue = ul_tbf->countdown_proc.llc_queue;
+	else
+		llc_queue = ul_tbf->tbf.gre->llc_queue;
+
 	/* dequeue next LLC frame, if any */
-	ul_tbf->llc_tx_msg = gprs_rlcmac_llc_queue_dequeue(ul_tbf->tbf.gre->llc_queue);
+	ul_tbf->llc_tx_msg = gprs_rlcmac_llc_queue_dequeue(llc_queue);
 	if (!ul_tbf->llc_tx_msg)
 		return;
 
@@ -354,9 +372,188 @@ void gprs_rlcmac_ul_tbf_schedule_next_llc_frame(struct gprs_rlcmac_ul_tbf *ul_tb
 	gprs_rlcmac_prim_call_up_cb(rlcmac_prim_tx);
 }
 
+/* TS 44.060 9.3.1.1 Countdown procedure */
+struct blk_count_state {
+	const struct gprs_rlcmac_ul_tbf *ul_tbf;
+	uint8_t blk_data_len; /* length of usable data block (single data unit w/o header) */
+	uint8_t bs_cv_max;
+	uint8_t nts;
+	uint8_t k;
+	uint8_t nts_x_k;
+	unsigned blk_count;
+	uint8_t offset; /* offset in bytes in the current blk */
+	bool extra_li0; /* if last appended chunk is an LI=0 case */
+};
+static void blk_count_state_init(struct blk_count_state *st, const struct gprs_rlcmac_ul_tbf *ul_tbf)
+{
+	OSMO_ASSERT(ul_tbf->cur_alloc.num_ts > 0);
+	memset(st, 0, sizeof(*st));
+	st->ul_tbf = ul_tbf;
+	st->blk_data_len = gprs_rlcmac_mcs_max_data_block_bytes(ul_tbf->tx_cs);
+	st->bs_cv_max = g_rlcmac_ctx->si13ro.u.PBCCH_Not_present.GPRS_Cell_Options.BS_CV_MAX;
+	st->nts = ul_tbf->cur_alloc.num_ts;
+	st->blk_count = 0;
+	st->offset = 0;
+
+	if (gprs_rlcmac_ul_tbf_in_contention_resolution(ul_tbf))
+		st->blk_data_len -= 4;
+
+	switch (ul_tbf->tx_cs) {
+	case GPRS_RLCMAC_MCS_7:
+	case GPRS_RLCMAC_MCS_8:
+	case GPRS_RLCMAC_MCS_9:
+		st->k = 2;
+		break;
+	default:
+		st->k = 1;
+	}
+	st->nts_x_k = st->nts * st->k;
+}
+
+static inline unsigned blk_count_to_x(const struct blk_count_state *st)
+{
+	if (st->blk_count == 0)
+		return 0;
+	return (st->blk_count + (st->nts_x_k - 1) - 1) / st->nts_x_k;
+}
+
+static void blk_count_append_llc(struct blk_count_state *st, unsigned int llc_payload_len)
+{
+	int chunk = llc_payload_len;
+	int space = st->blk_data_len - st->offset;
+	OSMO_ASSERT(st->offset < st->blk_data_len);
+
+	if (chunk == 0)
+		return; /* Should not happen in here? */
+
+	/* reset flag: */
+	st->extra_li0 = false;
+
+	/* if chunk will exceed block limit */
+	if (chunk > space) {
+		st->blk_count++;
+		st->offset = 0;
+		chunk -= space;
+		blk_count_append_llc(st, chunk);
+		return;
+	}
+	if (chunk == space) {
+		st->blk_count++;
+		st->offset = 0;
+		chunk -= space - 1; /* Extra LI=0 */
+		blk_count_append_llc(st, chunk);
+		/* case is_final==true (CV==0) has no extra LI=0. Store the
+		 * context to subtract if this was the last step. */
+		st->extra_li0 = true;
+		return;
+	}
+	/* chunk < space */
+	/* Append a new LI byte */
+	st->offset++;
+	st->offset += chunk;
+	if (st->blk_data_len - st->offset == 0) {
+		st->blk_count++;
+		st->offset = 0;
+	}
+}
+
+/* Returned as early return from function when amount of RLC blocks goes clearly over BS_CV_MAX */
+#define BLK_COUNT_TOOMANY 0xff
+/* We cannot early-check if extra_li0=true, since there may temporarily have too many rlc blocks: */
+#define BLK_COUNT_EARLY_CHECK_TOOMANY(st) (!(st)->extra_li0) && blk_count_to_x(st) > (st)->bs_cv_max)
+static uint8_t blk_count_append_llc_prio_queue(struct blk_count_state *st, const struct gprs_llc_prio_queue *pq)
+{
+	struct msgb *msg;
+
+	llist_for_each_entry(msg, &pq->queue, list) {
+		blk_count_append_llc(st, msgb_l2len(msg));
+		/* We cannot early-check if extra_li0=true, since there may temporarily have too many rlc blocks. */
+		if (BLK_COUNT_EARLY_CHECK_TOOMANY(st)
+			return BLK_COUNT_TOOMANY; /* early return, not entering countdown procedure */
+	}
+	return 0;
+}
+
+/* return BLK_COUNT_TOOMANY: not entering countdown procedure, X > BS_CV_MAX.
+_* return 0: check blk_count_to_x(st) */
+static uint8_t gprs_rlcmac_ul_tbf_calculate_cv(const struct gprs_rlcmac_ul_tbf *ul_tbf)
+{
+	struct blk_count_state st;
+	const struct gprs_rlcmac_llc_queue *q = ul_tbf->tbf.gre->llc_queue;
+	unsigned int i, j;
+	unsigned x;
+
+	blk_count_state_init(&st, ul_tbf);
+
+	/* TODO: Here we could do an heuristic optimization by doing a rough calculation
+	 * using gprs_rlcmac_llc_queue_size() and gprs_rlcmac_llc_queue_octets()
+	 * for cases were we are clearly above BS_CV_MAX. This is specially useful
+	 * when the LLC queue is long since we skip iterating counting lots of
+	 * data.
+	 * if (blk_count_herustic_toomany(&st))
+	 *	return 15;
+	 */
+
+	/* First of all, the current LLC frame in progress: */
+	if (ul_tbf->llc_tx_msg) {
+		blk_count_append_llc(&st, msgb_length(ul_tbf->llc_tx_msg));
+		if (BLK_COUNT_EARLY_CHECK_TOOMANY(&st)
+			goto done; /* early return, not entering countdown procedure */
+	}
+
+	for (i = 0; i < ARRAY_SIZE(q->pq); i++) {
+		for (j = 0; j < ARRAY_SIZE(q->pq[i]); j++) {
+			int rc;
+			if (llist_empty(&q->pq[i][j].queue))
+				continue;
+			rc = blk_count_append_llc_prio_queue(&st, &q->pq[i][j]);
+			if (rc == BLK_COUNT_TOOMANY)
+				goto done; /* early return, not entering countdown procedure */
+		}
+	}
+
+done:
+	/* In final block (CV==0), a chunk filling exactly an RLC block doesn't
+	 * have the LI=0 and 2 bytes (1 LI + 1 data) spanning next block. Fix calculation: */
+	if (st.extra_li0) {
+		OSMO_ASSERT(st.offset == 2);
+		st.offset -= 2;
+	}
+	/* Remaining one would already be a block. Include it before calculating "X": */
+	if (st.offset > 0) {
+		st.blk_count++;
+		st.offset = 0;
+	}
+	x = blk_count_to_x(&st);
+	return x <= st.bs_cv_max ? (uint8_t)x : 15;
+}
+
+static void gprs_rlcmac_ul_tbf_steal_llc_queue_from_gre(struct gprs_rlcmac_ul_tbf *ul_tbf)
+{
+	ul_tbf->countdown_proc.llc_queue = ul_tbf->tbf.gre->llc_queue;
+	ul_tbf->tbf.gre->llc_queue = gprs_rlcmac_llc_queue_alloc(ul_tbf->tbf.gre);
+}
+
+static void gprs_rlcmac_ul_tbf_check_countdown_proc(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi)
+{
+
+	if (ul_tbf->countdown_proc.active)
+		return;
+	ul_tbf->countdown_proc.cv = gprs_rlcmac_ul_tbf_calculate_cv(ul_tbf);
+	if (ul_tbf->countdown_proc.cv < 15) {
+		if (gprs_rlcmac_ul_tbf_shall_keep_open(ul_tbf, bi)) {
+			LOGPTBFUL(ul_tbf, LOGL_INFO, "Delaying start Countdown procedure CV=%u\n", ul_tbf->countdown_proc.cv);
+			ul_tbf->countdown_proc.cv = 15;
+			return;
+		}
+		LOGPTBFUL(ul_tbf, LOGL_DEBUG, "Entering Countdown procedure CV=%u\n", ul_tbf->countdown_proc.cv);
+		ul_tbf->countdown_proc.active = true;
+		gprs_rlcmac_ul_tbf_steal_llc_queue_from_gre(ul_tbf);
+	}
+}
+
 static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_rlcmac_rts_block_ind *bi, enum gprs_rlcmac_coding_scheme cs)
 {
-	struct gprs_rlcmac_llc_queue *llc_queue = ul_tbf->tbf.gre->llc_queue;
 	const uint16_t bsn = gprs_rlcmac_rlc_ul_window_v_s(ul_tbf->ulw);
 	struct gprs_rlcmac_rlc_block *blk;
 	struct gprs_rlcmac_rlc_block_info *rdbi;
@@ -365,6 +562,8 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r
 	int write_offset = 0;
 	enum gpr_rlcmac_append_result ar;
 
+	gprs_rlcmac_ul_tbf_check_countdown_proc(ul_tbf, bi);
+
 	if (!ul_tbf->llc_tx_msg || msgb_length(ul_tbf->llc_tx_msg) == 0)
 		gprs_rlcmac_ul_tbf_schedule_next_llc_frame(ul_tbf);
 	OSMO_ASSERT(ul_tbf->llc_tx_msg);
@@ -391,7 +590,7 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r
 	rdbi->data_len = block_data_len;
 
 	rdbi->ti = gprs_rlcmac_ul_tbf_in_contention_resolution(ul_tbf);
-	rdbi->cv = 15; /* Final Block Indicator, set late, if true */
+	rdbi->cv = ul_tbf->countdown_proc.cv--;
 	rdbi->bsn = bsn; /* Block Sequence Number */
 	rdbi->e = 1; /* Extension bit, maybe set later (1: no extension) */
 
@@ -407,7 +606,6 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r
 	}
 
 	do {
-		bool is_final;
 		int payload_written = 0;
 
 		if (msgb_length(ul_tbf->llc_tx_msg) == 0) {
@@ -424,14 +622,6 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r
 					  "LLC queue completely drained and there's "
 					  "still %d free bytes in rlcmac data block\n", space);
 
-				/* We may need to update fbi in header here
-				 * since ul_tbf->last_ul_drained_fn was updated above
-				 * Specially important when X2031 is 0. */
-				is_final = gprs_rlcmac_llc_queue_size(llc_queue) == 0 &&
-					   !gprs_rlcmac_ul_tbf_shall_keep_open(ul_tbf, bi);
-				if (is_final)
-					rdbi->cv = 0;
-
 				if (gprs_rlcmac_mcs_is_edge(cs)) {
 					/* in EGPRS there's no M bit, so we need
 					 * to flag padding with LI=127 */
@@ -442,12 +632,8 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r
 			}
 		}
 
-		is_final = gprs_rlcmac_llc_queue_size(llc_queue) == 0 &&
-			   !gprs_rlcmac_ul_tbf_shall_keep_open(ul_tbf, bi);
-
-		ar = gprs_rlcmac_enc_append_ul_data(rdbi, cs, ul_tbf->llc_tx_msg,
-						    &write_offset, &num_chunks, data,
-						    is_final, &payload_written);
+		ar = gprs_rlcmac_enc_append_ul_data(rdbi, cs, ul_tbf->llc_tx_msg, &write_offset,
+						    &num_chunks, data, &payload_written);
 
 		if (ar == GPRS_RLCMAC_AR_NEED_MORE_BLOCKS)
 			break;
@@ -460,8 +646,8 @@ static int create_new_bsn(struct gprs_rlcmac_ul_tbf *ul_tbf, const struct gprs_r
 		gprs_rlcmac_ul_tbf_schedule_next_llc_frame(ul_tbf);
 	} while (ar == GPRS_RLCMAC_AR_COMPLETED_SPACE_LEFT);
 
-	LOGPTBFUL(ul_tbf, LOGL_DEBUG, "data block (BSN %d, %s): %s\n",
-		  bsn, gprs_rlcmac_mcs_name(blk->cs_last),
+	LOGPTBFUL(ul_tbf, LOGL_DEBUG, "data block (BSN=%d, %s, CV=%u): %s\n",
+		  bsn, gprs_rlcmac_mcs_name(blk->cs_last), rdbi->cv,
 		  osmo_hexdump(blk->buf, block_data_len));
 	/* raise send state and set ack state array */
 	gprs_rlcmac_rlc_v_b_mark_unacked(&ul_tbf->ulw->v_b, bsn);
@@ -850,8 +1036,8 @@ static struct msgb *create_ul_acked_block(struct gprs_rlcmac_ul_tbf *ul_tbf,
 		rdbi->bsn = bsn;
 		is_final = is_final || rdbi->cv == 0;
 
-		LOGPTBFUL(ul_tbf, LOGL_DEBUG, "Copying data unit %d (BSN %d)\n",
-			  data_block_idx, bsn);
+		LOGPTBFUL(ul_tbf, LOGL_DEBUG, "Copying data unit %d (BSN=%d CV=%d)\n",
+			  data_block_idx, bsn, rdbi->cv);
 
 		gprs_rlcmac_rlc_copy_from_aligned_buffer(&rlc, data_block_idx, msg_data, block_data);
 	}

tests/rlcmac/rlcmac_prim_test.c

@@ -934,6 +934,71 @@ static void test_ul_tbf_last_data_cv0_retrans_max(void)
 	cleanup_test();
 }
 
+/* 9.3.1 Countdown procedure */
+static void test_ul_tbf_countdown_procedure(void)
+{
+	struct osmo_gprs_rlcmac_prim *rlcmac_prim;
+	int rc;
+
+	printf("=== %s start ===\n", __func__);
+	prepare_test();
+	uint32_t tlli = 0x2342;
+	uint8_t ul_tfi = 0;
+	uint8_t ts_nr = 7;
+	uint8_t usf = 0;
+	uint32_t rts_fn = 4;
+	uint8_t bs_cv_max = 4;
+	unsigned int i;
+	RlcMacDownlink_t dl_block;
+	struct msgb *llc_msg = msgb_alloc(200, "llc_msg");
+	Ack_Nack_Description_t *ack_desc = &dl_block.u.Packet_Uplink_Ack_Nack.u.PU_AckNack_GPRS_Struct.Ack_Nack_Description;
+
+	/* Submit an SI13 with bs_cv_max: */
+	rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_l1ctl_ccch_data_ind(0, create_si13(bs_cv_max));
+	rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim);
+	OSMO_ASSERT(rc == 0);
+
+
+	/* Submit LLC bytes */
+	msgb_put(llc_msg, msgb_tailroom(llc_msg));
+	memset(msgb_data(llc_msg), 0xab, msgb_length(llc_msg));
+	rlcmac_prim = osmo_gprs_rlcmac_prim_alloc_grr_unitdata_req(tlli, msgb_data(llc_msg), msgb_length(llc_msg));
+	rlcmac_prim->grr.unitdata_req.sapi = OSMO_GPRS_RLCMAC_LLC_SAPI_SNDCP3;
+	rc = osmo_gprs_rlcmac_prim_upper_down(rlcmac_prim);
+
+	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);
+	rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim);
+	OSMO_ASSERT(rc == 0);
+
+	/* Trigger transmission of LLC data (first 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);
+
+	/* PCU acks it: */
+	ul_ack_nack_init(&dl_block, ul_tfi, GPRS_RLCMAC_CS_2);
+	ack_desc->STARTING_SEQUENCE_NUMBER = 1;
+	ack_desc->FINAL_ACK_INDICATION = 0;
+	ul_ack_nack_mark(ack_desc, 0, true);
+	rlcmac_prim = create_dl_ctrl_block(&dl_block, ts_nr, rts_fn);
+	rc = osmo_gprs_rlcmac_prim_lower_up(rlcmac_prim);
+	OSMO_ASSERT(rc == 0);
+
+	for (i = 0; i < 6; 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);
+	}
+
+	printf("=== %s end ===\n", __func__);
+	msgb_free(llc_msg);
+	cleanup_test();
+}
+
 /* PCU allocates a DL TBF through PCH ImmAss for MS (when in packet-idle) */
 static void test_dl_tbf_ccch_assign(void)
 {
@@ -1128,6 +1193,7 @@ int main(int argc, char *argv[])
 	test_ul_tbf_n3104_timeout();
 	test_ul_tbf_t3182_timeout();
 	test_ul_tbf_last_data_cv0_retrans_max();
+	test_ul_tbf_countdown_procedure();
 	test_ul_tbf_request_another_ul_tbf();
 	test_dl_tbf_ccch_assign();
 	test_dl_tbf_ccch_assign_requests_ul_tbf_pacch();

tests/rlcmac/rlcmac_prim_test.err

@@ -23,10 +23,10 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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): 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) 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)
+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
@@ -35,13 +35,14 @@ 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 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): 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) 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)
+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
@@ -185,10 +186,10 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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): 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) 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)
+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
@@ -220,7 +221,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+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
@@ -252,7 +253,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+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
@@ -284,7 +285,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+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
@@ -326,10 +327,10 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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): 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) 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)
+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
@@ -338,13 +339,14 @@ 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 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): 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) 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)
+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
@@ -355,7 +357,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all block
 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
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (3)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
@@ -363,7 +365,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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)
+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{FINISHED}: Received Event LAST_UL_DATA_SENT
 DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=1
@@ -374,7 +376,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all block
 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
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (5)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
@@ -382,7 +384,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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)
+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{FINISHED}: Received Event LAST_UL_DATA_SENT
 DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=2
@@ -393,7 +395,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all block
 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
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+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 DEBUG TBF(UL:NR-0:TLLI-00002342) N3104 inc (7)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
@@ -401,7 +403,7 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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)
+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{FINISHED}: Received Event LAST_UL_DATA_SENT
 DLGLOBAL INFO UL_TBF{FINISHED}: Data block with CV=0 retransmit attempts=3
@@ -412,7 +414,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 0, because all block
 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
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN 0)
+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 NOTICE TBF(UL:NR-0:TLLI-00002342) N3104_MAX (9) reached
 DLGLOBAL INFO UL_TBF{FINISHED}: Received Event N3104_MAX
@@ -466,10 +468,10 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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): 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) 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)
+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
@@ -486,13 +488,14 @@ 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 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): 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) 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)
+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
@@ -529,10 +532,10 @@ DLGLOBAL DEBUG Rx from lower layers: L1CTL-PDCH_RTS.indication
 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): 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) 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)
+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
@@ -549,13 +552,14 @@ 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 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): 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) 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)
+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
@@ -566,7 +570,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all block
 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)
+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=1
@@ -577,7 +581,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all block
 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)
+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=2
@@ -588,7 +592,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all block
 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)
+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=3
@@ -599,7 +603,7 @@ DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Restarting at BSN 1, because all block
 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)
+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=4
@@ -611,6 +615,8 @@ 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 DL_TBF_ASS{IDLE}: Deallocated
+DLGLOBAL DEBUG Rx from lower layers: L1CTL-CCCH_DATA.indication
+DLGLOBAL DEBUG Rx SI13 from lower layers
 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
@@ -634,14 +640,123 @@ 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-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
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=0, CS-2, CV=15): 00 00 23 42 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 
+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 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 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 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 
+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=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 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
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=2, CS-2, CV=4): 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 
+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
+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 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 
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 3 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=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 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 
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 4 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=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 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 
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 5 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=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 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.
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Complete UL frame, len=0
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=6, CS-2, CV=0): 61 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 2b 2b 2b 2b 2b 
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) need_padding 0 spb_status 0 spb 0 (BSN1 6 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=6 CV=0)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 6, CS-2): 00 00 0c 61 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 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 INFO DL_TBF_ASS{IDLE}: Deallocated
+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 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 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}: Send RACH.req ra=0x7e
+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 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 startTimeFN=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 UL_TBF{ASSIGN}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 ul_slotmask=0x80
+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-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)
 DLGLOBAL DEBUG -- Chunk with length 14 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 0, CS-2): 39 00 00 23 42 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 
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) data block (BSN=0, CS-2, CV=0): 39 00 00 23 42 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 
 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)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) Copying data unit 0 (BSN=0 CV=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00002342) msg block (BSN 0, CS-2): 00 01 00 39 00 00 23 42 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 00 
 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT
 DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164
@@ -775,14 +890,15 @@ 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 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)
 DLGLOBAL DEBUG -- Chunk with length 14 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-00000001) Complete UL frame, len=0
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) data block (BSN 0, CS-2): 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 
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) data block (BSN=0, CS-2, CV=0): 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 
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) need_padding 0 spb_status 0 spb 0 (BSN1 0 BSN2 -1)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Copying 1 RLC blocks, 1 BSNs
-DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Copying data unit 0 (BSN 0)
+DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) Copying data unit 0 (BSN=0 CV=0)
 DLGLOBAL DEBUG TBF(UL:NR-0:TLLI-00000001) msg block (BSN 0, CS-2): 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 
 DLGLOBAL INFO UL_TBF{FLOW}: Received Event FIRST_UL_DATA_SENT
 DLGLOBAL INFO UL_TBF{FLOW}: First UL block sent, stop T3164

tests/rlcmac/rlcmac_prim_test.ok

@@ -115,11 +115,31 @@ 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 ===
-=== test_ul_tbf_request_another_ul_tbf start ===
+=== test_ul_tbf_countdown_procedure start ===
 sys={0.000000}, mono={0.000000}: clock_override_set
 test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7b
 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 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 ]
+RTS 0: FN=8
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 ts=7 data_len=34 data=[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 ]
+RTS 1: FN=13
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=13 ts=7 data_len=34 data=[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 ]
+RTS 2: FN=17
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=17 ts=7 data_len=34 data=[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 ]
+RTS 3: FN=21
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=34 data=[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 ]
+RTS 4: FN=26
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=26 ts=7 data_len=34 data=[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 ]
+RTS 5: FN=30
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=30 ts=7 data_len=34 data=[00 00 0c 61 ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab ab 2b 2b 2b 2b 2b 00 ]
+=== test_ul_tbf_countdown_procedure end ===
+test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
+=== test_ul_tbf_request_another_ul_tbf start ===
+sys={0.000000}, mono={0.000000}: clock_override_set
+test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7e
+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=[00 01 00 39 00 00 23 42 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 00 ]
 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=17 ts=7 data_len=23 data=[40 16 40 00 08 d0 a0 bc 00 00 00 00 00 00 70 00 38 00 00 2b 2b 2b 2b ]