Delay ImmAss(PCH, PktDlAss) if waiting for PKT_CTRL_ACK answering UL_ACK_NACK (FinACK=1)

In that state (ul_tbf=TBF_ST_FINISHED), we are unable to reach the MS to
assign a new DL TBF.
* MS Is not available in CCCH because it's attached the PDCH.
* MS won't be able to PKT_CTRL_ACK a PktDlAss on PACCH, because next
  thing it will do is to PKT_CTRL_ACK the UL_ACK_NACK(FINACK=1) we
  already polled it for, and immediatelly after that it will release the
  UL TBF on its side and go back to packet idle mode.

Hence, we must wait for MS to send the PKT_CTRL_ACK to us in order to be
able to assign the DL TBF in PCH (CCCH).

Related: OS#5700
Change-Id: I7a30db9cc7dae70e04054f1a4dba004bd1780d4a

10 files changed, 237 insertions, 72 deletions

diff --git a/src/gprs_ms.c b/src/gprs_ms.c
index f4da3a5c..5733a7cb 100644
--- a/src/gprs_ms.c
+++ b/src/gprs_ms.c
@@ -23,6 +23,7 @@
 #include "gprs_codel.h"
 #include "pcu_utils.h"
 #include "nacc_fsm.h"
+#include "tbf_ul_ack_fsm.h"
 
 #include <time.h>
 
@@ -1024,10 +1025,75 @@ static void ms_start_llc_timer(struct GprsMs *ms)
 	}
 }
 
