Avoid moving DL-TBF from old_msg to new_ms during ms_merge2023q1

The DL-TBF assigned to another MS object may have a totally different
set of reserved resources (TS set, TRX, etc.), so one cannot simply move
those to the new MS. To start with, if the 2 MS are on different TRX it
is clear that one of them will not be really in operation. That's most
probably the DL-TBF being in ASSIGN state on CCCH waiting for PCUIF_CNF
and later X2002 to trigger to start sending DL blocks, but without
confirmation whether the MS is really there. Since the other new MS
object probably has a UL-TBF, that's the one probably operative, and
hence a new DL-TBF can be created at that same time and assigned through
UL-TBF's PACCH.

Unit test test_ms_merge_dl_tbf_different_trx showcases the above
scenario.

Related: SYS#6231
Related: OS#5700
Related: 677bebbe5c49d4607322e96053fe14ddd78d9549
Change-Id: Ie8cb49d5492cfc4cbf8340f3f376b0e6105e8c82

4 files changed, 98 insertions, 61 deletions

diff --git a/src/gprs_ms.c b/src/gprs_ms.c
index 29d226fa..eb76fa29 100644
--- a/src/gprs_ms.c
+++ b/src/gprs_ms.c
@@ -453,15 +453,6 @@ void ms_merge_and_clear_ms(struct GprsMs *ms, struct GprsMs *old_ms)
 
 	llc_queue_move_and_merge(&ms->llc_queue, &old_ms->llc_queue);
 
-	if (!ms_dl_tbf(ms) && ms_dl_tbf(old_ms)) {
-		struct gprs_rlcmac_dl_tbf *dl_tbf = ms_dl_tbf(old_ms);
-		LOGPTBFDL(dl_tbf, LOGL_NOTICE,
-			  "Merge MS: Move DL TBF: %s => %s\n",
-			  old_ms_name, ms_name(ms));
-		/* Move the DL TBF to the new MS */
-		tbf_set_ms(dl_tbf_as_tbf(dl_tbf), ms);
-	}
-
 	/* Clean up the old MS object */
 	/* TODO: Use timer? */
 	if (ms_ul_tbf(old_ms) && !tbf_timers_pending((struct gprs_rlcmac_tbf *)ms_ul_tbf(old_ms), T_MAX))
diff --git a/src/tbf_dl_fsm.c b/src/tbf_dl_fsm.c
index 7d1f9b19..6b455dac 100644
--- a/src/tbf_dl_fsm.c
+++ b/src/tbf_dl_fsm.c
@@ -163,7 +163,19 @@ static void st_assign(struct osmo_fsm_inst *fi, uint32_t event, void *data)
 		 * listening on PDCH) in order to move to FLOW state and start
 		 * transmitting data to it. When X2002 triggers (see cb timer
 		 * end of the file) it will send  TBF_EV_ASSIGN_READY_CCCH back
-		 * to us here. */
+		 * to us here.
+		 */
+		if (!(ctx->state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH))) {
+			/* This can happen if we initiated a CCCH DlAss from an
+			 * older TBF object (same TLLI) towards BTS, and the DL-TBF
+			 * was recreated and is now trying to be assigned throguh
+			 * PACCH.
+			 */
+			LOGPTBFDL(ctx->dl_tbf, LOGL_INFO,
+				  "Ignoring event ASSIGN_PCUIF_CNF from BTS "
+				  "(CCCH was not requested on current assignment)\n");
+			break;
+		}
 		fi->T = -2002;
 		val = osmo_tdef_get(the_pcu->T_defs, fi->T, OSMO_TDEF_MS, -1);
 		sec = val / 1000;
diff --git a/tests/tbf/TbfTest.cpp b/tests/tbf/TbfTest.cpp
index 6769165f..aa3c1213 100644
--- a/tests/tbf/TbfTest.cpp
+++ b/tests/tbf/TbfTest.cpp
@@ -2449,7 +2449,9 @@ static void test_ms_merge_dl_tbf_different_trx(void)
 	gprs_bssgp_init(bts, 5234, 5234, 1, 1, false, 0, 0, 0);
 
 	/* Handle LLC frame 1. This will create the TBF we want in TRX1 and
-	 * we'll have it upgrade to multislot on TRX0 later. */
+	 * we'll have it upgrade to multislot on TRX0 later. This will trigger a
+	 * CCCH Dl ImAss towards BTS PCUIF. The confirmation from BTS is
+	 * injected further below (TBF_EV_ASSIGN_PCUIF_CNF). */
 	memset(llc_buf, 1, sizeof(llc_buf));
 	rc = dl_tbf_handle(bts, old_tlli, 0, imsi, ms_class, 0,
 			   delay_csec, llc_buf, sizeof(llc_buf));
