From d6eaef91cd3d8c48726bb4611c1fa3307945fda2 Mon Sep 17 00:00:00 2001 From: Thomas Kolb Date: Tue, 28 May 2024 23:53:11 +0200 Subject: [PATCH] Switch to new logging system The new system supports: - time-tagging of log messages - message priority levels with a threshold below which they are not printed - colored output of the message priority for easy identification - compile-time disabling of all logging per C module So far, it is integrated in the main and rx modules which generate most messages. Other modules will be migrated in the future. --- impl/CMakeLists.txt | 2 + impl/src/layer1/rx.c | 55 +++++----- impl/src/logger.c | 186 ++++++++++++++++++++++++++++++++ impl/src/logger.h | 52 +++++++++ impl/src/main.c | 60 ++++++----- impl/test/CMakeLists.txt | 4 + impl/test/layer1/test_rx_file.c | 39 ++++--- 7 files changed, 324 insertions(+), 74 deletions(-) create mode 100644 impl/src/logger.c create mode 100644 impl/src/logger.h diff --git a/impl/CMakeLists.txt b/impl/CMakeLists.txt index 679dfc1..0607a99 100644 --- a/impl/CMakeLists.txt +++ b/impl/CMakeLists.txt @@ -10,6 +10,8 @@ include_directories(src) set(sources src/utils.c src/utils.h + src/logger.c + src/logger.h src/jsonlogger.c src/jsonlogger.h src/var_array.c diff --git a/impl/src/layer1/rx.c b/impl/src/layer1/rx.c index 1b0e843..0776d78 100644 --- a/impl/src/layer1/rx.c +++ b/impl/src/layer1/rx.c @@ -15,6 +15,9 @@ #include "utils.h" +//#define LOGGER_DISABLE_ALL // define this to disable all logging from this module +#include "logger.h" + #define SYMBOL_BUFFER_SIZE 16384 #define HEADER_SIZE_BYTES 5 // including CRC @@ -25,14 +28,6 @@ #define MAX_COARSE_FREQ_OFFSET 0.20f -#define SHOW_DEBUG_LOG 0 - -#if SHOW_DEBUG_LOG -# define DEBUG_LOG(...) fprintf(stderr, "DBG: " __VA_ARGS__) -#else -# define DEBUG_LOG(...) {} -#endif - #define PLL_BW_HEADER 0.03f #define PLL_BW_DATA 0.01f @@ -44,7 +39,7 @@ static void update_nco_pll(nco_crcf nco, float phase_error, float bw) nco_crcf_adjust_phase(nco, pll_alpha * phase_error); nco_crcf_adjust_frequency(nco, pll_beta * phase_error); - /*DEBUG_LOG("NCO adjusted: f=%.6f, φ=%.6f\n", + /*LOG(LVL_DEBUG, "NCO adjusted: f=%.6f, φ=%.6f", nco_crcf_get_frequency(nco), nco_crcf_get_phase(nco));*/ } @@ -84,7 +79,7 @@ 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("@%zu: Preamble found: %.3f > %.3f\n", rx->sample_index, + LOG(LVL_INFO, "@%zu: Preamble found: %.3f > %.3f", rx->sample_index, abs_corr_out, 0.5f * preamble_get_symbol_count()); rx->packet_debug_info.preamble_correlation_peak = abs_corr_out; @@ -92,8 +87,8 @@ static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool d float phase_offset; float mean_frequency_error = correlator_get_mean_frequency_deviation(&rx->preamble_correlator, FREQ_EST_L, &phase_offset); - 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); + LOG(LVL_DEBUG, "@%zu: Phase offset: %.6f rad", rx->sample_index, phase_offset); + LOG(LVL_DEBUG, "@%zu: Preamble frequency deviation: %.6f rad/symbol", 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); @@ -101,7 +96,7 @@ 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("@%zu: New estimated carrier frequency: %.6f + %.6f/4 = %.6f rad/sample\n", + LOG(LVL_DEBUG, "@%zu: New estimated carrier frequency: %.6f + %.6f/4 = %.6f rad/sample", rx->sample_index, fcoarse, ffine, fcoarse+ffine/4); // store debug info @@ -121,7 +116,7 @@ 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("@%zu: Preamble not found: %.3f < %.3f\n", + //LOG(LVL_DEBUG, "@%zu: Preamble not found: %.3f < %.3f", // rx->sample_index, cabsf(corr_out), 0.5f * preamble_get_symbol_count()); // Run the frequency estimator for every incoming sample overy the last @@ -156,7 +151,7 @@ static bool acquire_preamble(layer1_rx_t *rx, const float complex sample, bool d //freq_est_history_write_idx = 0; - DEBUG_LOG("@%zu: Freq. est (x%d): %0.6f - Adj (x1): %.6f - carrier frequency (x1): %.6f\n", + LOG(LVL_DEBUG, "@%zu: Freq. est (x%d): %0.6f - Adj (x1): %.6f - carrier frequency (x1): %.6f", rx->sample_index, RRC_SPS, freq_est, freq_adjustment, nco_crcf_get_frequency(rx->carrier_coarse_nco)); @@ -201,7 +196,7 @@ static enum squelch_state_t update_and_check_squelch(layer1_rx_t *rx, unsigned i switch(agc_crcf_squelch_get_status(rx->agc)) { case LIQUID_AGC_SQUELCH_RISE: - DEBUG_LOG("Squelch disabled at #%zu RSSI = %.3f dB [thr: %.3f dB]\n", rx->sample_index, level, agc_crcf_squelch_get_threshold(rx->agc)); + LOG(LVL_DEBUG, "Squelch disabled at #%zu RSSI = %.3f dB [thr: %.3f dB]", rx->sample_index, level, agc_crcf_squelch_get_threshold(rx->agc)); result = SQUELCH_JUST_OPENED; break; @@ -210,7 +205,7 @@ static enum squelch_state_t update_and_check_squelch(layer1_rx_t *rx, unsigned i break; case LIQUID_AGC_SQUELCH_FALL: - DEBUG_LOG("Squelch enabled at #%zu RSSI = %.3f dB [thr: %.3f dB]\n", rx->sample_index, level, agc_crcf_squelch_get_threshold(rx->agc)); + LOG(LVL_DEBUG, "Squelch enabled at #%zu RSSI = %.3f dB [thr: %.3f dB]", rx->sample_index, level, agc_crcf_squelch_get_threshold(rx->agc)); // fall through case LIQUID_AGC_SQUELCH_SIGNALLO: case LIQUID_AGC_SQUELCH_ENABLED: @@ -261,7 +256,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("@%zu: agc: %f\n", rx->sample_index, agc_crcf_get_gain(rx->agc)); + //LOG(LVL_DEBUG, "@%zu: agc: %f", rx->sample_index, agc_crcf_get_gain(rx->agc)); for(unsigned int i = 0; i < sample_count; i++) { rx->sample_index++; @@ -344,7 +339,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("@%zu: Sym: %d; Phase error: %f %s\n", rx->sample_index, sym_demod, phase_error, + LOG(LVL_DUMP, "@%zu: Sym: %d; Phase error: %f %s", rx->sample_index, sym_demod, phase_error, (fabs(phase_error) > 0.3) ? "!!!" : ""); @@ -369,7 +364,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("@%zu: Header decoding failed!\n", rx->sample_index); + LOG(LVL_WARN, "@%zu: Header decoding failed!", rx->sample_index); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -378,7 +373,7 @@ 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("@%zu: Header CRC check failed! Expected: 0x%02x, received: 0x%02x\n", + LOG(LVL_WARN, "@%zu: Header CRC check failed! Expected: 0x%02x, received: 0x%02x", rx->sample_index, expected_crc, header[4]); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); @@ -391,7 +386,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("@%zu: Decoded MODCOD %d is invalid!\n", rx->sample_index, rx->modcod); + LOG(LVL_WARN, "@%zu: Decoded MODCOD %d is invalid!", rx->sample_index, rx->modcod); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -399,7 +394,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("@%zu: Packet length %u is not supported.\n", rx->sample_index, rx->payload_len_bytes); + LOG(LVL_WARN, "@%zu: Packet length %u is not supported.", rx->sample_index, rx->payload_len_bytes); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -412,7 +407,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("@%zu: Symbol count %u is too lange for buffer. Ignoring packet.\n", rx->sample_index, rx->payload_len_symbols); + LOG(LVL_WARN, "@%zu: Symbol count %u is too lange for buffer. Ignoring packet.", rx->sample_index, rx->payload_len_symbols); rx->state = RX_STATE_ACQUISITION; rx->callback(RX_EVT_HEADER_ERROR, rx, NULL, 0); break; @@ -420,10 +415,10 @@ 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 @%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"); + LOG(LVL_DUMP, "=== DECODED HEADER @%zu ===", rx->sample_index); + LOG(LVL_DUMP, "Payload length: %u symbols, %u bytes encoded, %u bytes decoded", rx->payload_len_symbols, rx->payload_len_enc_bytes, rx->payload_len_bytes); + LOG(LVL_DUMP, "CRC16: 0x%04x", rx->payload_crc); + LOG(LVL_DUMP, "======================"); //dump_array_cf(symbols_cpx, symbol_counter, 1.0f, "/tmp/hdr.cpx"); @@ -444,7 +439,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("@%zu: Sym: %d; Phase error: %f\n", rx->sample_index, sym_demod, phase_error); + //LOG(LVL_DEBUG, "@%zu: Sym: %d; Phase error: %f", rx->sample_index, sym_demod, phase_error); update_nco_pll(rx->carrier_fine_nco, phase_error, PLL_BW_DATA); @@ -491,7 +486,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); + LOG(LVL_DEBUG, "@%zu: RX state changed: %d -> %d", 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. diff --git a/impl/src/logger.c b/impl/src/logger.c new file mode 100644 index 0000000..776a4ec --- /dev/null +++ b/impl/src/logger.c @@ -0,0 +1,186 @@ +/* + * Copyright (c) 2015-2024 Thomas Kolb + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to + * deal in the Software without restriction, including without limitation the + * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or + * sell copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + */ + +#include +#include + +#include +#include + +#include + +#include "logger.h" + +// define constants +const char *LOGGER_STR_FATAL = "FATAL"; +const char *LOGGER_STR_ERR = "ERROR"; +const char *LOGGER_STR_WARN = "WARN "; +const char *LOGGER_STR_INFO = "INFO "; +const char *LOGGER_STR_DEBUG = "DEBUG"; +const char *LOGGER_STR_DUMP = "DUMP "; + +const char *LOGGER_COLOR_FATAL = "\033[1;31m"; +const char *LOGGER_COLOR_ERR = "\033[1;31m"; +const char *LOGGER_COLOR_WARN = "\033[1;33m"; +const char *LOGGER_COLOR_INFO = "\033[1;32m"; +const char *LOGGER_COLOR_DEBUG = "\033[1m"; +const char *LOGGER_COLOR_DUMP = "\033[1;30m"; +const char *LOGGER_COLOR_NONE = "\033[0m"; + +// global variables +int logger_verbosity; +int logger_use_colors; + +void logger_init(void) +{ + logger_verbosity = 2147483647; + logger_use_colors = 1; +} + +void logger_shutdown(void) +{ + // reserved for future use +} + +void logger_enable_colors(int enable) +{ + logger_use_colors = enable; +} + +void logger_set_verbosity(int verbosity) +{ + logger_verbosity = verbosity; +} + +void logger_debug_message(const char *prefix, const char *fmt, va_list ap) +{ + /* Guess we need no more than 100 bytes. */ + int n, size = 100; + char *p, *np; + va_list internal_ap; + + if ((p = (char*)malloc(size)) == NULL) { + fprintf(stderr, "[%s] FATAL: Cannot allocate string buffer while processing arguments.\n", LOGGER_STR_ERR); + return; + } + + while (1) { + /* Try to print in the allocated space. */ + va_copy(internal_ap, ap); + n = vsnprintf(p, size, fmt, internal_ap); + va_end(internal_ap); + + /* If that worked, return the string. */ + if (n > -1 && n < size) { + break; + } + + /* Else try again with more space. */ + if (n > -1) { /* glibc 2.1 */ + size = n+1; /* precisely what is needed */ + } else { /* glibc 2.0 */ + size *= 2; /* twice the old size */ + } + + if ((np = (char*)realloc (p, size)) == NULL) { + free(p); + fprintf(stderr, "[%s] FATAL: Cannot reallocate string buffer while processing arguments.\n", LOGGER_STR_ERR); + return; + } else { + p = np; + } + } + + // fprintf is thread-safe, so this always results in clean log lines. + // See flockfile(3). + fprintf(stderr, "%s %s\n", prefix, p); + + free(p); +} + +void logger_log(int level, const char *format, ...) +{ + va_list argptr; + + char timebuf[32]; + char timebuf2[32]; + + char prefixbuf[64]; + const char *prefixcolor = "", *prefixtext = ""; + + if(level > logger_verbosity) { + return; + } + + struct timeval tv; + gettimeofday(&tv, NULL); + strftime(timebuf, 32, "%Y-%M-%d %H:%M:%S.%%03d", localtime(&(tv.tv_sec))); + snprintf(timebuf2, 32, timebuf, tv.tv_usec/1000); + + if(level >= LVL_DUMP) { + if(logger_use_colors) { + prefixcolor = LOGGER_COLOR_DUMP; + } + + prefixtext = LOGGER_STR_DUMP; + } else if(level >= LVL_DEBUG) { + if(logger_use_colors) { + prefixcolor = LOGGER_COLOR_DEBUG; + } + + prefixtext = LOGGER_STR_DEBUG; + } else if(level >= LVL_INFO) { + if(logger_use_colors) { + prefixcolor = LOGGER_COLOR_INFO; + } + + prefixtext = LOGGER_STR_INFO; + } else if(level >= LVL_WARN) { + if(logger_use_colors) { + prefixcolor = LOGGER_COLOR_WARN; + } + + prefixtext = LOGGER_STR_WARN; + } else if(level >= LVL_ERR) { + if(logger_use_colors) { + prefixcolor = LOGGER_COLOR_ERR; + } + + prefixtext = LOGGER_STR_ERR; + } else { + if(logger_use_colors) { + prefixcolor = LOGGER_COLOR_FATAL; + } + + prefixtext = LOGGER_STR_FATAL; + } + + if(logger_use_colors) { + sprintf(prefixbuf, "%s [%s%s%s]", timebuf2, prefixcolor, prefixtext, LOGGER_COLOR_NONE); + } else { + sprintf(prefixbuf, "%s [%s]", timebuf2, prefixtext); + } + + va_start(argptr, format); + logger_debug_message(prefixbuf, format, argptr); + va_end(argptr); +} diff --git a/impl/src/logger.h b/impl/src/logger.h new file mode 100644 index 0000000..455528f --- /dev/null +++ b/impl/src/logger.h @@ -0,0 +1,52 @@ +/* + * Copyright (c) 2015-2024 Thomas Kolb + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to + * deal in the Software without restriction, including without limitation the + * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or + * sell copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + */ + +#ifndef LOGGER_H +#define LOGGER_H + +#include + +static const int LVL_FATAL = 0; /*!< Fatal message level */ +static const int LVL_ERR = 5; /*!< Error message level */ +static const int LVL_WARN = 50; /*!< Warning message level */ +static const int LVL_INFO = 100; /*!< Information message level */ +static const int LVL_DEBUG = 200; /*!< Debug message level */ +static const int LVL_DUMP = 500; /*!< Dump message level */ + +extern sem_t logger_semaphore; +extern int logger_verbosity; +extern int logger_use_colors; + +void logger_init(void); +void logger_shutdown(void); +void logger_enable_colors(int enable); +void logger_set_verbosity(int verbosity); + +void logger_log(int level, const char *format, ...); + +#ifndef LOGGER_DISABLE_ALL + #define LOG(level, ...) logger_log(level, __VA_ARGS__) +#else + #define LOG(level, ...) {} +#endif + +#endif // LOGGER_H diff --git a/impl/src/main.c b/impl/src/main.c index 4a86f71..08a1f8b 100644 --- a/impl/src/main.c +++ b/impl/src/main.c @@ -13,6 +13,7 @@ #include #include "utils.h" +#include "logger.h" #include "options.h" #include "jsonlogger.h" #include "debug_structs.h" @@ -29,7 +30,7 @@ #define RESULT_CHECK(stmt) { \ result_t res = stmt; \ if(res != OK) { \ - fprintf(stderr, "Error %d in %s:%d!\n", res, __FILE__, __LINE__); \ + LOG(LVL_FATAL, "Error %d in %s:%d!", res, __FILE__, __LINE__); \ exit(1); \ } \ } @@ -47,7 +48,7 @@ static void signal_handler(int signal, siginfo_t *info, void *ctx) (void)info; (void)ctx; - fprintf(stderr, "\nGracefully shutting down on signal %d.\n", signal); + LOG(LVL_INFO, "\nGracefully shutting down on signal %d.", signal); m_running = false; } @@ -59,11 +60,11 @@ static void block_tx_for(unsigned offset_ms) void print_complex_array(const char *varname, float complex const *array, size_t len) { - fprintf(stderr, "%s=np.array([%f%+fj", varname, crealf(array[0]), cimagf(array[0])); + LOG(LVL_DUMP, "%s=np.array([%f%+fj", varname, crealf(array[0]), cimagf(array[0])); for(size_t k = 1; k < len; k++) { - fprintf(stderr, ", %f%+fj", crealf(array[k]), cimagf(array[k])); + LOG(LVL_DUMP, ", %f%+fj", crealf(array[k]), cimagf(array[k])); } - fprintf(stderr, "])\n"); + LOG(LVL_DUMP, "])"); } @@ -115,10 +116,10 @@ void cb_rx(rx_evt_t evt, const struct layer1_rx_s *rx, uint8_t *packet_data, siz switch(evt) { case RX_EVT_CHECKSUM_ERROR: - //fprintf(stderr, "Received a message of %zu bytes, but decoding failed.\n", packet_len); - //fprintf(stderr, "=== FAILED PAYLOAD ===\n"); + //LOG(LVL_WARN, "Received a message of %zu bytes, but decoding failed.", packet_len); + //LOG(LVL_INFO, "=== FAILED PAYLOAD ==="); //hexdump(packet_data, packet_len); - //fprintf(stderr, "=======================\n"); + //LOG(LVL_INFO, "======================="); m_rx_stats.failed_decodes++; break; @@ -127,10 +128,10 @@ void cb_rx(rx_evt_t evt, const struct layer1_rx_s *rx, uint8_t *packet_data, siz break; case RX_EVT_PACKET_RECEIVED: - //fprintf(stderr, "A message of %zu bytes was decoded successfully.\n", packet_len); - //fprintf(stderr, "=== DECODED PAYLOAD (%4zu bytes) ===\n", packet_len); + //LOG(LVL_INFO, "A message of %zu bytes was decoded successfully.", packet_len); + //LOG(LVL_INFO, "=== DECODED PAYLOAD (%4zu bytes) ===", packet_len); //hexdump(packet_data, packet_len < 64 ? packet_len : 64); - //fprintf(stderr, "====================================\n"); + //LOG(LVL_INFO, "===================================="); m_rx_stats.successful_decodes++; @@ -143,7 +144,7 @@ void cb_rx(rx_evt_t evt, const struct layer1_rx_s *rx, uint8_t *packet_data, siz break; case RX_EVT_PREAMBLE_FOUND: - //fprintf(stderr, "Found preamble!\n"); + //LOG(LVL_DEBUG, "Found preamble!"); block_tx_for(TX_SWITCH_BACKOFF_PREAMBLE_MS); m_rx_stats.preambles_found++; break; @@ -180,14 +181,17 @@ int main(int argc, char **argv) sdr_ctx_t sdr; + // initialize the console logger + logger_init(); + int parsed_options = options_parse(argc, argv); - fprintf(stderr, "%d options parsed.\n", parsed_options); + LOG(LVL_DEBUG, "%d options parsed.", parsed_options); if(parsed_options < 0) { return EXIT_FAILURE; } if(!jsonlogger_init("jsonlog.fifo")) { - fprintf(stderr, "Could not initialize JSON logger.\n"); + LOG(LVL_FATAL, "Could not initialize JSON logger."); return EXIT_FAILURE; } @@ -255,7 +259,7 @@ int main(int argc, char **argv) // check free buffer space (50 ms required corresponding to 5000 baseband symbols) size_t buffer_free_space_samples = sdr_get_tx_buffer_free_space(&sdr); - fprintf(stderr, "TX buffer free: %zu\n", buffer_free_space_samples); + LOG(LVL_DEBUG, "TX buffer free: %zu", buffer_free_space_samples); if(buffer_free_space_samples < 400000) { // sample count for 200 ms at 2 MHz // try again after a short delay @@ -273,7 +277,7 @@ int main(int argc, char **argv) break; } - fprintf(stderr, "Transmitting packet with %d bytes.\n", ret); + LOG(LVL_DEBUG, "Transmitting packet with %d bytes.", ret); RESULT_CHECK(layer1_tx_reset(&tx)); @@ -300,11 +304,11 @@ int main(int argc, char **argv) break; } else if(ret2 != 0 && (buffer_used_samples < min_required_samples)) { // enqueue more packets before starting TX - fprintf(stderr, "Pre-buffering more packets: %zd / %zd samples.\n", buffer_used_samples, min_required_samples); + LOG(LVL_INFO, "Pre-buffering more packets: %zd / %zd samples.", buffer_used_samples, min_required_samples); continue; } - fprintf(stderr, "RX -> TX\n"); + LOG(LVL_INFO, "RX -> TX"); RESULT_CHECK(sdr_stop_rx(&sdr)); // transmit packets on the frequency where the last packet was received. @@ -315,7 +319,7 @@ int main(int argc, char **argv) on_air = true; } else if(on_air) { // ret == 0 - fprintf(stderr, "TX -> RX\n"); + LOG(LVL_INFO, "TX -> RX"); RESULT_CHECK(sdr_flush_tx_buffer(&sdr)); RESULT_CHECK(layer1_rx_reset(&rx)); @@ -341,7 +345,7 @@ int main(int argc, char **argv) if(sdr_receive(&sdr, rf_samples, &n_rf_samples, 100000, SDR_OVERSAMPLING) != OK) { rx_retries++; - fprintf(stderr, "sdr_receive() failed %d times.\n", rx_retries); + LOG(LVL_INFO, "sdr_receive() failed %d times.", rx_retries); if(rx_retries >= 3) { break; } else { @@ -359,14 +363,14 @@ int main(int argc, char **argv) double new = get_hires_time(); if(new >= next_stats_print_time) { double rate = total_samples / (new - old); - fprintf(stderr, "\nEstimated rate: %.3f MS/s\n", rate / 1e6); - fprintf(stderr, "Receiver statistics:\n"); - fprintf(stderr, " Preambles found: %8zd\n", m_rx_stats.preambles_found); - fprintf(stderr, " Successful decodes: %8zd (%6.2f %%)\n", + LOG(LVL_INFO, "\nEstimated rate: %.3f MS/s", rate / 1e6); + LOG(LVL_INFO, "Receiver statistics:"); + LOG(LVL_INFO, " Preambles found: %8zd", m_rx_stats.preambles_found); + LOG(LVL_INFO, " Successful decodes: %8zd (%6.2f %%)", m_rx_stats.successful_decodes, m_rx_stats.successful_decodes * 100.0f / m_rx_stats.preambles_found); - fprintf(stderr, " Header errors: %8zd (%6.2f %%)\n", + LOG(LVL_INFO, " Header errors: %8zd (%6.2f %%)", m_rx_stats.header_errors, m_rx_stats.header_errors * 100.0f / m_rx_stats.preambles_found); - fprintf(stderr, " Failed decodes: %8zd (%6.2f %%)\n", + LOG(LVL_INFO, " Failed decodes: %8zd (%6.2f %%)", m_rx_stats.failed_decodes, m_rx_stats.failed_decodes * 100.0f / m_rx_stats.preambles_found); next_stats_print_time += 0.5; @@ -397,5 +401,7 @@ int main(int argc, char **argv) jsonlogger_shutdown(); - fprintf(stderr, "Done.\n"); + LOG(LVL_INFO, "Done."); + + logger_shutdown(); } diff --git a/impl/test/CMakeLists.txt b/impl/test/CMakeLists.txt index b99f09a..d5c28a3 100644 --- a/impl/test/CMakeLists.txt +++ b/impl/test/CMakeLists.txt @@ -42,6 +42,8 @@ add_executable( ../src/var_array.h ../src/options.c ../src/options.h + ../src/logger.c + ../src/logger.h layer1/test_loopback.c ) @@ -89,6 +91,8 @@ add_executable( ../src/layer1/preamble.h ../src/utils.c ../src/utils.h + ../src/logger.c + ../src/logger.h ../src/options.c ../src/options.h ../src/var_array.c diff --git a/impl/test/layer1/test_rx_file.c b/impl/test/layer1/test_rx_file.c index 3b53da3..1fcbee5 100644 --- a/impl/test/layer1/test_rx_file.c +++ b/impl/test/layer1/test_rx_file.c @@ -5,6 +5,7 @@ #include #include "jsonlogger.h" +#include "logger.h" #include "layer1/rx.h" #include "config.h" @@ -63,10 +64,10 @@ void cb_rx(rx_evt_t evt, const layer1_rx_t *rx, uint8_t *packet_data, size_t pac switch(evt) { case RX_EVT_CHECKSUM_ERROR: - //fprintf(stderr, "Received a message of %zu bytes, but decoding failed.\n", packet_len); - //fprintf(stderr, "=== FAILED PAYLOAD ===\n"); + //LOG(LVL_WARN, "Received a message of %zu bytes, but decoding failed.", packet_len); + //LOG(LVL_INFO, "=== FAILED PAYLOAD ==="); //hexdump(packet_data, packet_len); - //fprintf(stderr, "=======================\n"); + //LOG(LVL_INFO, "======================="); m_rx_stats.failed_decodes++; break; @@ -75,10 +76,10 @@ void cb_rx(rx_evt_t evt, const layer1_rx_t *rx, uint8_t *packet_data, size_t pac break; case RX_EVT_PACKET_RECEIVED: - //fprintf(stderr, "A message of %zu bytes was decoded successfully.\n", packet_len); - //fprintf(stderr, "=== DECODED PAYLOAD (%4zu bytes) ===\n", packet_len); + //LOG(LVL_INFO, "A message of %zu bytes was decoded successfully.", packet_len); + //LOG(LVL_INFO, "=== DECODED PAYLOAD (%4zu bytes) ===", packet_len); //hexdump(packet_data, packet_len < 64 ? packet_len : 64); - //fprintf(stderr, "====================================\n"); + //LOG(LVL_INFO, "===================================="); m_rx_stats.successful_decodes++; break; @@ -103,10 +104,12 @@ void cb_rx(rx_evt_t evt, const layer1_rx_t *rx, uint8_t *packet_data, size_t pac int main(int argc, char **argv) { + logger_init(); + if(argc < 2) { - fprintf(stderr, "Not enough arguments!\n"); - fprintf(stderr, "usage: %s \n\n", argv[0]); - fprintf(stderr, "dump-file: HackRF dump in 8-bit signed interleaved I/Q format.\n"); + LOG(LVL_FATAL, "Not enough arguments!"); + LOG(LVL_INFO, "usage: %s ", argv[0]); + LOG(LVL_INFO, "dump-file: HackRF dump in 8-bit signed interleaved I/Q format."); return 1; } @@ -118,7 +121,7 @@ int main(int argc, char **argv) #if JSONLOGGER if(!jsonlogger_init("jsonlog_test.fifo")) { - fprintf(stderr, "Could not initialize JSON logger.\n"); + LOG(LVL_FATAL, "Could not initialize JSON logger."); return EXIT_FAILURE; } #endif @@ -129,7 +132,7 @@ int main(int argc, char **argv) inputfile = fopen(argv[1], "rb"); if(!inputfile) { - fprintf(stderr, "Could not open input file!\n"); + LOG(LVL_FATAL, "Could not open input file!"); return 1; } @@ -157,13 +160,13 @@ int main(int argc, char **argv) RESULT_CHECK(layer1_rx_process(&rx, bb_samples, n_bb_samples)); - fprintf(stderr, "Receiver statistics:\n"); - fprintf(stderr, " Preambles found: %8zd\n", m_rx_stats.preambles_found); - fprintf(stderr, " Successful decodes: %8zd (%6.2f %%)\n", + LOG(LVL_INFO, "Receiver statistics:"); + LOG(LVL_INFO, " Preambles found: %8zd", m_rx_stats.preambles_found); + LOG(LVL_INFO, " Successful decodes: %8zd (%6.2f %%)", m_rx_stats.successful_decodes, m_rx_stats.successful_decodes * 100.0f / m_rx_stats.preambles_found); - fprintf(stderr, " Header errors: %8zd (%6.2f %%)\n", + LOG(LVL_INFO, " Header errors: %8zd (%6.2f %%)", m_rx_stats.header_errors, m_rx_stats.header_errors * 100.0f / m_rx_stats.preambles_found); - fprintf(stderr, " Failed decodes: %8zd (%6.2f %%)\n", + LOG(LVL_INFO, " Failed decodes: %8zd (%6.2f %%)", m_rx_stats.failed_decodes, m_rx_stats.failed_decodes * 100.0f / m_rx_stats.preambles_found); } @@ -176,5 +179,7 @@ int main(int argc, char **argv) jsonlogger_shutdown(); #endif - fprintf(stderr, "Done.\n"); + LOG(LVL_INFO, "Done."); + + logger_shutdown(); }