Dump debug info from the RX via jsonlogger

impl/CMakeLists.txt

@@ -10,6 +10,10 @@ include_directories(src)
 set(sources
 	src/utils.c
 	src/utils.h
+	src/jsonlogger.c
+	src/jsonlogger.h
+	src/var_array.c
+	src/var_array.h
 	src/options.c
 	src/options.h
 	src/main.c

impl/src/debug_structs.h

@@ -1,6 +1,29 @@
 #ifndef DEBUG_STRUCTS_H
 #define DEBUG_STRUCTS_H
 
+#include "var_array.h"
+
+typedef struct
+{
+	var_array_cf_t preamble_symbols;
+	var_array_cf_t header_symbols;
+	var_array_cf_t data_symbols;
+
+	float preamble_correlation_peak;
+
+	float header_rssi;       // in dB
+	float data_rssi;         // in dB
+	float noise_floor_level; // in dB
+
+	float carrier_tracked_freq;  // in Hz
+	float initial_freq_offset;   // in Hz
+	float final_freq_offset;     // in Hz
+
+	float header_evm; // average error vector magnitude over header
+	float data_evm;   // average error vector magnitude over data
+} rx_packet_dbg_t;
+
+
 typedef struct {
 	size_t preambles_found;
 	size_t successful_decodes;

impl/src/jsonlogger.c

@@ -68,6 +68,21 @@ static bool end_message(void)
 	return true;
 }
 
+static bool dump_var_array_cf(const var_array_cf_t *varray)
+{
+	LOG_OR_RETURN("[");
+
+	if(varray->used > 0) {
+		LOG_OR_RETURN("[%g, %g]", crealf(varray->symbols[0]), cimagf(varray->symbols[0]));
+
+		for(size_t i = 1; i < varray->used; i++) {
+			LOG_OR_RETURN(", [%g, %g]", crealf(varray->symbols[i]), cimagf(varray->symbols[i]));
+		}
+	}
+
+	LOG_OR_RETURN("]");
+}
+
 
 bool jsonlogger_init(const char *fifoname)
 {
@@ -131,3 +146,33 @@ bool jsonlogger_log_rx_stats(const rx_stats_t *rx_stats)
 
 	return end_message();
 }
+
+
+bool jsonlogger_log_rx_packet_info(const rx_packet_dbg_t *rx_packet_dbg)
+{
+	if(!start_message()) {
+		return false;
+	}
+
+	LOG_OR_RETURN("\"preamble_symbols\": ");
+	dump_var_array_cf(&rx_packet_dbg->preamble_symbols);
+	LOG_OR_RETURN(", \"header_symbols\": ");
+	dump_var_array_cf(&rx_packet_dbg->header_symbols);
+	LOG_OR_RETURN(", \"data_symbols\": ");
+	dump_var_array_cf(&rx_packet_dbg->data_symbols);
+	LOG_OR_RETURN(", ");
+
+	LOG_OR_RETURN("\"preamble_correlation_peak\": %g, ", rx_packet_dbg->preamble_correlation_peak);
+	LOG_OR_RETURN("\"header_rssi_dB\": %g, ", rx_packet_dbg->header_rssi);
+	LOG_OR_RETURN("\"data_rssi_dB\": %g, ", rx_packet_dbg->data_rssi);
+	LOG_OR_RETURN("\"noise_floor_level_dB\": %g, ", rx_packet_dbg->noise_floor_level);
+
+	LOG_OR_RETURN("\"carrier_tracked_freq_Hz\": %g, ", rx_packet_dbg->carrier_tracked_freq);
+	LOG_OR_RETURN("\"initial_freq_offset_Hz\": %g, ", rx_packet_dbg->initial_freq_offset);
+	LOG_OR_RETURN("\"final_freq_offset_Hz\": %g, ", rx_packet_dbg->final_freq_offset);
+
+	LOG_OR_RETURN("\"header_evm\": %g, ", rx_packet_dbg->header_evm);
+	LOG_OR_RETURN("\"data_evm\": %g", rx_packet_dbg->data_evm);
+
+	return end_message();
+}

impl/src/jsonlogger.h

@@ -26,5 +26,6 @@ bool jsonlogger_log_simple_integer(const char *msg_type, int64_t value);
 bool jsonlogger_log_simple_double(const char *msg_type, double value);
 
 bool jsonlogger_log_rx_stats(const rx_stats_t *rx_stats);
+bool jsonlogger_log_rx_packet_info(const rx_packet_dbg_t *rx_packet_dbg);
 
 #endif // JSONLOGGER_H

impl/src/layer1/rx.c

@@ -50,6 +50,27 @@ static void update_nco_pll(nco_crcf nco, float phase_error, float bw)
 }
 
 