+/* Can we get to send a DL TBF ass to the MS? */
+static bool ms_is_reachable_for_dl_ass(const struct GprsMs *ms)
+{
+	struct gprs_rlcmac_ul_tbf *ul_tbf = ms_ul_tbf(ms);
+
+	/* This function assumes it is called when no DL TBF is present */
+	OSMO_ASSERT(!ms_dl_tbf(ms));
+
+	/* 3GPP TS 44.060 sec 7.1.3.1 Initiation of the Packet resource request procedure:
+	* "Furthermore, the mobile station shall not respond to PACKET DOWNLINK ASSIGNMENT
+	* or MULTIPLE TBF DOWNLINK ASSIGNMENT messages before contention resolution is
+	* completed on the mobile station side." */
+	/* The possible uplink TBF is used to trigger downlink assignment:
+	* - If there is no uplink TBF the MS is potentially in packet idle mode
+	* and hence assignment will be done over CCCH (PCH)
+	* - If there's an uplink TBF but it is finished (waiting for last PKT
+	* CTRL ACK after sending last Pkt UL ACK/NACK with FINAL_ACK=1, then we
+	* have no ways to contact the MS right now. Assignment will be delayed
+	* until PKT CTRL ACK is received and the TBF is released at the MS side
+	* (then assignment goes through PCH).
+	*/
+	if (!ul_tbf)
+		return true;
+	if (ul_tbf_contention_resolution_done(ul_tbf) &&
+	    !tbf_ul_ack_waiting_cnf_final_ack(ul_tbf))
+		return true;
+
+	return false;
+
+}
+
+/* This should be called only when MS is reachable, see ms_is_reachable_for_dl_ass(). */
+int ms_new_dl_tbf_assignment(struct GprsMs *ms)
+{
+	bool ss;
+	int8_t use_trx;
+	struct gprs_rlcmac_ul_tbf *ul_tbf;
+	struct gprs_rlcmac_dl_tbf *dl_tbf;
+
+	ul_tbf = ms_ul_tbf(ms);
+
+	if (ul_tbf) {
+		use_trx = tbf_get_trx((struct gprs_rlcmac_tbf *)ul_tbf)->trx_no;
+		ss = false;
+	} else {
+		use_trx = -1;
+		ss = true; /* PCH assignment only allows one timeslot */
+	}
+
+	/* set number of downlink slots according to multislot class */
+	dl_tbf = dl_tbf_alloc(ms->bts, ms, use_trx, ss);
+
+	if (!dl_tbf) {
+		LOGPMS(ms, DTBF, LOGL_NOTICE, "No PDCH resource\n");
+		return -EBUSY;
+	}
+
+	LOGPTBFDL(dl_tbf, LOGL_DEBUG, "[DOWNLINK] START\n");
+
+	/* Trigger the assignment now. */
+	tbf_dl_trigger_ass(dl_tbf, ul_tbf_as_tbf(ul_tbf));
+	return 0;
+}
+
 int ms_append_llc_dl_data(struct GprsMs *ms, uint16_t pdu_delay_csec, const uint8_t *data, uint16_t len)
 {
 	struct timespec expire_time;
 	struct gprs_rlcmac_dl_tbf *dl_tbf;
+	int rc = 0;
 
 	LOGPMS(ms, DTBFDL, LOGL_DEBUG, "appending %u bytes to DL LLC queue\n", len);
 
@@ -1041,10 +1107,17 @@ int ms_append_llc_dl_data(struct GprsMs *ms, uint16_t pdu_delay_csec, const uint
 	ms_start_llc_timer(ms);
 
 	dl_tbf = ms_dl_tbf(ms);
-	if (dl_tbf && tbf_state(dl_tbf_as_tbf_const(dl_tbf)) == TBF_ST_WAIT_RELEASE) {
-		LOGPTBFDL(dl_tbf, LOGL_DEBUG, "in WAIT RELEASE state (T3193), so reuse TBF\n");
-		tbf_establish_dl_tbf_on_pacch(dl_tbf_as_tbf(dl_tbf));
+	if (dl_tbf) {
+		if (tbf_state(dl_tbf_as_tbf_const(dl_tbf)) == TBF_ST_WAIT_RELEASE) {
+			LOGPTBFDL(dl_tbf, LOGL_DEBUG, "in WAIT RELEASE state (T3193), so reuse TBF\n");
+			tbf_establish_dl_tbf_on_pacch(dl_tbf_as_tbf(dl_tbf));
+		}
+	} else {
+		/* Check if we can create a DL TBF to start sending the enqueued
+		 * data. Otherwise it will be triggered later when it is reachable
+		* again. */
+		if (ms_is_reachable_for_dl_ass(ms))
+			rc = ms_new_dl_tbf_assignment(ms);
 	}
-
-	return 0;
+	return rc;
 }
diff --git a/src/gprs_ms.h b/src/gprs_ms.h
index 703e84bc..b9a13860 100644
--- a/src/gprs_ms.h
+++ b/src/gprs_ms.h
@@ -144,6 +144,7 @@ int ms_nacc_start(struct GprsMs *ms, Packet_Cell_Change_Notification_t *notif);
 bool ms_nacc_rts(const struct GprsMs *ms);
 struct msgb *ms_nacc_create_rlcmac_msg(struct GprsMs *ms, struct gprs_rlcmac_tbf *tbf, uint32_t fn, uint8_t ts);
 
+int ms_new_dl_tbf_assignment(struct GprsMs *ms);
 int ms_append_llc_dl_data(struct GprsMs *ms, uint16_t pdu_delay_csec, const uint8_t *data, uint16_t len);
 
 static inline bool ms_is_idle(const struct GprsMs *ms)
diff --git a/src/pdch.cpp b/src/pdch.cpp
index 48d8c73a..1df8db8f 100644
--- a/src/pdch.cpp
+++ b/src/pdch.cpp
@@ -385,9 +385,12 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet,
 		}
 		pdch_ulc_release_fn(ulc, fn);
 		osmo_fsm_inst_dispatch(ul_tbf->ul_ack_fsm.fi, TBF_UL_ACK_EV_RX_CTRL_ACK, NULL);
-		/* We only set polling on final UL ACK/NACK */
-		LOGPTBF(tbf, LOGL_DEBUG, "[UPLINK] END\n");
-		osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi, TBF_EV_FINAL_UL_ACK_CONFIRMED, NULL);
+		/* We only set polling on final UL ACK/NACK, something is wrong... */
+		if (tbf_state(tbf) == TBF_ST_FINISHED)
+			osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi, TBF_EV_FINAL_UL_ACK_CONFIRMED, (void*)false);
+			/* ul_tbf is freed here! */
+		else
+			LOGPTBFUL(ul_tbf, LOGL_ERROR, "Received POLL_UL_ACK for UL TBF in unexpected state!\n");
 		return;
 
 	case PDCH_ULC_POLL_UL_ASS:
