From a42d795002b958bacfa3ab7d28769cffb83632a6 Mon Sep 17 00:00:00 2001 From: Thomas Kolb Date: Tue, 7 May 2024 21:40:29 +0200 Subject: [PATCH] Dump debug info from the RX via jsonlogger --- impl/CMakeLists.txt | 4 ++ impl/src/debug_structs.h | 23 ++++++++ impl/src/jsonlogger.c | 45 +++++++++++++++ impl/src/jsonlogger.h | 1 + impl/src/layer1/rx.c | 94 ++++++++++++++++++++++++++------ impl/src/layer1/rx.h | 10 +++- impl/src/main.c | 6 +- impl/src/var_array.c | 48 ++++++++++++++++ impl/src/var_array.h | 22 ++++++++ impl/test/CMakeLists.txt | 4 ++ impl/test/layer1/test_loopback.c | 12 +++- impl/test/layer1/test_rx_file.c | 7 ++- 12 files changed, 253 insertions(+), 23 deletions(-) create mode 100644 impl/src/var_array.c create mode 100644 impl/src/var_array.h diff --git a/impl/CMakeLists.txt b/impl/CMakeLists.txt index b248034..679dfc1 100644 --- a/impl/CMakeLists.txt +++ b/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 diff --git a/impl/src/debug_structs.h b/impl/src/debug_structs.h index c1ca239..a54393f 100644 --- a/impl/src/debug_structs.h +++ b/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; diff --git a/impl/src/jsonlogger.c b/impl/src/jsonlogger.c index 4bb824d..d3c2de0 100644 --- a/impl/src/jsonlogger.c +++ b/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(); +} diff --git a/impl/src/jsonlogger.h b/impl/src/jsonlogger.h index ba523e2..71e273f 100644 --- a/impl/src/jsonlogger.h +++ b/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 diff --git a/impl/src/layer1/rx.c b/impl/src/layer1/rx.c index 8fffc62..852dd26 100644 --- a/impl/src/layer1/rx.c +++ b/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()]; - //correlator_get_input_history(&rx->preamble_correlator, input_history); + // store debug info + 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"); - //DEBUG_LOG("import matplotlib.pyplot as pp\n"); - //print_complex_array("pre", preamble_get_symbols(), preamble_get_symbol_count()); - //print_complex_array("recv", input_history, preamble_get_symbol_count()); - //DEBUG_LOG("pp.plot(np.angle(recv * pre.conj()))\n"); - //DEBUG_LOG("pp.show()\n"); + float complex input_history[preamble_get_symbol_count()]; + correlator_get_input_history(&rx->preamble_correlator, input_history); + + for(size_t i = 0; i < preamble_get_symbol_count(); i++) { + var_array_cf_append(&rx->packet_debug_info.preamble_symbols, input_history[i]); + } // 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); diff --git a/impl/src/layer1/rx.h b/impl/src/layer1/rx.h index cb6230a..7ddac52 100644 --- a/impl/src/layer1/rx.h +++ b/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; diff --git a/impl/src/main.c b/impl/src/main.c index f36f605..0eb265f 100644 --- a/impl/src/main.c +++ b/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); diff --git a/impl/src/var_array.c b/impl/src/var_array.c new file mode 100644 index 0000000..2acc3a2 --- /dev/null +++ b/impl/src/var_array.c @@ -0,0 +1,48 @@ +#include + +#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; +} diff --git a/impl/src/var_array.h b/impl/src/var_array.h new file mode 100644 index 0000000..d1cf525 --- /dev/null +++ b/impl/src/var_array.h @@ -0,0 +1,22 @@ +#ifndef VAR_ARRAY_H +#define VAR_ARRAY_H + +#include +#include +#include + +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 diff --git a/impl/test/CMakeLists.txt b/impl/test/CMakeLists.txt index 69089ec..c4d4f7c 100644 --- a/impl/test/CMakeLists.txt +++ b/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 ) diff --git a/impl/test/layer1/test_loopback.c b/impl/test/layer1/test_loopback.c index 739d62e..c44b308 100644 --- a/impl/test/layer1/test_loopback.c +++ b/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; } } diff --git a/impl/test/layer1/test_rx_file.c b/impl/test/layer1/test_rx_file.c index 06a5c4c..fbac813 100644 --- a/impl/test/layer1/test_rx_file.c +++ b/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; } }