+static void reset_packet_debug_info(layer1_rx_t *rx)
+{
+	var_array_cf_clear(&rx->packet_debug_info.preamble_symbols);
+	var_array_cf_clear(&rx->packet_debug_info.header_symbols);
+	var_array_cf_clear(&rx->packet_debug_info.data_symbols);
+
+	rx->packet_debug_info.preamble_correlation_peak = 0.0f;
+
+	rx->packet_debug_info.header_rssi = -1e38f;
+	rx->packet_debug_info.data_rssi = -1e38f;
+	rx->packet_debug_info.noise_floor_level = -1e38f;
+
+	rx->packet_debug_info.carrier_tracked_freq = -1e38f;
+	rx->packet_debug_info.initial_freq_offset = -1e38f;
+	rx->packet_debug_info.final_freq_offset = -1e38f;
+
+	rx->packet_debug_info.header_evm = -1e38f;
+	rx->packet_debug_info.data_evm = -1e38f;
+}
+
+
 static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool do_coarse_freq_est)
 {
 	static float complex freq_est_history[FREQ_EST_L];
@@ -59,10 +80,13 @@ static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool d
 
 	// preamble search
 	float complex corr_out = correlator_step(&rx->preamble_correlator, sample);
+	float         abs_corr_out = cabsf(corr_out);
 
-	if(cabsf(corr_out) > 0.5f * preamble_get_symbol_count()) {
+	if(abs_corr_out > 0.5f * preamble_get_symbol_count()) {
 		// Preamble found!
-		DEBUG_LOG("Preamble found: %.3f > %.3f\n", cabsf(corr_out), 0.5f * preamble_get_symbol_count());
+		DEBUG_LOG("Preamble found: %.3f > %.3f\n", abs_corr_out, 0.5f * preamble_get_symbol_count());
+
+		rx->packet_debug_info.preamble_correlation_peak = abs_corr_out;
 
 		float phase_offset;
 		float mean_frequency_error = correlator_get_mean_frequency_deviation(&rx->preamble_correlator, FREQ_EST_L, &phase_offset);
@@ -78,15 +102,16 @@ static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool d
 		float ffine = nco_crcf_get_frequency(rx->carrier_fine_nco);
 		DEBUG_LOG("New estimated carrier frequency: %.6f + %.6f/4 = %.6f rad/sample\n", fcoarse, ffine, fcoarse+ffine/4);
 
-		//float complex input_history[preamble_get_symbol_count()];
+		// store debug info
-		//correlator_get_input_history(&rx->preamble_correlator, input_history);
+		rx->packet_debug_info.carrier_tracked_freq = fcoarse * 4 * SYMBOL_RATE / (2.0f * (float)M_PI);
+		rx->packet_debug_info.initial_freq_offset = (fcoarse * 4 + ffine) * SYMBOL_RATE / (2.0f * (float)M_PI);
 
-		//DEBUG_LOG("import numpy as np\n");
+		float complex input_history[preamble_get_symbol_count()];
-		//DEBUG_LOG("import matplotlib.pyplot as pp\n");
+		correlator_get_input_history(&rx->preamble_correlator, input_history);
-		//print_complex_array("pre", preamble_get_symbols(), preamble_get_symbol_count());
+
-		//print_complex_array("recv", input_history, preamble_get_symbol_count());
+		for(size_t i = 0; i < preamble_get_symbol_count(); i++) {
-		//DEBUG_LOG("pp.plot(np.angle(recv * pre.conj()))\n");
+			var_array_cf_append(&rx->packet_debug_info.preamble_symbols, input_history[i]);
-		//DEBUG_LOG("pp.show()\n");
+		}
 
 		// start over with frequency estimation when preamble search restarts.
 		freq_est_history_write_idx = 0;
@@ -291,7 +316,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 
 					if(acquire_preamble(rx, symsync_out, !is_central_node)) {
 						// Preamble found and frequency corrected!
-						rx->callback(RX_EVT_PREAMBLE_FOUND, NULL, 0);
+						rx->callback(RX_EVT_PREAMBLE_FOUND, rx, NULL, 0);
 
 						// switch AGC to tracking mode
 						agc_crcf_set_bandwidth(rx->agc, AGC_BW_TRACKING);
@@ -306,6 +331,8 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 					nco_crcf_step(rx->carrier_fine_nco);
 					nco_crcf_mix_down(rx->carrier_fine_nco, symsync_out, &mixed_sample);
 
+					var_array_cf_append(&rx->packet_debug_info.header_symbols, mixed_sample);
+
 					if(symbol_counter < rx->hdr_len_symbols) {
 						unsigned int sym_demod;
 						modem_demodulate(rx->hdr_demod, mixed_sample, &sym_demod);
@@ -326,6 +353,11 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 						uint8_t header_enc[rx->hdr_len_enc_bytes];
 						uint8_t header[HEADER_SIZE_BYTES];
 
+						// store debug info about the header
+						rx->packet_debug_info.noise_floor_level = rx->noise_floor_level;
+						rx->packet_debug_info.header_rssi = agc_crcf_get_rssi(rx->agc);
+						rx->packet_debug_info.header_evm = -1e38f; // FIXME
+
 						ERR_CHECK_LIQUID(liquid_repack_bytes(
 									symbols_int, modem_get_bps(rx->hdr_demod), rx->hdr_len_symbols,
 									header_enc, 8, sizeof(header_enc), &nsyms));
@@ -333,7 +365,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 						if(fec_decode(rx->hdr_fec, sizeof(header), header_enc, header) != LIQUID_OK) {
 							DEBUG_LOG("Header decoding failed!\n");
 							rx->state = RX_STATE_ACQUISITION;
-							rx->callback(RX_EVT_HEADER_ERROR, NULL, 0);
+							rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0);
 							break;
 						}
 
@@ -343,7 +375,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 							DEBUG_LOG("Header CRC check failed! Expected: 0x%02x, received: 0x%02x\n",
 									expected_crc, header[4]);
 							rx->state = RX_STATE_ACQUISITION;
-							rx->callback(RX_EVT_HEADER_ERROR, NULL, 0);
+							rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0);
 							break;
 						}
 
@@ -355,7 +387,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 						if(!MODCOD_IS_VALID(rx->modcod)) {
 							DEBUG_LOG("Decoded MODCOD %d is invalid!\n", rx->modcod);
 							rx->state = RX_STATE_ACQUISITION;
-							rx->callback(RX_EVT_HEADER_ERROR, NULL, 0);
+							rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0);
 							break;
 						}
 
@@ -363,7 +395,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 						if(rx->payload_len_bytes == 0) {
 							DEBUG_LOG("Packet length %u is not supported.\n", rx->payload_len_bytes);
 							rx->state = RX_STATE_ACQUISITION;
-							rx->callback(RX_EVT_HEADER_ERROR, NULL, 0);
+							rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0);
 							break;
 						}
 