@@ -722,7 +725,7 @@ void gprs_rlcmac_pdch::rcv_resource_request(Packet_Resource_Request_t *request,
 				"block of final UL ACK/NACK\n", fn);
 			ul_tbf->n_reset(N3103);
 			pdch_ulc_release_node(ulc, item);
-			rc = osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi, TBF_EV_FINAL_UL_ACK_CONFIRMED, NULL);
+			rc = osmo_fsm_inst_dispatch(ul_tbf->state_fsm.fi, TBF_EV_FINAL_UL_ACK_CONFIRMED, (void*)true);
 			if (rc) {
 				/* FSM failed handling, get rid of previous finished UL TBF before providing a new one */
 				LOGPTBFUL(ul_tbf, LOGL_NOTICE,
diff --git a/src/tbf.cpp b/src/tbf.cpp
index 4f0162e0..d115b825 100644
--- a/src/tbf.cpp
+++ b/src/tbf.cpp
@@ -955,3 +955,8 @@ int tbf_establish_dl_tbf_on_pacch(struct gprs_rlcmac_tbf *tbf)
 {
 	return tbf->establish_dl_tbf_on_pacch();
 }
+
+struct gprs_rlcmac_trx *tbf_get_trx(struct gprs_rlcmac_tbf *tbf)
+{
+	return tbf->trx;
+}
diff --git a/src/tbf.h b/src/tbf.h
index b34476e7..d69ae5a2 100644
--- a/src/tbf.h
+++ b/src/tbf.h
@@ -149,6 +149,7 @@ bool tbf_is_control_ts(const struct gprs_rlcmac_tbf *tbf, uint8_t ts);
 bool tbf_can_upgrade_to_multislot(const struct gprs_rlcmac_tbf *tbf);
 int tbf_update(struct gprs_rlcmac_tbf *tbf);
 int tbf_establish_dl_tbf_on_pacch(struct gprs_rlcmac_tbf *tbf);
+struct gprs_rlcmac_trx *tbf_get_trx(struct gprs_rlcmac_tbf *tbf);
 #ifdef __cplusplus
 }
 #endif
diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp
index a8fb6fc4..0936e1c8 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -182,52 +182,6 @@ gprs_rlcmac_dl_tbf::gprs_rlcmac_dl_tbf(struct gprs_rlcmac_bts *bts_, GprsMs *ms)
 {
 }
 
-static int tbf_new_dl_assignment(struct gprs_rlcmac_bts *bts, GprsMs *ms,
-				 struct gprs_rlcmac_dl_tbf **tbf)
-{
-	bool ss;
-	int8_t use_trx;
-	struct gprs_rlcmac_ul_tbf *ul_tbf = NULL, *old_ul_tbf;
-	struct gprs_rlcmac_dl_tbf *dl_tbf = NULL;
-
-	ul_tbf = ms_ul_tbf(ms);
-
-	/* 3GPP TS 44.060 sec 7.1.3.1 Initiation of the Packet resource request procedure:
-	* "Furthermore, the mobile station shall not respond to PACKET DOWNLINK ASSIGNMENT
-	* or MULTIPLE TBF DOWNLINK ASSIGNMENT messages before contention resolution is
-	* completed on the mobile station side." */
-	if (ul_tbf && ul_tbf->m_contention_resolution_done
-	 && !tbf_ul_ack_waiting_cnf_final_ack(ul_tbf)) {
-		use_trx = ul_tbf->trx->trx_no;
-		ss = false;
-		old_ul_tbf = ul_tbf;
-	} else {
-		use_trx = -1;
-		ss = true; /* PCH assignment only allows one timeslot */
-		old_ul_tbf = NULL;
-	}
-
-	// Create new TBF (any TRX)
-/* FIXME: Copy and paste with alloc_ul_tbf */
-	/* set number of downlink slots according to multislot class */
-	dl_tbf = dl_tbf_alloc(bts, ms, use_trx, ss);
-
-	if (!dl_tbf) {
-		LOGPMS(ms, DTBF, LOGL_NOTICE, "No PDCH resource\n");
-		return -EBUSY;
-	}
-
-	LOGPTBFDL(dl_tbf, LOGL_DEBUG, "[DOWNLINK] START\n");
-
-	/* trigger downlink assignment and set state to ASSIGN.
-	 * we don't use old_downlink, so the possible uplink is used
-	 * to trigger downlink assignment. if there is no uplink,
-	 * AGCH is used. */
-	dl_tbf->trigger_ass(old_ul_tbf);
-	*tbf = dl_tbf;
-	return 0;
-}
-
 /**
  * TODO: split into unit test-able parts...
  */
@@ -286,13 +240,6 @@ int dl_tbf_handle(struct gprs_rlcmac_bts *bts,
 	rc = ms_append_llc_dl_data(ms, delay_csec, data, len);
 	if (rc < 0)
 		return rc;
-
-	dl_tbf = ms_dl_tbf(ms);
-	if (!dl_tbf) {
-		rc = tbf_new_dl_assignment(bts, ms, &dl_tbf);
-		if (rc < 0)
-			return rc;
-	}
 	return 0;
 }
 
diff --git a/src/tbf_fsm.c b/src/tbf_fsm.c
index 2b712e70..25253fdd 100644
--- a/src/tbf_fsm.c
+++ b/src/tbf_fsm.c
@@ -244,6 +244,9 @@ static void st_flow(struct osmo_fsm_inst *fi, uint32_t event, void *data)
 static void st_finished(struct osmo_fsm_inst *fi, uint32_t event, void *data)
 {
 	struct tbf_fsm_ctx *ctx = (struct tbf_fsm_ctx *)fi->priv;
+	struct GprsMs *ms;
+	bool new_ul_tbf_requested;
+
 	switch (event) {
 	case TBF_EV_DL_ACKNACK_MISS:
 		break;
@@ -254,9 +257,27 @@ static void st_finished(struct osmo_fsm_inst *fi, uint32_t event, void *data)
 		tbf_fsm_state_chg(fi, TBF_ST_WAIT_RELEASE);
 		break;
 	case TBF_EV_FINAL_UL_ACK_CONFIRMED:
+		OSMO_ASSERT(tbf_direction(ctx->tbf) == GPRS_RLCMAC_UL_TBF);
+		new_ul_tbf_requested = (bool)data;
+		/* Ref the MS, otherwise it may be freed after ul_tbf is
+		 * detached when sending event below. */
+		ms = tbf_ms(ctx->tbf);
+		ms_ref(ms);
 		/* UL TBF ACKed our transmitted UL ACK/NACK with final Ack
-		 * Indicator set to '1' t. We can free the TBF right away. */
+		 * Indicator set to '1'. We can free the TBF right away, the MS
+		 * also just released its TBF on its side. */
+		LOGPTBFUL(tbf_as_ul_tbf(ctx->tbf), LOGL_DEBUG, "[UPLINK] END\n");
 		tbf_free(ctx->tbf);
+		/* Here fi, ctx and ctx->tbf are already freed! */
+		/* TS 44.060 9.3.3.3.2: There might be LLC packets waiting in
+		 * the queue but the DL TBF assignment might have been delayed
+		 * because there was no way to reach the MS (because ul_tbf was
+		 * in packet-active mode with FINISHED state). If MS is going
+		 * back to packet-idle mode then we can assign the DL TBF on PCH
+		 * now. */
+		if (!new_ul_tbf_requested && ms_need_dl_tbf(ms))
+			ms_new_dl_tbf_assignment(ms);
+		ms_unref(ms);
 		break;
 	case TBF_EV_MAX_N3103:
 		ctx->T_release = 3169;
diff --git a/src/tbf_fsm.h b/src/tbf_fsm.h
index 9814c0ee..22266e74 100644
--- a/src/tbf_fsm.h
+++ b/src/tbf_fsm.h
@@ -32,7 +32,7 @@ enum tbf_fsm_event {
 	TBF_EV_LAST_DL_DATA_SENT, /* DL TBF sends RLCMAC block containing last DL avilable data buffered */
 	TBF_EV_LAST_UL_DATA_RECVD, /* UL TBF sends RLCMAC block containing last UL data (cv=0) */
 	TBF_EV_FINAL_ACK_RECVD, /* DL ACK/NACK with FINAL_ACK=1 received from MS */
-	TBF_EV_FINAL_UL_ACK_CONFIRMED, /* UL TBF: MS ACKs (CtrlAck or PktResReq) our UL ACK/NACK w/ FinalAckInd=1 */
+	TBF_EV_FINAL_UL_ACK_CONFIRMED, /* UL TBF: MS ACKs (CtrlAck or PktResReq) our UL ACK/NACK w/ FinalAckInd=1. data = (bool) MS requests establishment of a new UL-TBF. */
 	TBF_EV_MAX_N3101, /* MAX N3101 (max usf timeout) reached (UL TBF) */
 	TBF_EV_MAX_N3103, /* MAX N3103 (max Pkt Ctrl Ack for last UL ACK/NACK timeout) reached (UL TBF) */
 	TBF_EV_MAX_N3105, /* MAX N3105 (max poll timeout) reached (UL/DL TBF) */
diff --git a/tests/tbf/TbfTest.cpp b/tests/tbf/TbfTest.cpp
index 43ea8c7d..91d1f07f 100644
--- a/tests/tbf/TbfTest.cpp
+++ b/tests/tbf/TbfTest.cpp
@@ -1715,7 +1715,6 @@ static void send_dl_data(struct gprs_rlcmac_bts *bts, uint32_t tlli, const char
 
 	ms = bts_ms_by_imsi(bts, imsi);
 	OSMO_ASSERT(ms != NULL);
-	OSMO_ASSERT(ms_dl_tbf(ms) != NULL);
 
 	if (imsi[0] != '\0') {
 		ms2 = bts_ms_by_tlli(bts, tlli, GSM_RESERVED_TMSI);
@@ -1779,6 +1778,38 @@ static void test_tbf_single_phase()
 	TALLOC_FREE(the_pcu);
 }
 
+static void test_tbf_single_phase2()
+{
+	the_pcu = prepare_pcu();
+	struct gprs_rlcmac_bts *bts = bts_alloc(the_pcu, 0);
+	int ts_no = 7;
+	uint32_t fn = DUMMY_FN; /* 17,25,9 */
+	uint32_t tlli = 0xf1223344;
+	const char *imsi = "0011223344";
+	uint16_t qta = 31;
+	gprs_rlcmac_ul_tbf *ul_tbf;
+
+	fprintf(stderr, "=== start %s ===\n", __func__);
+
+	setup_bts(bts, ts_no);
+
+	ul_tbf = establish_ul_tbf_single_phase(bts, ts_no, tlli, &fn, qta);
+
+	print_ta_tlli(ul_tbf, true);
+	/* PCU sends CTRL ACK/NCK with FINAL_ACK=1, hence TBF is not in state FINISHED */
+	request_dl_rlc_block(bts, ul_tbf->trx->trx_no, ts_no, &fn);
+	OSMO_ASSERT(ul_tbf->state_is(TBF_ST_FINISHED));
+	/* Now data is sent but no DL TBF is created because MS is not reachable for DL Assignment */
+	send_dl_data(bts, tlli, imsi, (const uint8_t *)"TEST", 4);
+
+	/* After MS CTRL ACKs the FINAL_ACK=1 then it releases the TBF and goes
+	 * to packet-idle mode. Hence PCU will trigger ImmAss(PktDlAss) on PCH. */
+	send_control_ack(ul_tbf);
+
+	fprintf(stderr, "=== end %s ===\n", __func__);
+	TALLOC_FREE(the_pcu);
+}
+
 static void test_tbf_egprs_two_phase_puan(void)
 {
 	the_pcu = prepare_pcu();
@@ -3363,6 +3394,7 @@ int main(int argc, char **argv)
 	test_tbf_exhaustion();
 	test_tbf_dl_llc_loss();
 	test_tbf_single_phase();
+	test_tbf_single_phase2();
 	test_tbf_two_phase();
 	test_tbf_ra_update_rach();
 	test_tbf_dl_flow_and_rach_two_phase();
diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err
index 56e49971..564cafd6 100644
--- a/tests/tbf/TbfTest.err
+++ b/tests/tbf/TbfTest.err
@@ -1849,8 +1849,91 @@ Got MS: TLLI = 0xf1223344, TA = 7
 Modifying MS object, TLLI = 0xf1223344, IMSI '' -> '0011223344'
 Modifying MS object, TLLI: 0xf1223344 confirmed
 MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, UL) appending 4 bytes to DL LLC queue
-MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, UL) ********** DL-TBF starts here **********
-MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, UL) Allocating DL TBF
+=== end test_tbf_single_phase ===
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, UL) Destroying MS object
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0,) Detaching TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED)
+=== start test_tbf_single_phase2 ===
+PDCH(bts=0,trx=0,ts=7) PDCH state: disabled => enabled
+Found first unallocated TRX=0 TFI=0
+MS requests Uplink resource on CCCH/RACH: ra=0x03 (8 bit) Fn=2654167 qta=31
+MS requests single TS uplink transmission (one phase packet access)
+Creating MS object, TLLI = 0xffffffff
+MS(TLLI=0xffffffff, IMSI=, TA=220, 0/0,) ********** UL-TBF starts here **********
+MS(TLLI=0xffffffff, IMSI=, TA=220, 0/0,) Allocating UL TBF
+TBF{NEW}: Allocated
+UL_ASS_TBF{NONE}: Allocated
+DL_ASS_TBF{NONE}: Allocated
+UL_ACK_TBF{NONE}: Allocated
+[UL] algo A <single> (suggested TRX: -1): Alloc start
+- Skipping TS 0, because not enabled
+- Skipping TS 1, because not enabled
+- Skipping TS 2, because not enabled
+- Skipping TS 3, because not enabled
+- Skipping TS 4, because not enabled
+- Skipping TS 5, because not enabled
+- Skipping TS 6, because not enabled
+[UL] Assign uplink TS=7 TFI=0 USF=0
+PDCH(bts=0,trx=0,ts=7) Attaching TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=NEW), 1 TBFs, USFs = 01, TFIs = 00000001.
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=NEW) Setting Control TS 7
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=NEW) Allocated: trx = 0, ul_slots = 80, dl_slots = 00
+MS(TLLI=0xffffffff, IMSI=, TA=220, 0/0,) Attaching UL TBF: TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=NEW)
+TBF(UL-TFI_0){NEW}: Received Event ASSIGN_ADD_CCCH
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=NEW) set ass. type CCCH [prev CCCH:0, PACCH:0]
+TBF(UL-TFI_0){NEW}: state_chg to FLOW
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=FLOW) starting timer T3141 [Contention resolution (UL-TBF, CCCH)] with 10 sec. 0 microsec, cur_fn=2654167
+Modifying MS object, TLLI = 0xffffffff, TA 220 -> 7
+Tx Immediate Assignment on AGCH: TRX=0 (ARFCN 0) TS=7 TA=7 TSC=0 TFI=0 USF=0
+PDCH(bts=0,trx=0,ts=7) Got CS-1 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=184
+PDCH(bts=0,trx=0,ts=7) FN=2654167 Rx UL DATA from unexpected TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=FLOW)
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=FLOW) UL DATA TFI=0 received (V(Q)=0 .. V(R)=0)
+MS(TLLI=0xffffffff, IMSI=, TA=7, 0/0, UL) Link quality 12dB (old 12dB) left window [-256, 6], modifying uplink CS level: CS-1 -> CS-2
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=FLOW) Got CS-1 RLC data block: CV=0, BSN=0, SPB=0, PI=0, E=1, TI=1, bitoffs=24
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=FLOW) BSN 0 storing in window (0..63)
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=FLOW) data_length=20, data=f1 22 33 44 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
+TBF(TFI=0 TLLI=0xffffffff DIR=UL STATE=FLOW) Decoded premier TLLI=0xf1223344 of UL DATA TFI=0.
+Modifying MS object, UL TLLI: 0xffffffff -> 0xf1223344, not yet confirmed
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) Assembling frames: (len=20)
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) Frame 1 starts at offset 4, length=16, is_complete=1
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) complete UL frame len=16
+LLC [PCU -> SGSN] TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) len=16
+No bctx
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) No gaps in received block, last block: BSN=0 CV=0
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) Finished with UL TBF
+TBF(UL-TFI_0){FLOW}: Received Event LAST_UL_DATA_RECVD
+TBF(UL-TFI_0){FLOW}: state_chg to FINISHED
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) Scheduling Ack/Nack, because TLLI is included.
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) Scheduling final Ack/Nack, because all data was received and last block has CV==0.
+UL_ACK_TBF(UL-TFI_0){NONE}: Received Event SCHED_ACK
+UL_ACK_TBF(UL-TFI_0){NONE}: state_chg to SCHED_UL_ACK
+Got 'TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED)', TA=7
+Got MS: TLLI = 0xf1223344, TA = 7
+UL_ACK_TBF(UL-TFI_0){SCHED_UL_ACK}: Received Event CREATE_RLCMAC_MSG
+PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654167 + 17 = 2654184
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) stopping timer T3141 [Contention resolution success (UL-TBF, CCCH)]
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) Scheduled UL Acknowledgement polling on PACCH (FN=2654184, TS=7)
+UL_ACK_TBF(UL-TFI_0){SCHED_UL_ACK}: state_chg to WAIT_ACK
+PDCH(bts=0,trx=0,ts=7) FN=2654167 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED)
+Modifying MS object, TLLI = 0xf1223344, IMSI '' -> '0011223344'
+Modifying MS object, TLLI: 0xf1223344 confirmed
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, UL) appending 4 bytes to DL LLC queue
+Detected FN jump! 2654167 -> 2654184 (expected 2654171)
+PDCH(bts=0,trx=0,ts=7) FN=2654184 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++
+PDCH(bts=0,trx=0,ts=7) FN=2654184 ------------------------- RX : Uplink Control Block -------------------------
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) FN=2654184 Rx Packet Control Ack (reason=UL_ACK)
+UL_ACK_TBF(UL-TFI_0){WAIT_ACK}: Received Event RX_CTRL_ACK
+UL_ACK_TBF(UL-TFI_0){WAIT_ACK}: state_chg to NONE
+TBF(UL-TFI_0){FINISHED}: Received Event FINAL_UL_ACK_CONFIRMED
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) [UPLINK] END
+TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) free
+PDCH(bts=0,trx=0,ts=7) Detaching TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED), 1 TBFs, USFs = 01, TFIs = 00000001.
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0,) Detaching TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED)
+********** UL-TBF ends here **********
+UL_ACK_TBF(UL-TFI_0){NONE}: Deallocated
+TBF(UL-TFI_0){FINISHED}: Deallocated
+UL_ASS_TBF(UL-TFI_0){NONE}: Deallocated
+DL_ASS_TBF(UL-TFI_0){NONE}: Deallocated
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0,) ********** DL-TBF starts here **********
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0,) Allocating DL TBF
 TBF{NEW}: Allocated
 UL_ASS_TBF{NONE}: Allocated
 DL_ASS_TBF{NONE}: Allocated
