Osmocom Open Build Service

Changes of Revision 14

osmo-pcu.spec Changed

commit_091642a8f54c04e99c8f95ee897ce9036964c449.txt Added

commit_5c516fdbd24e205078858b1cbed74c677d926b16.txt Deleted

osmo-pcu_1.1.0.41.5c51.dsc -> osmo-pcu_1.1.0.46.0916.dsc Changed

osmo-pcu_1.1.0.41.5c51.tar.xz/.tarball-version -> osmo-pcu_1.1.0.46.0916.tar.xz/.tarball-version Changed

osmo-pcu_1.1.0.41.5c51.tar.xz/debian/changelog -> osmo-pcu_1.1.0.46.0916.tar.xz/debian/changelog Changed

osmo-pcu_1.1.0.41.5c51.tar.xz/src/gprs_ms.c -> osmo-pcu_1.1.0.46.0916.tar.xz/src/gprs_ms.c Changed

@@ -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>
 
@@ -98,7 +99,7 @@
 
 	LOGPTBFDL(dl_tbf, LOGL_DEBUG, "LLC receive timeout, requesting DL ACK\n");
 
-	tbf_dl_request_dl_ack(dl_tbf);
+	dl_tbf_request_dl_ack(dl_tbf);
 }
 
 static int ms_talloc_destructor(struct GprsMs *ms);
@@ -1024,10 +1025,85 @@
 	}
 }
 
+/* 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;
+
+}
+
+/* A new DL-TBF is allocated and assigned through PACCH using "tbf".
+ * "tbf" may be either a UL-TBF or a DL-TBF.
+ * Note: This should be called only when MS is reachable, see ms_is_reachable_for_dl_ass().
+ */
+int ms_new_dl_tbf_assigned_on_pacch(struct GprsMs *ms, struct gprs_rlcmac_tbf *tbf)
+{
+	OSMO_ASSERT(tbf);
+	const int8_t trx_no = tbf_get_trx(tbf)->trx_no;
+	const bool single_slot = false;
+	struct gprs_rlcmac_dl_tbf *dl_tbf;
+
+	dl_tbf = dl_tbf_alloc(ms->bts, ms, trx_no, single_slot);
+	if (!dl_tbf) {
+		LOGPMS(ms, DTBF, LOGL_NOTICE, "No PDCH resource\n");
+		return -EBUSY;
+	}
+
+	LOGPTBFDL(dl_tbf, LOGL_DEBUG, "DOWNLINK START (PACCH)\n");
+	dl_tbf_trigger_ass_on_pacch(dl_tbf, tbf);
+	return 0;
+}
+
+/* A new DL-TBF is allocated and assigned through PCH.
+ * Note: This should be called only when MS is reachable, see ms_is_reachable_for_dl_ass().
+ */
+int ms_new_dl_tbf_assigned_on_pch(struct GprsMs *ms)
+{
+	const int8_t trx_no = -1;
+	const bool single_slot = true;
+	struct gprs_rlcmac_dl_tbf *dl_tbf;
+
+	dl_tbf = dl_tbf_alloc(ms->bts, ms, trx_no, single_slot);
+
+	if (!dl_tbf) {
+		LOGPMS(ms, DTBF, LOGL_NOTICE, "No PDCH resource\n");
+		return -EBUSY;
+	}
+
+	LOGPTBFDL(dl_tbf, LOGL_DEBUG, "DOWNLINK START (PCH)\n");
+	dl_tbf_trigger_ass_on_pch(dl_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 +1117,21 @@
 	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");
+			rc = ms_new_dl_tbf_assigned_on_pacch(ms, 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)) {
+			if (ms_ul_tbf(ms))
+				rc = ms_new_dl_tbf_assigned_on_pacch(ms, ul_tbf_as_tbf(ms_ul_tbf(ms)));
+			else
+				rc = ms_new_dl_tbf_assigned_on_pch(ms);
+		}
 	}
-
-	return 0;
+	return rc;
 }

osmo-pcu_1.1.0.41.5c51.tar.xz/src/gprs_ms.h -> osmo-pcu_1.1.0.46.0916.tar.xz/src/gprs_ms.h Changed

osmo-pcu_1.1.0.41.5c51.tar.xz/src/pdch.cpp -> osmo-pcu_1.1.0.46.0916.tar.xz/src/pdch.cpp Changed

@@ -385,9 +385,12 @@
 		}
 		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:
@@ -418,7 +421,7 @@
 		 * TBF might have been released while the UL TBF has been
 		 * established */
 		if (ms_need_dl_tbf(new_tbf->ms()))
-			new_tbf->establish_dl_tbf_on_pacch();
+			ms_new_dl_tbf_assigned_on_pacch(new_tbf->ms(), new_tbf);
 		return;
 
 	case PDCH_ULC_POLL_DL_ASS:
@@ -722,7 +725,7 @@
 				"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,
@@ -750,6 +753,10 @@
 				ms_set_egprs_ms_class(ms, egprs_ms_class);
 		}
 