@@ -376,7 +408,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 						if(rx->payload_len_symbols > SYMBOL_BUFFER_SIZE) {
 							DEBUG_LOG("Symbol count %u is too lange for buffer. Ignoring packet.\n", rx->payload_len_symbols);
 							rx->state = RX_STATE_ACQUISITION;
-							rx->callback(RX_EVT_HEADER_ERROR, NULL, 0);
+							rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0);
 							break;
 						}
 
@@ -398,6 +430,8 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 					nco_crcf_step(rx->carrier_fine_nco);
 					nco_crcf_mix_down(rx->carrier_fine_nco, symsync_out, &mixed_sample);
 
+					var_array_cf_append(&rx->packet_debug_info.data_symbols, mixed_sample);
+
 					samples2dump2[nsamples2dump2++] = mixed_sample;
 					if(symbol_counter < rx->payload_len_symbols) {
 						unsigned int sym_demod;
@@ -417,6 +451,10 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 						unsigned char payload_enc[rx->payload_len_enc_bytes];
 						unsigned char payload[rx->payload_len_bytes+1];
 
+						// store debug info about the data
+						rx->packet_debug_info.data_rssi = agc_crcf_get_rssi(rx->agc);
+						rx->packet_debug_info.data_evm = -1e38f; // FIXME
+
 						ERR_CHECK_LIQUID(liquid_repack_bytes(
 									symbols_int, modem_get_bps(rx->payload_demod), rx->payload_len_symbols,
 									payload_enc, 8, sizeof(payload_enc), &nsyms));
@@ -434,9 +472,9 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 
 						//dump_array_cf(symbols_cpx, symbol_counter, 1.0f, "/tmp/payload.cpx");
 						if(valid) {
-							rx->callback(RX_EVT_PACKET_RECEIVED, payload, rx->payload_len_bytes);
+							rx->callback(RX_EVT_PACKET_RECEIVED, rx, payload, rx->payload_len_bytes);
 						} else {
-							rx->callback(RX_EVT_CHECKSUM_ERROR, payload, rx->payload_len_bytes);
+							rx->callback(RX_EVT_CHECKSUM_ERROR, rx, payload, rx->payload_len_bytes);
 						}
 
 						modem_destroy(rx->payload_demod);
@@ -451,6 +489,15 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t
 				// ensure the AGC is in acquisition mode again when
 				// RX_STATE_ACQUISITION is entered.
 				agc_crcf_set_bandwidth(rx->agc, AGC_BW_ACQUISITION);
+
+				// store final debug information
+				float fcoarse = nco_crcf_get_frequency(rx->carrier_coarse_nco);
+				float ffine = nco_crcf_get_frequency(rx->carrier_fine_nco);
+
+				rx->packet_debug_info.final_freq_offset = (fcoarse * 4 + ffine) * SYMBOL_RATE / (2.0f * (float)M_PI);
+				rx->callback(RX_EVT_PACKET_DEBUG_INFO_COMPLETE, rx, NULL, 0);
+
+				reset_packet_debug_info(rx);
 			}
 		}
 	}
