pebble/tests/fw/test_flash_logging.c
2025-01-27 11:38:16 -08:00

447 lines
13 KiB
C

/*
* Copyright 2024 Google LLC
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#include "clar.h"
#include "flash_region/flash_region.h"
#include "debug/flash_logging.h"
#include "util/math.h"
#include "util/size.h"
#include "util/string.h"
#include "fake_spi_flash.h"
#include "fake_system_task.h"
#include "stubs_logging.h"
#include "stubs_passert.h"
#include "stubs_pbl_malloc.h"
#include "stubs_print.h"
#include "stubs_serial.h"
#include "stubs_sleep.h"
#include "stubs_task_watchdog.h"
#include "system/logging.h"
#include "system/passert.h"
#include <stdbool.h>
#include <stdio.h>
#include <string.h>
#define FLASH_SIZE (4 * 1024 * 1024)
void test_flash_logging__initialize(void) {
fake_spi_flash_init(0, FLASH_SIZE);
}
void test_flash_logging__cleanup(void) {
uint32_t size = FLASH_REGION_DEBUG_DB_BEGIN - 0;
fake_flash_assert_region_untouched(0, size);
size = FLASH_SIZE - FLASH_REGION_DEBUG_DB_END;
fake_flash_assert_region_untouched(FLASH_REGION_DEBUG_DB_END, size);
fake_spi_flash_cleanup();
}
typedef struct {
char **msg_arr;
int curr_msg_idx;
int num_items;
int num_processed;
} ExpectedMessage;
static ExpectedMessage s_msg;
void test_flash_logging_get_info(uint32_t *tot_size, uint32_t *erase_unit_size,
uint32_t *chunk_size, uint32_t *page_hdr_size);
const uint8_t *version_get_build_id(size_t *out_len) {
static uint8_t build_id[20] = {
0xee, 0xd2, 0xbf, 0x50, 0x5b, 0x59, 0x04, 0xb5, 0x14, 0x98,
0x28, 0xb9, 0x56, 0x6d, 0x26, 0xc5, 0x9b, 0x68, 0xe9, 0xcc };
if (out_len) {
*out_len = sizeof(build_id);
}
return (uint8_t *)&build_id[0];
}
void version_copy_current_build_id_hex_string(char *buffer,
size_t buffer_bytes_left) {
size_t build_id_bytes_left;
const uint8_t *build_id = version_get_build_id(&build_id_bytes_left);
byte_stream_to_hex_string(buffer, buffer_bytes_left, build_id,
build_id_bytes_left, false);
}
int pbl_log_get_bin_format(char* buffer, int buffer_len, const uint8_t log_level,
const char* src_filename_path, int src_line_number, const char* fmt, ...) {
va_list fmt_args;
va_start(fmt_args, fmt);
int len = vsnprintf(buffer, buffer_len, fmt, fmt_args);
va_end(fmt_args);
return (len);
}
static char *get_expected_msg(void) {
cl_assert(s_msg.msg_arr != NULL);
cl_assert(s_msg.curr_msg_idx < s_msg.num_items);
char *expected_msg = NULL;
if (s_msg.num_processed != 0) {
expected_msg = s_msg.msg_arr[s_msg.curr_msg_idx - 1];
}
s_msg.curr_msg_idx++;
s_msg.num_processed++;
return (expected_msg);
}
static bool prv_flash_log_line_dump(uint8_t *msg, uint32_t tot_len) {
char buf[tot_len + 1];
memcpy(&buf, (char*)msg, tot_len);
buf[tot_len] = '\0';
// printf("-%s\n", buf);
char *expected_msg = get_expected_msg();
if (expected_msg) {
bool msg_matches_expected = (memcmp(msg, expected_msg, tot_len) == 0);
cl_assert(msg_matches_expected);
} else {
// the first line should always end with the build id
char build_id_string[64];
version_copy_current_build_id_hex_string(build_id_string, 64);
int id_len = strlen(build_id_string);
char *log_build_id = &buf[tot_len - id_len];
bool log_contains_build_id =
(memcmp(log_build_id, build_id_string, id_len) == 0);
cl_assert(log_contains_build_id);
}
return true;
}
bool s_completed = false;
bool s_completed_success = false;
static void prv_flash_log_dump_completed_cb(bool success) {
PBL_LOG(LOG_LEVEL_DEBUG, "Called prv_flash_log_dump_completed_cb(%d)", (int)success);
s_completed = true;
s_completed_success = success;
}
static void setup_and_test_expected_msg(char **msg_arr, int log_gen,
int start_idx, int num_items) {
for (int i = start_idx; i < num_items; i++) {
char *msg = msg_arr[i];
uint32_t addr = flash_logging_log_start(strlen(msg));
cl_assert(addr != FLASH_LOG_INVALID_ADDR);
bool rv = flash_logging_write((uint8_t *)msg, addr, strlen(msg));
cl_assert(rv);
}
ExpectedMessage newmsg = {
.msg_arr = msg_arr,
.curr_msg_idx = 0,
.num_items = (num_items + 1), // + 1 for build id line
.num_processed = 0,
};
s_msg = newmsg;
s_completed = false;
bool success = flash_dump_log_file(log_gen, prv_flash_log_line_dump,
prv_flash_log_dump_completed_cb);
cl_assert(success);
while (!s_completed) {
fake_system_task_callbacks_invoke_pending();
}
cl_assert(s_completed_success);
cl_assert_equal_i(s_msg.num_processed, s_msg.num_items);
}
static char **generate_unique_logs(size_t space_avail, size_t log_len,
int *num_logs) {
*num_logs = space_avail / (log_len + 2); // add 2 for overhead per log
char msg[log_len + 1];
char **msg_arr = malloc(*num_logs * sizeof(char *));
for (int i = 0; i < *num_logs; i++) {
uint32_t uniq_msg_id = 0xDEADDEAD - i + (i << 16);
char buf[20];
snprintf(buf, sizeof(buf), "%x", uniq_msg_id);
for (int j = 0; j < log_len; j += strlen(buf)) {
memcpy(&msg[j], buf, MIN(strlen(buf), log_len - j));
}
msg[log_len] = '\0';
msg_arr[i] = task_strdup(msg);
}
return (msg_arr);
}
static void free_logs(char **msg_arr, int num_logs) {
for (int i = 0; i < num_logs; i++) {
free(msg_arr[i]);
}
free(msg_arr);
}
//
// Actual Tests
//
//! Simple test to confirm that we can log and read back several messages
void test_flash_logging__basic(void) {
flash_logging_init();
const char *test_messages[] = {
"A simple test log message! Woohoo!",
"Another message",
"ABCDEFG 0123456789",
"Last simple test message"
};
int num_messages = ARRAY_LENGTH(test_messages);
setup_and_test_expected_msg((char **)test_messages, 0, 0, num_messages);
}
//! Auto generate unique log messages of uniform length which span multiple log
//! chunks. Try several log message lengths
void test_flash_logging__multi_region(void) {
const uint32_t header_overhead = 8 * 28;
const uint32_t space_avail = 64 * 1024 - header_overhead;
for (int log_len = 2; log_len < 128; log_len += 3) {
test_flash_logging__cleanup();
test_flash_logging__initialize();
flash_logging_init();
int num_logs;
char **logs = generate_unique_logs(space_avail, log_len, &num_logs);
setup_and_test_expected_msg(logs, 0, 0, num_logs);
free_logs(logs, num_logs);
}
}
//!
void test_flash_logging__wrap(void) {
flash_logging_init();
uint32_t tot_size, erase_size, page_size, page_hdr_size;
test_flash_logging_get_info(&tot_size, &erase_size, &page_size,
&page_hdr_size);
int num_pages = tot_size / page_size;
uint32_t space_avail = tot_size - num_pages * page_hdr_size;
// make sure the logs are of an appropriate size such that each page will
// be entirely filled
int log_len = 2;
cl_assert((page_size - page_hdr_size) % (2 + log_len) == 0);
// fill up all of our log record space
int num_logs;
char **logs = generate_unique_logs(space_avail, log_len, &num_logs);
setup_and_test_expected_msg(logs, 0, 0, num_logs);
// write two more additional logs which should cause the first erase
// region to get erased
logs = realloc(logs, sizeof(char *) * (num_logs + 2));
logs[num_logs] = task_strdup("Let's test if wrap around is working!");
logs[num_logs + 1] = task_strdup("This should be on an early page");
int start_log = num_logs / (tot_size / erase_size);
int num_wrapped = num_logs - start_log;
setup_and_test_expected_msg(&logs[start_log], 0, num_wrapped, num_wrapped + 2);
free_logs(logs, num_logs + 2);
}
//! Keep simulating reboots and generating new logs. Confirm that
//! the most recent generations are not removed during reboots.
void test_flash_logging__generations(void) {
uint32_t tot_size, erase_size, page_size, page_hdr_size;
test_flash_logging_get_info(&tot_size, &erase_size, &page_size,
&page_hdr_size);
int gens_avail = (tot_size - erase_size) / page_size;
char *log = malloc(100);
for (int i = 0; i < 533; i++) {
flash_logging_init();
// Write the new message
snprintf(log, 100, "Generation 0x%x", i);
setup_and_test_expected_msg(&log, 0, 0, 1);
for (int gen = 0; gen < MIN(gens_avail, i); gen++) {
// Check to make sure the most recent log gens are around
snprintf(log, 100, "Generation 0x%x", i - gen);
setup_and_test_expected_msg(&log, gen, 1, 1);
}
}
free(log);
}
//! Test the case where the most recent log generation has wrapped the logging
//! region many times. Confirm that upon reboot, the most recent messages from
//! that generation remain
static int s_long_lived_last_val = -1;
static bool flash_log_line_dump_long_lived(uint8_t *msg, uint32_t tot_len) {
static bool got_first_line = false;
if (!got_first_line) {
got_first_line = true;
return (true);
}
char buf[tot_len + 1];
memcpy(&buf, (char*)msg, tot_len);
buf[tot_len] = '\0';
PBL_LOG(LOG_LEVEL_DEBUG, "flash_log_line_dump_long_lived: got %s", buf);
int curr_val;
int filled = sscanf(buf, "Loop Counter %d", &curr_val);
cl_assert_equal_i(filled, 1);
if (s_long_lived_last_val != -1) {
cl_assert_equal_i(s_long_lived_last_val + 1, curr_val);
}
s_long_lived_last_val = curr_val;
PBL_LOG(LOG_LEVEL_DEBUG, "flash_log_line_dump_long_lived: got %s, last_val:%d", buf,
s_long_lived_last_val);
return (true);
}
void test_flash_logging__long_lived_log(void) {
flash_logging_init();
uint32_t start_addr = flash_logging_log_start(1);
char *msg = "h";
bool rv = flash_logging_write((uint8_t *)msg, start_addr, 1);
cl_assert(rv);
uint32_t tot_size, erase_size, page_size, page_hdr_size;
test_flash_logging_get_info(&tot_size, &erase_size, &page_size,
&page_hdr_size);
uint32_t addr = FLASH_LOG_INVALID_ADDR;
int loop_count = 0;
char *log = malloc(100);
int num_half_wraps = 0;
int tot_half_wraps = 5; // make odd so we wrap into the middle of the log region
while (num_half_wraps < tot_half_wraps) {
loop_count++;
snprintf(log, 100, "Loop Counter %d", loop_count);
addr = flash_logging_log_start(strlen(log));
cl_assert(addr != FLASH_LOG_INVALID_ADDR);
rv = flash_logging_write((uint8_t *)log, addr, strlen(log));
cl_assert(rv);
if (addr == start_addr || (addr == (start_addr + erase_size - page_size))) {
num_half_wraps++;
}
}
// simulate a reboot
flash_logging_init();
// check to see that the most recent messages (largest loop count numbers)
// are left
s_completed = false;
rv = flash_dump_log_file(1, flash_log_line_dump_long_lived, prv_flash_log_dump_completed_cb);
cl_assert(rv);
while (!s_completed) {
fake_system_task_callbacks_invoke_pending();
}
cl_assert(s_completed_success);
cl_assert_equal_i(s_long_lived_last_val, loop_count);
}
//! Check error handling for some of the different edge cases
void test_flash_logging__errors(void) {
flash_logging_init();
uint32_t start_addr = flash_logging_log_start(0);
cl_assert_equal_i(start_addr, FLASH_LOG_INVALID_ADDR);
char *msg = "0123456789";
start_addr = flash_logging_log_start(10);
cl_assert(start_addr != FLASH_LOG_INVALID_ADDR);
bool rv = flash_logging_write((uint8_t *)msg, start_addr, strlen(msg));
cl_assert(rv);
rv = flash_logging_write((uint8_t *)msg, start_addr, strlen(msg));
cl_assert(!rv);
setup_and_test_expected_msg(&msg, 0, 1, 1);
}
//! Make sure that when we chunk up our writes for a log message, the lines
//! are saved as expected and that bogus writes after a record has been written
//! do not take
void test_flash_logging__multi_writes_per_log(void) {
flash_logging_init();
const int log_len = 49;
int num_logs = 0;
char **logs = generate_unique_logs(20222, log_len, &num_logs);
for (int i = 0; i < num_logs; i++) {
uint8_t write_sizes[4] = { log_len / 2, log_len / 4, log_len / 8, log_len };
int bytes_remaining = log_len;
uint32_t addr = flash_logging_log_start(log_len);
cl_assert(addr != FLASH_LOG_INVALID_ADDR);
char *curr_msg = logs[i];
bool rv;
for (int j = 0; j < ARRAY_LENGTH(write_sizes); j++) {
int bytes_to_write = MIN(bytes_remaining, write_sizes[j]);
int offset = log_len - bytes_remaining;
rv = flash_logging_write((uint8_t *)&curr_msg[offset], addr,
bytes_to_write);
cl_assert(rv);
bytes_remaining -= bytes_to_write;
}
// try to write something past the end to ensure it doesn't take
uint8_t buf[128] = { 0 };
rv = flash_logging_write(&buf[0], addr, sizeof(buf));
cl_assert(!rv);
}
setup_and_test_expected_msg(logs, 0, num_logs, num_logs);
}