@@ -2478,28 +2480,21 @@ static void test_ms_merge_dl_tbf_different_trx(void)
 	rc = dl_tbf_handle(bts, new_tlli, old_tlli, imsi, ms_class, 0,
 			   delay_csec, llc_buf, sizeof(llc_buf));
 	OSMO_ASSERT(rc >= 0);
-	/* Here we assert DL-TBF is currently moved to the new MS, which is wrong! */
-	OSMO_ASSERT(dl_tbf == ms_dl_tbf(second_ms));
+	/* Here we assert a new DL-TBF is created in the new MS (hence old from TRX1 is deleted and new one is in TRX0): */
+	dl_tbf = ms_dl_tbf(second_ms);
+	OSMO_ASSERT(tbf_get_trx(dl_tbf) == trx0);
+	OSMO_ASSERT(dl_tbf->control_ts != old_dl_control_ts);
+	OSMO_ASSERT(dl_tbf == llist_first_entry_or_null(&trx0->dl_tbfs, struct llist_item, list)->entry);
+	OSMO_ASSERT(NULL == llist_first_entry_or_null(&trx1->dl_tbfs, struct llist_item, list));
 
 	/* Here BTS would answer with data_cnf and trigger
 	 * bts_rcv_imm_ass_cnf(), which would trigger TBF_EV_ASSIGN_PCUIF_CNF.
-	 * That in turn would set up timer X2002. Finally, X2002 timeout
-	 * moves it to ASSIGN state for multislot upgrade. We set X2002 timeout to 0 here to get
-	 * immediate trigger through osmo_select_main() */
+	 * Since that's for an older DL-TBF assignment which no longer exists, it is ignored. */
 	OSMO_ASSERT(osmo_tdef_set(the_pcu->T_defs, -2002, 0, OSMO_TDEF_MS) == 0);
 	osmo_fsm_inst_dispatch(ms_dl_tbf(second_ms)->state_fi, TBF_EV_ASSIGN_PCUIF_CNF, NULL);
 	osmo_select_main(0);
-	OSMO_ASSERT(dl_tbf == ms_dl_tbf(second_ms));
-	OSMO_ASSERT(dl_tbf->state_is(TBF_ST_ASSIGN));
-	/* Here we validate DL-TBF was intially allocated in TRX1 but moved to TRX0 during multislot upgrade: */
-	OSMO_ASSERT(tbf_get_trx(dl_tbf) == trx0);
-	OSMO_ASSERT(old_dl_control_ts != dl_tbf->control_ts);
-
-	/* dl_tbf is still in the list of trx1 so that the PktDlAss on the old
-	 * TRX/TS can be scheduled to assign the new TRX/TS allocation: */
-	OSMO_ASSERT(dl_tbf == llist_first_entry_or_null(&trx1->dl_tbfs, struct llist_item, list)->entry);
 
-	/* get the PACCH PktDlAss for the DL-TBF: */
+	/* get the PACCH PktDlAss for the DL-TBF, allocated one the UL-TBF from the new MS obj: */
 	request_dl_rlc_block(dl_tbf->bts, dl_tbf->control_ts, &fn);
 
 	fprintf(stderr, "=== end %s ===\n", __func__);
diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err
index ead39bcc..9ad295e6 100644
--- a/tests/tbf/TbfTest.err
+++ b/tests/tbf/TbfTest.err
@@ -2319,25 +2319,49 @@ TBF(UL:TFI-0-0-1:STATE-FLOW:GPRS:TLLI-0xf5667788) No gaps in received block, las
 Old MS: TLLI = 0xf1223344, TA = 7, IMSI = 0011223344, LLC = 0
 There is a new MS object for the same MS: (0xf1223344, '0011223344') -> (0xf5667788, '')
 MS(TLLI-0xf5667788:TA-7:MSCLS-1-0:UL) Merge MS: MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:UL:DL)