+		/* get measurements */
+		get_meas(meas, request);
+		ms_update_l1_meas(ms, meas);
+
 		ul_tbf = tbf_alloc_ul_pacch(bts, ms, trx_no());
 		if (!ul_tbf) {
 			handle_tbf_reject(bts, ms, trx_no(), ts_no);
@@ -769,10 +776,6 @@
 		ul_tbf->control_ts = ts_no;
 		/* schedule uplink assignment */
 		osmo_fsm_inst_dispatch(ul_tbf->ul_ass_fsm.fi, TBF_UL_ASS_EV_SCHED_ASS, NULL);
-
-		/* get measurements */
-		get_meas(meas, request);
-		ms_update_l1_meas(ul_tbf->ms(), meas);
 return_unref:
 		ms_unref(ms);
 		return;

osmo-pcu_1.1.0.41.5c51.tar.xz/src/tbf.cpp -> osmo-pcu_1.1.0.46.0916.tar.xz/src/tbf.cpp Changed

osmo-pcu_1.1.0.41.5c51.tar.xz/src/tbf.h -> osmo-pcu_1.1.0.46.0916.tar.xz/src/tbf.h Changed

osmo-pcu_1.1.0.41.5c51.tar.xz/src/tbf_dl.cpp -> osmo-pcu_1.1.0.46.0916.tar.xz/src/tbf_dl.cpp Changed

@@ -182,52 +182,6 @@
 {
 }
 
-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 @@
 	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;
 }
 
@@ -471,29 +418,41 @@
 	return create_dl_acked_block(fn, ts, bsn, bsn2);
 }
 
-/* depending on the current TBF, we assign on PACCH or AGCH */
-void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf)
+/* old_tbf (UL TBF or DL TBF) will send a Pkt Dl Ass on PACCH to assign tbf.
+ * Note: It is possible that "tbf == old_tbf" if the TBF is being updated. This can
+ * happen when we first assign over PCH (only single slot is possible) and we want
+ * to upgrade the DL-TBF to be multislot. See code calling tbf_update() for more
+ * information.
+ */
+void dl_tbf_trigger_ass_on_pacch(struct gprs_rlcmac_dl_tbf *tbf, struct gprs_rlcmac_tbf *old_tbf)
 {
+	OSMO_ASSERT(tbf);
+	OSMO_ASSERT(old_tbf);
 	/* stop pending timer */
-	stop_timers("assignment (DL-TBF)");
+	tbf_stop_timers(tbf, "DL assignment (PACCH)");
 
-	/* check for downlink tbf:  */
-	if (old_tbf) {
-		LOGPTBFDL(this, LOGL_DEBUG, "Send downlink assignment on PACCH, because %s exists\n", old_tbf->name());
-		osmo_fsm_inst_dispatch(old_tbf->dl_ass_fsm.fi, TBF_DL_ASS_EV_SCHED_ASS, NULL);
+	LOGPTBFDL(tbf, LOGL_DEBUG, "Send downlink assignment on PACCH, because %s exists\n", old_tbf->name());
+	osmo_fsm_inst_dispatch(old_tbf->dl_ass_fsm.fi, TBF_DL_ASS_EV_SCHED_ASS, NULL);
 
-		/* change state */
-		osmo_fsm_inst_dispatch(this->state_fsm.fi, TBF_EV_ASSIGN_ADD_PACCH, NULL);
-	} else {
-		LOGPTBFDL(this, LOGL_DEBUG, "Send downlink assignment on PCH, no TBF exist (IMSI=%s)\n",
-			  imsi());
+	/* change state */
+	osmo_fsm_inst_dispatch(tbf->state_fsm.fi, TBF_EV_ASSIGN_ADD_PACCH, NULL);
 
-		/* change state */
-		osmo_fsm_inst_dispatch(this->state_fsm.fi, TBF_EV_ASSIGN_ADD_CCCH, NULL);
+}
 
-		/* send immediate assignment */
-		bts_snd_dl_ass(bts, this);
-	}
+void dl_tbf_trigger_ass_on_pch(struct gprs_rlcmac_dl_tbf *tbf)
+{
+	/* stop pending timer */
+	struct GprsMs *ms = tbf_ms(tbf);
+
+	tbf_stop_timers(tbf, "DL assignment (PCH)");
+
+	LOGPTBFDL(tbf, LOGL_DEBUG, "Send downlink assignment on PCH, no TBF exist (IMSI=%s)\n", ms_imsi(ms));
+
+	/* change state */
+	osmo_fsm_inst_dispatch(tbf->state_fsm.fi, TBF_EV_ASSIGN_ADD_CCCH, NULL);
+
+	/* send immediate assignment */
+	bts_snd_dl_ass(ms->bts, tbf);
 }
 
 void gprs_rlcmac_dl_tbf::schedule_next_frame()
@@ -1014,6 +973,7 @@
 int gprs_rlcmac_dl_tbf::rcvd_dl_final_ack()
 {
 	uint16_t received;
+	int rc = 0;
 
 	osmo_fsm_inst_dispatch(this->state_fsm.fi, TBF_EV_FINAL_ACK_RECVD, NULL);
 
@@ -1027,9 +987,9 @@
 	/* check for LLC PDU in the LLC Queue */
 	if (llc_queue_size(llc_queue()) > 0)
 		/* we have more data so we will re-use this tbf */
-		establish_dl_tbf_on_pacch();
+		rc = ms_new_dl_tbf_assigned_on_pacch(ms(), dl_tbf_as_tbf(this));
 
-	return 0;
+	return rc;
 }
 
 int gprs_rlcmac_dl_tbf::rcvd_dl_ack(bool final_ack, unsigned first_bsn,
@@ -1068,7 +1028,7 @@
 	m_dl_ack_requested = true;
 }
 
-void tbf_dl_request_dl_ack(struct gprs_rlcmac_dl_tbf *dl_tbf) {
+void dl_tbf_request_dl_ack(struct gprs_rlcmac_dl_tbf *dl_tbf) {
 	dl_tbf->request_dl_ack();
 }
 
@@ -1325,8 +1285,3 @@
 	else
 		return NULL;
 }
-
-void tbf_dl_trigger_ass(struct gprs_rlcmac_dl_tbf *tbf, struct gprs_rlcmac_tbf *old_tbf)
-{
-	return tbf->trigger_ass(old_tbf);
-}

