path: root/test/flash_log.c

/* Copyright 2019 The ChromiumOS Authors
 * 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 "timer.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);
	last_used_timestamp = 0;
	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;
}

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();

	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);
	RUN_TEST(test_setting_base_timestamp);

	test_print_result();
}