@@ -1863,10 +1946,10 @@ DL_ASS_TBF{NONE}: Allocated
 - Skipping TS 5, because not enabled
 - Skipping TS 6, because not enabled
 [DL] Assign downlink TS=7 TFI=0
-PDCH(bts=0,trx=0,ts=7) Attaching TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW), 1 TBFs, USFs = 01, TFIs = 00000001.
+PDCH(bts=0,trx=0,ts=7) Attaching TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW), 1 TBFs, USFs = 00, TFIs = 00000001.
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) Setting Control TS 7
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 80, dl_slots = 80
-MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, UL) Attaching DL TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW)
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0,) Attaching DL TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) [DOWNLINK] START
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=0011223344)
 TBF(DL-TFI_0){NEW}: Received Event ASSIGN_ADD_CCCH
@@ -1874,9 +1957,8 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) set ass. type CCCH [prev CCCH:0, PAC
 TBF(DL-TFI_0){NEW}: state_chg to ASSIGN
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) TX: START Immediate Assignment Downlink (PCH)
  - TRX=0 (0) TS=7 TA=7
-=== end test_tbf_single_phase ===
-MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, UL DL) Destroying MS object
-MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, DL) Detaching TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED)
+=== end test_tbf_single_phase2 ===
+MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0, DL) Destroying MS object
 MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 0/0,) Detaching TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN)
 === start test_tbf_two_phase ===
 PDCH(bts=0,trx=0,ts=7) PDCH state: disabled => enabled