Improve logging

8 files changed, 117 insertions, 54 deletions

diff --git a/src/hid.c b/src/hid.c
index a6be20b..b030ce2 100644
--- a/src/hid.c
+++ b/src/hid.c
@@ -139,7 +139,7 @@ active_layers_push(uint layer, uint key)
 	uint i;
 
 	if (active_layers_top == ARRLEN(active_layers) - 1) {
-		WARN("Active stack overflow");
+		WARN(LOG_KEYMAP, "Active stack overflow");
 		return;
 	}
 
@@ -148,7 +148,7 @@ active_layers_push(uint layer, uint key)
 	active_layers[active_layers_top].key = key;
 
 	for (i = 0; i <= active_layers_top; i++) {
-		DEBUG("%i. ACTIVE %u %u", i,
+		DEBUG(LOG_KEYMAP, "%i. ACTIVE %u %u", i,
 			active_layers[i].layer, active_layers[i].key);
 	}
 }
@@ -177,7 +177,7 @@ void
 macro_held_push(uint32_t keysym)
 {
 	if (macro_held_cnt == MACRO_HOLD_MAX) {
-		WARN("Macro held keys overflow");
+		WARN(LOG_KEYMAP, "Macro held keys overflow");
 		return;
 	}
 
@@ -202,7 +202,7 @@ void
 add_keycode(uint8_t keycode)
 {
 	if (keyboard_report.cnt >= 6) {
-		WARN("HID report overflow");
+		WARN(LOG_HID, "HID report overflow");
 		return;
 	}
 
@@ -327,7 +327,7 @@ process_key(uint x, uint y, uint64_t now_us)
 {
 	if (keymat[y][x] != keymat_prev[y][x]) {
 		if (bounce_mat[y][x] > now_us - 50000) {
-			DEBUG("Bouncing prevented %i vs %i",
+			DEBUG(LOG_KEYMAT, "Bouncing prevented %i vs %i",
 				keymat[y][x], keymat_prev[y][x]);
 			keymat[y][x] = keymat_prev[y][x];
 		} else {
@@ -452,7 +452,7 @@ send_consumer_report(void)
 	sent = false;
 	if (memcmp(&consumer_report, &consumer_report_prev,
 			sizeof(consumer_report))) {
-		INFO("CONSUMER SEND");
+		INFO(LOG_HID, "CONSUMER SEND");
 		tud_hid_n_report(INST_HID_MISC, REPORT_ID_CONSUMER,
 			&consumer_report.code, 2);
 		memcpy(&consumer_report_prev, &consumer_report,
diff --git a/src/keymat.c b/src/keymat.c
index ebdba3a..3686053 100644
--- a/src/keymat.c
+++ b/src/keymat.c
@@ -5,6 +5,7 @@
 #include "pico/types.h"
 #include "hardware/gpio.h"
 #include "hardware/timer.h"
+#include "util.h"
 
 #include <string.h>
 
@@ -88,3 +89,21 @@ keymat_decode_half(int side, uint32_t mask)
 		}
 	}
 }
+
+void
+keymat_debug(void)
+{
+	uint x, y;
+
+	if (log_level_min > LOG_DEBUG)
+		return;
+
+	for (y = 0; y < KEY_ROWS; y++) {
+		for (x = 0; x < KEY_COLS; x++) {
+			if (!keymat_prev[y][x] && keymat[y][x])
+				DEBUG(LOG_KEYMAT, "Key pressed: %u %u", x, y);
+			else if (keymat_prev[y][x] && !keymat[y][x])
+				DEBUG(LOG_KEYMAT, "Key released: %u %u", x, y);
+		}
+	}
+}
diff --git a/src/keymat.h b/src/keymat.h
index 4ad6b42..2d0ad4a 100644
--- a/src/keymat.h
+++ b/src/keymat.h
@@ -17,6 +17,8 @@ void keymat_scan(void);
 uint32_t keymat_encode_half(int side);
 void keymat_decode_half(int side, uint32_t);
 
+void keymat_debug(void);
+
 extern bool keymat_prev[KEY_ROWS][KEY_COLS];
 extern bool keymat[KEY_ROWS][KEY_COLS];
 
diff --git a/src/main.c b/src/main.c
index 4146a24..0422fdb 100644
--- a/src/main.c
+++ b/src/main.c
@@ -50,7 +50,7 @@ main(void)
 		}
 
 		stop = board_millis();
-		DEBUG("Main loop: %i ms", stop - start);
+		DEBUG(LOG_TIMING, "Main loop: %i ms", stop - start);
 		start = stop;
 	}
 
@@ -134,17 +134,36 @@ process_cmd(char *cmd)
 		arg = cmd + strlen(cmd);
 	}
 
-	if (!strcmp(cmd, "log")) {
+	if (!strcmp(cmd, "log-level")) {
 		if (!strcmp(arg, "")) {
 			printf("Levels: debug, info, warn, err\n");
 		} else if (!strcmp(arg, "debug")) {
-			loglevel = LOG_DEBUG;
+			log_level_min = LOG_DEBUG;
 		} else if (!strcmp(arg, "info")) {
-			loglevel = LOG_INFO;
+			log_level_min = LOG_INFO;
 		} else if (!strcmp(arg, "warn")) {
-			loglevel = LOG_WARN;
+			log_level_min = LOG_WARN;
 		} else {
-			printf("Invalid log level\n");
+			printf("Invalid log level: %s\n", arg);
+		}
+	} else if (!strcmp(cmd, "log-groups")) {
+		log_group_mask = 0;
+		while (1) {
+			tok = strchr(arg, ',');
+			if (tok) *tok = '\0';
+			if (!strcmp(arg, "all")) {
+				log_group_mask |= LOG_ALL;
+			} else if (!strcmp(arg, "keymat")) {
+				log_group_mask |= LOG_KEYMAT;
+			} else if (!strcmp(arg, "timing")) {
+				log_group_mask |= LOG_TIMING;
+			} else if (strspn(arg, "\t ") == strlen(arg)) {
+				/* ignore */
+			} else {
+				printf("Invalid log facility: %s\n", arg);
+			}
+			if (!tok) break;
+			arg = tok + 1;
 		}
 	} else if (!strcmp(cmd, "warn")) {
 		if (*warnlog) {
diff --git a/src/split.c b/src/split.c
index 43b56e3..555ff55 100644
--- a/src/split.c
+++ b/src/split.c
@@ -31,6 +31,8 @@
 #elif SPLIT_SIDE == RIGHT
 #define UART_TX_PIN 1
 #define UART_RX_PIN 0
+#else
+#error "SPLIT_SIDE not set"
 #endif
 
 enum {
@@ -72,7 +74,7 @@ uart_tx_sm_init(void)
 {
 	pio_sm_config config;
 
-	uart_tx_sm = CLAIM_UNUSED_SM(pio0);
+	uart_tx_sm = claim_unused_sm(pio0);
 	uart_tx_sm_offset = pio_add_program(pio0, &uart_tx_program);
 
 	config = uart_tx_program_get_default_config(uart_tx_sm_offset);
@@ -92,7 +94,7 @@ uart_rx_sm_init(void)
 {
 	pio_sm_config config;
 
-	uart_rx_sm = CLAIM_UNUSED_SM(pio0);
+	uart_rx_sm = claim_unused_sm(pio0);
 	uart_rx_sm_offset = pio_add_program(pio0, &uart_rx_program);
 
 	config = uart_rx_program_get_default_config(uart_rx_sm_offset);
@@ -226,38 +228,38 @@ handle_cmd(uint8_t start)
 		return;
 
 	if (!uart_recv(&cmd, 1, false)) {
-		WARN("Got start byte without command");
+		WARN(LOG_SPLIT, "Got start byte without command");
 		return;
 	}
 
 	switch (cmd) {
 	case CMD_SCAN_KEYMAT_REQ:
 		if (split_role != SLAVE) {
-			WARN("Got SCAN_KEYMAT_REQ as master");
+			WARN(LOG_SPLIT, "Got SCAN_KEYMAT_REQ as master");
 			break;
 		}
 		scan_pending = true;
 		break;
 	case CMD_SCAN_KEYMAT_RESP:
 		if (split_role != MASTER) {
-			WARN("Got SCAN_KEYMAT_RESP as slave");
+			WARN(LOG_SPLIT, "Got SCAN_KEYMAT_RESP as slave");
 			break;
 		}
 		if (uart_recv((uint8_t *) &halfmat, 4, false) != 4)
-			WARN("Incomplete matrix received");
+			WARN(LOG_SPLIT, "Incomplete matrix received");
 		scan_pending = false;
 		break;
 	case CMD_SLAVE_WARN:
 		if (split_role != MASTER) {
-			WARN("Got SLAVE_WARN as slave");
+			WARN(LOG_SPLIT, "Got SLAVE_WARN as slave");
 			break;
 		}
 		memset(msgbuf, 0, sizeof(msgbuf));
 		uart_recv(msgbuf, sizeof(msgbuf)-1, true);
-		WARN("SLAVE: %s\n", msgbuf);
+		WARN(LOG_SPLIT, "SLAVE: %s\n", msgbuf);
 		break;
 	default:
-		WARN("Unknown uart cmd: %i", cmd);
+		WARN(LOG_SPLIT, "Unknown uart cmd: %i", cmd);
 		break;
 	}
 }
@@ -277,7 +279,7 @@ void
 irq_rx(void)
 {
 	if (pio_interrupt_get(pio0, 0)) {
-		DEBUG("UART RX ERR");
+		DEBUG(LOG_SPLIT, "UART RX ERR");
 		pio_interrupt_clear(pio0, 0);
 	}
 }
@@ -301,7 +303,7 @@ split_task(void)
 	if (split_role == MASTER) {
 		scan_pending = true;
 		if (!send_cmd(CMD_SCAN_KEYMAT_REQ)) {
-			WARN("UART send SCAN_KEYMAT_REQ failed");
+			WARN(LOG_SPLIT, "UART send SCAN_KEYMAT_REQ failed");
 			return;
 		}
 		keymat_next();
@@ -313,13 +315,16 @@ split_task(void)
 			tud_task();
 		}
 		if (scan_pending) {
-			WARN("Slave matrix scan timeout (%u)",
+			WARN(LOG_SPLIT | LOG_TIMING,
+				"Slave matrix scan timeout (%u)",
 				board_millis() - start_ms);
 		} else {
-			DEBUG("Slave matrix scan success (%u)",
+			DEBUG(LOG_SPLIT | LOG_TIMING,
+				"Slave matrix scan success (%u)",
 				board_millis() - start_ms);
 			keymat_decode_half(SPLIT_OPP(SPLIT_SIDE), halfmat);
 		}
+		keymat_debug();
 		scan_pending = false;
 	} else {
 		start_ms = board_millis();
@@ -330,9 +335,10 @@ split_task(void)
 		}
 		if (scan_pending) {
 			keymat_scan();
-			DEBUG("Sending SCAN_KEYMAT_RESP");
+			DEBUG(LOG_SPLIT, "Sending SCAN_KEYMAT_RESP");
 			if (!send_cmd(CMD_SCAN_KEYMAT_RESP)) {
-				WARN("UART send SCAN_KEYMAT_RESP failed");
+				WARN(LOG_SPLIT,
+					"UART send SCAN_KEYMAT_RESP failed");
 				return;
 			}
 			halfmat = keymat_encode_half(SPLIT_SIDE);
@@ -348,11 +354,11 @@ split_warn_master(const char *msg)
 	uint32_t len;
 
 	if (!send_cmd(CMD_SLAVE_WARN)) {
-		WARN("UART send SLAVE_WARN failed");
+		WARN(LOG_SPLIT, "UART send SLAVE_WARN failed");
 		return;
 	}
 
 	len = strlen(msg) + 1;
 	if (uart_send((const uint8_t *) msg, len) != len)
-		WARN("UART send warning failed");
+		WARN(LOG_SPLIT, "UART send warning failed");
 }
diff --git a/src/util.c b/src/util.c
index c2663be..25a6bcd 100644
--- a/src/util.c
+++ b/src/util.c
@@ -14,7 +14,8 @@
 #include <stdio.h>
 
 char warnlog[256];
-int loglevel = LOG_INFO;
+int log_level_min = LOG_INFO;
+int log_group_mask = LOG_ALL;
 
 static void
 __attribute__((format(printf, 1, 0)))
@@ -40,11 +41,17 @@ panic_task(const char *fmtstr, va_list ap, uint32_t sleep_ms)
 }
 
 void
-__attribute__ ((format (printf, 2, 3)))
-stdio_log(int level, const char *fmtstr, ...)
+__attribute__ ((format (printf, 3, 4)))
+stdio_log(int facility, int level, const char *fmtstr, ...)
 {
 	va_list ap, cpy;
 
+	if (!(facility & log_group_mask))
+		return;
+
+	if (level < log_level_min)
+		return;
+
 	if (level == LOG_WARN) {
 		led_start_blip(HARD_RED, 100);
 		va_copy(cpy, ap);
@@ -56,9 +63,6 @@ stdio_log(int level, const char *fmtstr, ...)
 			split_warn_master(warnlog);
 	}
 
-	if (level > loglevel)
-		return;
-
 	if (!tud_cdc_connected())
 		return;
 
diff --git a/src/util.h b/src/util.h
index 8f727f7..9226983 100644
--- a/src/util.h
+++ b/src/util.h
@@ -6,12 +6,13 @@
 #include <stdbool.h>
 #include <stdint.h>
 #include <stdarg.h>
+#include <sys/types.h>
 
 #define ARRLEN(x) (sizeof(x) / sizeof((x)[0]))
 
-#define WARN(...) stdio_log(LOG_WARN, "WARN : " __VA_ARGS__)
-#define INFO(...) stdio_log(LOG_INFO, "INFO : " __VA_ARGS__)
-#define DEBUG(...) stdio_log(LOG_DEBUG, "DEBUG: " __VA_ARGS__)
+#define WARN(group, ...) stdio_log(group, LOG_WARN, "WARN : " __VA_ARGS__)
+#define INFO(group, ...) stdio_log(group, LOG_INFO, "INFO : " __VA_ARGS__)
+#define DEBUG(group, ...) stdio_log(group, LOG_DEBUG, "DEBUG: " __VA_ARGS__)
 
 #define PANIC(...) blink_panic(200, HARD_RED, __VA_ARGS__);
 #define ASSERT(cond) do { \
@@ -19,21 +20,35 @@
 			#cond, __FILE__, __LINE__); \
 	} while (0)
 
-#define CLAIM_UNUSED_SM(pio) ({ \
-	int tmp = pio_claim_unused_sm(pio, false); \
-	ASSERT(tmp >= 0); \
-	(uint) tmp; })
-
 enum {
-	LOG_NONE,
-	LOG_WARN,
+	LOG_DEBUG,
 	LOG_INFO,
-	LOG_DEBUG
+	LOG_WARN
 };
 
-void stdio_log(int loglevel, const char *fmtstr, ...);
+enum {
+	LOG_NONE   = 0b000000,
+	LOG_MISC   = 0b000001,
+	LOG_KEYMAT = 0b000010,
+	LOG_KEYMAP = 0b000100,
+	LOG_HID    = 0b001000,
+	LOG_TIMING = 0b010000,
+	LOG_SPLIT  = 0b100000,
+	LOG_ALL    = 0b111111,
+};
+
+void stdio_log(int group, int level, const char *fmtstr, ...);
 
 void blink_panic(uint32_t blink_ms, uint32_t rgb, const char *fmtstr, ...);
 
+static inline uint
+claim_unused_sm(PIO pio)
+{
+	int tmp = pio_claim_unused_sm(pio, false);
+	ASSERT(tmp >= 0);
+	return (uint) tmp;
+}
+
 extern char warnlog[];
-extern int loglevel;
+extern int log_level_min;
+extern int log_group_mask;
diff --git a/src/ws2812.c b/src/ws2812.c
index b3e23f1..1f3ab78 100644
--- a/src/ws2812.c
+++ b/src/ws2812.c
@@ -12,16 +12,14 @@ ws2812_init(struct ws2812 *pix, PIO pio, uint pin)
 {
 	pio_sm_config config;
 	uint offset;
-	uint sm;
 
 	pix->pio = pio;
 	pix->pin = pin;
 
-	sm = CLAIM_UNUSED_SM(pio);
-	pix->sm = sm;
+	pix->sm = claim_unused_sm(pio);
 
 	pio_gpio_init(pio, pin);
-	pio_sm_set_consecutive_pindirs(pio, sm, pin, 1, true);
+	pio_sm_set_consecutive_pindirs(pio, pix->sm, pin, 1, true);
 
 	offset = pio_add_program(pix->pio, &ws2812_program);
 	config = ws2812_program_get_default_config(offset);
@@ -31,8 +29,8 @@ ws2812_init(struct ws2812 *pix, PIO pio, uint pin)
 	sm_config_set_clkdiv(&config,
 		(float) clock_get_hz(clk_sys) / (800000 * CYCLES_PER_BIT));
 
-	pio_sm_init(pio, sm, offset, &config);
-	pio_sm_set_enabled(pio, sm, true);
+	pio_sm_init(pio, pix->sm, offset, &config);
+	pio_sm_set_enabled(pio, pix->sm, true);
 
 	pix->init = true;
 }