Skip to content

Commit d6b7cdd

Browse files
authored
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
1 parent d7c8be6 commit d6b7cdd

18 files changed

+404
-1
lines changed

.github/workflows/build.yml

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,8 @@ jobs:
2727
target: esp32s3
2828
- path: 'components/aw9523/example'
2929
target: esp32
30+
- path: 'components/binary-log/example'
31+
target: esp32s3
3032
- path: 'components/bldc_haptics/example'
3133
target: esp32s3
3234
- path: 'components/bldc_motor/example'

.github/workflows/static_analysis.yml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -27,4 +27,4 @@ jobs:
2727
esp_idf_version: release/v5.2
2828

2929
# (Optional) cppcheck args
30-
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
30+
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

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -37,3 +37,6 @@
3737
[submodule "external/nearby"]
3838
path = external/nearby
3939
url = https://github.com/google/nearby
40+
[submodule "components/binary-log/detail"]
41+
path = components/binary-log/detail
42+
url = https://github.com/finger563/binary_log

components/binary-log/CMakeLists.txt

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,19 @@
1+
idf_component_register(
2+
INCLUDE_DIRS "include" "detail/include"
3+
SRC_DIRS "src"
4+
REQUIRES "")
5+
6+
# Build the unpacker tool and put it whereever the rest of the build binaries
7+
# are going for this build. This will ensure that the user can always run
8+
# `./build/unpacker <log-file>`
9+
add_custom_command(
10+
TARGET ${COMPONENT_TARGET}
11+
POST_BUILD
12+
DEPENDS ${COMPONENT_TARGET}
13+
WORKING_DIRECTORY ${COMPONENT_DIR}/detail
14+
COMMAND echo "Building binary-log unpacker"
15+
COMMAND mkdir -p build
16+
COMMAND cmake -B build -S .
17+
COMMAND cmake --build build
18+
COMMAND cp build/tools/unpacker/unpacker ${CMAKE_BINARY_DIR}/unpacker
19+
)

components/binary-log/detail

