tests: TbfTest: Unify stderr and stdout to ease debugging

osmo-pcu code is really verbose, and since log lines printing start and
end of tests are sent to a different file, it's really difficult to
understand which test outputs what.

Change-Id: I3e887158e2c9585c360d44f12f995f55861170f2

5 files changed, 153 insertions, 154 deletions

diff --git a/tests/Makefile.am b/tests/Makefile.am
index 42dade91..c5996360 100644
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -138,7 +138,7 @@ EXTRA_DIST = \
 	testsuite.at $(srcdir)/package.m4 $(TESTSUITE)	\
 	rlcmac/RLCMACTest.ok rlcmac/RLCMACTest.err \
 	alloc/AllocTest.ok alloc/AllocTest.err \
-	tbf/TbfTest.ok tbf/TbfTest.err \
+	tbf/TbfTest.err \
 	bitcomp/BitcompTest.ok bitcomp/BitcompTest.err \
 	types/TypesTest.ok types/TypesTest.err \
 	ms/MsTest.ok ms/MsTest.err alloc/MslotTest.ok \
diff --git a/tests/tbf/TbfTest.cpp b/tests/tbf/TbfTest.cpp
index 8d1b3448..5bf94b51 100644
--- a/tests/tbf/TbfTest.cpp
+++ b/tests/tbf/TbfTest.cpp
@@ -61,12 +61,12 @@ static void check_tbf(gprs_rlcmac_tbf *tbf)
 static void test_tbf_base()
 {
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	OSMO_ASSERT(GPRS_RLCMAC_DL_TBF == reverse(GPRS_RLCMAC_UL_TBF));
 	OSMO_ASSERT(GPRS_RLCMAC_UL_TBF == reverse(GPRS_RLCMAC_DL_TBF));
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_tlli_update()
@@ -74,7 +74,7 @@ static void test_tbf_tlli_update()
 	BTS the_bts;
 	GprsMs *ms, *ms_new;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	the_bts.bts_data()->alloc_algorithm = alloc_algorithm_a;
 	the_bts.bts_data()->trx[0].pdch[2].enable();
@@ -134,7 +134,7 @@ static void test_tbf_tlli_update()
 	OSMO_ASSERT(ul_tbf->ta() == 6);
 	OSMO_ASSERT(dl_tbf->ta() == 6);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static uint8_t llc_data[200];
@@ -241,7 +241,7 @@ static void test_tbf_final_ack(enum test_tbf_final_ack_mode test_mode)
 
 	uint8_t rbb[64/8];
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	gprs_rlcmac_dl_tbf *dl_tbf;
 	gprs_rlcmac_tbf *new_tbf;
@@ -297,7 +297,7 @@ static void test_tbf_final_ack(enum test_tbf_final_ack_mode test_mode)
 		OSMO_ASSERT(ms->dl_tbf() == NULL);
 	}
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 /* Receive an ACK */
@@ -322,7 +322,7 @@ static void test_tbf_delayed_release()
 
 	gprs_rlcmac_dl_tbf *dl_tbf;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bts = the_bts.bts_data();
 
@@ -373,7 +373,7 @@ static void test_tbf_delayed_release()
 	TBF_SET_ASS_STATE_DL(dl_tbf, GPRS_RLCMAC_DL_ASS_NONE);
 	check_tbf(dl_tbf);
 	tbf_free(dl_tbf);
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_imsi()
@@ -386,7 +386,7 @@ static void test_tbf_imsi()
 
 	gprs_rlcmac_dl_tbf *dl_tbf[2];
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no);
 
@@ -431,7 +431,7 @@ static void test_tbf_imsi()
 	ms1 = the_bts.ms_store().get_ms(0, 0, "001001000000002");
 	OSMO_ASSERT(ms1 == NULL);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_exhaustion()
@@ -445,7 +445,7 @@ static void test_tbf_exhaustion()
 
 	uint8_t buf[256] = {0};
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bssgp_nsi = gprs_ns_instantiate(&gprs_bssgp_ns_cb, tall_pcu_ctx);
 	if (!bssgp_nsi) {
@@ -472,7 +472,7 @@ static void test_tbf_exhaustion()
 	}
 
 	OSMO_ASSERT(rc == -EBUSY);
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 
 	gprs_bssgp_destroy();
 }
@@ -497,7 +497,7 @@ static void test_tbf_dl_llc_loss()
 		abort();
 	}
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bts = the_bts.bts_data();
 	setup_bts(&the_bts, ts_no);
@@ -550,13 +550,13 @@ static void test_tbf_dl_llc_loss()
 		msg = ms->dl_tbf()->create_dl_acked_block(fn += 4, 7);
 		fprintf(stderr, "MSG = %s\n", msgb_hexdump(msg));
 		if (!msgb_eq_data_print(msg, exp[expected_data - 1], GSM_MACBLOCK_LEN))
