/* * 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 #include #include #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); }