Simplify polling troubleshooting

* introduce enum describing poll kind and use it in set_polling()
* move state change into set_polling()
* move logging into set_polling() and unify output
* move duplicated code into static function
* adjust tests to match unified logging output

Change-Id: I14074207f8bbc18b3ebd60875bb99a0a3a4b399d
Related: OS#1524
diff --git a/src/bts.cpp b/src/bts.cpp
index 0f67536..add6ab3 100644
--- a/src/bts.cpp
+++ b/src/bts.cpp
@@ -1381,7 +1381,9 @@
 		}
 
 		/* set control ts to current MS's TS, until assignment complete */
-		LOGP(DRLCMAC, LOGL_DEBUG, "Change control TS to %d until assinment is complete.\n", ts_no);
+		LOGP(DRLCMAC, LOGL_DEBUG, "%s change control TS %d -> %d until assinment is complete.\n",
+		     tbf_name(ul_tbf), ul_tbf->control_ts, ts_no);
+
 		ul_tbf->control_ts = ts_no;
 		/* schedule uplink assignment */
 		ul_tbf->ul_ass_state = GPRS_RLCMAC_UL_ASS_SEND_ASS;
diff --git a/src/tbf.cpp b/src/tbf.cpp
index 5b28d9b..c5f4348 100644
--- a/src/tbf.cpp
+++ b/src/tbf.cpp
@@ -593,16 +593,50 @@
 	return 0;
 }
 
-void gprs_rlcmac_tbf::set_polling(uint32_t new_poll_fn, uint8_t ts)
+void gprs_rlcmac_tbf::set_polling(uint32_t new_poll_fn, uint8_t ts, enum gprs_rlcmac_tbf_poll_type t)
 {
-	LOGP(DRLCMAC, LOGL_DEBUG,
-		"%s: Scheduling polling at FN %d TS %d\n",
-		name(), new_poll_fn, ts);
+	const char *chan = "UNKNOWN";
+
+	if (state_flags & (1 << (GPRS_RLCMAC_FLAG_CCCH)))
+		chan = "CCCH";
+
+	if (state_flags & (1 << (GPRS_RLCMAC_FLAG_PACCH)))
+		chan = "PACCH";
+
+	if ((state_flags & (1 << (GPRS_RLCMAC_FLAG_PACCH))) && (state_flags & (1 << (GPRS_RLCMAC_FLAG_CCCH))))
+		LOGP(DRLCMACDL, LOGL_ERROR,
+		     "%s Attempt to schedule polling on %s (FN=%d, TS=%d) with both CCCH and PACCH flags set - FIXME!\n",
+		     name(), chan, poll_fn, poll_ts);
 
 	/* schedule polling */
 	poll_state = GPRS_RLCMAC_POLL_SCHED;
 	poll_fn = new_poll_fn;
 	poll_ts = ts;
+
+	switch (t) {
+	case GPRS_RLCMAC_POLL_UL_ASS:
+		ul_ass_state = GPRS_RLCMAC_UL_ASS_WAIT_ACK;
+
+		LOGP(DRLCMACDL, LOGL_INFO, "%s Scheduled UL Assignment polling on %s (FN=%d, TS=%d)\n",
+		     name(), chan, poll_fn, poll_ts);
+		break;
+	case GPRS_RLCMAC_POLL_DL_ASS:
+		dl_ass_state = GPRS_RLCMAC_DL_ASS_WAIT_ACK;
+
+		LOGP(DRLCMACDL, LOGL_INFO, "%s Scheduled DL Assignment polling on %s (FN=%d, TS=%d)\n",
+		     name(), chan, poll_fn, poll_ts);
+		break;
+	case GPRS_RLCMAC_POLL_UL_ACK:
+		ul_ack_state = GPRS_RLCMAC_UL_ACK_WAIT_ACK;
+
+		LOGP(DRLCMACUL, LOGL_DEBUG, "%s Scheduled UL Acknowledgement polling on %s (FN=%d, TS=%d)\n",
+		     name(), chan, poll_fn, poll_ts);
+		break;
+	case GPRS_RLCMAC_POLL_DL_ACK:
+		LOGP(DRLCMACDL, LOGL_DEBUG, "%s Scheduled DL Acknowledgement polling on %s (FN=%d, TS=%d)\n",
+		     name(), chan, poll_fn, poll_ts);
+		break;
+	}
 }
 
 void gprs_rlcmac_tbf::poll_timeout()