-TBF(DL:TFI-0-0-0:STATE-FINISHED:GPRS:IMSI-0011223344:TLLI-0xf1223344) Merge MS: Move DL TBF: MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:UL:DL) => MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:UL)
-MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:UL) Detaching TBF: TBF(DL:TFI-0-0-0:STATE-FINISHED:GPRS:IMSI-0011223344:TLLI-0xf1223344)
-MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:UL) Attaching DL TBF: TBF(DL:TFI-0-0-0:STATE-FINISHED:GPRS:IMSI-0011223344:TLLI-0xf5667788)
 TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344) free
 PDCH(bts=0,trx=0,ts=7) Detaching TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344), 2 TBFs, USFs = 03, TFIs = 00000003.
-MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0) Detaching TBF: TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344)
+MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:DL) Detaching TBF: TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344)
 ********** UL-TBF ends here **********
 UL_ACK_TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344){NONE}: Deallocated
 UL_TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344){FLOW}: Deallocated
 UL_ASS_TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344){NONE}: Deallocated
 DL_ASS_TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344){NONE}: Deallocated
-MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0) Clearing MS object
-MS(TA-7:MSCLS-1-0) Destroying MS object
+MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:DL) Clearing MS object
 Modifying MS object, TLLI: 0xf5667788 confirmed
-MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:UL:DL) appending 4 bytes to DL LLC queue
+MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:UL) appending 4 bytes to DL LLC queue
+MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:UL) ********** DL-TBF starts here **********
+MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:UL) Allocating DL TBF
+UL_ASS_TBF{NONE}: Allocated
+DL_ASS_TBF{NONE}: Allocated
+DL_TBF{NEW}: Allocated
+[DL] algo A <multi> (suggested TRX: 0): 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
+[DL] Assign downlink TS=7 TFI=1
+PDCH(bts=0,trx=0,ts=7) Attaching TBF(DL:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788), 2 TBFs, USFs = 02, TFIs = 00000003.
+TBF(DL:TFI-0-0-1:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788) Setting Control TS PDCH(bts=0,trx=0,ts=7)
+TBF(DL:TFI-0-0-1:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788) Allocated: trx = 0, ul_slots = 80, dl_slots = 80
+MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:UL) Attaching DL TBF: TBF(DL:TFI-0-0-1:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788)
+TBF(DL:TFI-0-0-1:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788) [DOWNLINK] START (PACCH)
+TBF(DL:TFI-0-0-1:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788) Send downlink assignment on PACCH, because TBF(UL:TFI-0-0-1:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf5667788) exists
+DL_ASS_TBF(UL:TFI-0-0-1:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf5667788){NONE}: Received Event SCHED_ASS
+DL_ASS_TBF(UL:TFI-0-0-1:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf5667788){NONE}: state_chg to SEND_ASS
+DL_TBF(DL:TFI-0-0-1:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788){NEW}: Received Event ASSIGN_ADD_PACCH
+TBF(DL:TFI-0-0-1:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788) set ass. type PACCH [prev CCCH:0, PACCH:0]
+DL_TBF(DL:TFI-0-0-1:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf5667788){NEW}: state_chg to ASSIGN
+TBF(DL:TFI-0-0-1:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf5667788) Starting timer X2001 [assignment (PACCH)] with 2 sec. 0 microsec
 New MS: TLLI = 0xf5667788, TA = 7, IMSI = 0011223344, LLC = 1
 MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:UL:DL) Destroying MS object
 MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0:DL) Detaching TBF: TBF(UL:TFI-0-0-1:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf5667788)
-MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0) Detaching TBF: TBF(DL:TFI-0-0-0:STATE-FINISHED:GPRS:IMSI-0011223344:TLLI-0xf5667788)
+MS(IMSI-0011223344:TLLI-0xf5667788:TA-7:MSCLS-1-0) Detaching TBF: TBF(DL:TFI-0-0-1:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf5667788)
+MS(TA-7:MSCLS-1-0:DL) Destroying MS object
+MS(TA-7:MSCLS-1-0) Detaching TBF: TBF(DL:TFI-0-0-0:STATE-FINISHED:GPRS)
 === end test_tbf_ra_update_rach ===
 === start test_tbf_dl_flow_and_rach_two_phase ===
 PDCH(bts=0,trx=0,ts=7) PDCH state: disabled => enabled