-			printf("%s failed at %u\n", __func__, expected_data);
+			fprintf(stderr, "%s failed at %u\n", __func__, expected_data);
 
 		expected_data += 1;
 	}
 	OSMO_ASSERT(expected_data-1 == 3);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 
 	gprs_bssgp_destroy();
 }
@@ -756,7 +756,7 @@ static gprs_rlcmac_ul_tbf *puan_urbb_len_issue(BTS *the_bts,
 	};
 
 	if (!msgb_eq_data_print(msg1, exp1, GSM_MACBLOCK_LEN)) {
-		printf("%s test failed on 1st segment!\n", __func__);
+		fprintf(stderr, "%s test failed on 1st segment!\n", __func__);
 		return NULL;
 	}
 
@@ -783,7 +783,7 @@ static gprs_rlcmac_ul_tbf *puan_urbb_len_issue(BTS *the_bts,
 	};
 
 	if (!msgb_eq_data_print(msg1, exp2, GSM_MACBLOCK_LEN)) {
-		printf("%s test failed on 2nd segment!\n", __func__);
+		fprintf(stderr, "%s test failed on 2nd segment!\n", __func__);
 		return NULL;
 	}
 	return ul_tbf;
@@ -1712,7 +1712,7 @@ static void test_tbf_single_phase()
 	uint16_t qta = 31;
 	gprs_rlcmac_ul_tbf *ul_tbf;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no);
 
@@ -1721,7 +1721,7 @@ static void test_tbf_single_phase()
 	print_ta_tlli(ul_tbf, true);
 	send_dl_data(&the_bts, tlli, imsi, (const uint8_t *)"TEST", 4);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_egprs_two_phase_puan(void)
@@ -1738,7 +1738,7 @@ static void test_tbf_egprs_two_phase_puan(void)
 	gprs_rlcmac_ul_tbf *ul_tbf;
 	uint8_t test_data[256];
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	memset(test_data, 1, sizeof(test_data));
 
@@ -1775,7 +1775,7 @@ static void test_tbf_egprs_two_phase_puan(void)
 	print_ta_tlli(ul_tbf, true);
 	send_dl_data(&the_bts, tlli, imsi, test_data, sizeof(test_data));
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 /*
  * Trigger rach for single block
@@ -1787,7 +1787,7 @@ static void test_immediate_assign_rej_single_block()
 	uint16_t qta = 31;
 	int ts_no = 7;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 4);
 
@@ -1806,7 +1806,7 @@ static void test_immediate_assign_rej_single_block()
 
 	OSMO_ASSERT(rc == -EINVAL);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 /*
@@ -1819,7 +1819,7 @@ static void test_immediate_assign_rej_multi_block()
 	uint16_t qta = 31;
 	int ts_no = 7;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 4);
 
@@ -1850,7 +1850,7 @@ static void test_immediate_assign_rej_multi_block()
 
 	OSMO_ASSERT(rc == -EBUSY);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_immediate_assign_rej()
@@ -1870,7 +1870,7 @@ static void test_tbf_two_phase()
 	uint8_t ms_class = 1;
 	gprs_rlcmac_ul_tbf *ul_tbf;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 4);
 
@@ -1880,7 +1880,7 @@ static void test_tbf_two_phase()
 	print_ta_tlli(ul_tbf, true);
 	send_dl_data(&the_bts, tlli, imsi, (const uint8_t *)"TEST", 4);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static inline void print_ms(const GprsMs *ms, bool old)
@@ -1902,7 +1902,7 @@ static void test_tbf_ra_update_rach()
 	gprs_rlcmac_ul_tbf *ul_tbf;
 	GprsMs *ms, *ms1, *ms2;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 4);
 
@@ -1950,7 +1950,7 @@ static void test_tbf_ra_update_rach()
 	ms = the_bts.ms_by_tlli(tlli2);
 	OSMO_ASSERT(ms == ms2);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_dl_flow_and_rach_two_phase()
@@ -1966,7 +1966,7 @@ static void test_tbf_dl_flow_and_rach_two_phase()
 	gprs_rlcmac_dl_tbf *dl_tbf;
 	GprsMs *ms, *ms1, *ms2;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 1);
 
@@ -2008,7 +2008,7 @@ static void test_tbf_dl_flow_and_rach_two_phase()
 	/* No queued packets should be lost */
 	OSMO_ASSERT(ms->llc_queue()->size() == 2);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 
@@ -2025,7 +2025,7 @@ static void test_tbf_dl_flow_and_rach_single_phase()
 	gprs_rlcmac_dl_tbf *dl_tbf;
 	GprsMs *ms, *ms1, *ms2;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 1);
 
@@ -2067,7 +2067,7 @@ static void test_tbf_dl_flow_and_rach_single_phase()
 	/* No queued packets should be lost */
 	OSMO_ASSERT(ms->llc_queue()->size() == 2);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_dl_reuse()
