diff --git a/impl/src/layer1/rx.c b/impl/src/layer1/rx.c index 1a4e30a..43e09db 100644 --- a/impl/src/layer1/rx.c +++ b/impl/src/layer1/rx.c @@ -84,15 +84,16 @@ static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool d if(abs_corr_out > 0.5f * preamble_get_symbol_count()) { // Preamble found! - DEBUG_LOG("Preamble found: %.3f > %.3f\n", abs_corr_out, 0.5f * preamble_get_symbol_count()); + DEBUG_LOG("@%zu: Preamble found: %.3f > %.3f\n", rx->sample_index, + 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); - DEBUG_LOG("Phase offset: %.6f rad\n", phase_offset); - DEBUG_LOG("Preamble frequency deviation: %.6f rad/symbol\n", mean_frequency_error); + DEBUG_LOG("@%zu: Phase offset: %.6f rad\n", rx->sample_index, phase_offset); + DEBUG_LOG("@%zu: Preamble frequency deviation: %.6f rad/symbol\n", rx->sample_index, mean_frequency_error); // Set the fine carrier correction NCO to the values estimated from the preamble nco_crcf_set_frequency(rx->carrier_fine_nco, mean_frequency_error); @@ -100,7 +101,8 @@ static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool d float fcoarse = nco_crcf_get_frequency(rx->carrier_coarse_nco); 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); + DEBUG_LOG("@%zu: New estimated carrier frequency: %.6f + %.6f/4 = %.6f rad/sample\n", + rx->sample_index, fcoarse, ffine, fcoarse+ffine/4); // store debug info rx->packet_debug_info.carrier_tracked_freq = fcoarse * 4 * SYMBOL_RATE / (2.0f * (float)M_PI); @@ -119,7 +121,8 @@ static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool d return true; // preamble found! } else if(do_coarse_freq_est) { // preamble not found. - //DEBUG_LOG("Preamble not found: %.3f < %.3f\n", cabsf(corr_out), 0.5f * preamble_get_symbol_count()); + //DEBUG_LOG("@%zu: Preamble not found: %.3f < %.3f\n", + // rx->sample_index, cabsf(corr_out), 0.5f * preamble_get_symbol_count()); // Run the frequency estimator for every incoming sample overy the last // FREQ_EST_L samples. This is an implementation that works with unknown @@ -153,8 +156,9 @@ static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool d //freq_est_history_write_idx = 0; - DEBUG_LOG("Freq. est (x%d): %0.6f - Adj (x1): %.6f - carrier frequency (x1): %.6f\n", - RRC_SPS, freq_est, freq_adjustment, nco_crcf_get_frequency(rx->carrier_coarse_nco)); + DEBUG_LOG("@%zu: Freq. est (x%d): %0.6f - Adj (x1): %.6f - carrier frequency (x1): %.6f\n", + rx->sample_index, RRC_SPS, freq_est, freq_adjustment, + nco_crcf_get_frequency(rx->carrier_coarse_nco)); freq_est_holdoff_samples = preamble_get_symbol_count() * 2; } @@ -257,7 +261,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t float complex filtered_samples[sample_count]; firfilt_crcf_execute_block(rx->channel_filter, (float complex *)samples, sample_count, filtered_samples); - DEBUG_LOG("\nagc: %f\n", agc_crcf_get_gain(rx->agc)); + //DEBUG_LOG("@%zu: agc: %f\n", rx->sample_index, agc_crcf_get_gain(rx->agc)); for(unsigned int i = 0; i < sample_count; i++) { rx->sample_index++; @@ -340,7 +344,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t modem_demodulate(rx->hdr_demod, mixed_sample, &sym_demod); float phase_error = modem_get_demodulator_phase_error(rx->hdr_demod); - DEBUG_LOG("Sym: %d; Phase error: %f %s\n", sym_demod, phase_error, + DEBUG_LOG("@%zu: Sym: %d; Phase error: %f %s\n", rx->sample_index, sym_demod, phase_error, (fabs(phase_error) > 0.3) ? "!!!" : ""); @@ -365,7 +369,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t header_enc, 8, sizeof(header_enc), &nsyms)); if(fec_decode(rx->hdr_fec, sizeof(header), header_enc, header) != LIQUID_OK) { - DEBUG_LOG("Header decoding failed!\n"); + DEBUG_LOG("@%zu: Header decoding failed!\n", rx->sample_index); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -374,8 +378,8 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t // CRC check if(crc_check_key(LIQUID_CRC_8, header, HEADER_SIZE_BYTES) != LIQUID_OK) { uint8_t expected_crc = crc_generate_key(LIQUID_CRC_8, header, 4); - DEBUG_LOG("Header CRC check failed! Expected: 0x%02x, received: 0x%02x\n", - expected_crc, header[4]); + DEBUG_LOG("@%zu: Header CRC check failed! Expected: 0x%02x, received: 0x%02x\n", + rx->sample_index, expected_crc, header[4]); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -387,7 +391,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t // check the received information if(!MODCOD_IS_VALID(rx->modcod)) { - DEBUG_LOG("Decoded MODCOD %d is invalid!\n", rx->modcod); + DEBUG_LOG("@%zu: Decoded MODCOD %d is invalid!\n", rx->sample_index, rx->modcod); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -395,7 +399,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t // check the payload length if(rx->payload_len_bytes == 0) { - DEBUG_LOG("Packet length %u is not supported.\n", rx->payload_len_bytes); + DEBUG_LOG("@%zu: Packet length %u is not supported.\n", rx->sample_index, rx->payload_len_bytes); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -408,7 +412,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t rx->payload_len_symbols = (rx->payload_len_enc_bytes * 8 + payload_bps - 1) / payload_bps; 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); + DEBUG_LOG("@%zu: Symbol count %u is too lange for buffer. Ignoring packet.\n", rx->sample_index, rx->payload_len_symbols); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -416,7 +420,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t assert(rx->payload_len_symbols < sizeof(symbols_int)/sizeof(symbols_int[0])); - DEBUG_LOG("=== DECODED HEADER ===\n"); + DEBUG_LOG("=== DECODED HEADER @%zu ===\n", rx->sample_index); DEBUG_LOG("Payload length: %u symbols, %u bytes encoded, %u bytes decoded\n", rx->payload_len_symbols, rx->payload_len_enc_bytes, rx->payload_len_bytes); DEBUG_LOG("CRC16: 0x%04x\n", rx->payload_crc); DEBUG_LOG("======================\n"); @@ -440,7 +444,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t modem_demodulate(rx->payload_demod, mixed_sample, &sym_demod); float phase_error = modem_get_demodulator_phase_error(rx->payload_demod); - //DEBUG_LOG("Sym: %d; Phase error: %f\n", sym_demod, phase_error); + //DEBUG_LOG("@%zu: Sym: %d; Phase error: %f\n", rx->sample_index, sym_demod, phase_error); update_nco_pll(rx->carrier_fine_nco, phase_error, PLL_BW_DATA); @@ -487,6 +491,7 @@ result_t layer1_rx_process(layer1_rx_t *rx, const float complex *samples, size_t } if(rx->state != last_state) { + DEBUG_LOG("@%zu: RX state changed: %d -> %d\n", rx->sample_index, last_state, rx->state); if(rx->state == RX_STATE_ACQUISITION) { // ensure the AGC is in acquisition mode again when // RX_STATE_ACQUISITION is entered.