@@ -2700,20 +2724,16 @@ TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS) Decoded premier TLLI=0xf1223344 of UL DATA TFI
 Modifying MS object, UL TLLI: 0xffffffff -> 0xf1223344, not yet confirmed
 MS(TLLI-0xf1223344:TA-7:MSCLS-0-0:UL) Merge MS: MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:DL)
 Modifying MS object, TLLI = 0xf1223344, MS class 0 -> 1
-TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf1223344) Merge MS: Move DL TBF: MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:DL) => MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:UL)
-MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0) Detaching TBF: TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf1223344)
-MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:UL) Attaching DL TBF: TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf1223344)
-MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0) Clearing MS object
-MS(TA-7:MSCLS-1-0) Destroying MS object
-UL_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS){FLOW}: Received Event FIRST_UL_DATA_RECVD
-TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf1223344) Got first UL data while DL-TBF pending, killing it
 TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf1223344) free
 PDCH(bts=0,trx=0,ts=7) Detaching TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf1223344), 1 TBFs, USFs = 01, TFIs = 00000001.
-MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0:UL) Detaching TBF: TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf1223344)
+MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0) Detaching TBF: TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-0011223344:TLLI-0xf1223344)
 ********** DL-TBF ends here **********
 DL_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf1223344){ASSIGN}: Deallocated
 UL_ASS_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf1223344){NONE}: Deallocated
 DL_ASS_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-0011223344:TLLI-0xf1223344){NONE}: Deallocated
+MS(IMSI-0011223344:TLLI-0xf1223344:TA-7:MSCLS-1-0) Clearing MS object
+MS(TA-7:MSCLS-1-0) Destroying MS object
+UL_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS){FLOW}: Received Event FIRST_UL_DATA_RECVD
 TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344) Assembling frames: (len=20)
 TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344) Frame 1 starts at offset 4, length=16, is_complete=1
 TBF(UL:TFI-0-0-0:STATE-FLOW:GPRS:IMSI-0011223344:TLLI-0xf1223344) complete UL frame len=16
@@ -9503,34 +9523,53 @@ MS(TLLI-0xecc1f953:TA-220:MSCLS-0-0) Attaching UL TBF: TBF(UL:TFI-0-0-0:STATE-NE
 There is a new MS object for the same MS: (0xa3c2f953, '001001000000001') -> (0xecc1f953, '')
 MS(TLLI-0xecc1f953:TA-220:MSCLS-0-0:UL) Merge MS: MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0:DL)
 Modifying MS object, TLLI = 0xecc1f953, MS class 0 -> 11
-TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) Merge MS: Move DL TBF: MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0:DL) => MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL)
+TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953) free
+PDCH(bts=0,trx=1,ts=5) Detaching TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953), 1 TBFs, USFs = 00, TFIs = 00000001.
 MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0) Detaching TBF: TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953)
-MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) Attaching DL TBF: TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953)
+********** DL-TBF ends here **********
+DL_TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953){ASSIGN}: Deallocated
+UL_ASS_TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953){NONE}: Deallocated
+DL_ASS_TBF(DL:TFI-0-1-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xa3c2f953){NONE}: Deallocated
 MS(IMSI-001001000000001:TLLI-0xa3c2f953:TA-220:MSCLS-11-0) Clearing MS object
 MS(TA-220:MSCLS-11-0) Destroying MS object
 Modifying MS object, TLLI: 0xecc1f953 confirmed
-MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL:DL) appending 19 bytes to DL LLC queue
-DL_TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){ASSIGN}: Received Event ASSIGN_PCUIF_CNF
-TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Starting timer X2002 [assignment (AGCH)] with 0 sec. 0 microsec
-DL_TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){ASSIGN}: Timeout of X2002
-TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Changing Control TS PDCH(bts=0,trx=1,ts=5) -> PDCH(bts=0,trx=0,ts=2)
-TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Upgrade to multislot
-PDCH(bts=0,trx=1,ts=5) Detaching TBF(DL:TFI-0-1-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 00, TFIs = 00000001.
-[DL] algo B <multi> (suggested TRX: -1): Alloc start
+MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) appending 19 bytes to DL LLC queue
+MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) ********** DL-TBF starts here **********
+MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) Allocating DL TBF
+UL_ASS_TBF{NONE}: Allocated
+DL_ASS_TBF{NONE}: Allocated
+DL_TBF{NEW}: Allocated
+[DL] algo B <multi> (suggested TRX: 0): Alloc start
 Found first unallocated TRX=0 TFI=0
 Selected DL slots: (TS=0)".DDDddd."(TS=7), multi
-[DL] algo B <multi> (suggested TRX: -1): using 3 slots
+[DL] algo B <multi> (suggested TRX: 0): using 3 slots
 - Assigning DL TS 1
-PDCH(bts=0,trx=0,ts=1) Attaching TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 00, TFIs = 00000001.
+PDCH(bts=0,trx=0,ts=1) Attaching TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 00, TFIs = 00000001.
 - Assigning DL TS 2
-PDCH(bts=0,trx=0,ts=2) Attaching TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 01, TFIs = 00000001.
+PDCH(bts=0,trx=0,ts=2) Attaching TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 01, TFIs = 00000001.
 - Assigning DL TS 3
-PDCH(bts=0,trx=0,ts=3) Attaching TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 00, TFIs = 00000001.
-TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Send downlink assignment on PACCH, because TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) exists
-DL_ASS_TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NONE}: Received Event SCHED_ASS
-DL_ASS_TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NONE}: state_chg to SEND_ASS
-DL_TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){ASSIGN}: Received Event ASSIGN_ADD_PACCH
-TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) set ass. type PACCH [prev CCCH:0, PACCH:0]
+PDCH(bts=0,trx=0,ts=3) Attaching TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953), 1 TBFs, USFs = 00, TFIs = 00000001.
+TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Setting Control TS PDCH(bts=0,trx=0,ts=2)
+TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Allocated: trx = 0, ul_slots = 04, dl_slots = 0e
+MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL) Attaching DL TBF: TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953)
+TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) [DOWNLINK] START (PACCH)
+TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Send downlink assignment on PACCH, because TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) exists
+DL_ASS_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NONE}: Received Event SCHED_ASS
+DL_ASS_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NONE}: state_chg to SEND_ASS
+DL_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NEW}: Received Event ASSIGN_ADD_PACCH
+TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) set ass. type PACCH [prev CCCH:0, PACCH:0]
+DL_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){NEW}: state_chg to ASSIGN
+TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Starting timer X2001 [assignment (PACCH)] with 2 sec. 0 microsec
+DL_TBF(DL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){ASSIGN}: Received Event ASSIGN_PCUIF_CNF
+TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Ignoring event ASSIGN_PCUIF_CNF from BTS (CCCH was not requested on current assignment)
+DL_ASS_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){SEND_ASS}: Received Event CREATE_RLCMAC_MSG
+PDCH(bts=0,trx=0,ts=2) POLL scheduled at FN 0 + 13 = 13
+TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) start Packet Downlink Assignment (PACCH) for TBF(DL:TFI-0-0-0:STATE-ASSIGN:GPRS:IMSI-001001000000001:TLLI-0xecc1f953)
++++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++
+------------------------- TX : Packet Downlink Assignment -------------------------
+TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953) Scheduled DL Assignment polling on PACCH (FN=13, TS=2)
+DL_ASS_TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953){SEND_ASS}: state_chg to WAIT_ACK
+PDCH(bts=0,trx=0,ts=2) FN=0 Scheduling control message at RTS for TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953)
 === end test_ms_merge_dl_tbf_different_trx ===
 MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:UL:DL) Destroying MS object
 MS(IMSI-001001000000001:TLLI-0xecc1f953:TA-220:MSCLS-11-0:DL) Detaching TBF: TBF(UL:TFI-0-0-0:STATE-NEW:GPRS:IMSI-001001000000001:TLLI-0xecc1f953)