diff --git a/CMakeLists.txt b/CMakeLists.txt index 5ceb1b8..ebc63e8 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -1,5 +1,5 @@ cmake_minimum_required(VERSION 3.16) -project(CALF VERSION 0.2.0 LANGUAGES CXX) +project(CALF VERSION 0.3.0 LANGUAGES CXX) # ------------------------------------------------------------------------- # Options & Defaults diff --git a/README.md b/README.md index 478f58f..19cc07f 100644 --- a/README.md +++ b/README.md @@ -10,51 +10,159 @@ [![C++ tests](https://github.com/High-Performance-IO/CALF/actions/workflows/cpp-tests.yml/badge.svg?branch=main)](https://github.com/High-Performance-IO/CALF/actions/workflows/cpp-tests.yml?query=branch%3Amain) [![Python tests](https://github.com/High-Performance-IO/CALF/actions/workflows/python-tests.yml/badge.svg?branch=main)](https://github.com/High-Performance-IO/CALF/actions/workflows/python-tests.yml?query=branch%3Amain) -Calf is a structured, header-only C++17 logging library for the [CAPIO](https://github.com/High-Performance-IO/capio) ecosystem. It supports indented JSON output and opt-in streaming Perfetto traces for lower-overhead trace creation. +CALF is a structured, header-only C++17 logging library for the +[CAPIO](https://github.com/High-Performance-IO/capio) ecosystem. It records +RAII scopes and events in one of two file formats: -Calf is designed to work in two distinct environments: +- **Perfetto** is the preferred format. It produces compact, streaming + `.perfetto-trace` files that open directly in the + [Perfetto UI](https://ui.perfetto.dev/). +- **JSON** is the dependency-free fallback. It produces readable `.log` files + containing valid, indented JSON. -- **STL safe processes**: uses `std::ofstream` for I/O (`StlLogger`) -- **CLI loggers (STL safe)**: logs to CLI (`StdOutLogger`) -- **NON STL safe processes**: uses raw syscalls whenever STL is not safe (`SyscallLogger`) -Both backends share the same JSON structure and produce identical output formats. +CALF provides three logging backends: -The C++ Perfetto format works with both `StlLogger` and `SyscallLogger`. It -writes standard `.perfetto-trace` protobuf streams that open directly in the -[Perfetto UI](https://ui.perfetto.dev/). Scopes are nested TrackEvent slices, -while `LOG` messages are instant TrackEvents with source locations and an -`args` debug annotation. +- `StlLogger` uses `std::fstream` and is intended for regular C++ processes. +- `SyscallLogger` uses raw Linux syscalls and is intended for syscall + interceptors or other environments where the STL is unsafe. +- `StdOutLogger` writes human-readable messages to standard output. + +`StlLogger` and `SyscallLogger` support both Perfetto and JSON with the same +logging macros. The selected file format is fixed when a target is built. ## Requirements - C++17 or later - CMake 3.16 or later -- Linux for `SyscallLogger` backend -- Python 3.10 or later for the Python bindings +- Linux when using `SyscallLogger` +- Python 3.10 or later when using the Python bindings -## Testing +## Quick start -The GoogleTest C++ suites and Python binding tests run on Linux and macOS. The -raw syscall logger suite is built only on Linux because that backend is not -supported on macOS. +Add CALF with `FetchContent`: -```bash -cmake -S . -B build -DCALF_TESTS=ON -cmake --build build --parallel -ctest --test-dir build --output-on-failure +```cmake +include(FetchContent) + +FetchContent_Declare( + calf + GIT_REPOSITORY https://github.com/High-Performance-IO/calf.git + GIT_TAG # Pin a commit for reproducible builds. + GIT_SHALLOW TRUE +) + +set(CALF_TESTS OFF CACHE BOOL "" FORCE) +set(CALF_BUILD_PYTHON_BINDINGS OFF CACHE BOOL "" FORCE) +FetchContent_MakeAvailable(calf) + +# Enables logging and selects Perfetto when CALF_PROTOBUF=ON. +calf_enable_log(my_server ON) ``` -`CALF_TESTS=ON` enables `CALF_PYTHON_TESTS` by default and builds the Python -extension needed by those tests. To run only the Python binding test target: +Use the logging macros in C++: -```bash -cmake --build build --target calf_python_tests +```cpp +#include + +void handle_request(int tid, const char *path) { + START_LOG(tid, "path=%s", path); + LOG("processing"); +} // The scope closes and its end timestamp is recorded here. +``` + +By default, this writes a Perfetto trace to: + +```text +./calf_logs//calf_.perfetto-trace +``` + +Open the file in . + +## Log formats + +### Perfetto format + +Perfetto is selected when a target links to `calf::protobuf`. The +`calf_enable_log` helper does this automatically when `CALF_PROTOBUF=ON`: + +```cmake +# Automatic: Perfetto if available, otherwise JSON. +calf_enable_log(my_server ON) + +# Explicit: require Perfetto. Configuration fails if CALF_PROTOBUF=OFF. +calf_enable_log(my_server ON PROTOBUF) +``` + +You can also select it by linking the target directly: + +```cmake +target_link_libraries(my_server PRIVATE calf::protobuf) ``` +CALF writes a standard Perfetto TrackEvent protobuf stream. Its logging model +maps to Perfetto as follows: -## Output format +| CALF operation | Perfetto representation | +|---|---| +| `START_LOG(...)` | Slice begin on the calling thread's track | +| Scope destruction | Slice end on the same track | +| `LOG(...)` | Instant event on the same track | +| C++ function name | Event name | +| Formatted message | `args` debug annotation | +| Source file and line | Perfetto source location | +| Nested CALF scopes | Nested Perfetto slices | -Each log scope opened by `START_LOG` becomes one JSON object in a root array. Inner `LOG` calls populate the `events` array. Scopes close with a `ts_exit` timestamp. +All threads in a process write to one trace: + +```text +$CALF_LOG_DIR//_.perfetto-trace +``` + +Each thread has its own Perfetto track. Timestamps use the monotonic clock in +nanoseconds. Writes are synchronized so packets from different threads cannot +interleave. Separate processes always use separate files. + +The trace is streamed as logging occurs; CALF does not build the complete trace +in memory. `StlLogger` uses generated protobuf support for the schema, while +`SyscallLogger` writes compatible protobuf bytes through raw syscalls. + +### JSON fallback + +JSON is selected automatically by `calf_enable_log(target ON)` when +`CALF_PROTOBUF=OFF`. It can also be requested explicitly: + +```cmake +# Disable protobuf support for the whole CALF build. +set(CALF_PROTOBUF OFF CACHE BOOL "" FORCE) +FetchContent_MakeAvailable(calf) +calf_enable_log(my_server ON) + +# Or keep protobuf available but use JSON for this target. +calf_enable_log(my_tool ON JSON) +``` + +Directly linking `calf::stl` or `calf::syscall` also uses JSON unless the target +additionally receives the Perfetto configuration through `calf::protobuf`: + +```cmake +target_link_libraries(my_server PRIVATE calf::stl) +target_link_libraries(my_interceptor PRIVATE calf::syscall) +``` + +This is a build-time fallback. CALF does not switch formats at runtime or +convert an existing Perfetto trace to JSON. + +JSON output uses one file per thread: + +```text +$CALF_LOG_DIR///.log +``` + +The default prefix is `stl_` for `StlLogger` and `syscall_` for +`SyscallLogger`. `CALF_LOG_PREFIX` overrides it. + +Each file contains one root array. Every `START_LOG` scope is an object, and +each `LOG` call is an event in that scope's `events` array: ```json [ @@ -66,149 +174,162 @@ Each log scope opened by `START_LOG` becomes one JSON object in a root array. In "args": "dirfd=4, pathname=/tmp/foo, flags=0", "events": [ { "ts": 43, "invoker": "get_file_location", "file": "location.hpp", "line": 96, "args": "path=/tmp/foo" }, - { "ts": 44, "invoker": "get_file_location", "file": "location.hpp", "line": 96, "args": "File found on node host0" } + { "ts": 44, "invoker": "get_file_location", "file": "location.hpp", "line": 96, "args": "file found on node host0" } ], "ts_exit": 45 } ] ``` -JSON output writes one file per thread. Perfetto output combines all threads in -one process into -`$CALF_LOG_DIR//_.perfetto-trace`. +Scope fields: -### Perfetto output +| Field | Meaning | +|---|---| +| `invoker` | Function that opened the scope | +| `file`, `line` | Source location of `START_LOG` | +| `ts_enter` | Scope start time in elapsed milliseconds | +| `args` | Expanded `START_LOG` format string | +| `events` | Ordered `LOG` events and any nested scopes | +| `ts_exit` | Scope end time in elapsed milliseconds | -Select Perfetto output by linking the application target with `calf::protobuf`. The -existing logger include and macro interface remain unchanged: +Event fields: -```cmake -target_link_libraries(my_server PRIVATE calf::protobuf) -``` +| Field | Meaning | +|---|---| +| `ts` | Event time in elapsed milliseconds | +| `invoker` | Function associated with the enclosing logger | +| `file`, `line` | Source location associated with the logger | +| `args` | Expanded `LOG` format string | + +Strings are JSON-escaped, and the file remains valid JSON after each completed +outer scope. Multiple outer scopes are appended to the same root array. + +## C++ usage + +### Regular processes -Projects using `calf_enable_log(target ON)` select Perfetto automatically when -`CALF_PROTOBUF=ON`. Use `calf_enable_log(target ON JSON)` only for targets that -intentionally require JSON output. +Use `StlLogger` in code where the C++ standard library is safe. Logging starts +enabled on every thread: ```cpp #include -void handle_request(const char *path) { - START_LOG(calf_current_tid(), "path=%s", path); - LOG("processing"); +void handle_request(int tid, const char *path) { + START_LOG(tid, "call(path=%s)", path); + LOG("processing path=%s", path); + LOG("done"); } ``` -CMake uses an installed Google Protobuf package for its minimal Perfetto schema -and tests, and otherwise downloads it through `FetchContent`. Without the -`calf::protobuf` link dependency, `StlLogger.h` and `SyscallLogger.h` produce -JSON. The syscall backend writes Perfetto protobuf bytes directly through raw -syscalls without constructing generated messages or allocating per event. -STL writes are synchronized across threads, while syscall writes use file locks -so packets cannot interleave. A process truncates its trace on the first write; -different processes always write separate files. +### Syscall interceptors +Use `SyscallLogger` where logging must avoid intercepted STL I/O. This backend +is Linux-only and starts disabled to prevent re-entrancy during setup. Enable it +after initialization: -## Integration - -### CMake FetchContent - -```cmake -include(FetchContent) - -FetchContent_Declare( - calf - GIT_REPOSITORY https://github.com/High-Performance-IO/calf.git - GIT_TAG # pin to a specific commit for reproducible builds - GIT_SHALLOW TRUE -) +```cpp +#include +#include -set(CALF_LOG ON CACHE BOOL "" FORCE) -set(CALF_BUILD_PYTHON_BINDINGS OFF CACHE BOOL "" FORCE) -set(CALF_TESTS OFF CACHE BOOL "" FORCE) +void setup() { + SET_CALF_SYSCALL_HANDLER(syscall_no_intercept); + ENABLE_LOGGER(); +} -FetchContent_MakeAvailable(calf) +long hook(long syscall_number, ...) { + START_LOG(capio_syscall(SYS_gettid), "call()"); + // Handle the syscall. +} ``` -Then link each target to the appropriate backend: +`SET_CALF_SYSCALL_HANDLER` redirects CALF's internal syscalls through +`syscall_no_intercept`. Temporarily suspend logging around operations that must +not be captured: -```cmake -# Server binary -target_link_libraries(my_server PRIVATE calf::stl) - -# POSIX syscall interceptor (.so) -target_link_libraries(my_interceptor PRIVATE calf::syscall) +```cpp +void internal_operation() { + DISABLE_LOGGER(); // Logging is restored when this scope exits. + // Perform internal syscalls. +} ``` -## CMake options - -| Flag | Default | Description | -|------|---------|-------------| -| `CALF_LOG` | `ON` | Enable logging macros. When disabled, logging macros are no-ops. | -| `CALF_TESTS` | `OFF` | Build and register the GoogleTest suites with CTest. | -| `CALF_PYTHON_TESTS` | Value of `CALF_TESTS` | Build the Python extension and register its binding tests. | -| `CALF_BUILD_PYTHON_BINDINGS` | `OFF` | Build and install the private `calf._py_calf` Python extension. | -| `CALF_PROTOBUF` | `ON` | Build the Perfetto trace logger and `calf::protobuf` target. | -| `CALF_DEFAULT_COMPONENT_NAME` | `calf` | Component directory and CLI header name used by configured targets. | -| `CALF_DEFAULT_LOG_DIR_NAME` | `./calf_logs` | Default log root when `CALF_LOG_DIR` is unset. | +### Macros -Pass flags during configuration with `-D=`. Common examples: +| Macro | Description | +|---|---| +| `START_LOG(tid, fmt, ...)` | Creates a scoped `Logger log` RAII object. | +| `LOG(fmt, ...)` | Adds an event to the current scope. | +| `ERR_EXIT(fmt, ...)` | Logs and terminates, or throws when configured to continue on error. | +| `ENABLE_LOGGER()` | Enables logging on the calling thread. | +| `DISABLE_LOGGER()` | Suspends logging until the current C++ scope exits. | +| `DBG(tid, lambda)` | Wraps a lambda in a debug-only scope; compiled out in release builds. | +| `SET_CALF_SYSCALL_HANDLER(handler)` | Sets the non-intercepted syscall handler for `SyscallLogger`. | + +## Configuration + +### CMake options + +| Option | Default | Description | +|---|---:|---| +| `CALF_LOG` | `ON` | Enables logging macros globally; when disabled, they are no-ops. | +| `CALF_PROTOBUF` | `ON` | Builds Perfetto support and the `calf::protobuf` target. | +| `CALF_PROTOBUF_FETCH` | `ON` | Fetches the required protobuf version when it is not installed. | +| `CALF_TESTS` | `OFF` | Builds and registers the C++ test suites. | +| `CALF_PYTHON_TESTS` | Value of `CALF_TESTS` | Builds the Python extension and registers binding tests. | +| `CALF_BUILD_PYTHON_BINDINGS` | `OFF` | Builds and installs the private `calf._py_calf` extension. | +| `CALF_DEFAULT_COMPONENT_NAME` | `calf` | Sets the default component used in paths and CLI headers. | +| `CALF_DEFAULT_LOG_DIR_NAME` | `./calf_logs` | Sets the log root used when `CALF_LOG_DIR` is unset. | + +Pass options during configuration with `-D