Add Circular buffer changes for Long run debug

Adds Circular buffer implementation for long run debug and analysis
This has scope for changes based on the initial analysis of issue.
One can log contents in circular buffer at run time and analyse the log
offline when the issue is reproduced.

3 files changed, 106 insertions, 4 deletions

diff --git a/src/bts.cpp b/src/bts.cpp
index 7595c6a..26ff578 100644
--- a/src/bts.cpp
+++ b/src/bts.cpp
@@ -44,6 +44,9 @@ extern void *tall_pcu_ctx;
 
 static BTS s_bts;
 
+char log_xx[8000][500];
+uint32_t log_ptr = 0;
+extern bool error_hit ;
 /**
  * For gcc-4.4 compat do not use extended initializer list but keep the
  * order from the enum here. Once we support GCC4.7 and up we can change
@@ -485,6 +488,10 @@ int BTS::rcv_rach(uint8_t ra, uint32_t Fn, int16_t qta)
 
 	LOGP(DRLCMAC, LOGL_DEBUG, "MS requests UL TBF on RACH, so we provide "
 		"one:\n");
+#if 1
+	sprintf(log_xx[log_ptr++ % 8000],"MS req UTBF on RACH,provide "
+		"one:\n");
+#endif
 	if ((ra & 0xf8) == 0x70) {
 		LOGP(DRLCMAC, LOGL_DEBUG, "MS requests single block "
 			"allocation\n");
@@ -1051,6 +1058,12 @@ void gprs_rlcmac_pdch::rcv_control_egprs_dl_ack_nack(EGPRS_PD_AckNack_t *ack_nac
 	LOGP(DRLCMAC, LOGL_DEBUG,
 		"RX: [PCU <- BTS] %s EGPRS Packet Downlink Ack/Nack\n",
 		tbf_name(tbf));
+
+	gprs_rlcmac_dl_tbf *dl_tbf = as_dl_tbf(tbf);
+#if 1
+	sprintf(log_xx[log_ptr++ % 8000],"RX: [PCU <- BTS] %s EGPRS Packet Downlink Ack/Nack rx_fn(%d) ts(%d), poll_fn(%d) curr_fn(%d), va(%d) vs(%d)\n",
+		tbf_name(tbf), fn, ts_no, tbf->poll_fn, bts()->current_frame_number(), dl_tbf->m_window.v_a(), dl_tbf->m_window.v_s());
+#endif
 	tbf->poll_state = GPRS_RLCMAC_POLL_NONE;
 
 	LOGP(DRLCMAC, LOGL_DEBUG, "EGPRS ACK/NACK: "
@@ -1071,7 +1084,26 @@ void gprs_rlcmac_pdch::rcv_control_egprs_dl_ack_nack(EGPRS_PD_AckNack_t *ack_nac
 		tbf->m_window.v_s(),
 		osmo_hexdump((const uint8_t *)&ack_nack->EGPRS_AckNack.Desc.URBB,
 			sizeof(ack_nack->EGPRS_AckNack.Desc.URBB)));
-
+#if 1
+	sprintf(log_xx[log_ptr++ % 8000],"EGPRS ACK/NACK: "
+		"ut: %d, final: %d, bow: %d, eow: %d, ssn: %d, have_crbb: %d, "
+		"urbb_len:%d, %p, %p, %d, %d, win: %d-%d, urbb: %s\n",
+		(int)ack_nack->EGPRS_AckNack.UnionType,
+		(int)ack_nack->EGPRS_AckNack.Desc.FINAL_ACK_INDICATION,
+		(int)ack_nack->EGPRS_AckNack.Desc.BEGINNING_OF_WINDOW,
+		(int)ack_nack->EGPRS_AckNack.Desc.END_OF_WINDOW,
+		(int)ack_nack->EGPRS_AckNack.Desc.STARTING_SEQUENCE_NUMBER,
+		(int)ack_nack->EGPRS_AckNack.Desc.Exist_CRBB,
+		(int)ack_nack->EGPRS_AckNack.Desc.URBB_LENGTH,
+		(void *)&ack_nack->EGPRS_AckNack.UnionType,
+		(void *)&ack_nack->EGPRS_AckNack.Desc,
+		(int)offsetof(EGPRS_AckNack_t, Desc),
+		(int)offsetof(EGPRS_AckNack_w_len_t, Desc),
+		tbf->m_window.v_a(),
+		tbf->m_window.v_s(),
+		osmo_hexdump((const uint8_t *)&ack_nack->EGPRS_AckNack.Desc.URBB,
+			sizeof(ack_nack->EGPRS_AckNack.Desc.URBB)));
+#endif
 	bits.data = bits_data;
 	bits.data_len = sizeof(bits_data);
 	bits.cur_bit = 0;
@@ -1155,10 +1187,16 @@ void gprs_rlcmac_pdch::rcv_resource_request(Packet_Resource_Request_t *request,
 		}
 
 		if (dl_tbf) {
+			uint32_t log_ptrx = log_ptr;
+			sprintf(log_xx[log_ptr++ % 8000],"Got RACH from "
+				"TLLI=0x%08x while %s still exists. "
+				"Release pending DL TBF=%d llc_size(%d) llc_octets(%d) log_ptr(%d)\n", tlli,
+				tbf_name(dl_tbf), dl_tbf->tfi(),  dl_tbf->llc_queue()->size(), dl_tbf->llc_queue()->octets(), log_ptrx);
 			LOGP(DRLCMACUL, LOGL_NOTICE, "Got RACH from "
 				"TLLI=0x%08x while %s still exists. "
 				"Release pending DL TBF\n", tlli,
 				tbf_name(dl_tbf));
+			error_hit = true;
 			tbf_free(dl_tbf);
 			dl_tbf = NULL;
 		}
@@ -1392,6 +1430,9 @@ int gprs_rlcmac_pdch::rcv_block_gprs(uint8_t *data, uint32_t fn,
 		break;
 	case GPRS_RLCMAC_CONTROL_BLOCK:
 		block = bitvec_alloc(len);
+
+		sprintf(log_xx[log_ptr++ % 8000],"%x %x %x %x %x %x %x %x %x %x %x %x %x %x %x %x %x %x %x %x %x %x %x \n",data[0], data[1], data[2], data[3], data[4], data[5], data[6], data[7], data[8], data[9], data[10], data[11], data[12], data[13], data[14], data[15], data[16], data[17], data[18], data[19], data[20], data[21], data[22]);
+
 		if (!block)
 			return -ENOMEM;
 		bitvec_unpack(block, data);
diff --git a/src/tbf.cpp b/src/tbf.cpp
index c77c5ee..bfc9858 100644
--- a/src/tbf.cpp
+++ b/src/tbf.cpp
@@ -42,6 +42,10 @@ extern void *tall_pcu_ctx;
 
 static void tbf_timer_cb(void *_tbf);
 
+extern char log_xx[8000][500];
+extern uint32_t log_ptr;
+extern bool error_hit;
+
 gprs_rlcmac_tbf::Meas::Meas() :
 	rssi_sum(0),
 	rssi_num(0)
@@ -491,6 +495,11 @@ void gprs_rlcmac_tbf::set_polling(uint32_t new_poll_fn, uint8_t ts)
 		"%s: Scheduling polling at FN %d TS %d\n",
 		name(), new_poll_fn, ts);
 
+	gprs_rlcmac_dl_tbf *dl_tbf = as_dl_tbf(this);
+#if 1
+	 sprintf(log_xx[log_ptr++ % 8000],"%s: Sc poll FN %d TS %d cur_fn(%d) va(%d) vs(%d)\n",
+                name(), new_poll_fn, ts,  bts->current_frame_number(), dl_tbf->m_window.v_a(), dl_tbf->m_window.v_s() );
+#endif
 	/* schedule polling */
 	poll_state = GPRS_RLCMAC_POLL_SCHED;
 	poll_fn = new_poll_fn;
