Feat/binary log (#364)

* feat(log): WIP adding support for binary logging

* WIP testing example more

* flesh out example more

* add simple tool for writing the appropriate files from copy-pasted data

* update gitignore for this folder to ignore log files

* update example to show use of run-length encoding and update python script with a little bit more info

* flesh out some more

* Update component to build unpacker automatically when the component is built. update readme accordingly

* update ci

* update docs

* remove p-ranav/binary_log

* update the repo to use finger563 fork

* update commit ref

* Update cmake lists to remove commented line and add comments about function

.github/workflows/build.yml

@@ -27,6 +27,8 @@ jobs:
           target: esp32s3
         - path: 'components/aw9523/example'
           target: esp32
+        - path: 'components/binary-log/example'
+          target: esp32s3
         - path: 'components/bldc_haptics/example'
           target: esp32s3
         - path: 'components/bldc_motor/example'

.github/workflows/static_analysis.yml

@@ -27,4 +27,4 @@ jobs:
         esp_idf_version: release/v5.2
 
         # (Optional) cppcheck args
-        cppcheck_args: -i$GITHUB_WORKSPACE/lib -i$GITHUB_WORKSPACE/external -i$GITHUB_WORKSPACE/components/esp_littlefs -i$GITHUB_WORKSPACE/components/esp-nimble-cpp -i$GITHUB_WORKSPACE/components/hid-rp/include/hid -i$GITHUB_WORKSPACE/components/lvgl -i$GITHUB_WORKSPACE/components/esp-dsp --force --enable=all --inline-suppr --inconclusive --platform=mips32 --suppressions-list=$GITHUB_WORKSPACE/suppressions.txt
+        cppcheck_args: -i$GITHUB_WORKSPACE/lib -i$GITHUB_WORKSPACE/external -i$GITHUB_WORKSPACE/components/binary-log/detail -i$GITHUB_WORKSPACE/components/esp_littlefs -i$GITHUB_WORKSPACE/components/esp-nimble-cpp -i$GITHUB_WORKSPACE/components/hid-rp/include/hid -i$GITHUB_WORKSPACE/components/lvgl -i$GITHUB_WORKSPACE/components/esp-dsp --force --enable=all --inline-suppr --inconclusive --platform=mips32 --suppressions-list=$GITHUB_WORKSPACE/suppressions.txt

.gitmodules

@@ -37,3 +37,6 @@
 [submodule "external/nearby"]
 	path = external/nearby
 	url = https://github.com/google/nearby
+[submodule "components/binary-log/detail"]
+	path = components/binary-log/detail
+	url = https://github.com/finger563/binary_log

components/binary-log/CMakeLists.txt

@@ -0,0 +1,19 @@
+idf_component_register(
+  INCLUDE_DIRS "include" "detail/include"
+  SRC_DIRS "src"
+  REQUIRES "")
+
+# Build the unpacker tool and put it whereever the rest of the build binaries
+# are going for this build. This will ensure that the user can always run
+# `./build/unpacker <log-file>`
+add_custom_command(
+  TARGET ${COMPONENT_TARGET}
+  POST_BUILD
+  DEPENDS ${COMPONENT_TARGET}
+  WORKING_DIRECTORY ${COMPONENT_DIR}/detail
+  COMMAND echo "Building binary-log unpacker"
+  COMMAND mkdir -p build
+  COMMAND cmake -B build -S .
+  COMMAND cmake --build build
+  COMMAND cp build/tools/unpacker/unpacker ${CMAKE_BINARY_DIR}/unpacker
+)

components/binary-log/example/.gitignore

@@ -0,0 +1 @@
+log.*

components/binary-log/example/CMakeLists.txt

@@ -0,0 +1,21 @@
+# The following lines of boilerplate have to be in your project's CMakeLists
+# in this exact order for cmake to work correctly
+cmake_minimum_required(VERSION 3.5)
+
+include($ENV{IDF_PATH}/tools/cmake/project.cmake)
+
+# add the component directories that we want to use
+set(EXTRA_COMPONENT_DIRS
+  "../../../components/"
+)
+
+set(
+  COMPONENTS
+  "main esptool_py espcoredump binary-log file_system format"
+  CACHE STRING
+  "List of components to include"
+  )
+
+project(binary_log_example)
+
+set(CMAKE_CXX_STANDARD 20)

components/binary-log/example/README.md

@@ -0,0 +1,75 @@
+# Binary Log Example
+
+This example shows how to use the `binary-log` component to format and store
+logs in a binary packed form, either to disk or into a ringbuffer in memory.
+
+This component simply exposes the
+[p-ranav/binary_log](https://github.com/p-ranav/binary_log) binary logger, with
+some modifications in a fork
+[finger563/binary_log](https://github.com/finger563/binary_log) to allow packer
+customization as is required on embedded systems such as with ESP-IDF.
+
+The `binary-log` does not support all datatypes, but only some base datatypes
+such as integer types, float types, and string types.
+
+The logger produces the following data:
+1. Log data - these are indexes and the arguments which point to either the
+   index data or the runfile data.
+2. Index data - these are static data (format strings, constant arguments, etc.)
+3. Runfile data - these are indices of the log file which run multiple times in
+   a row.
+
+For more information about the logging, its format, and the types supported,
+please see [p-ranav/binary_log](https://github.com/p-ranav/binary_log).
+
+## How to use example
+
+This example is designed to be run on an ESP dev board which has embedded
+flash - the partitions and build are configured to match the QtPy ESP32-S3,
+though if you modify the `sdkconfig.defaults` and the `partitions.csv` you could
+run it on other dev boards easily.
+
+The example does the following:
+1. Use standard `binary_log::packer` to log in a loop for three seconds to files
+   on the filesystem.
+2. Print the contents of the log files.
+3. Erase the file system.
+4. Use the `binary_log::ringbuffer_packer` to log in a loop for three seconds to
+   into an in-memory ringbuffer.
+5. Print the contents of the log buffers.
+
+### Unpacking the logs
+
+#### Getting the log data
+
+You can copy the text from the example output into
+[write_files.py](./write_files.py), then run that script, and it will produce
+the relevant `log.out`, `log.out.index`, and `log.out.runfile` on your computer.
+
+#### Unpacking the log data
+
+Once you've done that, you can unpack the log data using the `unpacker` that is
+automatically built when you build the app and is located within your `build`
+folder as `build/unpacker`:
+
+``` console
+./build/unpacker log.out > log.inflated
+```
+
+### Build and Flash
+
+Build the project and flash it to the board, then run monitor tool to view serial output:
+
+```
+idf.py -p PORT flash monitor
+```
+
+(Replace PORT with the name of the serial port to use.)
+
+(To exit the serial monitor, type ``Ctrl-]``.)
+
+See the Getting Started Guide for full steps to configure and use ESP-IDF to build projects.
+
+## Example Output
+
+![CleanShot 2025-01-31 at 14 31 23](https://github.com/user-attachments/assets/72e3c118-d5c0-4e48-b5ab-732e6b32e433)

components/binary-log/example/main/CMakeLists.txt

@@ -0,0 +1,2 @@
+idf_component_register(SRC_DIRS "."
+                       INCLUDE_DIRS ".")

components/binary-log/example/main/binary_log_example.cpp

@@ -0,0 +1,188 @@
+#include <chrono>
+#include <functional>
+#include <thread>
+
+#include <esp_core_dump.h>
+
+#include "binary-log.hpp"
+#include "file_system.hpp"
+#include "logger.hpp"
+
+using namespace std::chrono_literals;
+
+extern "C" void app_main(void) {
+  espp::Logger logger({.tag = "blog_example", .level = espp::Logger::Verbosity::INFO});
+
+  logger.info("Starting binary log example");
+  // initialize the file system
+  std::error_code ec;
+  auto &fs = espp::FileSystem::get();
+  auto root = fs.get_root_path();
+  const std::filesystem::path logfile = root / std::filesystem::path{"log.out"};
+
+  auto print_files = [&fs, &logger, &root, &logfile]() {
+    logger.info("Printing log file");
+    std::error_code ec;
+
+    size_t file_size = std::filesystem::file_size(logfile, ec);
+    std::ifstream ifs(logfile, std::ios::in | std::ios::binary);
+    // read bytes
+    std::vector<char> file_bytes(file_size);
+    ifs.read(file_bytes.data(), file_size);
+    ifs.close();
+    logger.info("Read {} bytes from log file", file_size);
+    logger.info("File contents:\n{::#02x}", file_bytes);
+
+    // now print the contents of the other two associated files
+    logger.info("Printing index file");
+    std::filesystem::path indexfile = logfile;
+    indexfile.replace_extension(logfile.extension().string() + ".index");
+    file_size = std::filesystem::file_size(indexfile, ec);
+    ifs.open(indexfile, std::ios::in | std::ios::binary);
+    // read bytes
+    file_bytes.resize(file_size);
+    ifs.read(file_bytes.data(), file_size);
+    ifs.close();
+    logger.info("Read {} bytes from index file", file_size);
+    logger.info("File contents:\n{::#02x}", file_bytes);
+
+    // print the contents of the runlength file
+    logger.info("Printing runlength file");
+    std::filesystem::path runlengthfile = logfile;
+    runlengthfile.replace_extension(logfile.extension().string() + ".runlength");
+    file_size = std::filesystem::file_size(runlengthfile, ec);
+    ifs.open(runlengthfile, std::ios::in | std::ios::binary);
+    // read bytes
+    file_bytes.resize(file_size);
+    ifs.read(file_bytes.data(), file_size);
+    ifs.close();
+    logger.info("Read {} bytes from runlength file", file_size);
+    logger.info("File contents:\n{::#02x}", file_bytes);
+
+    // print the contents of the file system
+    logger.info("Directory contents:\n{}", fs.list_directory(root, {}));
+  };
+
+  // first see if the file exists
+  if (std::filesystem::exists(logfile, ec)) {
+    logger.info("Removing existing log file");
+    fs.remove(logfile, ec);
+  }
+
+  {
+    //! [Binary Log example]
+    float num_seconds_to_run = 3.0f;
+    // create standard logger. This will buffer the logs in memory until the buffer is
+    // full or the logger is destroyed
+    logger.info("Creating binary log file: {}", logfile.c_str());
+    static constexpr size_t log_buffer_size = 1024;
+    static constexpr size_t index_buffer_size = 1024;
+    static constexpr size_t runlength_buffer_size = 1024;
+    using Packer = binary_log::packer<log_buffer_size, index_buffer_size, runlength_buffer_size>;
+    binary_log::binary_log<Packer> log(logfile);
+
+    logger.info("Starting binary logging for {}s", num_seconds_to_run);
+    auto start = std::chrono::high_resolution_clock::now();
+    auto now = std::chrono::high_resolution_clock::now();
+    float elapsed = std::chrono::duration<float>(now - start).count();
+    while (elapsed < num_seconds_to_run) {
+      now = std::chrono::high_resolution_clock::now();
+      elapsed = std::chrono::duration<float>(now - start).count();
+      auto remaining = num_seconds_to_run - elapsed;
+
+      // NOTE: use of a single log within the majority of this loop allows for
+      // run-length encoding of the log messages to be used to reduce the size
+      BINARY_LOG(log, "elapsed: {}s\nremaining: {}s", elapsed, remaining);
+
+      // print a log each second. to track it, just get the remainder
+      // milliseconds and see if they're less than 15
+      if (std::chrono::duration_cast<std::chrono::milliseconds>(now - start).count() % 1000 < 15) {
+        BINARY_LOG(log, "This is a log message at {}s", elapsed)
+      }
+
+      if (remaining < 0) {
+        BINARY_LOG(log, "You overstayed your welcome by {}s!", -remaining);
+      }
+      std::this_thread::sleep_for(10ms);
+    }
+    //! [Logger example]
+  }
+
+  // now print out the logger files
+  print_files();
+
+  // now erase the file system
+  logger.info("Erase file system");
+  fs.remove_contents(root, ec);
+
+  {
+    //! [Binary Log example]
+    float num_seconds_to_run = 3.0f;
+    // create ringbuffer logger. This will not write to disk, but instead will
+    // only store log data in memory. The log buffer will be a ring buffer,
+    // discarding the oldest data, while the index and runlength buffers will be
+    // simple arrays which will abort if they run out of space.
+    logger.info("Creating ringbuffer binary log");
+    static constexpr size_t log_buffer_size = 1024;
+    static constexpr size_t index_buffer_size = 1024;
+    static constexpr size_t runlength_buffer_size = 1024;
+    using Packer =
+        binary_log::ringbuffer_packer<log_buffer_size, index_buffer_size, runlength_buffer_size>;
+    binary_log::binary_log<Packer> log(logfile);
+
+    logger.info("Starting binary logging for {}s", num_seconds_to_run);
+    auto start = std::chrono::high_resolution_clock::now();
+    auto now = std::chrono::high_resolution_clock::now();
+    float elapsed = std::chrono::duration<float>(now - start).count();
+    while (elapsed < num_seconds_to_run) {
+      now = std::chrono::high_resolution_clock::now();
+      elapsed = std::chrono::duration<float>(now - start).count();
+      auto remaining = num_seconds_to_run - elapsed;
+
+      BINARY_LOG(log, "elapsed: {}s", elapsed);
+      BINARY_LOG(log, "remaining: {}s", remaining);
+
+      // print a log each second. to track it, just get the remainder
+      // milliseconds and see if they're less than 15
+      if (std::chrono::duration_cast<std::chrono::milliseconds>(now - start).count() % 1000 < 15) {
+        BINARY_LOG(log, "This is a log message at {}s", elapsed)
+      }
+
+      if (remaining < 0) {
+        BINARY_LOG(log, "You overstayed your welcome by {}s!", -remaining);
+      }
+      std::this_thread::sleep_for(10ms);
+    }
+    // Since this is a memory-based logger, we must flush and read out the data
+    // manually
+    log.flush();
+
+    const Packer &packer = log.get_packer();
+    auto log_buffer = packer.get_log_buffer();
+    auto index_buffer_sv = packer.get_index_buffer();
+    // convert the string view into a vector for easy printing with libfmt
+    std::vector<uint8_t> index_buffer(index_buffer_sv.begin(), index_buffer_sv.end());
+    auto runlength_buffer_sv = packer.get_runlength_buffer();
+    // convert the string view into a vector for easy printing with libfmt
+    std::vector<uint8_t> runlength_buffer(runlength_buffer_sv.begin(), runlength_buffer_sv.end());
+
+    logger.info("Log file size: {} bytes", log_buffer.size());
+    logger.info("Index file size: {} bytes", index_buffer.size());
+    logger.info("Runlength file size: {} bytes", runlength_buffer.size());
+    logger.info("--------------------------------");
+    logger.info("Total file size: {} bytes",
+                log_buffer.size() + index_buffer.size() + runlength_buffer.size());
+
+    logger.info("Log data:\n{::#02x}", log_buffer);
+    logger.info("Index data:\n{::#02x}", index_buffer);
+    logger.info("Runlength data:\n{::#02x}", runlength_buffer);
+    //! [Logger example]
+  }
+
+  logger.info("Finished binary log example");
+
+  // now loop forever
+  while (true) {
+    std::this_thread::sleep_for(1s);
+  }
+}

components/binary-log/example/partitions.csv

@@ -0,0 +1,6 @@
+# Name,   Type, SubType, Offset,  Size
+nvs,      data, nvs,     0x9000,  0x6000
+phy_init, data, phy,     0xf000,  0x1000
+factory,  app,  factory, 0x10000, 2M
+coredump, data, coredump,       , 256K
+littlefs, data, spiffs,         , 1M

components/binary-log/example/sdkconfig.defaults

@@ -0,0 +1,33 @@
+CONFIG_IDF_TARGET="esp32s3"
+
+# Common ESP-related
+#
+# binary_log requires exceptions right now...
+# CONFIG_COMPILER_CXX_EXCEPTIONS=y
+
+CONFIG_ESPTOOLPY_FLASHSIZE_4MB=y
+CONFIG_ESPTOOLPY_FLASHSIZE="4MB"
+
+CONFIG_FREERTOS_HZ=1000
+
+# Clock Frequency
+CONFIG_ESP_DEFAULT_CPU_FREQ_MHZ_240=y
+CONFIG_ESP_DEFAULT_CPU_FREQ_MHZ=240
+
+# Common ESP-related
+#
+CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE=4096
+CONFIG_ESP_MAIN_TASK_STACK_SIZE=10240
+CONFIG_ESP_TIMER_TASK_STACK_SIZE=4096
+
+# Partition Table
+CONFIG_PARTITION_TABLE_CUSTOM=y
+CONFIG_PARTITION_TABLE_CUSTOM_FILENAME="partitions.csv"
+
+# Even if the environment variable MEMFAULT_DISABLE=1 is set, cli.py can retrieve SystemInfo.
+CONFIG_FREERTOS_USE_TRACE_FACILITY=y
+CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS=y
+
+# Coredump
+CONFIG_ESP_COREDUMP_ENABLE_TO_FLASH=y
+CONFIG_ESP_COREDUMP_STACK_SIZE=2048