Submodule detail added at 7d8ba90
Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
log.*
Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,21 @@
1+
# The following lines of boilerplate have to be in your project's CMakeLists
2+
# in this exact order for cmake to work correctly
3+
cmake_minimum_required(VERSION 3.5)
4+
5+
include($ENV{IDF_PATH}/tools/cmake/project.cmake)
6+
7+
# add the component directories that we want to use
8+
set(EXTRA_COMPONENT_DIRS
9+
"../../../components/"
10+
)
11+
12+
set(
13+
COMPONENTS
14+
"main esptool_py espcoredump binary-log file_system format"
15+
CACHE STRING
16+
"List of components to include"
17+
)
18+
19+
project(binary_log_example)
20+
21+
set(CMAKE_CXX_STANDARD 20)
Lines changed: 75 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,75 @@
1+
# Binary Log Example
2+
3+
This example shows how to use the `binary-log` component to format and store
4+
logs in a binary packed form, either to disk or into a ringbuffer in memory.
5+
6+
This component simply exposes the
7+
[p-ranav/binary_log](https://github.com/p-ranav/binary_log) binary logger, with
8+
some modifications in a fork
9+
[finger563/binary_log](https://github.com/finger563/binary_log) to allow packer
10+
customization as is required on embedded systems such as with ESP-IDF.
11+
12+
The `binary-log` does not support all datatypes, but only some base datatypes
13+
such as integer types, float types, and string types.
14+
15+
The logger produces the following data:
16+
1. Log data - these are indexes and the arguments which point to either the
17+
index data or the runfile data.
18+
2. Index data - these are static data (format strings, constant arguments, etc.)
19+
3. Runfile data - these are indices of the log file which run multiple times in
20+
a row.
21+
22+
For more information about the logging, its format, and the types supported,
23+
please see [p-ranav/binary_log](https://github.com/p-ranav/binary_log).
24+
25+
## How to use example
26+
27+
This example is designed to be run on an ESP dev board which has embedded
28+
flash - the partitions and build are configured to match the QtPy ESP32-S3,
29+
though if you modify the `sdkconfig.defaults` and the `partitions.csv` you could
30+
run it on other dev boards easily.
31+
32+
The example does the following:
33+
1. Use standard `binary_log::packer` to log in a loop for three seconds to files
34+
on the filesystem.
35+
2. Print the contents of the log files.
36+
3. Erase the file system.
37+
4. Use the `binary_log::ringbuffer_packer` to log in a loop for three seconds to
38+
into an in-memory ringbuffer.
39+
5. Print the contents of the log buffers.
40+
41+
### Unpacking the logs
42+
43+
#### Getting the log data
44+
45+
You can copy the text from the example output into
46+
[write_files.py](./write_files.py), then run that script, and it will produce
47+
the relevant `log.out`, `log.out.index`, and `log.out.runfile` on your computer.
48+
49+
#### Unpacking the log data
50+
51+
Once you've done that, you can unpack the log data using the `unpacker` that is
52+
automatically built when you build the app and is located within your `build`
53+
folder as `build/unpacker`:
54+
55+
``` console
56+
./build/unpacker log.out > log.inflated
57+
```
58+
59+
### Build and Flash
60+
61+
Build the project and flash it to the board, then run monitor tool to view serial output:
62+
63+
```
64+
idf.py -p PORT flash monitor
65+
```
66+
67+
(Replace PORT with the name of the serial port to use.)
68+
69+
(To exit the serial monitor, type ``Ctrl-]``.)
70+
71+
See the Getting Started Guide for full steps to configure and use ESP-IDF to build projects.
72+
73+
## Example Output
74+
75+
![CleanShot 2025-01-31 at 14 31 23](https://github.com/user-attachments/assets/72e3c118-d5c0-4e48-b5ab-732e6b32e433)
Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,2 @@
1+
idf_component_register(SRC_DIRS "."
2+
INCLUDE_DIRS ".")
Lines changed: 188 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,188 @@
1+
#include <chrono>
2+
#include <functional>
3+
#include <thread>
4+
5+
#include <esp_core_dump.h>
6+
7+
#include "binary-log.hpp"
8+
#include "file_system.hpp"
9+
#include "logger.hpp"
10+
11+
using namespace std::chrono_literals;
12+
13+
extern "C" void app_main(void) {
14+
espp::Logger logger({.tag = "blog_example", .level = espp::Logger::Verbosity::INFO});
15+
16+
logger.info("Starting binary log example");
17+
// initialize the file system
18+
std::error_code ec;
19+
auto &fs = espp::FileSystem::get();
20+
auto root = fs.get_root_path();
21+
const std::filesystem::path logfile = root / std::filesystem::path{"log.out"};
22+
23+
auto print_files = [&fs, &logger, &root, &logfile]() {
24+
logger.info("Printing log file");
25+
std::error_code ec;
26+
27+
size_t file_size = std::filesystem::file_size(logfile, ec);
28+
std::ifstream ifs(logfile, std::ios::in | std::ios::binary);
29+
// read bytes
30+
std::vector<char> file_bytes(file_size);
31+
ifs.read(file_bytes.data(), file_size);
32+
ifs.close();
33+
logger.info("Read {} bytes from log file", file_size);
34+
logger.info("File contents:\n{::#02x}", file_bytes);
35+
36+
// now print the contents of the other two associated files
37+
logger.info("Printing index file");
38+
std::filesystem::path indexfile = logfile;
39+
indexfile.replace_extension(logfile.extension().string() + ".index");
40+
file_size = std::filesystem::file_size(indexfile, ec);
41+
ifs.open(indexfile, std::ios::in | std::ios::binary);
42+
// read bytes
43+
file_bytes.resize(file_size);
44+
ifs.read(file_bytes.data(), file_size);
45+
ifs.close();
46+
logger.info("Read {} bytes from index file", file_size);
47+
logger.info("File contents:\n{::#02x}", file_bytes);
48+
49+
// print the contents of the runlength file
50+
logger.info("Printing runlength file");
51+
std::filesystem::path runlengthfile = logfile;
52+
runlengthfile.replace_extension(logfile.extension().string() + ".runlength");
53+
file_size = std::filesystem::file_size(runlengthfile, ec);
54+
ifs.open(runlengthfile, std::ios::in | std::ios::binary);
55+
// read bytes
56+
file_bytes.resize(file_size);
57+
ifs.read(file_bytes.data(), file_size);
58+
ifs.close();
59+
logger.info("Read {} bytes from runlength file", file_size);
60+
logger.info("File contents:\n{::#02x}", file_bytes);
61+
62+
// print the contents of the file system
63+
logger.info("Directory contents:\n{}", fs.list_directory(root, {}));
64+
};
65+
66+
// first see if the file exists
67+
if (std::filesystem::exists(logfile, ec)) {
68+
logger.info("Removing existing log file");
69+
fs.remove(logfile, ec);
70+
}
71+
72+
{
73+
//! [Binary Log example]
74+
float num_seconds_to_run = 3.0f;
75+
// create standard logger. This will buffer the logs in memory until the buffer is
76+
// full or the logger is destroyed
77+
logger.info("Creating binary log file: {}", logfile.c_str());
78+
static constexpr size_t log_buffer_size = 1024;
79+
static constexpr size_t index_buffer_size = 1024;
80+
static constexpr size_t runlength_buffer_size = 1024;
81+
using Packer = binary_log::packer<log_buffer_size, index_buffer_size, runlength_buffer_size>;
82+
binary_log::binary_log<Packer> log(logfile);
83+
84+
logger.info("Starting binary logging for {}s", num_seconds_to_run);
85+
auto start = std::chrono::high_resolution_clock::now();
86+
auto now = std::chrono::high_resolution_clock::now();
87+
float elapsed = std::chrono::duration<float>(now - start).count();
88+
while (elapsed < num_seconds_to_run) {
89+
now = std::chrono::high_resolution_clock::now();
90+
elapsed = std::chrono::duration<float>(now - start).count();
91+
auto remaining = num_seconds_to_run - elapsed;
92+
93+
// NOTE: use of a single log within the majority of this loop allows for
94+
// run-length encoding of the log messages to be used to reduce the size
95+
BINARY_LOG(log, "elapsed: {}s\nremaining: {}s", elapsed, remaining);
96+
97+
// print a log each second. to track it, just get the remainder
98+
// milliseconds and see if they're less than 15
99+
if (std::chrono::duration_cast<std::chrono::milliseconds>(now - start).count() % 1000 < 15) {
100+
BINARY_LOG(log, "This is a log message at {}s", elapsed)
101+
}
102+
103+
if (remaining < 0) {
104+
BINARY_LOG(log, "You overstayed your welcome by {}s!", -remaining);
105+
}
106+
std::this_thread::sleep_for(10ms);
107+
}
108+
//! [Logger example]
109+
}
110+
111+
// now print out the logger files
112+
print_files();
113+
114+
// now erase the file system
115+
logger.info("Erase file system");
116+
fs.remove_contents(root, ec);
117+
118+
{
119+
//! [Binary Log example]
120+
float num_seconds_to_run = 3.0f;
121+
// create ringbuffer logger. This will not write to disk, but instead will
122+
// only store log data in memory. The log buffer will be a ring buffer,
123+
// discarding the oldest data, while the index and runlength buffers will be
124+
// simple arrays which will abort if they run out of space.
125+
logger.info("Creating ringbuffer binary log");
126+
static constexpr size_t log_buffer_size = 1024;
127+
static constexpr size_t index_buffer_size = 1024;
128+
static constexpr size_t runlength_buffer_size = 1024;
129+
using Packer =
130+
binary_log::ringbuffer_packer<log_buffer_size, index_buffer_size, runlength_buffer_size>;
131+
binary_log::binary_log<Packer> log(logfile);
132+
133+
logger.info("Starting binary logging for {}s", num_seconds_to_run);
134+
auto start = std::chrono::high_resolution_clock::now();
135+
auto now = std::chrono::high_resolution_clock::now();
136+
float elapsed = std::chrono::duration<float>(now - start).count();
137+
while (elapsed < num_seconds_to_run) {
138+
now = std::chrono::high_resolution_clock::now();
139+
elapsed = std::chrono::duration<float>(now - start).count();
140+
auto remaining = num_seconds_to_run - elapsed;
141+
142+
BINARY_LOG(log, "elapsed: {}s", elapsed);
143+
BINARY_LOG(log, "remaining: {}s", remaining);
144+
145+
// print a log each second. to track it, just get the remainder
146+
// milliseconds and see if they're less than 15
147+
if (std::chrono::duration_cast<std::chrono::milliseconds>(now - start).count() % 1000 < 15) {
148+
BINARY_LOG(log, "This is a log message at {}s", elapsed)
149+
}
150+
151+
if (remaining < 0) {
152+
BINARY_LOG(log, "You overstayed your welcome by {}s!", -remaining);
153+
}
154+
std::this_thread::sleep_for(10ms);
155+
}
156+
// Since this is a memory-based logger, we must flush and read out the data
157+
// manually
158+
log.flush();
159+
160+
const Packer &packer = log.get_packer();
161+
auto log_buffer = packer.get_log_buffer();
162+
auto index_buffer_sv = packer.get_index_buffer();
163+
// convert the string view into a vector for easy printing with libfmt
164+
std::vector<uint8_t> index_buffer(index_buffer_sv.begin(), index_buffer_sv.end());
165+
auto runlength_buffer_sv = packer.get_runlength_buffer();
166+
// convert the string view into a vector for easy printing with libfmt
167+
std::vector<uint8_t> runlength_buffer(runlength_buffer_sv.begin(), runlength_buffer_sv.end());
168+
169+
logger.info("Log file size: {} bytes", log_buffer.size());
170+
logger.info("Index file size: {} bytes", index_buffer.size());
171+
logger.info("Runlength file size: {} bytes", runlength_buffer.size());
172+
logger.info("--------------------------------");
173+
logger.info("Total file size: {} bytes",
174+
log_buffer.size() + index_buffer.size() + runlength_buffer.size());
175+
176+
logger.info("Log data:\n{::#02x}", log_buffer);
177+
logger.info("Index data:\n{::#02x}", index_buffer);
178+
logger.info("Runlength data:\n{::#02x}", runlength_buffer);
179+
//! [Logger example]
180+
}
181+
182+
logger.info("Finished binary log example");
183+
184+
// now loop forever
185+
while (true) {
186+
std::this_thread::sleep_for(1s);
187+
}
188+
}
Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
# Name, Type, SubType, Offset, Size
2+
nvs, data, nvs, 0x9000, 0x6000
3+
phy_init, data, phy, 0xf000, 0x1000
4+
factory, app, factory, 0x10000, 2M
5+
coredump, data, coredump, , 256K
6+
littlefs, data, spiffs, , 1M
Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,33 @@
1+
CONFIG_IDF_TARGET="esp32s3"
2+
3+
# Common ESP-related
4+
#
5+
# binary_log requires exceptions right now...
6+
# CONFIG_COMPILER_CXX_EXCEPTIONS=y
7+
8+
CONFIG_ESPTOOLPY_FLASHSIZE_4MB=y
9+
CONFIG_ESPTOOLPY_FLASHSIZE="4MB"
10+
11+
CONFIG_FREERTOS_HZ=1000
12+
13+
# Clock Frequency
14+
CONFIG_ESP_DEFAULT_CPU_FREQ_MHZ_240=y
15+
CONFIG_ESP_DEFAULT_CPU_FREQ_MHZ=240
16+
17+
# Common ESP-related
18+
#
19+
CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE=4096
20+
CONFIG_ESP_MAIN_TASK_STACK_SIZE=10240
21+
CONFIG_ESP_TIMER_TASK_STACK_SIZE=4096
22+
23+
# Partition Table
24+
CONFIG_PARTITION_TABLE_CUSTOM=y
25+
CONFIG_PARTITION_TABLE_CUSTOM_FILENAME="partitions.csv"
26+
27+
# Even if the environment variable MEMFAULT_DISABLE=1 is set, cli.py can retrieve SystemInfo.
28+
CONFIG_FREERTOS_USE_TRACE_FACILITY=y
29+
CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS=y
30+
31+
# Coredump
32+
CONFIG_ESP_COREDUMP_ENABLE_TO_FLASH=y
33+
CONFIG_ESP_COREDUMP_STACK_SIZE=2048

0 commit comments

Comments
 (0)