@@ -499,6 +508,9 @@ void gprs_rlcmac_tbf::set_polling(uint32_t new_poll_fn, uint8_t ts)
 
 void gprs_rlcmac_tbf::poll_timeout()
 {
+	sprintf(log_xx[log_ptr++ % 8000],"%s poll timeout for FN=%d, TS=%d (curr FN %d)\n",
+		tbf_name(this), poll_fn, poll_ts, bts->current_frame_number());
+
 	LOGP(DRLCMAC, LOGL_NOTICE, "%s poll timeout for FN=%d, TS=%d (curr FN %d)\n",
 		tbf_name(this), poll_fn, poll_ts, bts->current_frame_number());
 
@@ -540,6 +552,7 @@ void gprs_rlcmac_tbf::poll_timeout()
 		bts->rlc_ass_timedout();
 		if (n3105 == bts_data()->n3105) {
 			LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
+			sprintf(log_xx[log_ptr++ % 8000],"- N3105 exceeded 1 n3105(%d) cfg_n3105(%d) \n", n3105, bts_data()->n3105);
 			set_state(GPRS_RLCMAC_RELEASING);
 			tbf_timer_start(this, 3195, bts_data()->t3195, 0);
 			bts->rlc_ass_failed();
@@ -559,6 +572,9 @@ void gprs_rlcmac_tbf::poll_timeout()
 		n3105++;
 		bts->rlc_ass_timedout();
 		if (n3105 == bts->bts_data()->n3105) {
+#if 1
+			sprintf(log_xx[log_ptr++ % 8000],"- N3105 exceeded 2 n3105(%d) cfg_n3105(%d)\n", n3105, bts_data()->n3105);
+#endif
 			LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
 			set_state(GPRS_RLCMAC_RELEASING);
 			tbf_timer_start(this, 3195, bts_data()->t3195, 0);
@@ -571,6 +587,12 @@ void gprs_rlcmac_tbf::poll_timeout()
 		gprs_rlcmac_dl_tbf *dl_tbf = as_dl_tbf(this);
 
 		if (!(dl_tbf->state_flags & (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK))) {
+#if 1
+			sprintf(log_xx[log_ptr++ % 8000],"- Timeout for polling %s "
+				"PACKET DOWNLINK ACK. FN(%d) TS(%d) CURRENT_FN(%d) n3105(%d) cfgd_n3105(%d) va(%d) vs(%d)\n",
+			tbf_name(this),poll_fn, poll_ts, bts->current_frame_number(), dl_tbf->n3105, dl_tbf->bts->bts_data()->n3105, dl_tbf->m_window.v_a(), dl_tbf->m_window.v_s());
+#endif
+
 			LOGP(DRLCMAC, LOGL_NOTICE, "- Timeout for polling "
 				"PACKET DOWNLINK ACK.\n");
 			dl_tbf->rlcmac_diag();
@@ -582,6 +604,9 @@ void gprs_rlcmac_tbf::poll_timeout()
 		else
 			bts->rlc_ack_timedout();
 		if (dl_tbf->n3105 == dl_tbf->bts->bts_data()->n3105) {
+#if 1
+			sprintf(log_xx[log_ptr++ % 8000],"- N3105 exceeded 3 n3105(%d) cfg_n3105(%d)\n", dl_tbf->n3105, dl_tbf->bts->bts_data()->n3105);
+#endif
 			LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
 			dl_tbf->set_state(GPRS_RLCMAC_RELEASING);
 			tbf_timer_start(dl_tbf, 3195, dl_tbf->bts_data()->t3195, 0);
@@ -1168,10 +1193,17 @@ int gprs_rlcmac_tbf::set_tlli_from_ul(uint32_t new_tlli)
 	}
 
 	if (dl_tbf && dl_tbf->ms() != ms()) {
+		uint32_t log_ptrx = log_ptr;
 		LOGP(DRLCMACUL, LOGL_NOTICE, "Got RACH from "
 			"TLLI=0x%08x while %s still exists. "
 			"Killing pending DL TBF\n", tlli(),
 			tbf_name(dl_tbf));
+		sprintf(log_xx[log_ptr++ % 8000], "Got RACH from "
+			"TLLI=0x%08x while %s still exists. "
+			"Killing pending DL TBF llc_size(%d) llc_octets(%d) log_ptr(%d)\n", tlli(),
+			tbf_name(dl_tbf), dl_tbf->llc_queue()->size(), dl_tbf->llc_queue()->octets(), log_ptr);
+		error_hit = true;
+
 		tbf_free(dl_tbf);
 		dl_tbf = NULL;
 	}
diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp
index 74e3df9..0832827 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -43,7 +43,11 @@ extern "C" {
 
 /* After sending these frames, we poll for ack/nack. */
 #define POLL_ACK_AFTER_FRAMES 20
-
+extern char log_xx[8000][500];
+extern uint32_t log_ptr;
+bool  error_hit = false;
+int error_cnt = 0;
+int alive_cnt = 0;
 static inline void tbf_update_ms_class(struct gprs_rlcmac_tbf *tbf,
 					const uint8_t ms_class)
 {
@@ -357,9 +361,25 @@ int gprs_rlcmac_dl_tbf::take_next_bsn(uint32_t fn,
 	int data_len2, force_data_len = -1;
 	GprsCodingScheme cs2;
 	GprsCodingScheme force_cs;
+	int xx = 0;
 
 	bsn = m_window.resend_needed();
 
+	if (error_hit == true)
+		error_cnt++;
+
+	if (alive_cnt++ % 30000 == 0 )
+		LOGP(DRLCMAC, LOGL_ERROR, "dl Alive fn(%d) current_fn(%d)\n", fn,bts->current_frame_number());
+
+	if (error_cnt >= 100) {
+		LOGP(DRLCMAC, LOGL_ERROR, "log_ptr(%d)", log_ptr);
+
+		for(xx = 0; xx < 8000; xx++)
+			LOGP(DRLCMAC, LOGL_ERROR, log_xx[xx]);
+		error_cnt = 0;
+		log_ptr = 0;
+		error_hit = false;
+	}
 	if (previous_bsn >= 0) {
 		force_cs = m_rlc.block(previous_bsn)->cs_current_trans;
 		if (!force_cs.isEgprs())
@@ -727,6 +747,9 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 		LOGP(DRLCMACDL, LOGL_DEBUG, "- Copying data unit %d (BSN %d)\n",
 			data_block_idx, bsn);
 
+		sprintf(log_xx[log_ptr++ % 8000],"-%s %s Copying data unit %d (BSN %d) framenumber(%d) current_fn %d TS(%d)\n",
+				tbf_name(this),cs.name(), data_block_idx, bsn, fn, bts->current_frame_number(), ts);
+
 		Encoding::rlc_copy_from_aligned_buffer(&rlc, data_block_idx,
 			msg_data, block_data);
 		m_ctr_num_blocks[cs.to_num() - 1]++;
@@ -922,8 +945,14 @@ int gprs_rlcmac_dl_tbf::update_window(unsigned first_bsn,
 			 * control ack!
 			 * TODO: check whether this FIXME still makes sense
 			 */
-			LOGP(DRLCMACDL, LOGL_NOTICE, "- ack range is out of "
-				"V(A)..V(S) range %s Free TBF!\n", tbf_name(this));
+			uint32_t log_ptrx = log_ptr;
+			LOGP(DRLCMAC, LOGL_ERROR, "- ack range is out of "
+				"V(A) = %d ..V(S) = %d range %s Free TBF! num_blocks = %d dist = %d behind_last_bsn = %d first_bsn = %d log_ptr(%d)\n",m_window.v_a(), m_window.v_s(),
+				tbf_name(this), num_blocks, dist, behind_last_bsn, first_bsn, log_ptrx);
+			sprintf(log_xx[log_ptr++ % 8000],"- ack range is out of "
+				"V(A) = %d ..V(S) = %d range %s Free TBF! num_blocks = %d dist = %d behind_last_bsn = %d first_bsn = %d log_ptr(%d)\n",m_window.v_a(), m_window.v_s(),
+				tbf_name(this), num_blocks, dist, behind_last_bsn, first_bsn, log_ptrx);
+			 error_hit = true;
 			return 1; /* indicate to free TBF */
 		}
 	}