@@ -2085,7 +2085,7 @@ static void test_tbf_dl_reuse()
 	unsigned i;
 	RlcMacUplink_t ulreq = {0};
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 1);
 
@@ -2165,7 +2165,7 @@ static void test_tbf_dl_reuse()
 	OSMO_ASSERT(ms2->dl_tbf());
 	OSMO_ASSERT(ms2->dl_tbf()->state_is(GPRS_RLCMAC_FINISHED));
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_gprs_egprs()
@@ -2181,7 +2181,7 @@ static void test_tbf_gprs_egprs()
 
 	uint8_t buf[256] = {0};
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bssgp_nsi = gprs_ns_instantiate(&gprs_bssgp_ns_cb, tall_pcu_ctx);
 	if (!bssgp_nsi) {
@@ -2202,7 +2202,7 @@ static void test_tbf_gprs_egprs()
 		delay_csec, buf, sizeof(buf));
 
 	OSMO_ASSERT(rc == -EBUSY);
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 
 	gprs_bssgp_destroy();
 }
@@ -2230,7 +2230,7 @@ static inline void ws_check(gprs_rlcmac_dl_tbf *dl_tbf, const char *test, uint8_
 		tbf_free(dl_tbf);
 
 	if (end) {
-		printf("=== end %s ===\n", test);
+		fprintf(stderr, "=== end %s ===\n", test);
 		gprs_bssgp_destroy();
 	}
 }
