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

@@ -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

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);
+		LOG(LVL_DEBUG, "@%zu: Phase offset:                 %.6f rad", 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: 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);
+						LOG(LVL_DUMP, "=== DECODED HEADER @%zu ===", 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);
+						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);
-						DEBUG_LOG("CRC16: 0x%04x\n", rx->payload_crc);
+						LOG(LVL_DUMP, "CRC16: 0x%04x", rx->payload_crc);
-						DEBUG_LOG("======================\n");
+						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.

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 <stdio.h>
+#include <malloc.h>
+
+#include <time.h>
+#include <sys/time.h>
+
+#include <stdarg.h>
+
+#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);
+}

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 <semaphore.h>
+
+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

impl/src/main.c

@@ -13,6 +13,7 @@
 #include <signal.h>
 
 #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);
+			//LOG(LVL_WARN, "Received a message of %zu bytes, but decoding failed.", packet_len);
-			//fprintf(stderr, "=== FAILED PAYLOAD ===\n");
+			//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);
+			//LOG(LVL_INFO, "A message of %zu bytes was decoded successfully.", packet_len);
-			//fprintf(stderr, "=== DECODED PAYLOAD (%4zu bytes) ===\n", 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);
+				LOG(LVL_INFO, "\nEstimated rate: %.3f MS/s", rate / 1e6);
-				fprintf(stderr, "Receiver statistics:\n");
+				LOG(LVL_INFO, "Receiver statistics:");
-				fprintf(stderr, "  Preambles found:    %8zd\n", m_rx_stats.preambles_found);
+				LOG(LVL_INFO, "  Preambles found:    %8zd", m_rx_stats.preambles_found);
-				fprintf(stderr, "  Successful decodes: %8zd (%6.2f %%)\n",
+				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();
 }

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

impl/test/layer1/test_rx_file.c

@@ -5,6 +5,7 @@
 #include <liquid/liquid.h>
 
 #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);
+			//LOG(LVL_WARN, "Received a message of %zu bytes, but decoding failed.", packet_len);
-			//fprintf(stderr, "=== FAILED PAYLOAD ===\n");
+			//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);
+			//LOG(LVL_INFO, "A message of %zu bytes was decoded successfully.", packet_len);
-			//fprintf(stderr, "=== DECODED PAYLOAD (%4zu bytes) ===\n", 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");
+		LOG(LVL_FATAL, "Not enough arguments!");
-		fprintf(stderr, "usage: %s <dump-file>\n\n", argv[0]);
+		LOG(LVL_INFO,  "usage: %s <dump-file>", argv[0]);
-		fprintf(stderr, "dump-file: HackRF dump in 8-bit signed interleaved I/Q format.\n");
+		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");
+		LOG(LVL_INFO, "Receiver statistics:");
-		fprintf(stderr, "  Preambles found:    %8zd\n", m_rx_stats.preambles_found);
+		LOG(LVL_INFO, "  Preambles found:    %8zd", m_rx_stats.preambles_found);
-		fprintf(stderr, "  Successful decodes: %8zd (%6.2f %%)\n",
+		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();
 }