Turn CBMEM console into a ring buffer that can persist across reboots

This patch allows the CBMEM console to persist across reboots, which
should greatly help post factum debugging of issues involving multiple
reboots. In order to prevent the console from filling up, it will
instead operate as a ring buffer that continues to evict the oldest
lines once full. (This means that if even a single boot doesn't fit into
the buffer, we will now drop the oldest lines whereas previous code
would've dropped the newest lines instead.)

The console control structure is modified in a sorta
backwards-compatible way, so that new readers can continue to work with
old console buffers and vice versa. When an old reader reads a new
buffer that has already once overflowed (i.e. is operating in true ring
buffer mode) it will print lines out of order, but it will at least
still print out the whole console content and not do any illegal memory
accesses (assuming it correctly implemented cursor overflow as it was
already possible before this patch).

BUG=chromium:651966
TEST=Rebooted and confirmed output repeatedly on a Kevin and a Falco.
Also confirmed correct behavior across suspend/resume for the latter.

Change-Id: Ifcbf59d58e1ad20995b98d111c4647281fbb45ff
Signed-off-by: Julius Werner <jwerner@chromium.org>
Reviewed-on: https://review.coreboot.org/18301
Tested-by: build bot (Jenkins)
Reviewed-by: Aaron Durbin <adurbin@chromium.org>

4 files changed, 163 insertions, 182 deletions

diff --git a/payloads/coreinfo/bootlog_module.c b/payloads/coreinfo/bootlog_module.c
index 1d990d1d0c..b3f0deeea5 100644
--- a/payloads/coreinfo/bootlog_module.c
+++ b/payloads/coreinfo/bootlog_module.c
@@ -35,6 +35,9 @@ struct cbmem_console {
 	u8 body[0];
 } __attribute__ ((__packed__));
 
+#define CURSOR_MASK ((1 << 28) - 1)
+#define OVERFLOW (1 << 31)
+
 
 static u32 char_width(char c, u32 cursor, u32 screen_width)
 {
@@ -114,23 +117,28 @@ static int bootlog_module_init(void)
 	}
 	/* Extract console information */
 	char *buffer = (char *)(&(console->body));
-	u32 buffer_size = console->size;
-	u32 cursor = console->cursor;
+	u32 size = console->size;
+	u32 cursor = console->cursor & CURSOR_MASK;
 
-	/* The cursor may be bigger than buffer size when the buffer is full */
-	if (cursor >= buffer_size) {
-		cursor = buffer_size - 1;
+	/* The cursor may be bigger than buffer size with older console code */
+	if (cursor >= size) {
+		cursor = size - 1;
 	}
 
 	/* Calculate how much characters will be displayed on screen */
-	u32 chars_count = calculate_chars_count(buffer, cursor + 1, SCREEN_X, LINES_SHOWN);
+	u32 chars_count = calculate_chars_count(buffer, cursor, SCREEN_X, LINES_SHOWN);
+	u32 overflow_chars_count = 0;
+	if (console->cursor & OVERFLOW) {
+		overflow_chars_count = calculate_chars_count(buffer + cursor,
+			size - cursor, SCREEN_X, LINES_SHOWN);
+	}
 
 	/* Sanity check, chars_count must be padded to full line */
-	if (chars_count % SCREEN_X != 0) {
+	if (chars_count % SCREEN_X || overflow_chars_count % SCREEN_X) {
 		return -2;
 	}
 
-	g_lines_count = chars_count / SCREEN_X;
+	g_lines_count = (chars_count + overflow_chars_count) / SCREEN_X;
 	g_max_cursor_line = MAX(g_lines_count - 1 - LINES_SHOWN, 0);
 
 	g_buf = malloc(chars_count);
@@ -138,17 +146,26 @@ static int bootlog_module_init(void)
 		return -3;
 	}
 
-	if (sanitize_buffer_for_display(buffer, cursor + 1,
-									g_buf, chars_count,
-									SCREEN_X) < 0) {
-		free(g_buf);
-		g_buf = NULL;
-		return -4;
+	if (console->cursor & OVERFLOW) {
+		if (sanitize_buffer_for_display(buffer + cursor, size - cursor,
+				g_buf, overflow_chars_count, SCREEN_X) < 0) {
+			goto err_free;
+		}
+	}
+	if (sanitize_buffer_for_display(buffer, cursor,
+					g_buf + overflow_chars_count,
+					chars_count, SCREEN_X) < 0) {
+		goto err_free;
 	}
 
 	/* TODO: Maybe a _cleanup hook where we call free()? */
 
 	return 0;
+
+err_free:
+	free(g_buf);
+	g_buf = NULL;
+	return -4;
 }
 
 static int bootlog_module_redraw(WINDOW *win)
diff --git a/payloads/libpayload/drivers/cbmem_console.c b/payloads/libpayload/drivers/cbmem_console.c
index 687344400c..76c2abb74d 100644
--- a/payloads/libpayload/drivers/cbmem_console.c
+++ b/payloads/libpayload/drivers/cbmem_console.c
@@ -36,6 +36,9 @@ struct cbmem_console {
 	uint8_t body[0];
 } __attribute__ ((__packed__));
 
+#define CURSOR_MASK ((1 << 28) - 1)
+#define OVERFLOW (1 << 31)
+
 static struct cbmem_console *cbmem_console_p;
 
 static struct console_output_driver cbmem_console_driver =
@@ -43,18 +46,32 @@ static struct console_output_driver cbmem_console_driver =
 	.write = &cbmem_console_write,
 };
 
+static void do_write(const void *buffer, size_t count)
+{
+	memcpy(cbmem_console_p->body + (cbmem_console_p->cursor & CURSOR_MASK),
+	       buffer, count);
+	cbmem_console_p->cursor += count;
+}
+
 void cbmem_console_init(void)
 {
 	cbmem_console_p = lib_sysinfo.cbmem_cons;
-	if (cbmem_console_p)
+	if (cbmem_console_p && cbmem_console_p->size)
 		console_add_output_driver(&cbmem_console_driver);
 }
 
 void cbmem_console_write(const void *buffer, size_t count)
 {
-	if (cbmem_console_p->cursor + count >= cbmem_console_p->size)
-		return;
+	while ((cbmem_console_p->cursor & CURSOR_MASK) + count >=
+	       cbmem_console_p->size) {
+		size_t still_fits = cbmem_console_p->size -
+				    (cbmem_console_p->cursor & CURSOR_MASK);
+		do_write(buffer, still_fits);
+		cbmem_console_p->cursor &= ~CURSOR_MASK;
+		cbmem_console_p->cursor |= OVERFLOW;
+		buffer += still_fits;
+		count -= still_fits;
+	}
 
-	memcpy(cbmem_console_p->body + cbmem_console_p->cursor, buffer, count);
-	cbmem_console_p->cursor += count;
+	do_write(buffer, count);
 }
diff --git a/src/lib/cbmem_console.c b/src/lib/cbmem_console.c
index 284506619f..d570bbaa9a 100644
--- a/src/lib/cbmem_console.c
+++ b/src/lib/cbmem_console.c
@@ -23,9 +23,11 @@
 
 /*
  * Structure describing console buffer. It is overlaid on a flat memory area,
- * with body covering the extent of the memory. Once the buffer is
- * full, the cursor keeps going but the data is dropped on the floor. This
- * allows to tell how much data was lost in the process.
+ * with body covering the extent of the memory. Once the buffer is full,
+ * output will wrap back around to the start of the buffer. The high bit of the
+ * cursor field gets set to indicate that this happened. If the underlying
+ * storage allows this, the buffer will persist across multiple boots and append
+ * to the previous log.
  */
 struct cbmem_console {
 	u32 size;
@@ -33,10 +35,13 @@ struct cbmem_console {
 	u8  body[0];
 }  __attribute__ ((__packed__));
 
-static struct cbmem_console *cbmem_console_p CAR_GLOBAL;
+#define MAX_SIZE (1 << 28)	/* can't be changed without breaking readers! */
+#define CURSOR_MASK (MAX_SIZE - 1)	/* bits 31-28 are reserved for flags */
+#define OVERFLOW (1 << 31)		/* set if in ring-buffer mode */
+_Static_assert(CONFIG_CONSOLE_CBMEM_BUFFER_SIZE <= MAX_SIZE,
+	"cbmem_console format cannot support buffers larger than 256MB!");
 
-static void copy_console_buffer(struct cbmem_console *old_cons_p,
-	struct cbmem_console *new_cons_p);
+static struct cbmem_console *cbmem_console_p CAR_GLOBAL;
 
 #ifdef __PRE_RAM__
 /*
@@ -62,38 +67,36 @@ static void copy_console_buffer(struct cbmem_console *old_cons_p,
 static u8 static_console[STATIC_CONSOLE_SIZE];
 #endif
 
-/* flags for init */
-#define CBMEMC_RESET	(1<<0)
-#define CBMEMC_APPEND	(1<<1)
-
-static inline struct cbmem_console *current_console(void)
+static struct cbmem_console *current_console(void)
 {
 	return car_sync_var(cbmem_console_p);
 }
 
-static inline void current_console_set(struct cbmem_console *new_console_p)
+static void current_console_set(struct cbmem_console *new_console_p)
 {
 	car_set_var(cbmem_console_p, new_console_p);
 }
 
-static inline void init_console_ptr(void *storage, u32 total_space, int flags)
+static int buffer_valid(struct cbmem_console *cbm_cons_p, u32 total_space)
+{
+	return (cbm_cons_p->cursor & CURSOR_MASK) < cbm_cons_p->size &&
+	       cbm_cons_p->size <= MAX_SIZE &&
+	       cbm_cons_p->size == total_space - sizeof(struct cbmem_console);
+}
+
+static void init_console_ptr(void *storage, u32 total_space)
 {
 	struct cbmem_console *cbm_cons_p = storage;
 
-	if (!cbm_cons_p || total_space == 0) {
+	if (!cbm_cons_p || total_space <= sizeof(struct cbmem_console)) {
 		current_console_set(NULL);
 		return;
 	}
 
-	if (flags & CBMEMC_RESET) {
+	if (!buffer_valid(cbm_cons_p, total_space)) {
 		cbm_cons_p->size = total_space - sizeof(struct cbmem_console);
 		cbm_cons_p->cursor = 0;
 	}
-	if (flags & CBMEMC_APPEND) {
-		struct cbmem_console *tmp_cons_p = current_console();
-		if (tmp_cons_p)
-			copy_console_buffer(tmp_cons_p, cbm_cons_p);
-	}
 
 	current_console_set(cbm_cons_p);
 }
@@ -101,149 +104,74 @@ static inline void init_console_ptr(void *storage, u32 total_space, int flags)
 void cbmemc_init(void)
 {
 #ifdef __PRE_RAM__
-	int flags = 0;
-
-	/* If in bootblock always initialize the console first. */
-	if (ENV_BOOTBLOCK)
-		flags = CBMEMC_RESET;
-	else if (ENV_ROMSTAGE) {
-		/* Initialize console for the first time in romstage when
-		 * there's no prior stage that initialized it first. */
-		if (!IS_ENABLED(CONFIG_VBOOT_STARTS_IN_BOOTBLOCK) &&
-		    !IS_ENABLED(CONFIG_BOOTBLOCK_CONSOLE))
-			flags = CBMEMC_RESET;
-	} else if (ENV_VERSTAGE) {
-		/*
-		 * Initialize console for the first time in verstage when
-		 * there is no console in bootblock. Otherwise honor the
-		 * bootblock console when verstage comes right after
-		 * bootblock.
-		 */
-		if (IS_ENABLED(CONFIG_VBOOT_STARTS_IN_BOOTBLOCK) &&
-		    !IS_ENABLED(CONFIG_BOOTBLOCK_CONSOLE))
-			flags = CBMEMC_RESET;
-	}
-
-	init_console_ptr(_preram_cbmem_console,
-			_preram_cbmem_console_size, flags);
+	/* Pre-RAM environments use special buffer placed by linker script. */
+	init_console_ptr(_preram_cbmem_console, _preram_cbmem_console_size);
 #else
-	/*
-	 * Initializing before CBMEM is available, use static buffer to store
-	 * the log.
-	 */
-	init_console_ptr(static_console, sizeof(static_console), CBMEMC_RESET);
+	/* Post-RAM uses static (BSS) buffer before CBMEM is reinitialized. */
+	init_console_ptr(static_console, sizeof(static_console));
 #endif
 }
 
 void cbmemc_tx_byte(unsigned char data)
 {
 	struct cbmem_console *cbm_cons_p = current_console();
-	u32 cursor;
 
-	if (!cbm_cons_p)
+	if (!cbm_cons_p || !cbm_cons_p->size)
 		return;
 
-	cursor = cbm_cons_p->cursor++;
-	if (cursor < cbm_cons_p->size)
-		cbm_cons_p->body[cursor] = data;
+	u32 flags = cbm_cons_p->cursor & ~CURSOR_MASK;
+	u32 cursor = cbm_cons_p->cursor & CURSOR_MASK;
+
+	cbm_cons_p->body[cursor++] = data;
+	if (cursor >= cbm_cons_p->size) {
+		cursor = 0;
+		flags |= OVERFLOW;
+	}
+
+	cbm_cons_p->cursor = flags | cursor;
 }
 
 /*
- * Copy the current console buffer (either from the cache as RAM area, or from
- * the static buffer, pointed at by cbmem_console_p) into the CBMEM console
- * buffer space (pointed at by new_cons_p), concatenating the copied data with
- * the CBMEM console buffer contents.
- *
- * If there is overflow - add to the destination area a string, reporting the
- * overflow and the number of dropped characters.
+ * Copy the current console buffer (either from the cache as RAM area or from
+ * the static buffer, pointed at by src_cons_p) into the newly initialized CBMEM
+ * console. The use of cbmemc_tx_byte() ensures that all special cases for the
+ * target console (e.g. overflow) will be handled. If there had been an
+ * overflow in the source console, log a message to that effect.
  */
-static void copy_console_buffer(struct cbmem_console *old_cons_p,
-	struct cbmem_console *new_cons_p)
+static void copy_console_buffer(struct cbmem_console *src_cons_p)
 {
-	u32 copy_size, dropped_chars;
-	u32 cursor = new_cons_p->cursor;
+	u32 c;
 
-	if (old_cons_p->cursor < old_cons_p->size)
-		copy_size = old_cons_p->cursor;
-	else
-		copy_size = old_cons_p->size;
-
-	if (cursor > new_cons_p->size)
-		copy_size = 0;
-	else if (cursor + copy_size > new_cons_p->size)
-		copy_size = new_cons_p->size - cursor;
+	if (!src_cons_p)
+		return;
 
-	dropped_chars = old_cons_p->cursor - copy_size;
-	if (dropped_chars) {
-		/* Reserve 80 chars to report overflow, if possible. */
-		if (copy_size < 80)
-			return;
-		copy_size -= 80;
-		dropped_chars += 80;
+	if (src_cons_p->cursor & OVERFLOW) {
+		const char overflow_warning[] = "\n*** Pre-CBMEM console "
+			"overflowed, log truncated ***\n";
+		for (c = 0; c < sizeof(overflow_warning) - 1; c++)
+			cbmemc_tx_byte(overflow_warning[c]);
+		for (c = src_cons_p->cursor & CURSOR_MASK;
+		     c < src_cons_p->size; c++)
+			cbmemc_tx_byte(src_cons_p->body[c]);
 	}
 
-	memcpy(new_cons_p->body + cursor, old_cons_p->body,
-	       copy_size);
-
-	cursor += copy_size;
-
-	if (dropped_chars) {
-		const char loss_str1[] = "\n\n*** Log truncated, ";
-		const char loss_str2[] = " characters dropped. ***\n\n";
-
-		/*
-		 * When running from ROM sprintf is not available, a simple
-		 * itoa implementation is used instead.
-		 */
-		int got_first_digit = 0;
-
-		/* Way more than possible number of dropped characters. */
-		u32 mult = 100000;
-
-		strcpy((char *)new_cons_p->body + cursor, loss_str1);
-		cursor += sizeof(loss_str1) - 1;
-
-		while (mult) {
-			int digit = dropped_chars / mult;
-			if (got_first_digit || digit) {
-				new_cons_p->body[cursor++] = digit + '0';
-				dropped_chars %= mult;
-				/* Excessive, but keeps it simple */
-				got_first_digit = 1;
-			}
-			mult /= 10;
-		}
+	for (c = 0; c < (src_cons_p->cursor & CURSOR_MASK); c++)
+		cbmemc_tx_byte(src_cons_p->body[c]);
 
-		strcpy((char *)new_cons_p->body + cursor, loss_str2);
-		cursor += sizeof(loss_str2) - 1;
-	}
-	new_cons_p->cursor = cursor;
+	/* Invalidate the source console, so it will be reinitialized on the
+	   next reboot. Otherwise, we might copy the same bytes again. */
+	src_cons_p->size = 0;
 }
 
 static void cbmemc_reinit(int is_recovery)
 {
-	struct cbmem_console *cbm_cons_p;
 	const size_t size = CONFIG_CONSOLE_CBMEM_BUFFER_SIZE;
-	int flags = CBMEMC_APPEND;
-
-	/* No appending when no preram console available and adding for
-	 * the first time. */
-	if (!ENV_RAMSTAGE && !ENV_POSTCAR && _preram_cbmem_console_size == 0)
-		flags = CBMEMC_RESET;
-
-	/* Need to reset the newly added cbmem console in romstage. */
-	if (ENV_ROMSTAGE)
-		flags |= CBMEMC_RESET;
+	/* If CBMEM entry already existed, old contents are not altered. */
+	struct cbmem_console *cbmem_cons_p = cbmem_add(CBMEM_ID_CONSOLE, size);
+	struct cbmem_console *previous_cons_p = current_console();
 
-	/* Need to reset the newly added cbmem console in ramstage
-	 * when there was no console in preram environment. */
-	if (ENV_RAMSTAGE && IS_ENABLED(CONFIG_LATE_CBMEM_INIT))
-		flags |= CBMEMC_RESET;
-
-	/* If CBMEM entry already existed, old contents is not altered. */
-	cbm_cons_p = cbmem_add(CBMEM_ID_CONSOLE, size);
-
-	init_console_ptr(cbm_cons_p, size, flags);
+	init_console_ptr(cbmem_cons_p, size);
+	copy_console_buffer(previous_cons_p);
 }
 ROMSTAGE_CBMEM_INIT_HOOK(cbmemc_reinit)
 RAMSTAGE_CBMEM_INIT_HOOK(cbmemc_reinit)
@@ -253,14 +181,18 @@ POSTCAR_CBMEM_INIT_HOOK(cbmemc_reinit)
 void cbmem_dump_console(void)
 {
 	struct cbmem_console *cbm_cons_p;
-	int cursor;
+	u32 cursor;
 
 	cbm_cons_p = current_console();
 	if (!cbm_cons_p)
 		return;
 
 	uart_init(0);
-	for (cursor = 0; cursor < cbm_cons_p->cursor; cursor++)
+	if (cbm_cons_p->cursor & OVERFLOW)
+		for (cursor = cbm_cons_p->cursor & CURSOR_MASK;
+		     cursor < cbm_cons_p->size; cursor++)
+			uart_tx_byte(0, cbm_cons_p->body[cursor]);
+	for (cursor = 0; cursor < (cbm_cons_p->cursor & CURSOR_MASK); cursor++)
 		uart_tx_byte(0, cbm_cons_p->body[cursor]);
 }
 #endif
diff --git a/util/cbmem/cbmem.c b/util/cbmem/cbmem.c
index e60505222a..7b7f10d53f 100644
--- a/util/cbmem/cbmem.c
+++ b/util/cbmem/cbmem.c
@@ -601,52 +601,67 @@ static void dump_timestamps(int mach_readable)
 	unmap_memory();
 }
 
+struct cbmem_console {
+	u32 size;
+	u32 cursor;
+	u8  body[0];
+}  __attribute__ ((__packed__));
+
+#define CBMC_CURSOR_MASK ((1 << 28) - 1)
+#define CBMC_OVERFLOW (1 << 31)
+
 /* dump the cbmem console */
 static void dump_console(void)
 {
-	void *console_p;
+	struct cbmem_console *console_p;
 	char *console_c;
-	uint32_t size;
-	uint32_t cursor;
+	size_t size, cursor;
 
 	if (console.tag != LB_TAG_CBMEM_CONSOLE) {
 		fprintf(stderr, "No console found in coreboot table.\n");
 		return;
 	}
 
-	console_p = map_memory_size((unsigned long)console.cbmem_addr,
-					2 * sizeof(uint32_t), 1);
-	/* The in-memory format of the console area is:
-	 *  u32  size
-	 *  u32  cursor
-	 *  char console[size]
-	 * Hence we have to add 8 to get to the actual console string.
-	 */
-	size = ((uint32_t *)console_p)[0];
-	cursor = ((uint32_t *)console_p)[1];
-	/* Cursor continues to go on even after no more data fits in
-	 * the buffer but the data is dropped in this case.
-	 */
-	if (size > cursor)
+	size = sizeof(*console_p);
+	console_p = map_memory_size((unsigned long)console.cbmem_addr, size, 1);
+	cursor = console_p->cursor & CBMC_CURSOR_MASK;
+	if (!(console_p->cursor & CBMC_OVERFLOW) && cursor < console_p->size)
 		size = cursor;
-	console_c = calloc(1, size + 1);
+	else
+		size = console_p->size;
 	unmap_memory();
+
+	console_c = malloc(size + 1);
 	if (!console_c) {
 		fprintf(stderr, "Not enough memory for console.\n");
 		exit(1);
 	}
+	console_c[size] = '\0';
 
 	console_p = map_memory_size((unsigned long)console.cbmem_addr,
-	                            size + sizeof(size) + sizeof(cursor), 1);
-	aligned_memcpy(console_c, console_p + 8, size);
+	                            size + sizeof(*console_p), 1);
+	if (console_p->cursor & CBMC_OVERFLOW) {
+		if (cursor >= size) {
+			printf("cbmem: ERROR: CBMEM console struct is illegal, "
+			       "output may be corrupt or out of order!\n\n");
+			cursor = 0;
+		}
+		aligned_memcpy(console_c, console_p->body + cursor,
+			       size - cursor);
+		aligned_memcpy(console_c + size - cursor,
+			       console_p->body, cursor);
+	} else {
+		aligned_memcpy(console_c, console_p->body, size);
+	}
 
+	/* 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]))
+			console_c[cursor] = '?';
 	printf("%s\n", console_c);
-	if (size < cursor)
-		printf("%d %s lost\n", cursor - size,
-			(cursor - size) == 1 ? "byte":"bytes");
 
 	free(console_c);
-
 	unmap_memory();
 }