@@ -2243,7 +2243,7 @@ static void test_tbf_ws()
 	uint8_t ms_class = 12;
 	gprs_rlcmac_dl_tbf *dl_tbf;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bssgp_nsi = gprs_ns_instantiate(&gprs_bssgp_ns_cb, tall_pcu_ctx);
 	if (!bssgp_nsi) {
@@ -2286,7 +2286,7 @@ static void test_tbf_update_ws(void)
 	uint8_t ms_class = 11;
 	gprs_rlcmac_dl_tbf *dl_tbf;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bssgp_nsi = gprs_ns_instantiate(&gprs_bssgp_ns_cb, tall_pcu_ctx);
 	if (!bssgp_nsi) {
@@ -2334,7 +2334,7 @@ static void test_tbf_puan_urbb_len(void)
 	gprs_rlcmac_ul_tbf *ul_tbf;
 	uint8_t test_data[256];
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	memset(test_data, 1, sizeof(test_data));
 
@@ -2348,7 +2348,7 @@ static void test_tbf_puan_urbb_len(void)
 	print_ta_tlli(ul_tbf, true);
 	send_dl_data(&the_bts, tlli, imsi, test_data, sizeof(test_data));
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static gprs_rlcmac_ul_tbf *tbf_li_decoding(BTS *the_bts,
@@ -2479,7 +2479,7 @@ static void test_tbf_li_decoding(void)
 	gprs_rlcmac_ul_tbf *ul_tbf;
 	uint8_t test_data[256];
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	memset(test_data, 1, sizeof(test_data));
 
@@ -2493,7 +2493,7 @@ static void test_tbf_li_decoding(void)
 	print_ta_tlli(ul_tbf, true);
 	send_dl_data(&the_bts, tlli, imsi, test_data, sizeof(test_data));
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 /*
@@ -2522,7 +2522,7 @@ static void test_tbf_epdan_out_of_rx_window(void)
 
 	memset(&ul_control_block, 0, sizeof(RlcMacUplink_t));
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bts = the_bts.bts_data();
 
@@ -2589,7 +2589,7 @@ static void test_tbf_epdan_out_of_rx_window(void)
 
 	bitvec_free(block);
 	tbf_free(dl_tbf);
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_egprs_two_phase_spb(void)
@@ -2605,7 +2605,7 @@ static void test_tbf_egprs_two_phase_spb(void)
 	gprs_rlcmac_ul_tbf *ul_tbf;
 	uint8_t test_data[256];
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	memset(test_data, 1, sizeof(test_data));
 
@@ -2619,7 +2619,7 @@ static void test_tbf_egprs_two_phase_spb(void)
 	print_ta_tlli(ul_tbf, true);
 	send_dl_data(&the_bts, tlli, imsi, test_data, sizeof(test_data));
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_egprs_two_phase()
@@ -2635,7 +2635,7 @@ static void test_tbf_egprs_two_phase()
 	gprs_rlcmac_ul_tbf *ul_tbf;
 	uint8_t test_data[256];
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	memset(test_data, 1, sizeof(test_data));
 
@@ -2649,7 +2649,7 @@ static void test_tbf_egprs_two_phase()
 	print_ta_tlli(ul_tbf, true);
 	send_dl_data(&the_bts, tlli, imsi, test_data, sizeof(test_data));
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void establish_and_use_egprs_dl_tbf(BTS *the_bts, int mcs)
@@ -2666,7 +2666,7 @@ static void establish_and_use_egprs_dl_tbf(BTS *the_bts, int mcs)
 
 	gprs_rlcmac_dl_tbf *dl_tbf;
 
-	printf("Testing MCS-%d\n", mcs);
+	fprintf(stderr, "Testing MCS-%d\n", mcs);
 
 	memset(test_data, 1, sizeof(test_data));
 	the_bts->bts_data()->initial_mcs_dl = mcs;
@@ -2794,7 +2794,7 @@ static void egprs_spb_to_normal_validation(BTS *the_bts,
 	struct gprs_rlc_dl_header_egprs_3 *egprs3;
 	struct gprs_rlc_dl_header_egprs_2 *egprs2;
 
-	printf("Testing retx for MCS %u to reseg_mcs %u\n", mcs, demanded_mcs);
+	fprintf(stderr, "Testing retx for MCS %u to reseg_mcs %u\n", mcs, demanded_mcs);
 
 	dl_tbf = tbf_init(the_bts, mcs);
 
@@ -2874,7 +2874,7 @@ static void establish_and_use_egprs_dl_tbf_for_spb(BTS *the_bts,
 	struct msgb *msg;
 	struct gprs_rlc_dl_header_egprs_3 *egprs3;
 
-	printf("Testing retx for MCS %u to reseg_mcs %u\n", mcs, demanded_mcs);
+	fprintf(stderr, "Testing retx for MCS %u to reseg_mcs %u\n", mcs, demanded_mcs);
 
 	dl_tbf = tbf_init(the_bts, mcs);
 
@@ -2962,7 +2962,7 @@ static void establish_and_use_egprs_dl_tbf_for_retx(BTS *the_bts,
 	gprs_rlcmac_dl_tbf *dl_tbf;
 	struct msgb *msg;
 
-	printf("Testing retx for MCS %u - %u\n", mcs, demanded_mcs);
+	fprintf(stderr, "Testing retx for MCS %u - %u\n", mcs, demanded_mcs);
 
 	dl_tbf = tbf_init(the_bts, mcs);
 
@@ -3057,7 +3057,7 @@ static void test_tbf_egprs_retx_dl(void)
 	gprs_rlcmac_bts *bts;
 	uint8_t ts_no = 4;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bts = the_bts.bts_data();
 	bts->cs_downgrade_threshold = 0;
@@ -3077,7 +3077,7 @@ static void test_tbf_egprs_retx_dl(void)
 	establish_and_use_egprs_dl_tbf_for_retx(&the_bts, 7, 5);
 	establish_and_use_egprs_dl_tbf_for_retx(&the_bts, 9, 6);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_egprs_spb_dl(void)
@@ -3086,7 +3086,7 @@ static void test_tbf_egprs_spb_dl(void)
 	gprs_rlcmac_bts *bts;
 	uint8_t ts_no = 4;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bts = the_bts.bts_data();
 	bts->cs_downgrade_threshold = 0;
@@ -3108,7 +3108,7 @@ static void test_tbf_egprs_spb_dl(void)
 	/* check MCS6->(MCS3+MCS3)->MCS6 case */
 	egprs_spb_to_normal_validation(&the_bts, 6, 3);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_tbf_egprs_dl()
@@ -3118,7 +3118,7 @@ static void test_tbf_egprs_dl()
 	uint8_t ts_no = 4;
 	int i;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	bts = the_bts.bts_data();
 
@@ -3131,7 +3131,7 @@ static void test_tbf_egprs_dl()
 	for (i = 1; i <= 9; i++)
 		establish_and_use_egprs_dl_tbf(&the_bts, i);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 
@@ -3145,7 +3145,7 @@ static void test_packet_access_rej_prr_no_other_tbfs()
 	uint32_t tlli = 0xffeeddcc;
 	struct gprs_rlcmac_ul_tbf *ul_tbf = NULL;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 4);
 
@@ -3166,7 +3166,7 @@ static void test_packet_access_rej_prr_no_other_tbfs()
 
 	ul_tbf->handle_timeout();
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 static void test_packet_access_rej_prr()
@@ -3186,7 +3186,7 @@ static void test_packet_access_rej_prr()
 	MS_Radio_Access_capability_t *pmsradiocap = NULL;
 	Multislot_capability_t *pmultislotcap = NULL;
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 
 	setup_bts(&the_bts, ts_no, 4);
 
@@ -3241,7 +3241,7 @@ static void test_packet_access_rej_prr()
 
 	OSMO_ASSERT(rc == 0);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 }
 
 void test_packet_access_rej_epdan()
@@ -3253,7 +3253,7 @@ void test_packet_access_rej_epdan()
 				 0x2b, 0x2b, 0x2b, 0x2b, 0x2b, 0x2b, 0x2b
 	};
 
-	printf("=== start %s ===\n", __func__);
+	fprintf(stderr, "=== start %s ===\n", __func__);
 	setup_bts(&the_bts, 4);
 	static gprs_rlcmac_dl_tbf *dl_tbf = tbf_init(&the_bts, 1);
 
