common: add flash event log facility

This patch adds implementation and test for a generic logger saving
log entries in the flash.

The entries payload are limited to 64 bytes in size, each entry starts
with a header, which includes
 - 8 bit type type to allow to interpret the payload
 - 6 bit size field (two top bits of the byte are left for user flags,
   not yet used)
 - 32 bit timestamp to allow to identify newer log entries (presently
   this is just a monotonically increasing number)
 - 8 bit crc field protecting the entire entry

The entries are padded to make sure that they are ending on the flash
write boundary.

The location of the log is defined by the platform using it. There is
a provision for allowing the platform to register a callback which is
needed to be called to allow write access to the log (as is the case
on H1).

While the device is running, the log is growing until the allotted
flash space is 90% full. If there is an attempt save another entry
after that the log is compacted, namely the last 25% worth of flash
space is preserved, the log space is erased and the saved contents
written back.

On restarts the log is compacted if its size exceeds 75% of the
allotted flash space.

An API is provided to add entries to the log and to retrieve an entry
newer than a certain timestamp value. Thus starting with timestamp
zero will result in reading the very first log entry. To read the next
entry, the read function needs to be called with the timestamp value
of the current entry. This allows to browse the entire log, one entry
at a time.

A CLI command compiled in when CONFIG_CMD_FLASH_LOG is defined, allows
to add log and retrieve log entries.

BUG=b:63760920
BRANCH=cr50, cr50-mp
TEST=the included test case can be invoked by

     make run-flash_log

   and it passes. More tests are done when the rest of the patch stack
   is added.

Change-Id: I3dcdf2704a1e08fd3101183e434ac4a4e4cf1b9a
Signed-off-by: Vadim Bendebury <vbendeb@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/1525143
Reviewed-by: Randall Spangler <rspangler@chromium.org>
Reviewed-by: Andrey Pronin <apronin@chromium.org>

4 files changed, 246 insertions, 0 deletions

diff --git a/test/build.mk b/test/build.mk
index 362667a17e..979fc352fe 100644
--- a/test/build.mk
+++ b/test/build.mk
@@ -29,6 +29,7 @@ test-list-host += entropy
 test-list-host += extpwr_gpio
 test-list-host += fan
 test-list-host += flash
+test-list-host += flash_log
 test-list-host += float
 test-list-host += fp
 test-list-host += hooks
@@ -88,6 +89,7 @@ entropy-y=entropy.o
 extpwr_gpio-y=extpwr_gpio.o
 fan-y=fan.o
 flash-y=flash.o
+flash_log-y=flash_log.o
 hooks-y=hooks.o
 host_command-y=host_command.o
 inductive_charging-y=inductive_charging.o
