1 files changed, 154 insertions, 190 deletions

diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp
index 3d27883..dd24963 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -28,18 +28,28 @@
 #include <gprs_codel.h>
 #include <decoding.h>
 #include <encoding.h>
-
+#include <gprs_coding_scheme.h>
+#include <gprs_ms.h>
+#include <gprs_ms_storage.h>
+#include <llc.h>
 #include "pcu_utils.h"
 
 extern "C" {
 #include <osmocom/core/msgb.h>
 #include <osmocom/core/talloc.h>
 #include <osmocom/gprs/gprs_bssgp_bss.h>
+	#include <osmocom/core/bitvec.h>
+	#include <osmocom/core/linuxlist.h>
+	#include <osmocom/core/logging.h>
+	#include <osmocom/core/rate_ctr.h>
+	#include <osmocom/core/timer.h>
+	#include <osmocom/core/utils.h>
+	#include <osmocom/gsm/gsm_utils.h>
+	#include <osmocom/gsm/protocol/gsm_04_08.h>
 }
 
 #include <errno.h>
 #include <string.h>
-#include <math.h>
 
 /* After sending these frames, we poll for ack/nack. */
 #define POLL_ACK_AFTER_FRAMES 20
@@ -58,8 +68,7 @@ static void llc_timer_cb(void *_tbf)
 	if (tbf->state_is_not(GPRS_RLCMAC_FLOW))
 		return;
 
-	LOGP(DRLCMAC, LOGL_DEBUG,
-		"%s LLC receive timeout, requesting DL ACK\n", tbf_name(tbf));
+	LOGPTBFDL(tbf, LOGL_DEBUG, "LLC receive timeout, requesting DL ACK\n");
 
 	tbf->request_dl_ack();
 }
