flash_log: add api for setting base timestamp

The Cr50 environment does not have a wall clock, which makes it
impossible to associate flash log entries with real time.

This patch provides an API which allows to set a base time value and
then use it plus current Cr50 uptime to generate more sensible flash
log timestamps.

Care is taken to ensure that attempts to set timestamp base such that
it would cause a log timestamps rollback do not succeed.

A unit test is being added to verify this behavior.

BRANCH=none
BUG=b:132287488
TEST='make buildall -j' (which runs the new tests) succeeds.

Change-Id: I7521df1bac5aef67e0cf634c183bf1618655f48d
Signed-off-by: Vadim Bendebury <vbendeb@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/1610719
Legacy-Commit-Queue: Commit Bot <commit-bot@chromium.org>
Reviewed-by: Andrey Pronin <apronin@chromium.org>

3 files changed, 117 insertions, 7 deletions

diff --git a/common/flash_log.c b/common/flash_log.c
index f5a138516a..c59511a3b5 100644
--- a/common/flash_log.c
+++ b/common/flash_log.c
@@ -106,8 +106,19 @@ static struct {
 
 /* Location where next entry is going to be added. */
 static uint16_t log_write_cursor;
-/* Timestamp of the next entry (when real time is not available). */
-static uint32_t log_stamp;
+/*
+ * Base time in seconds, during init set to the time of the latest present log
+ * entry +1, expected be set by the host to current time. Log entries
+ * timestamps are set to this value plus uptime.
+ */
+static uint32_t log_tstamp_base;
+
+/*
+ * Keep track of the last used timestamp value to make sure there are no two
+ * entries with the same timestamp.
+ */
+test_mockable_static uint32_t last_used_timestamp;
+
 /* Set to True after log has been initialized. */
 static uint8_t log_inited;
 test_mockable_static uint8_t log_event_in_progress;
@@ -263,6 +274,7 @@ static enum ec_error_list flash_log_add_event_core(uint8_t type, uint8_t size,
 	size_t padded_entry_size;
 	size_t entry_size;
 	enum ec_error_list rv = EC_ERROR_INVAL;
+	uint32_t new_timestamp;
 
 	if (size > MAX_FLASH_LOG_PAYLOAD_SIZE)
 		return rv;
@@ -293,7 +305,18 @@ static enum ec_error_list flash_log_add_event_core(uint8_t type, uint8_t size,
 
 	entry_size = sizeof(e.r) + size;
 
-	e.r.timestamp = ++log_stamp;
+	new_timestamp = flash_log_get_tstamp();
+
+	/*
+	 * Avoid rolling back or logging more than one entry with the same
+	 * timestamp.
+	 */
+	if (last_used_timestamp >= new_timestamp)
+		last_used_timestamp += 1;
+	else
+		last_used_timestamp = new_timestamp;
+
+	e.r.timestamp = last_used_timestamp;
 	e.r.size = size;
 	e.r.type = type;
 	e.r.crc = 0;
@@ -425,11 +448,14 @@ test_export_static void flash_log_init(void)
 
 	r = log_offset_to_addr(read_cursor);
 	while (entry_is_valid(r)) {
-		log_stamp = r->timestamp + 1;
+		last_used_timestamp = r->timestamp;
 		read_cursor += FLASH_LOG_ENTRY_SIZE(r->size);
 		r = log_offset_to_addr(read_cursor);
 	}
 
+	/* Should be updated by the AP soon after booting. */
+	log_tstamp_base = last_used_timestamp + 1;
+
 	log_write_cursor = read_cursor;
 	log_inited = 1;
 
@@ -462,6 +488,21 @@ test_export_static void flash_log_init(void)
 }
 DECLARE_HOOK(HOOK_INIT, flash_log_init, HOOK_PRIO_DEFAULT);
 
+uint32_t flash_log_get_tstamp(void)
+{
+	return log_tstamp_base + get_time().val/1000000;
+}
+
+enum ec_error_list flash_log_set_tstamp(uint32_t tstamp)
+{
+	if (tstamp <= last_used_timestamp)
+		return EC_ERROR_INVAL;
+
+	log_tstamp_base = tstamp - get_time().val/1000000;
+
+	return EC_SUCCESS;
+}
+
 #ifdef CONFIG_CMD_FLASH_LOG
 /*
  * Display Flash event log.
@@ -499,10 +540,10 @@ static int command_flash_log(int argc, char **argv)
 						     sizeof(e))) > 0) {
 			size_t i;
 
-			ccprintf("%08x:%02x", e.r.timestamp, e.r.type);
+			ccprintf("%10u:%02x", e.r.timestamp, e.r.type);
 			for (i = 0; i < FLASH_LOG_PAYLOAD_SIZE(e.r.size); i++) {
 				if (i && !(i % 16)) {
-					ccprintf("\n           ");
+					ccprintf("\n          ");
 					cflush();
 				}
 				ccprintf(" %02x", e.r.payload[i]);
diff --git a/include/flash_log.h b/include/flash_log.h
index bbdd8bb0b3..ee56226be6 100644
--- a/include/flash_log.h
+++ b/include/flash_log.h
@@ -132,10 +132,21 @@ int flash_log_dequeue_event(uint32_t event_after, void *buffer,
 void flash_log_register_flash_control_callback(
 	void (*flash_control)(int enable));
 
+/*
+ * Set log timestamp base. The argument is current epoch time in seconds.
+ * Return value of EC_ERROR_INVAL indicates attempt to set the timestamp base
+ * to a value below the latest log entry timestamp.
+ */
+enum ec_error_list flash_log_set_tstamp(uint32_t tstamp);
+
+/* Get current log timestamp value. */
+uint32_t flash_log_get_tstamp(void);
+
 #if defined(TEST_BUILD)
 void flash_log_init(void);
-extern uint8_t log_event_in_progress;
+extern uint32_t last_used_timestamp;
 extern uint32_t lock_failures_count;
+extern uint8_t log_event_in_progress;
 #endif
 
 #endif /* __CROS_EC_EVENT_LOG_H */
diff --git a/test/flash_log.c b/test/flash_log.c
index 20ae939f23..48c842371e 100644
--- a/test/flash_log.c
+++ b/test/flash_log.c
@@ -10,6 +10,7 @@
 #include "common.h"
 #include "flash_log.h"
 #include "test_util.h"
+#include "timer.h"
 #include "util.h"
 
 struct log_stats {
@@ -25,6 +26,7 @@ static int verify_single_entry(uint8_t fill_byte, int expected_type)
 	uint8_t *log_base = (void *)CONFIG_FLASH_LOG_BASE;
 
 	memset(log_base, fill_byte, CONFIG_FLASH_LOG_SPACE);
+	last_used_timestamp = 0;
 	flash_log_init();
 
 	/* After initialization there should be a single log entry. */
@@ -204,6 +206,61 @@ static int test_lock_failure_reporting(void)
 	return EC_SUCCESS;
 }
 
+static int test_setting_base_timestamp(void)
+{
+	union entry_u eu;
+	uint32_t saved_stamp;
+	timestamp_t ts;
+	uint32_t delta_time;
+	/* Value collected on May 13 2019 */
+	uint32_t recent_seconds_since_epoch = 1557793625;
+
+	ts.val = 0;
+	force_time(ts);
+	TEST_ASSERT(verify_single_entry(0xff, FE_LOG_START) == EC_SUCCESS);
+	TEST_ASSERT(flash_log_dequeue_event(0, eu.entry, sizeof(eu)) > 0);
+
+	saved_stamp = eu.r.timestamp;
+
+	/* Let the next log timestamp be 1000 s later. */
+	delta_time = 1000;
+
+	/*
+	 * Move internal clock uptime of 1000 s (convert value to microseconds
+	 * first).
+	 */
+	ts.val = ((uint64_t)saved_stamp + delta_time) * 1000000;
+	force_time(ts);
+
+	/* Verify that the second event is within 1001 s from the first one. */
+	flash_log_add_event(FE_LOG_TEST, 0, NULL);
+	TEST_ASSERT(flash_log_dequeue_event(saved_stamp, eu.entry, sizeof(eu)) >
+		    0);
+	TEST_ASSERT((eu.r.timestamp - saved_stamp - delta_time) < 2);
+
+	/* Set timestamp base to current time. */
+	TEST_ASSERT(flash_log_set_tstamp(recent_seconds_since_epoch) ==
+		    EC_SUCCESS);
+
+	/* Create an entry with the latest timestamp. */
+	flash_log_add_event(FE_LOG_TEST, 0, NULL);
+
+	/* Verify that it has been logged with the correct timestamp. */
+	TEST_ASSERT(flash_log_dequeue_event(eu.r.timestamp, eu.entry,
+					    sizeof(eu)) > 0);
+	TEST_ASSERT((eu.r.timestamp - recent_seconds_since_epoch) < 2);
+
+	/* Verify that it is impossible to roll timestamps back. */
+	TEST_ASSERT(flash_log_set_tstamp(recent_seconds_since_epoch - 100) ==
+		    EC_ERROR_INVAL);
+
+	/* But is possible to roll further forward. */
+	TEST_ASSERT(flash_log_set_tstamp(recent_seconds_since_epoch + 100) ==
+		    EC_SUCCESS);
+
+	return EC_SUCCESS;
+}
+
 void run_test(void)
 {
 	test_reset();
@@ -213,6 +270,7 @@ void run_test(void)
 	RUN_TEST(test_run_time_compaction);
 	RUN_TEST(test_init_time_compaction);
 	RUN_TEST(test_lock_failure_reporting);
+	RUN_TEST(test_setting_base_timestamp);
 
 	test_print_result();
 }