@@ -508,12 +555,23 @@ result_t layer1_rx_init(layer1_rx_t *rx, rx_callback_t callback)
 	rx->hdr_len_enc_bytes = fec_get_enc_msg_length(HEADER_CHANNEL_CODE, HEADER_SIZE_BYTES);
 	rx->hdr_len_symbols = (rx->hdr_len_enc_bytes * 8 + hdr_bps - 1) / hdr_bps;
 
+	// initialize debug info
+	var_array_cf_init(&rx->packet_debug_info.preamble_symbols);
+	var_array_cf_init(&rx->packet_debug_info.header_symbols);
+	var_array_cf_init(&rx->packet_debug_info.data_symbols);
+
+	reset_packet_debug_info(rx);
+
 	return OK;
 }
 
 
 result_t layer1_rx_shutdown(layer1_rx_t *rx)
 {
+	var_array_cf_free(&rx->packet_debug_info.preamble_symbols);
+	var_array_cf_free(&rx->packet_debug_info.header_symbols);
+	var_array_cf_free(&rx->packet_debug_info.data_symbols);
+
 	firfilt_crcf_destroy(rx->channel_filter);
 
 	agc_crcf_destroy(rx->agc);

impl/src/layer1/rx.h

@@ -5,6 +5,7 @@
 
 #include "modcod.h"
 #include "correlator.h"
+#include "debug_structs.h"
 
 #include "results.h"
 
@@ -20,13 +21,15 @@ typedef enum {
 	RX_EVT_PREAMBLE_FOUND,
 	RX_EVT_HEADER_ERROR,
 	RX_EVT_CHECKSUM_ERROR,
+	RX_EVT_PACKET_DEBUG_INFO_COMPLETE,
 } rx_evt_t;
 
 
-typedef void (*rx_callback_t)(rx_evt_t evt, uint8_t *packet_data, size_t packet_len);
+struct layer1_rx_s;
+typedef void (*rx_callback_t)(rx_evt_t evt, const struct layer1_rx_s *rx, uint8_t *packet_data, size_t packet_len);
 
 
-typedef struct
+typedef struct layer1_rx_s
 {
 	// Input channel filter
 	firfilt_crcf channel_filter;
@@ -69,6 +72,9 @@ typedef struct
 	uint16_t payload_crc;
 	uint16_t payload_len_enc_bytes;
 	modcod_t modcod;
+
+	// packet debugging information
+	rx_packet_dbg_t packet_debug_info;
 } layer1_rx_t;
 
 

impl/src/main.c

@@ -108,7 +108,7 @@ void hexdump(const uint8_t *data, size_t len)
 }
 
 
-void cb_rx(rx_evt_t evt, uint8_t *packet_data, size_t packet_len)
+void cb_rx(rx_evt_t evt, const struct layer1_rx_s *rx, uint8_t *packet_data, size_t packet_len)
 {
 	int ret;
 
@@ -147,6 +147,10 @@ void cb_rx(rx_evt_t evt, uint8_t *packet_data, size_t packet_len)
 			block_tx_for(TX_SWITCH_BACKOFF_PREAMBLE_MS);
 			m_rx_stats.preambles_found++;
 			break;
+
+		case RX_EVT_PACKET_DEBUG_INFO_COMPLETE:
+			jsonlogger_log_rx_packet_info(&rx->packet_debug_info);
+			break;
 	}
 
 	jsonlogger_log_rx_stats(&m_rx_stats);

impl/src/var_array.c