osmo-pcu_1.1.0.41.5c51.tar.xz/src/tbf_dl.h -> osmo-pcu_1.1.0.46.0916.tar.xz/src/tbf_dl.h Changed

osmo-pcu_1.1.0.41.5c51.tar.xz/src/tbf_fsm.c -> osmo-pcu_1.1.0.46.0916.tar.xz/src/tbf_fsm.c Changed

@@ -244,6 +244,9 @@
 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 @@
 		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_assigned_on_pch(ms);
+		ms_unref(ms);
 		break;
 	case TBF_EV_MAX_N3103:
 		ctx->T_release = 3169;
@@ -366,8 +387,7 @@
 		ctx->state_flags &= GPRS_RLCMAC_FLAG_TO_MASK;
 
 		tbf_update(ctx->tbf);
-
-		tbf_dl_trigger_ass(dl_tbf, ctx->tbf);
+		dl_tbf_trigger_ass_on_pacch(dl_tbf, ctx->tbf);
 	} else
 		LOGPTBF(ctx->tbf, LOGL_NOTICE, "Continue flow after IMM.ASS confirm\n");
 }

osmo-pcu_1.1.0.41.5c51.tar.xz/src/tbf_fsm.h -> osmo-pcu_1.1.0.46.0916.tar.xz/src/tbf_fsm.h Changed

osmo-pcu_1.1.0.41.5c51.tar.xz/tests/tbf/TbfTest.cpp -> osmo-pcu_1.1.0.46.0916.tar.xz/tests/tbf/TbfTest.cpp Changed

@@ -1715,7 +1715,6 @@
 
 	ms = bts_ms_by_imsi(bts, imsi);
 	OSMO_ASSERT(ms != NULL);
-	OSMO_ASSERT(ms_dl_tbf(ms) != NULL);
 
 	if (imsi0 != '\0') {
 		ms2 = bts_ms_by_tlli(bts, tlli, GSM_RESERVED_TMSI);
@@ -1779,6 +1778,38 @@
 	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 @@
 	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();

osmo-pcu_1.1.0.41.5c51.tar.xz/tests/tbf/TbfTest.err -> osmo-pcu_1.1.0.46.0916.tar.xz/tests/tbf/TbfTest.err Changed

@@ -140,7 +140,7 @@
 TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xffeeddcc, IMSI=, TA=0, 45/0, DL) Attaching DL TBF: TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW)
-TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT_RELEASE) Trigger downlink assignment on PACCH
+TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW) DOWNLINK START (PACCH)
 TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT_RELEASE) exists
 DL_ASS_TBF(DL-TFI_0){WAIT_ACK}: Received Event SCHED_ASS
 DL_ASS_TBF(DL-TFI_0){WAIT_ACK}: Event SCHED_ASS not permitted
@@ -253,7 +253,7 @@
 TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xffeeddcc, IMSI=, TA=0, 45/0, DL) Attaching DL TBF: TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW)
-TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT_RELEASE) Trigger downlink assignment on PACCH
+TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW) DOWNLINK START (PACCH)
 TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=NEW) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=WAIT_RELEASE) exists
 DL_ASS_TBF(DL-TFI_0){WAIT_ACK}: Received Event SCHED_ASS
 DL_ASS_TBF(DL-TFI_0){WAIT_ACK}: Event SCHED_ASS not permitted
@@ -660,7 +660,7 @@
 TBF(TFI=0 TLLI=0xc0000000 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=0 TLLI=0xc0000000 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000000, IMSI=001001000000000, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=0 TLLI=0xc0000000 DIR=DL STATE=NEW)