@@ -3261,13 +3261,13 @@ void test_packet_access_rej_epdan()
 
 	struct msgb *msg = dl_tbf->create_packet_access_reject();
 
-	printf("packet reject: %s\n",
+	fprintf(stderr, "packet reject: %s\n",
 			osmo_hexdump(msg->data, 23));
 
 	if (!msgb_eq_data_print(msg, exp, GSM_MACBLOCK_LEN))
-		printf("%s test failed!\n", __func__);
+		fprintf(stderr, "%s test failed!\n", __func__);
 
-	printf("=== end %s ===\n", __func__);
+	fprintf(stderr, "=== end %s ===\n", __func__);
 
 }
 
diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err
index 0bc1c428..7dd14f4f 100644
--- a/tests/tbf/TbfTest.err
+++ b/tests/tbf/TbfTest.err
@@ -1,3 +1,6 @@
+=== start test_tbf_base ===
+=== end test_tbf_base ===
+=== start test_tbf_tlli_update ===
 ********** DL-TBF starts here **********
 Allocating DL TBF: MS_CLASS=0/0
 Creating MS object, TLLI = 0x00000000
@@ -35,6 +38,8 @@ Modifying MS object, TLLI: 0x00000000 -> 0x00002342, already confirmed partly
 The MS object cannot fully confirm an unexpected TLLI: 0x00004232, partly confirmed
 Modifying MS object, TLLI: 0x00002342 -> 0x00004232, already confirmed partly
 Modifying MS object, TLLI = 0x00004232, TA 4 -> 6
+=== end test_tbf_tlli_update ===
+=== start test_tbf_final_ack ===
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -123,6 +128,8 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=RELEASING),
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=1 TLLI=0xffeeddcc DIR=DL STATE=RELEASING)
 ********** DL-TBF ends here **********
 Destroying MS object, TLLI = 0xffeeddcc
+=== end test_tbf_final_ack ===
+=== start test_tbf_final_ack ===
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -211,6 +218,8 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING),
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING)
 ********** DL-TBF ends here **********
 Destroying MS object, TLLI = 0xffeeddcc
+=== end test_tbf_final_ack ===
+=== start test_tbf_delayed_release ===
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -464,6 +473,8 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING),
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+=== end test_tbf_delayed_release ===
+=== start test_tbf_imsi ===
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -529,6 +540,8 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=1 TLLI=0xf1000002 DIR=DL STATE=RELEASING),
 Detaching TBF from MS object, TLLI = 0xf1000002, TBF = TBF(TFI=1 TLLI=0xf1000002 DIR=DL STATE=RELEASING)
 Destroying MS object, TLLI = 0xf1000002
 ********** DL-TBF ends here **********
+=== end test_tbf_imsi ===
+=== start test_tbf_exhaustion ===
 ********** DL-TBF starts here **********
 Allocating DL TBF: MS_CLASS=45/0
 Creating MS object, TLLI = 0x00000000
@@ -1336,7 +1349,9 @@ Modifying MS object, TLLI = 0x00000000, MS class 0 -> 45
 [DL] Slot Allocation (Algorithm A) for class 45
 [DL] algo A <single> (suggested TRX: -1): failed to find a usable TRX (TFI exhausted)
 No PDCH resource
+=== end test_tbf_exhaustion ===
 Destroying MS object, TLLI = 0x00000000
+=== start test_tbf_dl_llc_loss ===
 ********** DL-TBF starts here **********
 Allocating DL TBF: MS_CLASS=45/0
 Creating MS object, TLLI = 0x00000000
@@ -1424,6 +1439,8 @@ TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=FINISHED) Scheduling Ack/Nack polling, be
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=FINISHED) Polling cannot be scheduled in this TS 7 (first control TS 4)
 TBF(TFI=0 TLLI=0xc0123456 DIR=DL STATE=FINISHED) msg block (BSN 2, CS-1): 07 01 04 4d 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 
 MSG = 07 01 04 4d 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 03 
+=== end test_tbf_dl_llc_loss ===
+=== start test_tbf_single_phase ===
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 MS requests UL TBF on RACH, so we provide one: ra=0x03 Fn=2654167 qta=31 is_11bit=0:
@@ -1496,6 +1513,8 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NULL) changes state from NULL to ASSIGN
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) TX: START Immediate Assignment Downlink (PCH)
  - TRX=0 (0) TS=7 TA=7 pollFN=-1
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) appending 4 bytes
+=== end test_tbf_single_phase ===
+=== start test_tbf_two_phase ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -1578,6 +1597,8 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NULL) changes state from NULL to ASSIGN
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) set ass. type PACCH [prev CCCH:0, PACCH:0]
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) appending 4 bytes
+=== end test_tbf_two_phase ===
+=== start test_tbf_ra_update_rach ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -1777,6 +1798,8 @@ Clearing MS object, TLLI: 0xf1223344, IMSI: '0011223344'
 TBF(TFI=0 TLLI=0xf5667788 DIR=DL STATE=FINISHED) appending 4 bytes
 Modifying MS object, TLLI: 0xf5667788 confirmed
 New MS: TLLI = 0xf5667788, TA = 7, IMSI = 0011223344, LLC = 1