@@ -1152,11 +1186,7 @@
 	talloc_free(mac_control_block);
 
 	if (poll_ass_dl) {
-		set_polling(new_poll_fn, ts);
-		dl_ass_state = GPRS_RLCMAC_DL_ASS_WAIT_ACK;
-		LOGP(DRLCMACDL, LOGL_INFO,
-			"%s Scheduled DL Assignment polling on FN=%d, TS=%d\n",
-			name(), poll_fn, poll_ts);
+		set_polling(new_poll_fn, ts, GPRS_RLCMAC_POLL_DL_ASS);
 	} else {
 		dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
 		new_dl_tbf->set_state(GPRS_RLCMAC_FLOW);
@@ -1253,11 +1283,7 @@
 	bitvec_free(ass_vec);
 	talloc_free(mac_control_block);
 
-	set_polling(new_poll_fn, ts);
-	ul_ass_state = GPRS_RLCMAC_UL_ASS_WAIT_ACK;
-	LOGP(DRLCMACDL, LOGL_INFO,
-		"%s Scheduled UL Assignment polling on FN=%d, TS=%d\n",
-		name(), poll_fn, poll_ts);
+	set_polling(new_poll_fn, ts, GPRS_RLCMAC_POLL_UL_ASS);
 
 	return msg;
 }
diff --git a/src/tbf.h b/src/tbf.h
index 9cc70e6..95e1e89 100644
--- a/src/tbf.h
+++ b/src/tbf.h
@@ -54,6 +54,13 @@
 	GPRS_RLCMAC_RELEASING,	/* releasing, wait to free TBI/USF */
 };
 
+enum gprs_rlcmac_tbf_poll_type {
+	GPRS_RLCMAC_POLL_UL_ASS,
+	GPRS_RLCMAC_POLL_DL_ASS,
+	GPRS_RLCMAC_POLL_UL_ACK,
+	GPRS_RLCMAC_POLL_DL_ACK,
+};
+
 enum gprs_rlcmac_tbf_poll_state {
 	GPRS_RLCMAC_POLL_NONE = 0,
 	GPRS_RLCMAC_POLL_SCHED, /* a polling was scheduled */
@@ -173,7 +180,7 @@
 
 	int check_polling(uint32_t fn, uint8_t ts,
 		uint32_t *poll_fn, unsigned int *rrbp);
-	void set_polling(uint32_t poll_fn, uint8_t ts);
+	void set_polling(uint32_t poll_fn, uint8_t ts, enum gprs_rlcmac_tbf_poll_type t);
 	void poll_timeout();
 
 	/** tlli handling */
diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp
index 8ce13a7..b350720 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -853,10 +853,8 @@
 
 		rc = check_polling(fn, ts, &new_poll_fn, &rrbp);
 		if (rc >= 0) {
-			set_polling(new_poll_fn, ts);
+			set_polling(new_poll_fn, ts, GPRS_RLCMAC_POLL_DL_ACK);
 
-			LOGP(DRLCMACDL, LOGL_DEBUG, "Polling scheduled in this "
-				"TS %d\n", ts);
 			m_tx_counter = 0;
 			/* start timer whenever we send the final block */
 			if (is_final)
diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp
index 1e0898a..81d3b24 100644
--- a/src/tbf_ul.cpp
+++ b/src/tbf_ul.cpp
@@ -158,9 +158,8 @@
 	m_contention_resolution_done = 1;
 
 	if (final) {
-		set_polling(new_poll_fn, ts);
+		set_polling(new_poll_fn, ts, GPRS_RLCMAC_POLL_UL_ACK);
 		/* waiting for final acknowledge */
-		ul_ack_state = GPRS_RLCMAC_UL_ACK_WAIT_ACK;
 		m_final_ack_sent = 1;
 	} else
 		ul_ack_state = GPRS_RLCMAC_UL_ACK_NONE;