diff options
| -rw-r--r-- | common/flash_log.c | 53 | ||||
| -rw-r--r-- | include/flash_log.h | 13 | ||||
| -rw-r--r-- | test/flash_log.c | 58 |
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(); } |