From 7cd8ba6eda6979d61a3a0685057b20bf2da9be31 Mon Sep 17 00:00:00 2001
From: Julius Werner <jwerner@chromium.org>
Date: Fri, 21 Jan 2022 15:15:29 -0800
Subject: [PATCH] console: Add loglevel prefix to interactive consoles

In an attempt to make loglevels more visible (and therefore useful,
hopefully), this patch adds a prefix indicating the log level to every
line sent to an "interactive" console (such as a UART). If the code
contains a `printk(BIOS_DEBUG, "This is a debug message!\n"), it will
now show up as

  [DEBUG]  This is a debug message!

on the UART output.

"Stored" consoles (such as in CBMEM) will get a similar but more
space-efficient feature in a later CL.

Signed-off-by: Julius Werner <jwerner@chromium.org>
Change-Id: Ic83413475400821f8097ef1819a293ee8926bb0b
Reviewed-on: https://review.coreboot.org/c/coreboot/+/61306
Tested-by: build bot (Jenkins) <no-reply@coreboot.org>
Reviewed-by: Raul Rangel <rrangel@chromium.org>
---
 src/commonlib/include/commonlib/loglevel.h | 23 +++++++++++++++++++
 src/console/console.c                      | 25 +++++++++++++--------
 src/console/printk.c                       | 26 ++++++++++++++++++++++
 src/include/console/streams.h              |  5 +++++
 4 files changed, 70 insertions(+), 9 deletions(-)

diff --git a/src/commonlib/include/commonlib/loglevel.h b/src/commonlib/include/commonlib/loglevel.h
index f2687509af..68b228528c 100644
--- a/src/commonlib/include/commonlib/loglevel.h
+++ b/src/commonlib/include/commonlib/loglevel.h
@@ -157,4 +157,27 @@
 #define BIOS_NEVER	9
 /** @} */
 
+#ifndef __ASSEMBLER__
+
+/*
+ * When printing logs, lines should be printed with the following prefixes in
+ * front of them according to the BIOS_LOG_PREFIX_PATTERN printf() pattern.
+ */
+#define BIOS_LOG_PREFIX_PATTERN "[%.5s]  "
+#define BIOS_LOG_PREFIX_MAX_LEVEL BIOS_SPEW
+static const char bios_log_prefix[BIOS_LOG_PREFIX_MAX_LEVEL + 1][5] = {
+	/* Note: These strings are *not* null-terminated to save space. */
+	[BIOS_EMERG]   = "EMERG",
+	[BIOS_ALERT]   = "ALERT",
+	[BIOS_CRIT]    = "CRIT ",
+	[BIOS_ERR]     = "ERROR",
+	[BIOS_WARNING] = "WARN ",
+	[BIOS_NOTICE]  = "NOTE ",
+	[BIOS_INFO]    = "INFO ",
+	[BIOS_DEBUG]   = "DEBUG",
+	[BIOS_SPEW]    = "SPEW ",
+};
+
+#endif /* __ASSEMBLER__ */
+
 #endif /* LOGLEVEL_H */
diff --git a/src/console/console.c b/src/console/console.c
index 67da10794e..5b8a872e0e 100644
--- a/src/console/console.c
+++ b/src/console/console.c
@@ -25,28 +25,35 @@ void console_hw_init(void)
 	__system76_ec_init();
 }
 
-void console_tx_byte(unsigned char byte)
+void console_interactive_tx_byte(unsigned char byte, void *data_unused)
 {
-	__cbmemc_tx_byte(byte);
-	__spkmodem_tx_byte(byte);
-	__qemu_debugcon_tx_byte(byte);
-
-	/* Some consoles want newline conversion
-	 * to keep terminals happy.
-	 */
 	if (byte == '\n') {
+		/* Some consoles want newline conversion to keep terminals happy. */
 		__uart_tx_byte('\r');
 		__usb_tx_byte('\r');
 	}
 
+	__spkmodem_tx_byte(byte);
+	__qemu_debugcon_tx_byte(byte);
 	__uart_tx_byte(byte);
 	__ne2k_tx_byte(byte);
 	__usb_tx_byte(byte);
 	__spiconsole_tx_byte(byte);
-	__flashconsole_tx_byte(byte);
 	__system76_ec_tx_byte(byte);
 }
 
+void console_stored_tx_byte(unsigned char byte, void *data_unused)
+{
+	__flashconsole_tx_byte(byte);
+	__cbmemc_tx_byte(byte);
+}
+
+void console_tx_byte(unsigned char byte)
+{
+	console_interactive_tx_byte(byte, NULL);
+	console_stored_tx_byte(byte, NULL);
+}
+
 void console_tx_flush(void)
 {
 	__uart_tx_flush();
diff --git a/src/console/printk.c b/src/console/printk.c
index ef3d29f490..ddd14c0589 100644
--- a/src/console/printk.c
+++ b/src/console/printk.c
@@ -67,9 +67,35 @@ union log_state {
 	};
 };
 
+static void wrap_interactive_printf(const char *fmt, ...)
+{
+	va_list args;
+	va_start(args, fmt);
+	vtxprintf(console_interactive_tx_byte, fmt, args, NULL);
+}
+
+static void line_start(union log_state state)
+{
+	if (state.level > BIOS_LOG_PREFIX_MAX_LEVEL)
+		return;
+	if (state.speed == CONSOLE_LOG_FAST)
+		return;
+
+	/* Interactive consoles get a `[DEBUG]  ` style readable prefix. */
+	wrap_interactive_printf(BIOS_LOG_PREFIX_PATTERN, bios_log_prefix[state.level]);
+}
+
 static void wrap_putchar(unsigned char byte, void *data)
 {
 	union log_state state = { .as_ptr = data };
+	static bool line_started = false;
+
+	if (byte == '\n') {
+		line_started = false;
+	} else if (!line_started) {
+		line_start(state);
+		line_started = true;
+	}
 
 	if (state.speed == CONSOLE_LOG_FAST)
 		__cbmemc_tx_byte(byte);
diff --git a/src/include/console/streams.h b/src/include/console/streams.h
index 44d96e2cc3..f8b1216aac 100644
--- a/src/include/console/streams.h
+++ b/src/include/console/streams.h
@@ -10,6 +10,11 @@ void console_hw_init(void);
 void console_tx_byte(unsigned char byte);
 void console_tx_flush(void);
 
+/* Interactive consoles that are usually displayed in real time on a terminal. */
+void console_interactive_tx_byte(unsigned char byte, void *data_unused);
+/* Consoles that store logs on some medium for later retrieval. */
+void console_stored_tx_byte(unsigned char byte, void *data_unused);
+
 /*
  * Write number_of_bytes data bytes from buffer to the serial device.
  * If number_of_bytes is zero, wait until all serial data is output.