diff --git a/test/flash_log.c b/test/flash_log.c
new file mode 100644
index 0000000000..20ae939f23
--- /dev/null
+++ b/test/flash_log.c
@@ -0,0 +1,218 @@
+/* Copyright 2019 The Chromium OS Authors. All rights reserved.
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ *
+ * Test Cr-50 Non-Voltatile memory module
+ */
+
+#include <stdlib.h>
+
+#include "common.h"
+#include "flash_log.h"
+#include "test_util.h"
+#include "util.h"
+
+struct log_stats {
+	size_t total_size;
+	size_t entry_count;
+};
+
+static int verify_single_entry(uint8_t fill_byte, int expected_type)
+{
+	int entry_size;
+	union entry_u e;
+	size_t i;
+	uint8_t *log_base = (void *)CONFIG_FLASH_LOG_BASE;
+
+	memset(log_base, fill_byte, CONFIG_FLASH_LOG_SPACE);
+	flash_log_init();
+
+	/* After initialization there should be a single log entry. */
+	entry_size = flash_log_dequeue_event(0, e.entry, sizeof(e.entry));
+	TEST_ASSERT(entry_size == sizeof(e.r));
+	TEST_ASSERT(e.r.type == expected_type);
+
+	entry_size = flash_log_dequeue_event(e.r.timestamp, e.entry,
+					     sizeof(e.entry));
+	TEST_ASSERT(entry_size == 0);
+
+	/* Verify proper entry padding. */
+	i = sizeof(e.r);
+	TEST_ASSERT(i % CONFIG_FLASH_WRITE_SIZE);
+	for (; i % CONFIG_FLASH_WRITE_SIZE; i++)
+		TEST_ASSERT(log_base[i] == FE_LOG_PAD);
+
+	TEST_ASSERT(log_base[i] == 0xff); /* First byte above padding. */
+
+	return EC_SUCCESS;
+}
+
+static int test_init_from_scratch(void)
+{
+	return verify_single_entry(0xff, FE_LOG_START);
+}
+
+static int test_init_from_corrupted(void)
+{
+	/* Let's mess up the log space. */
+	return verify_single_entry(0x55, FE_LOG_CORRUPTED);
+}
+
+static int verify_log(struct log_stats *stats)
+{
+	union entry_u e;
+	size_t actual_size;
+	size_t actual_count;
+	int entry_size;
+
+	e.r.timestamp = 0;
+	actual_size = 0;
+	actual_count = 0;
+
+	while ((entry_size = flash_log_dequeue_event(e.r.timestamp, e.entry,
+						     sizeof(e))) > 0) {
+		actual_count++;
+		actual_size += FLASH_LOG_ENTRY_SIZE(e.r.size);
+	}
+
+	TEST_ASSERT(entry_size == 0);
+
+	stats->total_size = actual_size;
+	stats->entry_count = actual_count;
+
+	return EC_SUCCESS;
+}
+
+static int fill_to_threshold(size_t threshold, struct log_stats *stats)
+{
+	int i;
+	uint8_t entry_type;
+	uint8_t payload_size;
+	uint8_t p[MAX_FLASH_LOG_PAYLOAD_SIZE];
+	size_t total_size;
+	size_t entry_count;
+
+	/* Start with an only entry in the log. */
+	TEST_ASSERT(verify_single_entry(0xff, FE_LOG_START) == EC_SUCCESS);
+
+	srand(0); /* Let's make sure it is consistent. */
+	entry_count = 1;
+	total_size = FLASH_LOG_ENTRY_SIZE(0);
+
+	/* Let's fill up the log to compaction limit. */
+	do {
+		entry_type = rand() % 0xfe;
+		payload_size = rand() % MAX_FLASH_LOG_PAYLOAD_SIZE;
+		for (i = 0; i < payload_size; i++)
+			p[i] = (i + entry_type) & 0xff;
+
+		flash_log_add_event(entry_type, payload_size, p);
+		total_size += FLASH_LOG_ENTRY_SIZE(payload_size);
+		entry_count++;
+	} while (total_size <= threshold);
+
+	TEST_ASSERT(verify_log(stats) == EC_SUCCESS);
+	TEST_ASSERT(stats->total_size == total_size);
+	TEST_ASSERT(stats->entry_count == entry_count);
+
+	/* This should get the log over the compaction threshold. */
+	flash_log_add_event(entry_type, payload_size, p);
+	TEST_ASSERT(verify_log(stats) == EC_SUCCESS);
+
+	return EC_SUCCESS;
+}
+
+static int test_run_time_compaction(void)
+{
+	struct log_stats stats;
+
+	TEST_ASSERT(fill_to_threshold(RUN_TIME_LOG_FULL_WATERMARK, &stats) ==
+		    EC_SUCCESS);
+
+	/*
+	 * Compacted space is guaranteed not to exceed the threshold plus the
+	 * size of the largest possible entry.
+	 */
+	TEST_ASSERT(stats.total_size <
+		    (COMPACTION_SPACE_PRESERVE +
+		     FLASH_LOG_ENTRY_SIZE(MAX_FLASH_LOG_PAYLOAD_SIZE)));
+
+	return EC_SUCCESS;
+}
+
+static int test_init_time_compaction(void)
+{
+	struct log_stats stats;
+
+	TEST_ASSERT(fill_to_threshold(STARTUP_LOG_FULL_WATERMARK, &stats) ==
+		    EC_SUCCESS);
+
+	/*
+	 * Init should roll the log back below the compaction preservation
+	 * threshold.
+	 */
+	flash_log_init();
+	TEST_ASSERT(verify_log(&stats) == EC_SUCCESS);
+
+	/*
+	 * Compacted space is guaranteed not to exceed the threshold plus the
+	 * size of the largest possible entry.
+	 */
+	TEST_ASSERT(stats.total_size <
+		    (COMPACTION_SPACE_PRESERVE +
+		     FLASH_LOG_ENTRY_SIZE(MAX_FLASH_LOG_PAYLOAD_SIZE)));
+
+	return EC_SUCCESS;
+}
+
+static int test_lock_failure_reporting(void)
+{
+	union entry_u e;
+
+	TEST_ASSERT(test_init_from_scratch() == EC_SUCCESS);
+	lock_failures_count = 0;
+	log_event_in_progress = 1;
+
+	/* This should fail. */
+	flash_log_add_event(FE_LOG_TEST, 0, NULL);
+
+	/* Lock count should have been incremented. */
+	TEST_ASSERT(lock_failures_count == 1);
+
+	/* This should also fail. */
+	TEST_ASSERT(flash_log_dequeue_event(0, e.entry, sizeof(e.entry)) ==
+		    -EC_ERROR_BUSY);
+
+	log_event_in_progress = 0;
+	/* This should succeed. */
+	flash_log_add_event(FE_LOG_TEST, 0, NULL);
+
+	TEST_ASSERT(lock_failures_count == 0);
+
+	/* There should be three entries in the log now. */
+	flash_log_dequeue_event(0, e.entry, sizeof(e.entry));
+	TEST_ASSERT(e.r.type == FE_LOG_START);
+
+	flash_log_dequeue_event(e.r.timestamp, e.entry, sizeof(e.entry));
+	TEST_ASSERT(e.r.type == FE_LOG_LOCKS);
+	TEST_ASSERT(FLASH_LOG_PAYLOAD_SIZE(e.r.size) == 1);
+	TEST_ASSERT(e.r.payload[0] == 1);
+
+	flash_log_dequeue_event(e.r.timestamp, e.entry, sizeof(e.entry));
+	TEST_ASSERT(e.r.type == FE_LOG_TEST);
+
+	return EC_SUCCESS;
+}
+
+void run_test(void)
+{
+	test_reset();
+
+	RUN_TEST(test_init_from_scratch);
+	RUN_TEST(test_init_from_corrupted);
+	RUN_TEST(test_run_time_compaction);
+	RUN_TEST(test_init_time_compaction);
+	RUN_TEST(test_lock_failure_reporting);
+
+	test_print_result();
+}
diff --git a/test/flash_log.tasklist b/test/flash_log.tasklist
new file mode 100644
index 0000000000..503898de80
--- /dev/null
+++ b/test/flash_log.tasklist
@@ -0,0 +1,17 @@
+/* Copyright 2019 The Chromium OS Authors. All rights reserved.
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+/**
+ * List of enabled tasks in the priority order
+ *
+ * The first one has the lowest priority.
+ *
+ * For each task, use the macro TASK_TEST(n, r, d, s) where :
+ * 'n' in the name of the task
+ * 'r' in the main routine of the task
+ * 'd' in an opaque parameter passed to the routine at startup
+ * 's' is the stack size in bytes; must be a multiple of 8
+ */
+#define CONFIG_TEST_TASK_LIST
diff --git a/test/test_config.h b/test/test_config.h
index b5f81f4e1e..22f497bcc0 100644
--- a/test/test_config.h
+++ b/test/test_config.h
@@ -36,6 +36,15 @@
 #define CONFIG_BACKLIGHT_REQ_GPIO GPIO_PCH_BKLTEN
 #endif
 
+#ifdef TEST_FLASH_LOG
+#define CONFIG_CRC8
+#define CONFIG_FLASH_ERASED_VALUE32 (-1U)
+#define CONFIG_FLASH_LOG
+#define CONFIG_FLASH_LOG_BASE (CONFIG_PROGRAM_MEMORY_BASE + 0x800)
+#define CONFIG_FLASH_LOG_SPACE 0x800
+#define CONFIG_MALLOC
+#endif
+
 #ifdef TEST_KB_8042
 #define CONFIG_KEYBOARD_PROTOCOL_8042
 #endif