-TBF(TFI=0 TLLI=0xc0000000 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=0 TLLI=0xc0000000 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=0 TLLI=0xc0000000 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000000)
 TBF(DL-TFI_0){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=0 TLLI=0xc0000000 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -690,7 +690,7 @@
 TBF(TFI=1 TLLI=0xc0000001 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=1 TLLI=0xc0000001 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000001, IMSI=001001000000001, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=1 TLLI=0xc0000001 DIR=DL STATE=NEW)
-TBF(TFI=1 TLLI=0xc0000001 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=1 TLLI=0xc0000001 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=1 TLLI=0xc0000001 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000001)
 TBF(DL-TFI_1){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=1 TLLI=0xc0000001 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -720,7 +720,7 @@
 TBF(TFI=2 TLLI=0xc0000002 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=2 TLLI=0xc0000002 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000002, IMSI=001001000000002, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=2 TLLI=0xc0000002 DIR=DL STATE=NEW)
-TBF(TFI=2 TLLI=0xc0000002 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=2 TLLI=0xc0000002 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=2 TLLI=0xc0000002 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000002)
 TBF(DL-TFI_2){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=2 TLLI=0xc0000002 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -750,7 +750,7 @@
 TBF(TFI=3 TLLI=0xc0000003 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=3 TLLI=0xc0000003 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000003, IMSI=001001000000003, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=3 TLLI=0xc0000003 DIR=DL STATE=NEW)
-TBF(TFI=3 TLLI=0xc0000003 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=3 TLLI=0xc0000003 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=3 TLLI=0xc0000003 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000003)
 TBF(DL-TFI_3){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=3 TLLI=0xc0000003 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -780,7 +780,7 @@
 TBF(TFI=4 TLLI=0xc0000004 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=4 TLLI=0xc0000004 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000004, IMSI=001001000000004, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=4 TLLI=0xc0000004 DIR=DL STATE=NEW)
-TBF(TFI=4 TLLI=0xc0000004 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=4 TLLI=0xc0000004 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=4 TLLI=0xc0000004 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000004)
 TBF(DL-TFI_4){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=4 TLLI=0xc0000004 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -810,7 +810,7 @@
 TBF(TFI=5 TLLI=0xc0000005 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=5 TLLI=0xc0000005 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000005, IMSI=001001000000005, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=5 TLLI=0xc0000005 DIR=DL STATE=NEW)
-TBF(TFI=5 TLLI=0xc0000005 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=5 TLLI=0xc0000005 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=5 TLLI=0xc0000005 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000005)
 TBF(DL-TFI_5){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=5 TLLI=0xc0000005 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -840,7 +840,7 @@
 TBF(TFI=6 TLLI=0xc0000006 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=6 TLLI=0xc0000006 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000006, IMSI=001001000000006, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=6 TLLI=0xc0000006 DIR=DL STATE=NEW)
-TBF(TFI=6 TLLI=0xc0000006 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=6 TLLI=0xc0000006 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=6 TLLI=0xc0000006 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000006)
 TBF(DL-TFI_6){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=6 TLLI=0xc0000006 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -870,7 +870,7 @@
 TBF(TFI=7 TLLI=0xc0000007 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=7 TLLI=0xc0000007 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000007, IMSI=001001000000007, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=7 TLLI=0xc0000007 DIR=DL STATE=NEW)
-TBF(TFI=7 TLLI=0xc0000007 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=7 TLLI=0xc0000007 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=7 TLLI=0xc0000007 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000007)
 TBF(DL-TFI_7){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=7 TLLI=0xc0000007 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -900,7 +900,7 @@
 TBF(TFI=8 TLLI=0xc0000008 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=8 TLLI=0xc0000008 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000008, IMSI=001001000000008, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=8 TLLI=0xc0000008 DIR=DL STATE=NEW)
-TBF(TFI=8 TLLI=0xc0000008 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=8 TLLI=0xc0000008 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=8 TLLI=0xc0000008 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000008)
 TBF(DL-TFI_8){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=8 TLLI=0xc0000008 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -930,7 +930,7 @@
 TBF(TFI=9 TLLI=0xc0000009 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=9 TLLI=0xc0000009 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000009, IMSI=001001000000009, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=9 TLLI=0xc0000009 DIR=DL STATE=NEW)
-TBF(TFI=9 TLLI=0xc0000009 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=9 TLLI=0xc0000009 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=9 TLLI=0xc0000009 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000009)
 TBF(DL-TFI_9){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=9 TLLI=0xc0000009 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -960,7 +960,7 @@
 TBF(TFI=10 TLLI=0xc000000a DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=10 TLLI=0xc000000a DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000000a, IMSI=001001000000010, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=10 TLLI=0xc000000a DIR=DL STATE=NEW)
-TBF(TFI=10 TLLI=0xc000000a DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=10 TLLI=0xc000000a DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=10 TLLI=0xc000000a DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000010)
 TBF(DL-TFI_10){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=10 TLLI=0xc000000a DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -990,7 +990,7 @@
 TBF(TFI=11 TLLI=0xc000000b DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=11 TLLI=0xc000000b DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000000b, IMSI=001001000000011, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=11 TLLI=0xc000000b DIR=DL STATE=NEW)
-TBF(TFI=11 TLLI=0xc000000b DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=11 TLLI=0xc000000b DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=11 TLLI=0xc000000b DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000011)
 TBF(DL-TFI_11){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=11 TLLI=0xc000000b DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1020,7 +1020,7 @@
 TBF(TFI=12 TLLI=0xc000000c DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=12 TLLI=0xc000000c DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000000c, IMSI=001001000000012, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=12 TLLI=0xc000000c DIR=DL STATE=NEW)
-TBF(TFI=12 TLLI=0xc000000c DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=12 TLLI=0xc000000c DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=12 TLLI=0xc000000c DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000012)
 TBF(DL-TFI_12){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=12 TLLI=0xc000000c DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1050,7 +1050,7 @@
 TBF(TFI=13 TLLI=0xc000000d DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=13 TLLI=0xc000000d DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000000d, IMSI=001001000000013, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=13 TLLI=0xc000000d DIR=DL STATE=NEW)
-TBF(TFI=13 TLLI=0xc000000d DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=13 TLLI=0xc000000d DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=13 TLLI=0xc000000d DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000013)
 TBF(DL-TFI_13){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=13 TLLI=0xc000000d DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1080,7 +1080,7 @@
 TBF(TFI=14 TLLI=0xc000000e DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=14 TLLI=0xc000000e DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000000e, IMSI=001001000000014, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=14 TLLI=0xc000000e DIR=DL STATE=NEW)
-TBF(TFI=14 TLLI=0xc000000e DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=14 TLLI=0xc000000e DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=14 TLLI=0xc000000e DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000014)
 TBF(DL-TFI_14){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=14 TLLI=0xc000000e DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1110,7 +1110,7 @@
 TBF(TFI=15 TLLI=0xc000000f DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=15 TLLI=0xc000000f DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000000f, IMSI=001001000000015, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=15 TLLI=0xc000000f DIR=DL STATE=NEW)
-TBF(TFI=15 TLLI=0xc000000f DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=15 TLLI=0xc000000f DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=15 TLLI=0xc000000f DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000015)
 TBF(DL-TFI_15){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=15 TLLI=0xc000000f DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1140,7 +1140,7 @@
 TBF(TFI=16 TLLI=0xc0000010 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=16 TLLI=0xc0000010 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000010, IMSI=001001000000016, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=16 TLLI=0xc0000010 DIR=DL STATE=NEW)
-TBF(TFI=16 TLLI=0xc0000010 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=16 TLLI=0xc0000010 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=16 TLLI=0xc0000010 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000016)
 TBF(DL-TFI_16){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=16 TLLI=0xc0000010 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1170,7 +1170,7 @@
 TBF(TFI=17 TLLI=0xc0000011 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=17 TLLI=0xc0000011 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000011, IMSI=001001000000017, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=17 TLLI=0xc0000011 DIR=DL STATE=NEW)
-TBF(TFI=17 TLLI=0xc0000011 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=17 TLLI=0xc0000011 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=17 TLLI=0xc0000011 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000017)
 TBF(DL-TFI_17){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=17 TLLI=0xc0000011 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1200,7 +1200,7 @@
 TBF(TFI=18 TLLI=0xc0000012 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=18 TLLI=0xc0000012 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000012, IMSI=001001000000018, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=18 TLLI=0xc0000012 DIR=DL STATE=NEW)
-TBF(TFI=18 TLLI=0xc0000012 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=18 TLLI=0xc0000012 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=18 TLLI=0xc0000012 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000018)
 TBF(DL-TFI_18){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=18 TLLI=0xc0000012 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1230,7 +1230,7 @@
 TBF(TFI=19 TLLI=0xc0000013 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=19 TLLI=0xc0000013 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000013, IMSI=001001000000019, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=19 TLLI=0xc0000013 DIR=DL STATE=NEW)
-TBF(TFI=19 TLLI=0xc0000013 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=19 TLLI=0xc0000013 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=19 TLLI=0xc0000013 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000019)
 TBF(DL-TFI_19){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=19 TLLI=0xc0000013 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1260,7 +1260,7 @@
 TBF(TFI=20 TLLI=0xc0000014 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=20 TLLI=0xc0000014 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000014, IMSI=001001000000020, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=20 TLLI=0xc0000014 DIR=DL STATE=NEW)
-TBF(TFI=20 TLLI=0xc0000014 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=20 TLLI=0xc0000014 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=20 TLLI=0xc0000014 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000020)
 TBF(DL-TFI_20){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=20 TLLI=0xc0000014 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1290,7 +1290,7 @@
 TBF(TFI=21 TLLI=0xc0000015 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=21 TLLI=0xc0000015 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000015, IMSI=001001000000021, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=21 TLLI=0xc0000015 DIR=DL STATE=NEW)
-TBF(TFI=21 TLLI=0xc0000015 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=21 TLLI=0xc0000015 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=21 TLLI=0xc0000015 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000021)
 TBF(DL-TFI_21){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=21 TLLI=0xc0000015 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1320,7 +1320,7 @@
 TBF(TFI=22 TLLI=0xc0000016 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=22 TLLI=0xc0000016 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000016, IMSI=001001000000022, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=22 TLLI=0xc0000016 DIR=DL STATE=NEW)
-TBF(TFI=22 TLLI=0xc0000016 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=22 TLLI=0xc0000016 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=22 TLLI=0xc0000016 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000022)
 TBF(DL-TFI_22){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=22 TLLI=0xc0000016 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1350,7 +1350,7 @@
 TBF(TFI=23 TLLI=0xc0000017 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=23 TLLI=0xc0000017 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000017, IMSI=001001000000023, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=23 TLLI=0xc0000017 DIR=DL STATE=NEW)
-TBF(TFI=23 TLLI=0xc0000017 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=23 TLLI=0xc0000017 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=23 TLLI=0xc0000017 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000023)
 TBF(DL-TFI_23){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=23 TLLI=0xc0000017 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1380,7 +1380,7 @@
 TBF(TFI=24 TLLI=0xc0000018 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=24 TLLI=0xc0000018 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000018, IMSI=001001000000024, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=24 TLLI=0xc0000018 DIR=DL STATE=NEW)
-TBF(TFI=24 TLLI=0xc0000018 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=24 TLLI=0xc0000018 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=24 TLLI=0xc0000018 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000024)
 TBF(DL-TFI_24){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=24 TLLI=0xc0000018 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1410,7 +1410,7 @@
 TBF(TFI=25 TLLI=0xc0000019 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=25 TLLI=0xc0000019 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0000019, IMSI=001001000000025, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=25 TLLI=0xc0000019 DIR=DL STATE=NEW)
-TBF(TFI=25 TLLI=0xc0000019 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=25 TLLI=0xc0000019 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=25 TLLI=0xc0000019 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000025)
 TBF(DL-TFI_25){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=25 TLLI=0xc0000019 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1440,7 +1440,7 @@
 TBF(TFI=26 TLLI=0xc000001a DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=26 TLLI=0xc000001a DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000001a, IMSI=001001000000026, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=26 TLLI=0xc000001a DIR=DL STATE=NEW)
-TBF(TFI=26 TLLI=0xc000001a DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=26 TLLI=0xc000001a DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=26 TLLI=0xc000001a DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000026)
 TBF(DL-TFI_26){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=26 TLLI=0xc000001a DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1470,7 +1470,7 @@
 TBF(TFI=27 TLLI=0xc000001b DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=27 TLLI=0xc000001b DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000001b, IMSI=001001000000027, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=27 TLLI=0xc000001b DIR=DL STATE=NEW)
-TBF(TFI=27 TLLI=0xc000001b DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=27 TLLI=0xc000001b DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=27 TLLI=0xc000001b DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000027)
 TBF(DL-TFI_27){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=27 TLLI=0xc000001b DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1500,7 +1500,7 @@
 TBF(TFI=28 TLLI=0xc000001c DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=28 TLLI=0xc000001c DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000001c, IMSI=001001000000028, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=28 TLLI=0xc000001c DIR=DL STATE=NEW)
-TBF(TFI=28 TLLI=0xc000001c DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=28 TLLI=0xc000001c DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=28 TLLI=0xc000001c DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000028)
 TBF(DL-TFI_28){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=28 TLLI=0xc000001c DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1530,7 +1530,7 @@
 TBF(TFI=29 TLLI=0xc000001d DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=29 TLLI=0xc000001d DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000001d, IMSI=001001000000029, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=29 TLLI=0xc000001d DIR=DL STATE=NEW)
-TBF(TFI=29 TLLI=0xc000001d DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=29 TLLI=0xc000001d DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=29 TLLI=0xc000001d DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000029)
 TBF(DL-TFI_29){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=29 TLLI=0xc000001d DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1560,7 +1560,7 @@
 TBF(TFI=30 TLLI=0xc000001e DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=30 TLLI=0xc000001e DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000001e, IMSI=001001000000030, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=30 TLLI=0xc000001e DIR=DL STATE=NEW)
-TBF(TFI=30 TLLI=0xc000001e DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=30 TLLI=0xc000001e DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=30 TLLI=0xc000001e DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000030)
 TBF(DL-TFI_30){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=30 TLLI=0xc000001e DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1590,7 +1590,7 @@
 TBF(TFI=31 TLLI=0xc000001f DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=31 TLLI=0xc000001f DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc000001f, IMSI=001001000000031, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=31 TLLI=0xc000001f DIR=DL STATE=NEW)
-TBF(TFI=31 TLLI=0xc000001f DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=31 TLLI=0xc000001f DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=31 TLLI=0xc000001f DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000000031)
 TBF(DL-TFI_31){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=31 TLLI=0xc000001f DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1705,7 +1705,7 @@
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0123456, IMSI=001001000123456, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW)
-TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000123456)
 TBF(DL-TFI_0){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1742,7 +1742,7 @@
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0123456, IMSI=001001000123456, TA=0, 45/0,) Attaching DL TBF: TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW)
 MS(TLLI=0xc0123456, IMSI=001001000123456, TA=0, 45/0, DL) Cancel scheduled MS release
-TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001000123456)
 TBF(DL-TFI_0){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -1849,8 +1849,91 @@
 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,20 +1946,19 @@
 - 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)
-TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) DOWNLINK START
+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 (PCH)
 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
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
 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
@@ -1969,7 +2051,7 @@
 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, 1/0, UL) 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) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -2071,7 +2153,7 @@
 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, 1/0, UL) 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) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -2264,6 +2346,7 @@
 PDCH(bts=0,trx=0,ts=7) FN=2654270 PKT RESOURCE REQ: MS requests UL TBF throguh SBA
 Modifying MS object, TLLI = 0xf1223344, TA 220 -> 7
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: CS-1 -> CS-2
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) ********** UL-TBF starts here **********
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -2290,7 +2373,6 @@
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: CS-1 -> CS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654270 + 13 = 2654283
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
@@ -2341,7 +2423,7 @@
 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, 1/0, UL) 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) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -2441,6 +2523,7 @@
 PDCH(bts=0,trx=0,ts=7) FN=2654270 PKT RESOURCE REQ: MS requests UL TBF throguh SBA
 Modifying MS object, TLLI = 0xf1223344, TA 220 -> 7
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: CS-1 -> CS-2
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) ********** UL-TBF starts here **********
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -2467,7 +2550,6 @@
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: CS-1 -> CS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654270 + 13 = 2654283
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
@@ -2518,7 +2600,7 @@
 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, 1/0, UL) 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) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -2616,6 +2698,7 @@
 PDCH(bts=0,trx=0,ts=7) FN=2654270 PKT RESOURCE REQ: MS requests UL TBF throguh SBA
 Modifying MS object, TLLI = 0xf1223344, TA 220 -> 7
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: CS-1 -> CS-2
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) ********** UL-TBF starts here **********
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -2642,7 +2725,6 @@
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xf1223344, IMSI=, TA=7, 1/0, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: CS-1 -> CS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654270 + 13 = 2654283
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) start Packet Uplink Assignment (PACCH)
@@ -2693,7 +2775,7 @@
 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, 1/0, UL) 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) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -3418,7 +3500,7 @@
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NEW) Setting Control TS 7
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 80, dl_slots = 80
 MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/0, UL DL) Attaching DL TBF: TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NEW)
-TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) Trigger downlink assignment on PACCH
+TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NEW) DOWNLINK START (PACCH)
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=NEW) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT_RELEASE) exists
 DL_ASS_TBF(DL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(DL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -3685,7 +3767,7 @@
 TBF(TFI=0 TLLI=0xc0006789 DIR=DL STATE=NEW) Setting Control TS 4
 TBF(TFI=0 TLLI=0xc0006789 DIR=DL STATE=NEW) Allocated: trx = 0, ul_slots = 10, dl_slots = 10
 MS(TLLI=0xc0006789, IMSI=001001123456789, TA=220, 45/0,) Attaching DL TBF: TBF(TFI=0 TLLI=0xc0006789 DIR=DL STATE=NEW)
-TBF(TFI=0 TLLI=0xc0006789 DIR=DL STATE=NEW) DOWNLINK START
+TBF(TFI=0 TLLI=0xc0006789 DIR=DL STATE=NEW) DOWNLINK START (PCH)
 TBF(TFI=0 TLLI=0xc0006789 DIR=DL STATE=NEW) Send downlink assignment on PCH, no TBF exist (IMSI=001001123456789)
 TBF(DL-TFI_0){NEW}: Received Event ASSIGN_ADD_CCCH
 TBF(TFI=0 TLLI=0xc0006789 DIR=DL STATE=NEW) set ass. type CCCH prev CCCH:0, PACCH:0
@@ -3806,6 +3888,7 @@
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
 Modifying MS object, TLLI = 0xf1223344, EGPRS MS class 0 -> 1
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) ********** UL-TBF starts here **********
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -3834,7 +3917,6 @@
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654270 + 13 = 2654283
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
@@ -3888,7 +3970,7 @@
 MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/1, UL) Attaching DL TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 64, base(64) slots(1) ws_pdch(0)
 ws(64)
-TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START
+TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW EGPRS) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -3917,6 +3999,7 @@
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
 Modifying MS object, TLLI = 0xf1223344, EGPRS MS class 0 -> 1
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) ********** UL-TBF starts here **********
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -3945,7 +4028,6 @@
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654270 + 13 = 2654283
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
@@ -4122,7 +4204,7 @@
 MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/1, UL) Attaching DL TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 64, base(64) slots(1) ws_pdch(0)
 ws(64)
-TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START
+TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW EGPRS) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -6868,6 +6950,7 @@
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
 Modifying MS object, TLLI = 0xf1223344, EGPRS MS class 0 -> 1
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) ********** UL-TBF starts here **********
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -6896,7 +6979,6 @@
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654270 + 13 = 2654283
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
@@ -6973,7 +7055,7 @@
 MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/1, UL) Attaching DL TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 64, base(64) slots(1) ws_pdch(0)
 ws(64)
-TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START
+TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW EGPRS) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -7065,6 +7147,7 @@
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
 Modifying MS object, TLLI = 0xf1223344, EGPRS MS class 0 -> 1
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) ********** UL-TBF starts here **********
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -7093,7 +7176,6 @@
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654270 + 13 = 2654283
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
@@ -7159,7 +7241,7 @@
 MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/1, UL) Attaching DL TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 64, base(64) slots(1) ws_pdch(0)
 ws(64)
-TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START
+TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW EGPRS) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -7490,6 +7572,7 @@
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
 Modifying MS object, TLLI = 0xf1223344, EGPRS MS class 0 -> 1
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) ********** UL-TBF starts here **********
 MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -7518,7 +7601,6 @@
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xf1223344, IMSI=, TA=7, 1/1, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654270 + 13 = 2654283
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
@@ -8068,7 +8150,7 @@
 MS(TLLI=0xf1223344, IMSI=0011223344, TA=7, 1/1, UL) Attaching DL TBF: TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) setting EGPRS DL window size to 192, base(128) slots(1) ws_pdch(64)
 ws(192)
-TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START
+TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) DOWNLINK START (PACCH)
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NEW EGPRS) Send downlink assignment on PACCH, because TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW EGPRS) exists
 DL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 DL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
@@ -8831,6 +8913,7 @@
 Modifying MS object, TLLI = 0xffeeddcc, MS class 0 -> 11
 Modifying MS object, TLLI = 0xffeeddcc, EGPRS MS class 0 -> 11
 MS(TLLI=0xffeeddcc, IMSI=, TA=7, 11/11,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xffeeddcc, IMSI=, TA=7, 11/11,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xffeeddcc, IMSI=, TA=7, 11/11,) ********** UL-TBF starts here **********
 MS(TLLI=0xffeeddcc, IMSI=, TA=7, 11/11,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -8859,7 +8942,6 @@
 TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_0){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_0){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xffeeddcc, IMSI=, TA=7, 11/11, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 UL_ASS_TBF(UL-TFI_0){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
 PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 2654218 + 13 = 2654231
 TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN EGPRS) start Packet Uplink Assignment (PACCH)
@@ -8877,6 +8959,7 @@
 Modifying MS object, TLLI = 0xffeeddcd, MS class 0 -> 11
 Modifying MS object, TLLI = 0xffeeddcd, EGPRS MS class 0 -> 11
 MS(TLLI=0xffeeddcd, IMSI=, TA=7, 11/11,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xffeeddcd, IMSI=, TA=7, 11/11,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xffeeddcd, IMSI=, TA=7, 11/11,) ********** UL-TBF starts here **********
 MS(TLLI=0xffeeddcd, IMSI=, TA=7, 11/11,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -8905,7 +8988,6 @@
 TBF(TFI=1 TLLI=0xffeeddcd DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_1){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_1){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xffeeddcd, IMSI=, TA=7, 11/11, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 PDCH(bts=0,trx=0,ts=7) Expiring FN=56 but previous FN=2654231 is still reserved!
 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654231, reason=UL_ASS): TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN EGPRS)
 TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=2654231, TS=7 (curr FN 56)
@@ -8930,6 +9012,7 @@
 Modifying MS object, TLLI = 0xffeeddce, MS class 0 -> 11
 Modifying MS object, TLLI = 0xffeeddce, EGPRS MS class 0 -> 11
 MS(TLLI=0xffeeddce, IMSI=, TA=7, 11/11,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xffeeddce, IMSI=, TA=7, 11/11,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xffeeddce, IMSI=, TA=7, 11/11,) ********** UL-TBF starts here **********
 MS(TLLI=0xffeeddce, IMSI=, TA=7, 11/11,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -8958,7 +9041,6 @@
 TBF(TFI=2 TLLI=0xffeeddce DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_2){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_2){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xffeeddce, IMSI=, TA=7, 11/11, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 PDCH(bts=0,trx=0,ts=7) Expiring FN=60 but previous FN=2654231 is still reserved!
 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654231, reason=UL_ASS): TBF(TFI=1 TLLI=0xffeeddcd DIR=UL STATE=ASSIGN EGPRS)
 TBF(TFI=1 TLLI=0xffeeddcd DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=2654231, TS=7 (curr FN 60)
@@ -8983,6 +9065,7 @@
 Modifying MS object, TLLI = 0xffeeddcf, MS class 0 -> 11
 Modifying MS object, TLLI = 0xffeeddcf, EGPRS MS class 0 -> 11
 MS(TLLI=0xffeeddcf, IMSI=, TA=7, 11/11,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xffeeddcf, IMSI=, TA=7, 11/11,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xffeeddcf, IMSI=, TA=7, 11/11,) ********** UL-TBF starts here **********
 MS(TLLI=0xffeeddcf, IMSI=, TA=7, 11/11,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -9011,7 +9094,6 @@
 TBF(TFI=3 TLLI=0xffeeddcf DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_3){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_3){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xffeeddcf, IMSI=, TA=7, 11/11, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 PDCH(bts=0,trx=0,ts=7) Expiring FN=65 but previous FN=2654231 is still reserved!
 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654231, reason=UL_ASS): TBF(TFI=2 TLLI=0xffeeddce DIR=UL STATE=ASSIGN EGPRS)
 TBF(TFI=2 TLLI=0xffeeddce DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=2654231, TS=7 (curr FN 65)
@@ -9036,6 +9118,7 @@
 Modifying MS object, TLLI = 0xffeeddd0, MS class 0 -> 11
 Modifying MS object, TLLI = 0xffeeddd0, EGPRS MS class 0 -> 11
 MS(TLLI=0xffeeddd0, IMSI=, TA=7, 11/11,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xffeeddd0, IMSI=, TA=7, 11/11,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xffeeddd0, IMSI=, TA=7, 11/11,) ********** UL-TBF starts here **********
 MS(TLLI=0xffeeddd0, IMSI=, TA=7, 11/11,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -9064,7 +9147,6 @@
 TBF(TFI=4 TLLI=0xffeeddd0 DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_4){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_4){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xffeeddd0, IMSI=, TA=7, 11/11, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 PDCH(bts=0,trx=0,ts=7) Expiring FN=69 but previous FN=2654231 is still reserved!
 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654231, reason=UL_ASS): TBF(TFI=3 TLLI=0xffeeddcf DIR=UL STATE=ASSIGN EGPRS)
 TBF(TFI=3 TLLI=0xffeeddcf DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=2654231, TS=7 (curr FN 69)
@@ -9089,6 +9171,7 @@
 Modifying MS object, TLLI = 0xffeeddd1, MS class 0 -> 11
 Modifying MS object, TLLI = 0xffeeddd1, EGPRS MS class 0 -> 11
 MS(TLLI=0xffeeddd1, IMSI=, TA=7, 11/11,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xffeeddd1, IMSI=, TA=7, 11/11,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xffeeddd1, IMSI=, TA=7, 11/11,) ********** UL-TBF starts here **********
 MS(TLLI=0xffeeddd1, IMSI=, TA=7, 11/11,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -9117,7 +9200,6 @@
 TBF(TFI=5 TLLI=0xffeeddd1 DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_5){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_5){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xffeeddd1, IMSI=, TA=7, 11/11, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 PDCH(bts=0,trx=0,ts=7) Expiring FN=73 but previous FN=2654231 is still reserved!
 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654231, reason=UL_ASS): TBF(TFI=4 TLLI=0xffeeddd0 DIR=UL STATE=ASSIGN EGPRS)
 TBF(TFI=4 TLLI=0xffeeddd0 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=2654231, TS=7 (curr FN 73)
@@ -9142,6 +9224,7 @@
 Modifying MS object, TLLI = 0xffeeddd2, MS class 0 -> 11
 Modifying MS object, TLLI = 0xffeeddd2, EGPRS MS class 0 -> 11
 MS(TLLI=0xffeeddd2, IMSI=, TA=7, 11/11,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xffeeddd2, IMSI=, TA=7, 11/11,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xffeeddd2, IMSI=, TA=7, 11/11,) ********** UL-TBF starts here **********
 MS(TLLI=0xffeeddd2, IMSI=, TA=7, 11/11,) Allocating UL TBF
 TBF{NEW}: Allocated
@@ -9170,7 +9253,6 @@
 TBF(TFI=6 TLLI=0xffeeddd2 DIR=UL STATE=ASSIGN EGPRS) change control TS 7 -> 7 until assignment is complete.
 UL_ASS_TBF(UL-TFI_6){NONE}: Received Event SCHED_ASS
 UL_ASS_TBF(UL-TFI_6){NONE}: state_chg to SEND_ASS
-MS(TLLI=0xffeeddd2, IMSI=, TA=7, 11/11, UL) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 PDCH(bts=0,trx=0,ts=7) Expiring FN=78 but previous FN=2654231 is still reserved!
 PDCH(bts=0,trx=0,ts=7) Timeout for registered POLL (FN=2654231, reason=UL_ASS): TBF(TFI=5 TLLI=0xffeeddd1 DIR=UL STATE=ASSIGN EGPRS)
 TBF(TFI=5 TLLI=0xffeeddd1 DIR=UL STATE=ASSIGN EGPRS) poll timeout for FN=2654231, TS=7 (curr FN 78)
@@ -9195,6 +9277,7 @@
 Modifying MS object, TLLI = 0xffeeddd3, MS class 0 -> 11
 Modifying MS object, TLLI = 0xffeeddd3, EGPRS MS class 0 -> 11
 MS(TLLI=0xffeeddd3, IMSI=, TA=7, 11/11,) Enabled EGPRS, mode EGPRS
+MS(TLLI=0xffeeddd3, IMSI=, TA=7, 11/11,) Link quality 12dB (old 12dB) left window -256, 6, modifying uplink CS level: MCS-1 -> MCS-2
 MS(TLLI=0xffeeddd3, IMSI=, TA=7, 11/11,) ********** UL-TBF starts here **********
 MS(TLLI=0xffeeddd3, IMSI=, TA=7, 11/11,) Allocating UL TBF
 TBF{NEW}: Allocated