+=== end test_tbf_ra_update_rach ===
+=== start test_tbf_dl_flow_and_rach_two_phase ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -1948,6 +1971,8 @@ 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 0, length=20, is_complete=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) No gaps in received block, last block: BSN=0 CV=15
 New MS: TLLI = 0xf1223344, TA = 7, IMSI = 0011223344, LLC = 2
+=== end test_tbf_dl_flow_and_rach_two_phase ===
+=== start test_tbf_dl_flow_and_rach_single_phase ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -2097,6 +2122,8 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) Scheduling Ack/Nack, because TL
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) Scheduling Ack/Nack, because last block has CV==0.
 TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FINISHED) changes UL ACK state from GPRS_RLCMAC_UL_ACK_NONE to GPRS_RLCMAC_UL_ACK_SEND_ACK
 New MS: TLLI = 0xf1223344, TA = 7, IMSI = 0011223344, LLC = 2
+=== end test_tbf_dl_flow_and_rach_single_phase ===
+=== start test_tbf_dl_reuse ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -3031,8 +3058,12 @@ TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Scheduled DL Acknowledgement po
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) starting timer T3191 [final block (DL-TBF)] with 5 sec. 0 microsec, cur_fn=0
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Scheduled Ack/Nack polling on FN=2654461, TS=7
 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) msg block (BSN 10, CS-1): 0f 03 14 4d 43 20 50 41 43 4b 45 54 20 30 39 20 28 54 42 46 20 32 29 
+=== end test_tbf_dl_reuse ===
+=== start test_tbf_gprs_egprs ===
 Not accepting non-EGPRS phone in EGPRS-only mode
 No PDCH resource
+=== end test_tbf_gprs_egprs ===
+=== start test_tbf_ws ===
 ********** DL-TBF starts here **********
 Allocating DL TBF: MS_CLASS=12/0
 Creating MS object, TLLI = 0x00000000
@@ -3111,6 +3142,8 @@ PDCH(TS 5, TRX 0): Detaching TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0x00000000, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0x00000000
 ********** DL-TBF ends here **********
+=== end test_tbf_ws ===
+=== start test_tbf_egprs_two_phase ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -3201,6 +3234,8 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NULL EGPRS) changes state from NULL to AS
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) appending 256 bytes
+=== end test_tbf_egprs_two_phase ===
+=== start test_tbf_egprs_two_phase_spb ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -3421,6 +3456,9 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NULL EGPRS) changes state from NULL to AS
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) appending 256 bytes
+=== end test_tbf_egprs_two_phase_spb ===
+=== start test_tbf_egprs_dl ===
+Testing MCS-1
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -3727,6 +3765,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing MCS-2
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -3983,6 +4022,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing MCS-3
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -4201,6 +4241,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing MCS-4
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -4387,6 +4428,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing MCS-5
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -4553,6 +4595,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing MCS-6
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -4701,6 +4744,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing MCS-7
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -4844,6 +4888,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing MCS-8
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -4976,6 +5021,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing MCS-9
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5108,6 +5154,9 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+=== end test_tbf_egprs_dl ===
+=== start test_tbf_egprs_retx_dl ===
+Testing retx for MCS 6 - 6
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5163,6 +5212,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 1 - 9
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5218,6 +5268,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 2 - 8
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5273,6 +5324,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 5 - 7
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5344,6 +5396,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 6 - 9
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5415,6 +5468,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 7 - 5
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5486,6 +5540,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 9 - 6
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5557,6 +5612,9 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+=== end test_tbf_egprs_retx_dl ===
+=== start test_tbf_egprs_spb_dl ===
+Testing retx for MCS 6 to reseg_mcs 3
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5619,6 +5677,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 5 to reseg_mcs 2
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5681,6 +5740,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 4 to reseg_mcs 1
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5743,6 +5803,7 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+Testing retx for MCS 6 to reseg_mcs 3
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -5812,6 +5873,8 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+=== end test_tbf_egprs_spb_dl ===
+=== start test_tbf_puan_urbb_len ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -5921,6 +5984,8 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NULL EGPRS) changes state from NULL to AS
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) appending 256 bytes
+=== end test_tbf_puan_urbb_len ===
+=== start test_tbf_update_ws ===
 ********** DL-TBF starts here **********
 Allocating DL TBF: MS_CLASS=11/11
 Creating MS object, TLLI = 0x00000000
@@ -5973,6 +6038,8 @@ PDCH(TS 5, TRX 0): Detaching TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0x00000000, TBF = TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0x00000000
 ********** DL-TBF ends here **********