@@ -0,0 +1,48 @@
+#include <stdio.h>
+
+#include "var_array.h"
+
+bool var_array_cf_init(var_array_cf_t *array)
+{
+	array->used = 0;
+	array->allocated = 64;
+	array->symbols = reallocarray(NULL, array->allocated, sizeof(float complex));
+
+	return (array->symbols != NULL);
+}
+
+
+void var_array_cf_free(var_array_cf_t *array)
+{
+	if(array->symbols) {
+		free(array->symbols);
+		array->symbols = NULL;
+	}
+
+	array->used = 0;
+	array->allocated = 0;
+}
+
+void var_array_cf_clear(var_array_cf_t *array)
+{
+	array->used = 0;
+}
+
+bool var_array_cf_append(var_array_cf_t *array, float complex symbol)
+{
+	if(array->used == array->allocated) {
+		size_t new_size = 2 * array->allocated;
+		float complex *new_symbols = reallocarray(array->symbols, new_size, sizeof(float complex));
+
+		if(!new_symbols) {
+			perror("reallocarray");
+			return false;
+		}
+
+		array->allocated = new_size;
+		array->symbols = new_symbols;
+	}
+
+	array->symbols[array->used++] = symbol;
+	return true;
+}

impl/src/var_array.h

@@ -0,0 +1,22 @@
+#ifndef VAR_ARRAY_H
+#define VAR_ARRAY_H
+
+#include <stdbool.h>
+#include <stdlib.h>
+#include <complex.h>
+
+typedef struct
+{
+	float complex *symbols;
+	size_t         used;
+	size_t         allocated;
+} var_array_cf_t;
+
+
+bool var_array_cf_init(var_array_cf_t *array);
+void var_array_cf_free(var_array_cf_t *array);
+
+void var_array_cf_clear(var_array_cf_t *array);
+bool var_array_cf_append(var_array_cf_t *array, float complex symbol);
+
+#endif // VAR_ARRAY_H

impl/test/CMakeLists.txt

@@ -38,6 +38,8 @@ add_executable(
 	../src/layer1/modcod.h
 	../src/utils.c
 	../src/utils.h
+	../src/var_array.c
+	../src/var_array.h
 	../src/options.c
 	../src/options.h
 	layer1/test_loopback.c
@@ -89,6 +91,8 @@ add_executable(
 	../src/utils.h
 	../src/options.c
 	../src/options.h
+	../src/var_array.c
+	../src/var_array.h
 	../src/config.h
 	layer1/test_rx_file.c
 )

impl/test/layer1/test_loopback.c

@@ -76,8 +76,10 @@ void hexdump(const uint8_t *data, size_t len)
 }
 
 
-void cb_rx(rx_evt_t evt, uint8_t *packet_data, size_t packet_len)
+void cb_rx(rx_evt_t evt, const layer1_rx_t *rx, uint8_t *packet_data, size_t packet_len)
 {
+	(void)rx;
+
 	switch(evt)
 	{
 		case RX_EVT_CHECKSUM_ERROR:
@@ -94,9 +96,17 @@ void cb_rx(rx_evt_t evt, uint8_t *packet_data, size_t packet_len)
 			fprintf(stderr, "====================================\n");
 			break;
 
+		case RX_EVT_HEADER_ERROR:
+			fprintf(stderr, "Header decoding failed!\n");
+			break;
+
 		case RX_EVT_PREAMBLE_FOUND:
 			fprintf(stderr, "Found preamble!\n");
 			break;
+
+		case RX_EVT_PACKET_DEBUG_INFO_COMPLETE:
+			// FIXME: print debug info
+			break;
 	}
 }
 

impl/test/layer1/test_rx_file.c

@@ -56,10 +56,11 @@ static result_t sdr_rf_to_baseband(nco_crcf nco, firdecim_crcf  decim,
 }
 
 
-void cb_rx(rx_evt_t evt, uint8_t *packet_data, size_t packet_len)
+void cb_rx(rx_evt_t evt, const layer1_rx_t *rx, uint8_t *packet_data, size_t packet_len)
 {
 	(void)packet_data;
 	(void)packet_len;
+	(void)rx;
 
 	switch(evt)
 	{
@@ -88,6 +89,10 @@ void cb_rx(rx_evt_t evt, uint8_t *packet_data, size_t packet_len)
 			//fprintf(stderr, "Found preamble!\n");
 			m_stats.preambles_found++;
 			break;
+
+		case RX_EVT_PACKET_DEBUG_INFO_COMPLETE:
+			// FIXME: print debug info
+			break;
 	}
 }