@@ -87,7 +96,7 @@ int gprs_rlcmac_dl_tbf::append_data(const uint8_t ms_class,
 				const uint16_t pdu_delay_csec,
 				const uint8_t *data, const uint16_t len)
 {
-	LOGP(DRLCMAC, LOGL_INFO, "%s append\n", tbf_name(this));
+	LOGPTBFDL(this, LOGL_DEBUG, "appending %u bytes\n", len);
 	gprs_llc_queue::MetaInfo info;
 	struct msgb *llc_msg = msgb_alloc(len, "llc_pdu_queue");
 	if (!llc_msg)
@@ -101,9 +110,7 @@ int gprs_rlcmac_dl_tbf::append_data(const uint8_t ms_class,
 	start_llc_timer();
 
 	if (state_is(GPRS_RLCMAC_WAIT_RELEASE)) {
-		LOGP(DRLCMAC, LOGL_DEBUG,
-			"%s in WAIT RELEASE state "
-			"(T3193), so reuse TBF\n", tbf_name(this));
+		LOGPTBFDL(this, LOGL_DEBUG, "in WAIT RELEASE state (T3193), so reuse TBF\n");
 		tbf_update_ms_class(this, ms_class);
 		establish_dl_tbf_on_pacch();
 	}
@@ -118,7 +125,7 @@ static int tbf_new_dl_assignment(struct gprs_rlcmac_bts *bts,
 				const uint8_t egprs_ms_class,
 				struct gprs_rlcmac_dl_tbf **tbf)
 {
-	uint8_t ss;
+	bool ss;
 	int8_t use_trx;
 	uint16_t ta = GSM48_TA_INVALID;
 	struct gprs_rlcmac_ul_tbf *ul_tbf = NULL, *old_ul_tbf;
@@ -136,11 +143,11 @@ static int tbf_new_dl_assignment(struct gprs_rlcmac_bts *bts,
 	if (ul_tbf && ul_tbf->m_contention_resolution_done
 	 && !ul_tbf->m_final_ack_sent) {
 		use_trx = ul_tbf->trx->trx_no;
-		ss = 0;
+		ss = false;
 		old_ul_tbf = ul_tbf;
 	} else {
 		use_trx = -1;
-		ss = 1; /* PCH assignment only allows one timeslot */
+		ss = true; /* PCH assignment only allows one timeslot */
 		old_ul_tbf = NULL;
 	}
 
@@ -150,13 +157,13 @@ static int tbf_new_dl_assignment(struct gprs_rlcmac_bts *bts,
 	dl_tbf = tbf_alloc_dl_tbf(bts, ms, use_trx, ms_class, egprs_ms_class, ss);
 
 	if (!dl_tbf) {
-		LOGP(DRLCMAC, LOGL_NOTICE, "No PDCH resource\n");
+		LOGP(DTBF, LOGL_NOTICE, "No PDCH resource\n");
 		return -EBUSY;
 	}
 	dl_tbf->update_ms(tlli, GPRS_RLCMAC_DL_TBF);
 	dl_tbf->ms()->set_ta(ta);
 
-	LOGP(DRLCMAC, LOGL_DEBUG, "%s [DOWNLINK] START\n", tbf_name(dl_tbf));
+	LOGPTBFDL(dl_tbf, LOGL_DEBUG, "[DOWNLINK] START\n");
 
 	/* Store IMSI for later look-up and PCH retransmission */
 	dl_tbf->assign_imsi(imsi);
@@ -200,28 +207,25 @@ int gprs_rlcmac_dl_tbf::handle(struct gprs_rlcmac_bts *bts,
 		if (ms_old && ms_old != ms) {
 			/* The TLLI has changed (RAU), so there are two MS
 			 * objects for the same MS */
-			LOGP(DRLCMAC, LOGL_NOTICE,
-				"There is a new MS object for the same MS: "
-				"(0x%08x, '%s') -> (0x%08x, '%s')\n",
-				ms_old->tlli(), ms_old->imsi(),
-				ms->tlli(), ms->imsi());
+			LOGP(DTBF, LOGL_NOTICE,
+			     "There is a new MS object for the same MS: (0x%08x, '%s') -> (0x%08x, '%s')\n",
+			     ms_old->tlli(), ms_old->imsi(), ms->tlli(), ms->imsi());
 
 			GprsMs::Guard guard_old(ms_old);
 
 			if (!dl_tbf && ms_old->dl_tbf()) {
-				LOGP(DRLCMAC, LOGL_NOTICE,
-					"%s IMSI %s: "
-					"moving DL TBF to new MS object\n",
-					ms_old->dl_tbf()->name(), imsi);
+				LOGP(DTBF, LOGL_NOTICE,
+				     "IMSI %s, old TBF %s: moving DL TBF to new MS object\n",
+				     imsi, ms_old->dl_tbf()->name());
 				dl_tbf = ms_old->dl_tbf();
 				/* Move the DL TBF to the new MS */
 				dl_tbf->set_ms(ms);
 			}
 			/* Clean up the old MS object */
 			/* TODO: Put this into a separate function, use timer? */
-			if (ms_old->ul_tbf() && ms_old->ul_tbf()->T == 0)
+			if (ms_old->ul_tbf() && !ms_old->ul_tbf()->timers_pending(T_MAX))
 				tbf_free(ms_old->ul_tbf());
-			if (ms_old->dl_tbf() && ms_old->dl_tbf()->T == 0)
+			if (ms_old->dl_tbf() && !ms_old->dl_tbf()->timers_pending(T_MAX))
 				tbf_free(ms_old->dl_tbf());
 
 			ms->merge_old_ms(ms_old);
@@ -305,10 +309,10 @@ drop_frame:
 	}
 
 	if (frames) {
-		LOGP(DRLCMACDL, LOGL_NOTICE, "%s Discarding LLC PDU "
+		LOGPTBFDL(this, LOGL_NOTICE, "Discarding LLC PDU "
 			"because lifetime limit reached, "
 			"count=%u new_queue_size=%zu\n",
-			tbf_name(this), frames, llc_queue_size());
+			  frames, llc_queue_size());
 		if (frames > 0xff)
 			frames = 0xff;
 		if (octets > 0xffffff)
@@ -329,7 +333,7 @@ bool gprs_rlcmac_dl_tbf::restart_bsn_cycle()
 	 * should never happen if MS works correctly.
 	 */
 	if (m_window.window_empty()) {
-		LOGP(DRLCMACDL, LOGL_DEBUG, "- MS acked all blocks\n");
+		LOGPTBFDL(this, LOGL_DEBUG, "MS acked all blocks\n");
 		return false;
 	}
 
@@ -339,9 +343,8 @@ bool gprs_rlcmac_dl_tbf::restart_bsn_cycle()
 	/* At this point there should be at least one unacked block
 	 * to be resent. If not, this is an software error. */
 	if (resend == 0) {
-		LOGP(DRLCMACDL, LOGL_ERROR, "Software error: "
-			"There are no unacknowledged blocks, but V(A) "
-			" != V(S). PLEASE FIX!\n");
+		LOGPTBFDL(this, LOGL_ERROR,
+			  "FIXME: Software error: There are no unacknowledged blocks, but V(A) != V(S). PLEASE FIX!\n");
 		return false;
 	}
 
@@ -380,15 +383,13 @@ int gprs_rlcmac_dl_tbf::take_next_bsn(uint32_t fn,
 					ms()->current_cs_dl(),
 					bts->bts_data()->dl_arq_type);
 
-			LOGP(DRLCMACDL, LOGL_DEBUG,
-				"- initial_cs_dl(%d) last_mcs(%d)"
-				" demanded_mcs(%d) cs_trans(%d)"
-				" arq_type(%d) bsn(%d)\n",
-				m_rlc.block(bsn)->cs_init.to_num(),
-				m_rlc.block(bsn)->cs_last.to_num(),
-				ms()->current_cs_dl().to_num(),
-				m_rlc.block(bsn)->cs_current_trans.to_num(),
-				bts->bts_data()->dl_arq_type, bsn);
+			LOGPTBFDL(this, LOGL_DEBUG,
+				  "initial_cs_dl(%d) last_mcs(%d) demanded_mcs(%d) cs_trans(%d) arq_type(%d) bsn(%d)\n",
+				  m_rlc.block(bsn)->cs_init.to_num(),
+				  m_rlc.block(bsn)->cs_last.to_num(),
+				  ms()->current_cs_dl().to_num(),
+				  m_rlc.block(bsn)->cs_current_trans.to_num(),
+				  bts->bts_data()->dl_arq_type, bsn);
 
 			/* TODO: Need to remove this check when MCS-8 -> MCS-6
 			 * transistion is handled.
@@ -404,21 +405,21 @@ int gprs_rlcmac_dl_tbf::take_next_bsn(uint32_t fn,
 		data_len2 = m_rlc.block(bsn)->len;
 		if (force_data_len > 0 && force_data_len != data_len2)
 			return -1;
-		LOGP(DRLCMACDL, LOGL_DEBUG, "- Resending BSN %d\n", bsn);
+		LOGPTBFDL(this, LOGL_DEBUG, "Resending BSN %d\n", bsn);
 		/* re-send block with negative aknowlegement */
 		m_window.m_v_b.mark_unacked(bsn);
 		bts->rlc_resent();
 	} else if (state_is(GPRS_RLCMAC_FINISHED)) {
-		LOGP(DRLCMACDL, LOGL_DEBUG, "- Restarting at BSN %d, "
-			"because all blocks have been transmitted.\n",
-			m_window.v_a());
+		LOGPTBFDL(this, LOGL_DEBUG,
+			  "Restarting at BSN %d, because all blocks have been transmitted.\n",
+			  m_window.v_a());
 		bts->rlc_restarted();
 		if (restart_bsn_cycle())
 			return take_next_bsn(fn, previous_bsn, may_combine);
 	} else if (dl_window_stalled()) {
-		LOGP(DRLCMACDL, LOGL_NOTICE, "- Restarting at BSN %d, "
-			"because the window is stalled.\n",
-			m_window.v_a());
+		LOGPTBFDL(this, LOGL_NOTICE,
+			  "Restarting at BSN %d, because the window is stalled.\n",
+			  m_window.v_a());
 		bts->rlc_stalled();
 		if (restart_bsn_cycle())
 			return take_next_bsn(fn, previous_bsn, may_combine);
@@ -426,31 +427,31 @@ int gprs_rlcmac_dl_tbf::take_next_bsn(uint32_t fn,
 		GprsCodingScheme new_cs;
 		/* New blocks may be send */
 		new_cs = force_cs ? force_cs : current_cs();
-		LOGP(DRLCMACDL, LOGL_DEBUG,
-			"- Sending new block at BSN %d, CS=%s\n",
-			m_window.v_s(), new_cs.name());
+		LOGPTBFDL(this, LOGL_DEBUG,
+			  "Sending new block at BSN %d, CS=%s\n",
+			  m_window.v_s(), new_cs.name());
 
 		bsn = create_new_bsn(fn, new_cs);
 	} else if (!m_window.window_empty()) {
-		LOGP(DRLCMACDL, LOGL_DEBUG, "- Restarting at BSN %d, "
-			"because all blocks have been transmitted (FLOW).\n",
-			m_window.v_a());
+		LOGPTBFDL(this, LOGL_DEBUG,
+			  "Restarting at BSN %d, because all blocks have been transmitted (FLOW).\n",
+			  m_window.v_a());
 		bts->rlc_restarted();
 		if (restart_bsn_cycle())
 			return take_next_bsn(fn, previous_bsn, may_combine);
 	} else {
 		/* Nothing left to send, create dummy LLC commands */
-		LOGP(DRLCMACDL, LOGL_DEBUG,
-			"- Sending new dummy block at BSN %d, CS=%s\n",
-			m_window.v_s(), current_cs().name());
+		LOGPTBFDL(this, LOGL_DEBUG,
+			  "Sending new dummy block at BSN %d, CS=%s\n",
+			  m_window.v_s(), current_cs().name());
 		bsn = create_new_bsn(fn, current_cs());
 		/* Don't send a second block, so don't set cs_current_trans */
 	}
 
 	if (bsn < 0) {
 		/* we just send final block again */
-		LOGP(DRLCMACDL, LOGL_DEBUG,
-			"- Nothing else to send, Re-transmit final block!\n");
+		LOGPTBFDL(this, LOGL_DEBUG,
+			  "Nothing else to send, Re-transmit final block!\n");
 		bsn = m_window.v_s_mod(-1);
 		bts->rlc_final_block_resent();
 		bts->rlc_resent();
@@ -470,9 +471,8 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(uint32_t fn, uint8_t ts)
 	int bsn, bsn2 = -1;
 	bool may_combine;
 
-	LOGP(DRLCMACDL, LOGL_DEBUG, "%s downlink (V(A)==%d .. "
-		"V(S)==%d)\n", tbf_name(this),
-		m_window.v_a(), m_window.v_s());
+	LOGPTBFDL(this, LOGL_DEBUG, "downlink (V(A)==%d .. V(S)==%d)\n",
+		  m_window.v_a(), m_window.v_s());
 
 	bsn = take_next_bsn(fn, -1, &may_combine);
 	if (bsn < 0)
@@ -488,29 +488,26 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(uint32_t fn, uint8_t ts)
 void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf)
 {
 	/* stop pending timer */
-	stop_timer();
+	stop_timers("assignment (DL-TBF)");
 
 	/* check for downlink tbf:  */
 	if (old_tbf) {
-		LOGP(DRLCMACDL, LOGL_DEBUG, "Send dowlink assignment on PACCH, because %s exists\n", tbf_name(old_tbf));
-		old_tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_SEND_ASS;
+		LOGPTBFDL(this, LOGL_DEBUG, "Send dowlink assignment on PACCH, because %s exists\n", old_tbf->name());
+		TBF_SET_ASS_STATE_DL(old_tbf, GPRS_RLCMAC_DL_ASS_SEND_ASS);
 		old_tbf->was_releasing = old_tbf->state_is(GPRS_RLCMAC_WAIT_RELEASE);
 
 		/* change state */
-		set_state(GPRS_RLCMAC_ASSIGN);
-		if (!(state_flags & (1 << GPRS_RLCMAC_FLAG_CCCH)))
-			state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH);
+		TBF_SET_ASS_ON(this, GPRS_RLCMAC_FLAG_PACCH, true);
 
 		/* start timer */
-		tbf_timer_start(this, 0, Tassign_pacch);
+		T_START(this, T0, T_ASS_PACCH_SEC, 0, "assignment (PACCH)", true);
 	} else {
-		LOGP(DRLCMACDL, LOGL_DEBUG, "Send dowlink assignment for %s on PCH, no TBF exist (IMSI=%s)\n",
-		     tbf_name(this), imsi());
+		LOGPTBFDL(this, LOGL_DEBUG, "Send dowlink assignment on PCH, no TBF exist (IMSI=%s)\n",
+			  imsi());
 		was_releasing = state_is(GPRS_RLCMAC_WAIT_RELEASE);
 
 		/* change state */
-		set_state(GPRS_RLCMAC_ASSIGN);
-		state_flags |= (1 << GPRS_RLCMAC_FLAG_CCCH);
+		TBF_SET_ASS_ON(this, GPRS_RLCMAC_FLAG_CCCH, false);
 
 		/* send immediate assignment */
 		bts->snd_dl_ass(this, 0, imsi());
@@ -530,9 +527,7 @@ void gprs_rlcmac_dl_tbf::schedule_next_frame()
 	if (!msg)
 		return;
 
-	LOGP(DRLCMACDL, LOGL_INFO,
-		"- Dequeue next LLC for %s (len=%d)\n",
-		tbf_name(this), msg->len);
+	LOGPTBFDL(this, LOGL_DEBUG, "Dequeue next LLC (len=%d)\n", msg->len);
 
 	m_llc.put_frame(msg->data, msg->len);
 	bts->llc_frame_sched();
@@ -598,11 +593,9 @@ int gprs_rlcmac_dl_tbf::create_new_bsn(const uint32_t fn, GprsCodingScheme cs)
 			 * arrive, so request a DL ack/nack now */
 			request_dl_ack();
 
-			LOGP(DRLCMACDL, LOGL_DEBUG,
-				"-- Empty chunk, "
-				"added LLC dummy command of size %d, "
-				"drained_since=%d\n",
-				m_llc.frame_length(), frames_since_last_drain(fn));
+			LOGPTBFDL(this, LOGL_DEBUG,
+				  "Empty chunk, added LLC dummy command of size %d, drained_since=%d\n",
+				  m_llc.frame_length(), frames_since_last_drain(fn));
 		}
 
 		is_final = llc_queue_size() == 0 && !keep_open(fn);
@@ -616,24 +609,23 @@ int gprs_rlcmac_dl_tbf::create_new_bsn(const uint32_t fn, GprsCodingScheme cs)
 		if (ar == Encoding::AR_NEED_MORE_BLOCKS)
 			break;
 
-		LOGP(DRLCMACDL, LOGL_INFO, "Complete DL frame for %s"
-			"len=%d\n", tbf_name(this), m_llc.frame_length());
+		LOGPTBFDL(this, LOGL_DEBUG, "Complete DL frame, len=%d\n", m_llc.frame_length());
 		gprs_rlcmac_dl_bw(this, m_llc.frame_length());
 		bts->llc_dl_bytes(m_llc.frame_length());
 		m_llc.reset();
 
 		if (is_final) {
 			request_dl_ack();
-			set_state(GPRS_RLCMAC_FINISHED);
+			TBF_SET_STATE(this, GPRS_RLCMAC_FINISHED);
 		}
 
 		/* dequeue next LLC frame, if any */
 		schedule_next_frame();
 	} while (ar == Encoding::AR_COMPLETED_SPACE_LEFT);
 
-	LOGP(DRLCMACDL, LOGL_DEBUG, "data block (BSN %d, %s): %s\n",
-		bsn, rlc_data->cs_last.name(),
-		osmo_hexdump(rlc_data->block, block_data_len));
+	LOGPTBFDL(this, LOGL_DEBUG, "data block (BSN %d, %s): %s\n",
+		  bsn, rlc_data->cs_last.name(),
+		  osmo_hexdump(rlc_data->block, block_data_len));
 	/* raise send state and set ack state array */
 	m_window.m_v_b.mark_unacked(bsn);
 	m_window.increment_send();
@@ -641,25 +633,19 @@ int gprs_rlcmac_dl_tbf::create_new_bsn(const uint32_t fn, GprsCodingScheme cs)
 	return bsn;
 }
 
-void gprs_rlcmac_dl_tbf::clear_poll_timeout_flag()
-{
-	state_flags &= ~(1 << GPRS_RLCMAC_FLAG_TO_DL_ACK);
-}
-
 bool gprs_rlcmac_dl_tbf::handle_ack_nack()
 {
 	bool ack_recovered = false;
 
 	state_flags |= (1 << GPRS_RLCMAC_FLAG_DL_ACK);
-	if ((state_flags & (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK))) {
-		clear_poll_timeout_flag();
+	if (check_n_clear(GPRS_RLCMAC_FLAG_TO_DL_ACK)) {
 		ack_recovered = true;
 	}
 
 	/* reset N3105 */
-	n3105 = 0;
-	stop_t3191();
-	poll_state = GPRS_RLCMAC_POLL_NONE;
+	n_reset(N3105);
+	t_stop(T3191, "ACK/NACK received");
+	TBF_POLL_SCHED_UNSET(this);
 
 	return ack_recovered;
 }
@@ -673,7 +659,7 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 	unsigned msg_len;
 	bool need_poll;
 	/* TODO: support MCS-7 - MCS-9, where data_block_idx can be 1 */
-	unsigned int data_block_idx = 0;
+	uint8_t data_block_idx = 0;
 	unsigned int rrbp;
 	uint32_t new_poll_fn;
 	int rc;
@@ -735,10 +721,8 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 
 	spb = get_egprs_dl_spb(index);
 
-	LOGP(DRLCMACDL, LOGL_DEBUG, "- need_padding %d spb_status %d spb %d"
-			"(BSN1 %d BSN2 %d)\n",
-			need_padding,
-			spb_status, spb, index, index2);
+	LOGPTBFDL(this, LOGL_DEBUG, "need_padding %d spb_status %d spb %d (BSN1 %d BSN2 %d)\n",
+		  need_padding, spb_status, spb, index, index2);
 
 	gprs_rlc_data_info_init_dl(&rlc, cs, need_padding, spb);
 
@@ -757,10 +741,10 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 	OSMO_ASSERT(rlc.num_data_blocks <= ARRAY_SIZE(rlc.block_info));
 	OSMO_ASSERT(rlc.num_data_blocks > 0);
 
-	LOGP(DRLCMACDL, LOGL_DEBUG, "- Copying %u RLC blocks, %u BSNs\n", rlc.num_data_blocks, num_bsns);
+	LOGPTBFDL(this, LOGL_DEBUG, "Copying %u RLC blocks, %u BSNs\n", rlc.num_data_blocks, num_bsns);
 
-	/* Copy block(s) to RLC message */
-	for (data_block_idx = 0; data_block_idx < rlc.num_data_blocks;
+	/* Copy block(s) to RLC message: the num_data_blocks cannot be more than 2 - see assert above */
+	for (data_block_idx = 0; data_block_idx < OSMO_MIN(rlc.num_data_blocks, 2);
 		data_block_idx++)
 	{
 		int bsn;
@@ -784,7 +768,7 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 			OSMO_ASSERT(m_rlc.block(bsn)->next_ps >= EGPRS_PS_1);
 			OSMO_ASSERT(m_rlc.block(bsn)->next_ps <= EGPRS_PS_3);
 		}
-		OSMO_ASSERT(data_block_idx < 2); /* punct defined above as 2-element array */
+
 		punct[data_block_idx] = m_rlc.block(bsn)->next_ps;
 
 		rdbi = &rlc.block_info[data_block_idx];
@@ -819,8 +803,8 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 		rdbi->bsn = bsn;
 		is_final = is_final || rdbi->cv == 0;
 
-		LOGP(DRLCMACDL, LOGL_DEBUG, "- Copying data unit %d (BSN %d)\n",
-			data_block_idx, bsn);
+		LOGPTBFDL(this, LOGL_DEBUG, "Copying data unit %d (BSN %d)\n",
+			  data_block_idx, bsn);
 
 		Encoding::rlc_copy_from_aligned_buffer(&rlc, data_block_idx,
 			msg_data, block_data);
@@ -842,15 +826,15 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 	if (m_tx_counter >= POLL_ACK_AFTER_FRAMES || m_dl_ack_requested ||
 			need_poll) {
 		if (m_dl_ack_requested) {
-			LOGP(DRLCMACDL, LOGL_DEBUG, "- Scheduling Ack/Nack "
-				"polling, because is was requested explicitly "
-				"(e.g. first final block sent).\n");
+			LOGPTBFDL(this, LOGL_DEBUG,
+				  "Scheduling Ack/Nack polling, because is was requested explicitly "
+				  "(e.g. first final block sent).\n");
 		} else if (need_poll) {
-			LOGP(DRLCMACDL, LOGL_DEBUG, "- Scheduling Ack/Nack "
-				"polling, because polling timed out.\n");
+			LOGPTBFDL(this, LOGL_DEBUG,
+				  "Scheduling Ack/Nack polling, because polling timed out.\n");
 		} else {
-			LOGP(DRLCMACDL, LOGL_DEBUG, "- Scheduling Ack/Nack "
-				"polling, because %d blocks sent.\n",
+			LOGPTBFDL(this, LOGL_DEBUG,
+				  "Scheduling Ack/Nack polling, because %d blocks sent.\n",
 				POLL_ACK_AFTER_FRAMES);
 		}
 
@@ -861,9 +845,9 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 			m_tx_counter = 0;
 			/* start timer whenever we send the final block */
 			if (is_final)
-				tbf_timer_start(this, 3191, bts_data()->t3191, 0);
+				T_START(this, T3191, bts_data()->t3191, 0, "final block (DL-TBF)", true);
 
-			clear_poll_timeout_flag();
+			state_flags &= ~(1 << GPRS_RLCMAC_FLAG_TO_DL_ACK); /* clear poll timeout flag */
 
 			/* Clear request flag */
 			m_dl_ack_requested = false;
@@ -874,18 +858,18 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 
 			m_last_dl_poll_fn = poll_fn;
 
-			LOGP(DRLCMACDL, LOGL_INFO,
-				"%s Scheduled Ack/Nack polling on FN=%d, TS=%d\n",
-				name(), poll_fn, poll_ts);
+			LOGPTBFDL(this, LOGL_INFO,
+				  "Scheduled Ack/Nack polling on FN=%d, TS=%d\n",
+				  poll_fn, poll_ts);
 		}
 	}
 
 	Encoding::rlc_write_dl_data_header(&rlc, msg_data);
 
-	LOGP(DRLCMACDL, LOGL_DEBUG, "msg block (BSN %d, %s%s): %s\n",
-		index, cs.name(),
-		need_padding ? ", padded" : "",
-		msgb_hexdump(dl_msg));
+	LOGPTBFDL(this, LOGL_DEBUG, "msg block (BSN %d, %s%s): %s\n",
+		  index, cs.name(),
+		  need_padding ? ", padded" : "",
+		  msgb_hexdump(dl_msg));
 
 	/* Increment TX-counter */
 	m_tx_counter++;
@@ -969,10 +953,9 @@ int gprs_rlcmac_dl_tbf::analyse_errors(char *show_rbb, uint8_t ssn,
 		}
 	}
 
-	LOGP(DRLCMACDL, LOGL_DEBUG, "%s DL analysis, range=%d:%d, lost=%d, recv=%d, "
-		"skipped=%d, bsn=%d, info='%s'\n",
-		name(), m_window.v_a(), m_window.v_s(), lost, received,
-		skipped, bsn, info);
+	LOGPTBFDL(this, LOGL_DEBUG,
+		  "DL analysis, range=%d:%d, lost=%d, recv=%d, skipped=%d, bsn=%d, info='%s'\n",
+		  m_window.v_a(), m_window.v_s(), lost, received, skipped, bsn, info);
 
 	res->received_packets = received_packets;
 	res->lost_packets = lost_packets;
@@ -985,6 +968,11 @@ int gprs_rlcmac_dl_tbf::analyse_errors(char *show_rbb, uint8_t ssn,
 	return lost * 100 / (lost + received);
 }
 
+gprs_rlc_dl_window *gprs_rlcmac_dl_tbf::window()
+{
+	return &m_window;
+}
+
 int gprs_rlcmac_dl_tbf::update_window(unsigned first_bsn,
 	const struct bitvec *rbb)
 {
@@ -1001,9 +989,9 @@ int gprs_rlcmac_dl_tbf::update_window(unsigned first_bsn,
 
 	Decoding::extract_rbb(rbb, show_rbb);
 	/* show received array in debug */
-	LOGP(DRLCMACDL, LOGL_DEBUG, "- ack:  (BSN=%d)\"%s\""
-		"(BSN=%d)  R=ACK I=NACK\n", first_bsn,
-		show_rbb, m_window.mod_sns(behind_last_bsn - 1));
+	LOGPTBFDL(this, LOGL_DEBUG,
+		  "ack:  (BSN=%d)\"%s\"(BSN=%d)  R=ACK I=NACK\n",
+		  first_bsn, show_rbb, m_window.mod_sns(behind_last_bsn - 1));
 
 	error_rate = analyse_errors(show_rbb, behind_last_bsn, &ana_res);
 
@@ -1025,11 +1013,9 @@ int gprs_rlcmac_dl_tbf::update_window(unsigned first_bsn,
 
 	/* show receive state array in debug (V(A)..V(S)-1) */
 	m_window.show_state(show_v_b);
-	LOGP(DRLCMACDL, LOGL_DEBUG, "- V(B): (V(A)=%d)\"%s\""
-		"(V(S)-1=%d)  A=Acked N=Nacked U=Unacked "
-		"X=Resend-Unacked I=Invalid\n",
-		m_window.v_a(), show_v_b,
-		m_window.v_s_mod(-1));
+	LOGPTBFDL(this, LOGL_DEBUG,
+		  "V(B): (V(A)=%d)\"%s\"(V(S)-1=%d)  A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid\n",
+		  m_window.v_a(), show_v_b, m_window.v_s_mod(-1));
 	return 0;
 }
 
@@ -1044,9 +1030,9 @@ int gprs_rlcmac_dl_tbf::update_window(const uint8_t ssn, const uint8_t *rbb)
 
 	Decoding::extract_rbb(rbb, show_rbb);
 	/* show received array in debug (bit 64..1) */
-	LOGP(DRLCMACDL, LOGL_DEBUG, "- ack:  (BSN=%d)\"%s\""
-		"(BSN=%d)  R=ACK I=NACK\n", m_window.mod_sns(ssn - 64),
-		show_rbb, m_window.mod_sns(ssn - 1));
+	LOGPTBFDL(this, LOGL_DEBUG,
+		  "ack:  (BSN=%d)\"%s\"(BSN=%d)  R=ACK I=NACK\n",
+		  m_window.mod_sns(ssn - 64), show_rbb, m_window.mod_sns(ssn - 1));
 
 	/* apply received array to receive state (SSN-64..SSN-1) */
 	/* calculate distance of ssn from V(S) */
@@ -1058,8 +1044,7 @@ int gprs_rlcmac_dl_tbf::update_window(const uint8_t ssn, const uint8_t *rbb)
 		 * to previous TBF
 		 * FIXME: we should implement polling for
 		 * control ack!*/
-		LOGP(DRLCMACDL, LOGL_NOTICE, "- ack range is out of "
-			"V(A)..V(S) range %s Free TBF!\n", tbf_name(this));
+		LOGPTBFDL(this, LOGL_NOTICE, "ack range is out of V(A)..V(S) range - Free TBF!\n");
 		return 1; /* indicate to free TBF */
 	}
 
@@ -1084,16 +1069,13 @@ int gprs_rlcmac_dl_tbf::update_window(const uint8_t ssn, const uint8_t *rbb)
 
 	/* show receive state array in debug (V(A)..V(S)-1) */
 	m_window.show_state(show_v_b);
-	LOGP(DRLCMACDL, LOGL_DEBUG, "- V(B): (V(A)=%d)\"%s\""
-		"(V(S)-1=%d)  A=Acked N=Nacked U=Unacked "
-		"X=Resend-Unacked I=Invalid\n",
-		m_window.v_a(), show_v_b,
-		m_window.v_s_mod(-1));
+	LOGPTBFDL(this, LOGL_DEBUG,
+		  "V(B): (V(A)=%d)\"%s\"(V(S)-1=%d)  A=Acked N=Nacked U=Unacked X=Resend-Unacked I=Invalid\n",
+		  m_window.v_a(), show_v_b, m_window.v_s_mod(-1));
 
 	if (state_is(GPRS_RLCMAC_FINISHED) && m_window.window_empty()) {
-		LOGP(DRLCMACDL, LOGL_NOTICE, "Received acknowledge of "
-			"all blocks, but without final ack "
-			"inidcation (don't worry)\n");
+		LOGPTBFDL(this, LOGL_NOTICE,
+			  "Received acknowledge of all blocks, but without final ack inidcation (don't worry)\n");
 	}
 	return 0;
 }
@@ -1121,21 +1103,18 @@ int gprs_rlcmac_dl_tbf::release()
 	/* report all outstanding packets as received */
 	gprs_rlcmac_received_lost(this, received, 0);
 
-	set_state(GPRS_RLCMAC_WAIT_RELEASE);
+	TBF_SET_STATE(this, GPRS_RLCMAC_WAIT_RELEASE);
 
 	/* start T3193 */
-	tbf_timer_start(this, 3193,
-		bts_data()->t3193_msec / 1000,
-		(bts_data()->t3193_msec % 1000) * 1000);
+	T_START(this, T3193, bts_data()->t3193_msec / 1000, (bts_data()->t3193_msec % 1000) * 1000,
+		  "release (DL-TBF)", true);
 
 	/* reset rlc states */
 	m_tx_counter = 0;
 	m_wait_confirm = 0;
 	m_window.reset();
 
-	/* keep to flags */
-	state_flags &= GPRS_RLCMAC_FLAG_TO_MASK;
-	state_flags &= ~(1 << GPRS_RLCMAC_FLAG_CCCH);
+	TBF_ASS_TYPE_UNSET(this, GPRS_RLCMAC_FLAG_CCCH);
 
 	return 0;
 }
@@ -1156,46 +1135,43 @@ int gprs_rlcmac_dl_tbf::abort()
 		 * (partly) encoded in chunk 1 of block V(A). (optional) */
 	}
 
-	set_state(GPRS_RLCMAC_RELEASING);
+	TBF_SET_STATE(this, GPRS_RLCMAC_RELEASING);
 
 	/* reset rlc states */
 	m_window.reset();
 
-	/* keep to flags */
-	state_flags &= GPRS_RLCMAC_FLAG_TO_MASK;
-	state_flags &= ~(1 << GPRS_RLCMAC_FLAG_CCCH);
+	TBF_ASS_TYPE_UNSET(this, GPRS_RLCMAC_FLAG_CCCH);
 
 	return 0;
 }
 
-int gprs_rlcmac_dl_tbf::rcvd_dl_ack(uint8_t final_ack, unsigned first_bsn,
+int gprs_rlcmac_dl_tbf::rcvd_dl_ack(bool final_ack, unsigned first_bsn,
 	struct bitvec *rbb)
 {
 	int rc;
-	LOGP(DRLCMACDL, LOGL_DEBUG, "%s downlink acknowledge\n", tbf_name(this));
+	LOGPTBFDL(this, LOGL_DEBUG, "downlink acknowledge\n");
 
 	rc = update_window(first_bsn, rbb);
 
 	if (final_ack) {
-		LOGP(DRLCMACDL, LOGL_DEBUG, "- Final ACK received.\n");
+		LOGPTBFDL(this, LOGL_DEBUG, "Final ACK received.\n");
 		rc = maybe_start_new_window();
 	} else if (state_is(GPRS_RLCMAC_FINISHED) && m_window.window_empty()) {
-		LOGP(DRLCMACDL, LOGL_NOTICE, "Received acknowledge of "
-			"all blocks, but without final ack "
-			"indication (don't worry)\n");
+		LOGPTBFDL(this, LOGL_NOTICE,
+			  "Received acknowledge of all blocks, but without final ack indication (don't worry)\n");
 	}
 
 	return rc;
 }
 
-int gprs_rlcmac_dl_tbf::rcvd_dl_ack(uint8_t final_ack, uint8_t ssn, uint8_t *rbb)
+int gprs_rlcmac_dl_tbf::rcvd_dl_ack(bool final_ack, uint8_t ssn, uint8_t *rbb)
 {
-	LOGP(DRLCMACDL, LOGL_DEBUG, "%s downlink acknowledge\n", tbf_name(this));
+	LOGPTBFDL(this, LOGL_DEBUG, "downlink acknowledge\n");
 
 	if (!final_ack)
 		return update_window(ssn, rbb);
 
-	LOGP(DRLCMACDL, LOGL_DEBUG, "- Final ACK received.\n");
+	LOGPTBFDL(this, LOGL_DEBUG, "Final ACK received.\n");
 	return maybe_start_new_window();
 }
 
@@ -1211,7 +1187,7 @@ void gprs_rlcmac_dl_tbf::request_dl_ack()
 
 bool gprs_rlcmac_dl_tbf::need_control_ts() const
 {
-	if (poll_state != GPRS_RLCMAC_POLL_NONE)
+	if (poll_scheduled())
 		return false;
 
 	return state_flags & (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK) ||
@@ -1252,7 +1228,7 @@ bool gprs_rlcmac_dl_tbf::keep_open(unsigned fn) const
 {
 	int keep_time_frames;
 
-	if (bts_data()->dl_tbf_idle_msec <= 0)
+	if (bts_data()->dl_tbf_idle_msec == 0)
 		return false;
 
 	keep_time_frames = msecs_to_frames(bts_data()->dl_tbf_idle_msec);
@@ -1301,11 +1277,11 @@ enum egprs_rlc_dl_reseg_bsn_state
 				*block_data = &rlc_data->block[22];
 				break;
 			default:
-				LOGP(DRLCMACDL, LOGL_ERROR, "Software error: "
-				"--%s hit invalid condition. headerType(%d) "
-				" blockstatus(%d) cs(%s) PLEASE FIX!\n", name(),
-				cs_current_trans.headerTypeData(),
-				*block_status_dl, cs_init.name());
+				LOGPTBFDL(this, LOGL_ERROR,
+					  "FIXME: Software error: hit invalid condition. "
+					  "headerType(%d) blockstatus(%d) cs(%s) PLEASE FIX!\n",
+					  cs_current_trans.headerTypeData(),
+					  *block_status_dl, cs_init.name());
 				break;
 
 			}
@@ -1379,23 +1355,11 @@ enum egprs_rlcmac_dl_spb gprs_rlcmac_dl_tbf::get_egprs_dl_spb(const int bsn)
 	return EGPRS_RLCMAC_DL_NO_RETX;
 }
 
-void gprs_rlcmac_dl_tbf::egprs_calc_window_size()
+void gprs_rlcmac_dl_tbf::set_window_size()
 {
-	struct gprs_rlcmac_bts *bts_data = bts->bts_data();
-	unsigned int num_pdch = pcu_bitcount(dl_slots());
-	unsigned int ws = bts_data->ws_base + num_pdch * bts_data->ws_pdch;
-
-	ws = (ws / 32) * 32;
-	ws = OSMO_MAX(64, ws);
-
-	if (num_pdch == 1)
-		ws = OSMO_MIN(192, ws);
-	else
-		ws = OSMO_MIN(128 * num_pdch, ws);
-
-	LOGP(DRLCMAC, LOGL_INFO, "%s: Setting EGPRS window size to %d\n",
-		name(), ws);
-
+	uint16_t ws = egprs_window_size(bts->bts_data(), dl_slots());
+	LOGPTBFDL(this, LOGL_INFO, "setting EGPRS DL window size to %u, base(%u) slots(%u) ws_pdch(%u)\n",
+		  ws, bts->bts_data()->ws_base, pcu_bitcount(dl_slots()), bts->bts_data()->ws_pdch);
 	m_window.set_ws(ws);
 }