+=== end test_tbf_update_ws ===
+=== start test_tbf_li_decoding ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -6076,6 +6143,8 @@ TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=NULL EGPRS) changes state from NULL to AS
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) set ass. type PACCH [prev CCCH:0, PACCH:0]
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) starting timer T0 [assignment (PACCH)] with 2 sec. 0 microsec, cur_fn=0
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) appending 256 bytes
+=== end test_tbf_li_decoding ===
+=== start test_tbf_epdan_out_of_rx_window ===
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -6115,6 +6184,8 @@ PDCH(TS 4, TRX 0): Detaching TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EG
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=RELEASING EGPRS)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** DL-TBF ends here **********
+=== end test_tbf_epdan_out_of_rx_window ===
+=== start test_immediate_assign_rej_multi_block ===
 MS requests UL TBF on RACH, so we provide one: ra=0x78 Fn=2654167 qta=31 is_11bit=0:
 ********** UL-TBF starts here **********
 Allocating UL TBF: MS_CLASS=0/0
@@ -6305,11 +6376,15 @@ Creating MS object, TLLI = 0x00000000
 - Skipping TS 7, because no USF available
 [UL] algo A <single> (suggested TRX: -1): failed to allocate a TS, no USF available
 No PDCH resource sending Immediate Assignment Uplink (AGCH) reject
+=== end test_immediate_assign_rej_multi_block ===
 Destroying MS object, TLLI = 0x00000000
+=== start test_immediate_assign_rej_single_block ===
 MS requests UL TBF on RACH, so we provide one: ra=0x70 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 No PDCH available.
 No PDCH resource for single block allocation.sending Immediate Assignment Uplink (AGCH) reject
+=== end test_immediate_assign_rej_single_block ===
+=== start test_tbf_egprs_two_phase_puan ===
 MS requests UL TBF on RACH, so we provide one: ra=0x73 Fn=2654167 qta=31 is_11bit=0:
 MS requests single block allocation
 RX: [PCU <- BTS] RACH  qbit-ta=31 ra=0x73, Fn=2654167 (17,25,9), SBFn=2654270
@@ -7711,6 +7786,8 @@ Received RTS for PDCH: TRX=0 TS=7 FN=2654283 block_nr=11 scheduling USF=0 for re
 Got 'TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW EGPRS)', TA=7
 Got MS: TLLI = 0xf1223344, TA = 7
 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN EGPRS) appending 256 bytes
+=== end test_tbf_egprs_two_phase_puan ===
+=== start test_packet_access_rej_epdan ===
 Searching for first unallocated TFI: TRX=0
  Found TFI=0.
 ********** DL-TBF starts here **********
@@ -7736,6 +7813,9 @@ TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) changes DL ASS state from GPRS_RLCM
 TBF(TFI=0 TLLI=0x00000000 DIR=DL STATE=NULL) changes state from NULL to FLOW
 The MS object cannot fully confirm an unexpected TLLI: 0xffeeddcc, partly confirmed
 TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) appending 100 bytes
+packet reject: 40 84 7f f7 6e e6 41 4b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
+=== end test_packet_access_rej_epdan ===
+=== start test_packet_access_rej_prr ===
 MS requests UL TBF on RACH, so we provide one: ra=0x78 Fn=2654167 qta=31 is_11bit=0:
 ********** UL-TBF starts here **********
 Allocating UL TBF: MS_CLASS=0/0
@@ -7940,7 +8020,9 @@ TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN) changes UL ASS state from GPRS_RL
 Received RTS for PDCH: TRX=0 TS=7 FN=2654218 block_nr=8 scheduling USF=0 for required uplink resource of UL TFI=0
 TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN) starting timer T0 [reject (PACCH)] with 0 sec. 2000 microsec, cur_fn=0
 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN) (TRX=0, TS=7)
+=== end test_packet_access_rej_prr ===
 Destroying MS object, TLLI = 0x00000000
+=== start test_packet_access_rej_prr_no_other_tbfs ===
 Creating MS object, TLLI = 0x00000000
 Modifying MS object, UL TLLI: 0x00000000 -> 0xffeeddcc, not yet confirmed
 TBF(TFI=0 TLLI=0x00000000 DIR=UL STATE=NULL) changes state from NULL to ASSIGN
@@ -7955,3 +8037,4 @@ TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN) stopping timer T0 [freeing TBF]
 Detaching TBF from MS object, TLLI = 0xffeeddcc, TBF = TBF(TFI=0 TLLI=0xffeeddcc DIR=UL STATE=ASSIGN)
 Destroying MS object, TLLI = 0xffeeddcc
 ********** UL-TBF ends here **********
