console: Add loglevel marker codes to stored consoles

In order to provide the same loglevel prefixes and highlighting that
were recently introduced for "interactive" consoles (e.g. UART) to
"stored" consoles (e.g. CBMEM) but minimize the amont of extra storage
space wasted on this info, this patch will write a 1-byte control
character marker indicating the loglevel to the start of every line
logged in those consoles. The `cbmem` utility will then interpret those
markers and translate them back into loglevel prefixes and escape
sequences as needed.

Since coreboot and userspace log readers aren't always in sync,
occasionally an older reader may come across these markers and not know
how to interpret them... but that should usually be fine, as the range
chosen contains non-printable ASCII characters that normally have no
effect on the terminal. At worst the outdated reader would display one
garbled character at the start of every line which isn't that bad.
(Older versions of the `cbmem` utility will translate non-printable
characters into `?` question marks.)

Signed-off-by: Julius Werner <jwerner@chromium.org>
Change-Id: I86073f48aaf1e0a58e97676fb80e2475ec418ffc
Reviewed-on: https://review.coreboot.org/c/coreboot/+/61308
Tested-by: build bot (Jenkins) <no-reply@coreboot.org>
Reviewed-by: Raul Rangel <rrangel@chromium.org>

src/commonlib/include/commonlib/loglevel.h

@@ -201,6 +201,20 @@ static const char bios_log_escape[BIOS_LOG_PREFIX_MAX_LEVEL + 1][8] = {
 	[BIOS_SPEW]    = "0",
 };
 
+/*
+ * When storing console logs somewhere for later retrieval, log level prefixes
+ * and escape sequences should not be stored raw to preserve space. Instead, a
+ * non-printable control character marker is inserted into the log to indicate
+ * the log level. Decoders reading this character should translate it back into
+ * the respective escape sequence and prefix. If a decoder doesn't support this
+ * feature, the non-printable character should usually be harmless.
+ */
+#define BIOS_LOG_MARKER_START 0x10
+#define BIOS_LOG_MARKER_END (BIOS_LOG_MARKER_START + BIOS_LOG_PREFIX_MAX_LEVEL)
+#define BIOS_LOG_IS_MARKER(c) ((c) >= BIOS_LOG_MARKER_START && (c) <= BIOS_LOG_MARKER_END)
+#define BIOS_LOG_LEVEL_TO_MARKER(level) (BIOS_LOG_MARKER_START + (level))
+#define BIOS_LOG_MARKER_TO_LEVEL(c) ((c) - BIOS_LOG_MARKER_START)
+
 #endif /* __ASSEMBLER__ */
 
 #endif /* LOGLEVEL_H */

src/console/printk.c

@@ -78,8 +78,16 @@ static void line_start(union log_state state)
 {
 	if (state.level > BIOS_LOG_PREFIX_MAX_LEVEL)
 		return;
-	if (state.speed == CONSOLE_LOG_FAST)
+
+	/* Stored consoles just get a single control char marker to save space. If we are in
+	   LOG_FAST mode, just write the marker to CBMC and exit -- the rest of this function
+	   implements the LOG_ALL case. */
+	unsigned char marker = BIOS_LOG_LEVEL_TO_MARKER(state.level);
+	if (state.speed == CONSOLE_LOG_FAST) {
+		__cbmemc_tx_byte(marker);
 		return;
+	}
+	console_stored_tx_byte(marker, NULL);
 
 	/* Interactive consoles get a `[DEBUG]  ` style readable prefix,
 	   and potentially an escape sequence for highlighting. */

src/lib/cbmem_console.c

@@ -182,12 +182,16 @@ void cbmem_dump_console_to_uart(void)
 	if (current_console->cursor & OVERFLOW) {
 		for (cursor = current_console->cursor & CURSOR_MASK;
 		     cursor < current_console->size; cursor++) {
+			if (BIOS_LOG_IS_MARKER(current_console->body[cursor]))
+				continue;
 			if (current_console->body[cursor] == '\n')
 				uart_tx_byte(console_index, '\r');
 			uart_tx_byte(console_index, current_console->body[cursor]);
 		}
 	}
 	for (cursor = 0; cursor < (current_console->cursor & CURSOR_MASK); cursor++) {
+		if (BIOS_LOG_IS_MARKER(current_console->body[cursor]))
+			continue;
 		if (current_console->body[cursor] == '\n')
 			uart_tx_byte(console_index, '\r');
 		uart_tx_byte(console_index, current_console->body[cursor]);
@@ -206,9 +210,11 @@ void cbmem_dump_console(void)
 	if (current_console->cursor & OVERFLOW)
 		for (cursor = current_console->cursor & CURSOR_MASK;
 		     cursor < current_console->size; cursor++)
-			do_putchar(current_console->body[cursor]);
+			if (!BIOS_LOG_IS_MARKER(current_console->body[cursor]))
+				do_putchar(current_console->body[cursor]);
 	for (cursor = 0; cursor < (current_console->cursor & CURSOR_MASK); cursor++)
-		do_putchar(current_console->body[cursor]);
+		if (!BIOS_LOG_IS_MARKER(current_console->body[cursor]))
+			do_putchar(current_console->body[cursor]);
 
 	console_paused = false;
 }

util/cbmem/cbmem.c

@@ -18,6 +18,7 @@
 #include <assert.h>
 #include <regex.h>
 #include <commonlib/bsd/cbmem_id.h>
+#include <commonlib/loglevel.h>
 #include <commonlib/timestamp_serialized.h>
 #include <commonlib/tcpa_log_serialized.h>
 #include <commonlib/coreboot_tables.h>
@@ -783,7 +784,8 @@ static void dump_console(enum console_print_type type)
 	/* Slight memory corruption may occur between reboots and give us a few
 	   unprintable characters like '\0'. Replace them with '?' on output. */
 	for (cursor = 0; cursor < size; cursor++)
-		if (!isprint(console_c[cursor]) && !isspace(console_c[cursor]))
+		if (!isprint(console_c[cursor]) && !isspace(console_c[cursor])
+		    && !BIOS_LOG_IS_MARKER(console_c[cursor]))
 			console_c[cursor] = '?';
 
 	/* We detect the reboot cutoff by looking for a bootblock, romstage or
@@ -822,7 +824,23 @@ static void dump_console(enum console_print_type type)
 		cursor = previous;
 	}
 
-	puts(console_c + cursor);
+	char c;
+	int tty = isatty(fileno(stdout));
+	while ((c = console_c[cursor++])) {
+		if (BIOS_LOG_IS_MARKER(c)) {
+			int lvl = BIOS_LOG_MARKER_TO_LEVEL(c);
+			if (tty)
+				printf(BIOS_LOG_ESCAPE_PATTERN, bios_log_escape[lvl]);
+			printf(BIOS_LOG_PREFIX_PATTERN, bios_log_prefix[lvl]);
+		} else {
+			putchar(c);
+			if (tty && c == '\n')
+				printf(BIOS_LOG_ESCAPE_RESET);
+		}
+	}
+	if (tty)
+		printf(BIOS_LOG_ESCAPE_RESET);
+
 	free(console_c);
 	unmap_memory(&console_mapping);
 }