+=== end test_packet_access_rej_prr_no_other_tbfs ===
diff --git a/tests/tbf/TbfTest.ok b/tests/tbf/TbfTest.ok
deleted file mode 100644
index 077ec4ee..00000000
--- a/tests/tbf/TbfTest.ok
+++ /dev/null
@@ -1,83 +0,0 @@
-=== start test_tbf_base ===
-=== end test_tbf_base ===
-=== start test_tbf_tlli_update ===
-=== end test_tbf_tlli_update ===
-=== start test_tbf_final_ack ===
-=== end test_tbf_final_ack ===
-=== start test_tbf_final_ack ===
-=== end test_tbf_final_ack ===
-=== start test_tbf_delayed_release ===
-=== end test_tbf_delayed_release ===
-=== start test_tbf_imsi ===
-=== end test_tbf_imsi ===
-=== start test_tbf_exhaustion ===
-=== end test_tbf_exhaustion ===
-=== start test_tbf_dl_llc_loss ===
-=== end test_tbf_dl_llc_loss ===
-=== start test_tbf_single_phase ===
-=== end test_tbf_single_phase ===
-=== start test_tbf_two_phase ===
-=== end test_tbf_two_phase ===
-=== start test_tbf_ra_update_rach ===
-=== end test_tbf_ra_update_rach ===
-=== start test_tbf_dl_flow_and_rach_two_phase ===
-=== end test_tbf_dl_flow_and_rach_two_phase ===
-=== start test_tbf_dl_flow_and_rach_single_phase ===
-=== end test_tbf_dl_flow_and_rach_single_phase ===
-=== start test_tbf_dl_reuse ===
-=== end test_tbf_dl_reuse ===
-=== start test_tbf_gprs_egprs ===
-=== end test_tbf_gprs_egprs ===
-=== start test_tbf_ws ===
-=== end test_tbf_ws ===
-=== start test_tbf_egprs_two_phase ===
-=== end test_tbf_egprs_two_phase ===
-=== start test_tbf_egprs_two_phase_spb ===
-=== end test_tbf_egprs_two_phase_spb ===
-=== start test_tbf_egprs_dl ===
-Testing MCS-1
-Testing MCS-2
-Testing MCS-3
-Testing MCS-4
-Testing MCS-5
-Testing MCS-6
-Testing MCS-7
-Testing MCS-8
-Testing MCS-9
-=== end test_tbf_egprs_dl ===
-=== start test_tbf_egprs_retx_dl ===
-Testing retx for MCS 6 - 6
-Testing retx for MCS 1 - 9
-Testing retx for MCS 2 - 8
-Testing retx for MCS 5 - 7
-Testing retx for MCS 6 - 9
-Testing retx for MCS 7 - 5
-Testing retx for MCS 9 - 6
-=== end test_tbf_egprs_retx_dl ===
-=== start test_tbf_egprs_spb_dl ===
-Testing retx for MCS 6 to reseg_mcs 3
-Testing retx for MCS 5 to reseg_mcs 2
-Testing retx for MCS 4 to reseg_mcs 1
-Testing retx for MCS 6 to reseg_mcs 3
-=== end test_tbf_egprs_spb_dl ===
-=== start test_tbf_puan_urbb_len ===
-=== end test_tbf_puan_urbb_len ===
-=== start test_tbf_update_ws ===
-=== end test_tbf_update_ws ===
-=== start test_tbf_li_decoding ===
-=== end test_tbf_li_decoding ===
-=== start test_tbf_epdan_out_of_rx_window ===
-=== end test_tbf_epdan_out_of_rx_window ===
-=== start test_immediate_assign_rej_multi_block ===
-=== end test_immediate_assign_rej_multi_block ===
-=== start test_immediate_assign_rej_single_block ===
-=== end test_immediate_assign_rej_single_block ===
-=== start test_tbf_egprs_two_phase_puan ===
-=== end test_tbf_egprs_two_phase_puan ===
-=== start test_packet_access_rej_epdan ===
-packet reject: 40 84 7f f7 6e e6 41 4b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 
-=== end test_packet_access_rej_epdan ===
-=== start test_packet_access_rej_prr ===
-=== end test_packet_access_rej_prr ===
-=== start test_packet_access_rej_prr_no_other_tbfs ===
-=== end test_packet_access_rej_prr_no_other_tbfs ===
diff --git a/tests/testsuite.at b/tests/testsuite.at
index 09b02475..8a319bd8 100644
--- a/tests/testsuite.at
+++ b/tests/testsuite.at
@@ -24,9 +24,8 @@ AT_CLEANUP
 
 AT_SETUP([tbf])
 AT_KEYWORDS([tbf])
-cat $abs_srcdir/tbf/TbfTest.ok > expout
 cat $abs_srcdir/tbf/TbfTest.err > experr
-AT_CHECK([$OSMO_QEMU $abs_top_builddir/tests/tbf/TbfTest], [0], [expout], [experr])
+AT_CHECK([$OSMO_QEMU $abs_top_builddir/tests/tbf/TbfTest], [0], [ignore], [experr])
 AT_CLEANUP
 
 AT_SETUP([bitcomp])