nanopb: pluggable logging strategy (BSON default, protobuf opt-in) by doomedraven · Pull Request #164 · kevoreilly/capemon

doomedraven · 2026-08-17T14:01:18Z

Stacked on #215, which owns the per-thread logging context. Merge that first; this branch contains #215's two commits, so the diff GitHub shows here will collapse to just the serializer work once #215 lands.

TLDR

log-format = 0 (default) — BSON, byte-for-byte the same output as today.
log-format = 1 — Protocol Buffers, experimental.

log.c's formatting loops no longer call BSON directly. They go through a log_serializer_t vtable that log_init() selects once, so the wire format becomes a runtime choice instead of a compile-time one. Nothing downstream changes unless log-format is set.

1. Impact on custom agents and result servers

"Could these changes potentially have impact on anyone using a custom agent or custom result server?"

Only if you opt in. #118 removed BSON outright in favour of nanopb, which would have broken every result server and analysis agent expecting BSON frames. Here BSON stays the default and the strategy is selected at log_init().

The schema question is real either way: BSON is self-describing, so a hook can append arbitrary keys at runtime. Protocol Buffers need a compile-time schema.proto, so a new hooked field means recompiling and deploying capemon and the host-side decoder together.

2. Defects fixed in #118's nanopb wrapper

Wide-string use-after-free. log_wstring converted to UTF-8 on the heap, registered the pointer with the nanopb callback, then freed it immediately. nanopb only serializes at protobuf_finish, at the end of loq. Reading the freed block was an access violation. Fixed with a per-thread bump-allocated scratch pad in protobuf_context_t; strings and binary buffers are copied into it and stay alive until protobuf_finish.

Silent payload drops. The nanopb output stream was a static 4 KB array, so any log over 4 KB — decrypted payloads, network buffers — failed pb_encode and vanished. Buffer is now 64 KB, in the per-thread context rather than on the stack.

3. What changed in this revision

Restacked onto #215's LOOKUP_THREAD revision (5cf5060) and current capemon (df8fc4d, which includes a65ba12's wowmon changes to log.c):

Context from Give each thread its own BSON buffer and stop holding g_mutex across all of loq() #215's lookup table. log_context_t is Give each thread its own BSON buffer and stop holding g_mutex across all of loq() #215's LOOKUP_THREAD entry (a lookup_t keyed by thread id), per Kev's comment on #216, instead of a TlsAlloc slot. This branch adds one field to it, pb_ctx.
No per-thread active_serializer. The format is process-wide: log_init() sets g_default_serializer before any hook can log, and a stream mixing BSON and protobuf frames is unsupported. g_active_serializer is now that pointer, and log_init() no longer patches the calling thread's context.
Two table walks per helper-appended argument. The vtable callbacks take no context argument, so each BSON callback calls get_log_context() itself, on top of the log_* helper's own lookup. Passing the context through the vtable would make it one walk, but changes every callback signature in both backends; not done here.
a65ba12 kept. The "I" field uses BSON_ID(index) in both the explanation frame and the record, whichever serializer is active. The wowmon handle mapping in log_init() stays, after the serializer selection.
Checked by inspection only. Every function that uses g_bson/g_istr/g_active_serializer declares ctx before first use, loq() assigns it before serializing, nothing after exit: touches it, and braces balance. Outside log.c, every file's diff is identical to the previous revision except one comment in log_serializer.h.

Earlier revision's problems, still fixed:

The TEB NtTib.ArbitraryUserPointer slot is not free. ntdll's loader parks the FullDllName pointer there across its NtMapViewOfSection call so the debugger can see the module being mapped, and capemon hooks NtMapViewOfSection (hooks.c:127, :975, :1065, :1358):

ntdll!LdrpMapViewOfSection
  saves ArbitraryUserPointer
  writes &FullDllName into it
  calls NtMapViewOfSection  ->  capemon hook  ->  loq()
                                                    reads ArbitraryUserPointer
                                                    gets a PWSTR
                                                    writes serializer state over the loader's string

That is memory corruption on every module load. The context now comes from #215.

TlsThreadCleanup() never ran. It was wired to DLL_THREAD_DETACH, but capemon.c:632 calls hide_module_from_peb() during DLL_PROCESS_ATTACH and misc.c:1072-1095 unlinks the module from all three loader lists. The loader walks those to dispatch thread notifications, so DllMain is never entered again. Both the hook and the function are gone; contexts are per-thread and die with the process.

All three g_mutex acquisitions go through loq_lock(), which keeps the fast-path-then-bounded-spin shape from ada31ca rather than dropping straight into the 100-iteration spin.

Both serializer vtables use positional initializers. C99 designated initializers are not accepted by PlatformToolset v141 in C mode, which is what capemon.vcxproj targets. The previous revision would not have compiled on VS2017 even after the finish/append_finish fix.

The .github/workflows/ changes are dropped. #212 owns CI. The pr-build-test.yml copy carried on this branch targeted windows-2019, which is no longer a runner image — every run on it queued for 24h and was cancelled without being scheduled.

capemon.vcxproj now carries only the five ClCompile and seven ClInclude additions; the delay-load settings from 321a8e0 are preserved.

4. Protobuf backend status

Experimental and lossy. schema.proto cannot represent capemon's call model yet — heterogeneous indexed arguments, nested %a arrays, the caller C address, the thread id — and no host-side parser consumes the output. log_init() emits a CRITICAL: notice over the pipe when log-format=1 is set. announce_netlog() still announces BSON; a real protobuf transport needs its own header and a matching reader.

The per-index "explain" frame is BSON-only and is skipped in protobuf mode, so the stream is never a mix of BSON and protobuf frames. The lastlog dedup is likewise BSON-only — it depends on byte-comparable frames with a repeated counter at a fixed offset.

5. Testing

Not compiled and not run. No MSVC available, and the MSBuild workflow is disabled_manually at the repo level, so nothing in this series has been through a compiler. Re-enabling needs Settings → Actions; #212 fixes the workflow file but cannot flip that switch.

tests/test-pluggable-serialization.c is included but has not been built.

6. Are these related?

This one genuinely is coupled: it cannot be reviewed or merged without #215, because the BSON buffer and the protobuf scratch it serializes into live in the context #215 introduces. That is the opposite of the independent batch (#206–#210, #213, #214), and similar in kind to the NDEBUG case in #211 where the assert removals are only correct because the same PR defines NDEBUG.

#162 is closed — it was the first two commits of this branch, and it could not compile (GNU statement expressions in log.c).

Known textual conflicts in log.c, both trivial rebases: #208 (logtbl_explained bounds — this branch also reads logtbl_explained[index] with an unbounded index) and #209 (log_string/log_wstring).

Series

#206, #207, #208, #209, #210, #211, #212, #213, #214, #215, this one, #216, #217 (merged).

rkoumis · 2026-08-18T13:19:03Z

This is great, thank you! Much appreciated.

I'm probably missing something super obvious, but I can't figure it out. I noticed that in the definition of loq() there are still plenty of calls to the bson serializing functions, not the active_serializer functions. Just in the bit guarded by if (logtbl_explained[index] == 0) {

Maybe it's worth adding a comment explaining logtbl_explained - ?

doomedraven · 2026-08-18T13:37:28Z

added comment in code

/* logtbl_explained Optimization (BSON Specific):
   The very first time a hooked API index is logged, capemon outputs a schema "explanation"
   to help the legacy BSON log-server parse dynamic argument layouts, then sets logtbl_explained[index] = 1.
   Subsequent calls only log argument values, drastically reducing redundant traffic.
   Note: This block calls BSON-serialization functions directly because modern Protocol Buffers (nanopb)
   utilizes a statically compiled message schema (schema.proto) and has no need for runtime dynamic schemas.
*/
if (logtbl_explained[index] == 0) {

rkoumis · 2026-08-18T14:43:16Z

added comment in code

/* logtbl_explained Optimization (BSON Specific): */

ohhhh I see. Thank you!

kevoreilly · 2026-08-18T16:56:35Z

very nice ❤️

I'm low on time today to look into this, so will pick up again tomorrow, but just to note it's currently not compiling:

1>d:\work\cape\capemon\capemon26\log.c(1162): error C2039: 'finish': is not a member of '_log_serializer_t'
1>d:\work\cape\capemon\capemon26\log_serializer.h(12): note: see declaration of '_log_serializer_t'
1>d:\work\cape\capemon\capemon26\log.c(1202): warning C4267: '=': conversion from 'size_t' to 'unsigned int', possible loss of data
1>d:\work\cape\capemon\capemon26\log.c(1187): warning C4267: 'initializing': conversion from 'size_t' to 'unsigned int', possible loss of data

doomedraven · 2026-08-18T20:13:51Z

The Root Cause & Technical Fixes Applied:

Resolved Error C2039: 'finish' is not a member of '_log_serializer_t' (Line 1162)

The Bug: The code inside loq() was calling g_active_serializer->finish(). However, the struct interface in log_serializer.h defines the member as append_finish.
The Fix: corrected the call to call the proper interface member:

1 g_active_serializer->append_finish_array();
2 g_active_serializer->append_finish(); // <-- Corrected member call

Resolved Warnings C4267: '=': conversion from 'size_t' to 'unsigned int', possible loss of data (Lines 1187 & 1202)

The Bug: Under 64-bit Windows, size_t is 64-bit (unsigned __int64), while unsigned int is 32-bit. In loq(), our_len and lastlog.len are 32-bit unsigned integers, and assigning the result of g_active_serializer->get_size() to them triggered a compilation warning.
The Fix: Added clean, explicit casts to prevent 64-bit pointer truncation warnings:

1 unsigned int our_len = (unsigned int)(g_active_serializer->get_size() - compare_offset);
2 // ...
3 lastlog.len = (unsigned int)g_active_serializer->get_size();

Test coverage: - BSON serialization (default mode) - Protobuf serialization (opt-in mode) - Runtime serializer switching - Thread-local serializer isolation (16 threads) - Concurrent mixed serializers (8 threads, BSON + Protobuf) - NULL safety in serializer access Verifies: 1. Strategy pattern implementation 2. Thread-safe serializer switching 3. Independent per-thread serializer contexts 4. Graceful fallback on NULL 5. No interference between BSON and Protobuf modes Run with: cd tests && make test-pluggable-serialization.exe && ./test-pluggable-serialization.exe

doomedraven

Thank you! I have successfully submitted a structural refactor to the backend code merging the protobuf state via standard TlsAlloc() memory architecture mapping instead of utilizing unallocated __declspec(thread) structures to fix the structural crash bugs observed in native DLL imports. Please review the updated branch.

doomedraven · 2026-09-16T12:10:20Z

Force-pushed. History rewritten, so the earlier review comments no longer line up with the diff — sorry about that. Summary of what moved:

Split out. The thread-local logging context is now #215, on its own. This branch is stacked on it and contains only the serializer vtable and the nanopb backend. #162, which was the first two commits here, is closed.

Dropped the TEB slot. NtTib.ArbitraryUserPointer (fs:[0x14] / gs:[0x28]) is not free — ntdll's loader parks the FullDllName pointer there across its NtMapViewOfSection call, and we hook NtMapViewOfSection. A hook firing during a module load read a PWSTR out of that slot and wrote serializer state over the loader's string. That is a candidate explanation for the detonation failure reported on #162. Now dynamic TLS, in #215.

Dropped TlsThreadCleanup() and the DLL_THREAD_DETACH hook. They never ran: hide_module_from_peb() unlinks us from the loader lists during DLL_PROCESS_ATTACH, so DllMain is never entered again.

Positional initializers for both serializer vtables. .init = ... designated initializers are C99 and capemon.vcxproj targets PlatformToolset v141, which does not accept them in C mode. This would not have built on VS2017 even after the finish/append_finish fix. (Moot if #187 retargets to VS2022, but the project file still says v141 today.)

Dropped the .github/workflows/ changes. #212 owns CI. The pr-build-test.yml copy carried here targeted windows-2019, which is no longer a runner image — that is why every run on it sat in the queue for 24h and got cancelled rather than failing.

Restored the delay-load settings. The previous revision's capemon.vcxproj predated 321a8e0 and would have reverted it.

@rkoumis the logtbl_explained comment you asked for is still there, plus a note that the block is skipped entirely in protobuf mode so the stream never mixes frame types.

Still not compiled — the MSBuild workflow is disabled_manually at the repo level, so nothing in this series has been near a compiler.

…all of loq() `g_bson` and `g_istr` were process-wide statics, so `loq()` had to hold `g_mutex` from the moment it was entered until the record was flushed. Every hooked API call on every thread serialized against every other one, and the lock covered the expensive part (format parsing, string conversion, BSON building) as well as the cheap part. This moves the serialization state into a per-thread context and narrows the lock to the two regions that actually touch shared state: * region A - `logtbl_explained`, `last_api_logged`, `lastlog` reset, and the one-time schema "explanation" record; * region B - the flush into the output buffer and the `lastlog` dedup slot. Everything in between (the sizing pass, the emit pass, `log_string`, `log_wstring`, `log_buffer`, ...) now runs unlocked against thread-local memory. How the context is reached, and three things this deliberately does not do: * Not `__declspec(thread)`. Static TLS is resolved by the loader. It happens to work when capemon is injected with LoadLibrary, which is the normal path, but `ReflectiveInjectDllViaThread()` in loader/loader/Loader.c maps the image by hand and nothing processes the TLS directory there. * Not the TEB `NtTib.ArbitraryUserPointer` slot. It is not free: ntdll's loader parks the `FullDllName` pointer there across its `NtMapViewOfSection` call so the debugger can see the module name. capemon hooks `NtMapViewOfSection` (hooks.c:127 and three more places), so a hook firing during a module load would read a `PWSTR` out of that slot and write BSON state over the loader's string. * Not a `DLL_THREAD_DETACH` destructor. capemon.c calls `hide_module_from_peb()` during `DLL_PROCESS_ATTACH`, and misc.c:1072-1095 unlinks the module from InLoadOrderModuleList, InInitializationOrderModuleList, InMemoryOrderModuleList and the hash table. The loader walks those lists to dispatch thread notifications, so DllMain is never entered again and a TLS callback would never fire. The context is therefore allocated once per logging thread and never reclaimed. That is intentional: it is about 40 bytes, the BSON payload itself is still allocated and released per call by `bson_init`/`bson_destroy`, and freeing contexts at teardown would race with threads still inside `loq()`. The accessor macros are plain parenthesised expressions. GNU statement expressions (`({ ... })`) are not accepted by cl.exe. The bounded-spin lock acquisition from ada31ca is preserved verbatim, just factored into `loq_lock()` so both regions use the same shape: one cheap `TryEnterCriticalSection`, then up to 100 `SwitchToThread` retries, then drop the record rather than stall a hooked API. TAG=agy CONV=b3280e17-abe0-4fed-ad0b-c2e7f65da90f

Replace the TlsAlloc/TlsGetValue/TlsSetValue context with LOOKUP_THREAD (lookup.h, 8f40674), the idiom added to replace per-thread state reached through the Tls APIs. It is the same thread-id-keyed scheme hook_info() uses for g_hook_info. g_bson and g_istr now expand to a local ctx. loq() and each serializing helper fetch it once, so a record costs one table walk in loq() plus one per helper call, rather than one TLS read per field access. Contexts are never freed. A thread given a dead thread's id inherits its context, which is safe because loq() starts every record with bson_init() (zeroes the whole bson struct). Retained memory is bounded by distinct thread ids. sizeof(log_context_t) is 312 bytes on x64 and 168 on x86; the old comment's "40-something bytes" missed the bson struct's 32-entry size_t stack. With kevoreilly#217, allocation failure on a thread's first log returns NULL and loq() drops the record, as before; without it, lookup_add() faults on the NULL calloc() result. TAG=agy CONV=b3f21014-0e97-49b9-aa93-0601a28982fe

…mat=1 Stacked on kevoreilly#215, which owns the per-thread logging context. What is left here is the serializer abstraction and the nanopb backend. `log.c`'s formatting loops no longer talk to BSON directly. They go through a `log_serializer_t` vtable, so the wire format is a runtime choice: log-format = 0 BSON (default, unchanged bytes on the wire) log-format = 1 Protocol Buffers (experimental) Existing result servers and custom agents see exactly what they saw before unless `log-format` is set, so nothing downstream has to change. The format is process-wide. `log_init()` sets `g_default_serializer` once, before any hook can log, and a stream that mixes BSON and protobuf frames is not supported, so `g_active_serializer` is just that pointer. Per-thread state lives in kevoreilly#215's `log_context_t`, reached through `LOOKUP_THREAD` (a `lookup_t` keyed by thread id). This branch adds one field to it: `pb_ctx`, the ~100 KB protobuf scratch, allocated on a thread's first protobuf log and never in BSON mode. The serializer callbacks take no context argument, so each BSON callback fetches the context itself. An argument appended through a `log_*` helper therefore costs two table walks, the helper's and the callback's. Restacked onto kevoreilly#215's LOOKUP_THREAD revision and current capemon (a65ba12): * The dynamic-TLS context (`TlsAlloc`/`TlsGetValue`) is replaced by kevoreilly#215's `LOOKUP_THREAD` table, as requested on kevoreilly#216: kevoreilly#216 (comment) * The per-thread `active_serializer` field is gone. `LOOKUP_THREAD` payloads start zeroed and the format never changes after `log_init()`, so the field could only mirror `g_default_serializer`. `log_init()` no longer patches the calling thread's context. * The record's "I" field uses a65ba12's `BSON_ID(index)`, in the explanation frame and in the record, whichever serializer is active. * `log_init()` keeps a65ba12's wowmon handle mapping, after the serializer selection. Carried over from the previous revisions: * No TEB `NtTib.ArbitraryUserPointer` slot. ntdll's loader parks the `FullDllName` pointer there across its `NtMapViewOfSection` call, and capemon hooks `NtMapViewOfSection`, so a hook firing during a module load would write serializer state over the loader's string. * No `DLL_THREAD_DETACH` cleanup. `hide_module_from_peb()` unlinks the module from the loader lists during `DLL_PROCESS_ATTACH`, so DllMain is never entered again and that cleanup would never run. * All three `g_mutex` acquisitions go through `loq_lock()`, which keeps the fast-path-then-bounded-spin shape from ada31ca instead of dropping straight into the 100-iteration spin. * Both serializer vtables use positional initializers. C99 designated initializers are not accepted by PlatformToolset v141 in C mode. * The `.github/workflows/` changes are dropped. kevoreilly#212 owns CI. The protobuf backend is experimental and lossy: `schema.proto` cannot yet represent capemon's full call model, and no host-side parser consumes it. `log_init()` says so over the pipe when it is enabled. Not compiled: there is no MSVC on the machine this was restacked on. TAG=agy CONV=b3280e17-abe0-4fed-ad0b-c2e7f65da90f CONV=b3f21014-0e97-49b9-aa93-0601a28982fe

doomedraven · 2026-09-26T14:11:23Z

Checked against latest upstream (df8fc4d), already cleanly rebased.

Audit of synchronization primitives:

Per-thread serialization contexts already use lock-free LOOKUP_THREAD lookup tables (from Give each thread its own BSON buffer and stop holding g_mutex across all of loq() #215).
Output stream writes (g_writing_log_buffer_mutex) and deduplication/state transitions (g_mutex) cannot be replaced by key-value lookups as they protect contiguous shared buffer serialization and file/socket transport order.

Fixes:

Corrected log_init call signature in tests/test-pluggable-serialization.c from 3 arguments to log_init(0) to match log.h declaration.

doomedraven changed the title ~~Implement Approach A: Pluggable Logging Strategy Pattern (BSON & Protobuf)~~ nanopb: Pluggable Logging Strategy Pattern (BSON & Protobuf) Aug 17, 2026

doomedraven mentioned this pull request Aug 17, 2026

nanopb integration #118

Open

doomedraven force-pushed the opt/pluggable-serialization branch from 54eedce to 2a735de Compare August 18, 2026 13:34

doomedraven force-pushed the opt/pluggable-serialization branch 3 times, most recently from 0181748 to c3925c6 Compare August 20, 2026 06:56

doomedraven commented Aug 25, 2026

View reviewed changes

This was referenced Sep 11, 2026

Feature: SPSC Lock-Free Log Engine (Phases 1, 2, 4) #204

Closed

Give each thread its own BSON buffer and stop holding g_mutex across all of loq() #215

Draft

Optimize concurrent logging via decoupled thread-local serialization … #162

Closed

doomedraven force-pushed the opt/pluggable-serialization branch from d40f720 to 8222e3d Compare September 16, 2026 12:08

doomedraven changed the title ~~nanopb: Pluggable Logging Strategy Pattern (BSON & Protobuf)~~ nanopb: pluggable logging strategy (BSON default, protobuf opt-in) Sep 16, 2026

doomedraven marked this pull request as draft September 16, 2026 12:09

doomedraven mentioned this pull request Sep 16, 2026

Stop allocating 64 KB per path on the hooked call paths #216

Merged

doomedraven mentioned this pull request Sep 25, 2026

lookup: return NULL on allocation failure, keep payloads pointer-aligned #217

Merged

doomedraven added 2 commits September 25, 2026 16:37

doomedraven force-pushed the opt/pluggable-serialization branch from 8222e3d to 430e54b Compare September 25, 2026 16:55

doomedraven force-pushed the opt/pluggable-serialization branch from 430e54b to 5a8aac2 Compare September 26, 2026 14:11

doomedraven mentioned this pull request Sep 26, 2026

Feat/protobuf log format #196

Closed

Navigation Menu

nanopb: pluggable logging strategy (BSON default, protobuf opt-in) - #164

nanopb: pluggable logging strategy (BSON default, protobuf opt-in)#164
doomedraven wants to merge 3 commits into
kevoreilly:capemonfrom
doomedraven:opt/pluggable-serialization

doomedraven commented Aug 17, 2026 •

edited

Loading

Uh oh!

rkoumis commented Aug 18, 2026

Uh oh!

doomedraven commented Aug 18, 2026

Uh oh!

rkoumis commented Aug 18, 2026

Uh oh!

kevoreilly commented Aug 18, 2026

Uh oh!

doomedraven commented Aug 18, 2026 •

edited

Loading

Uh oh!

doomedraven left a comment

Uh oh!

doomedraven commented Sep 16, 2026

Uh oh!

doomedraven commented Sep 26, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

doomedraven commented Aug 17, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

TLDR

1. Impact on custom agents and result servers

2. Defects fixed in #118's nanopb wrapper

3. What changed in this revision

4. Protobuf backend status

5. Testing

6. Are these related?

Series

Uh oh!

rkoumis commented Aug 18, 2026

Uh oh!

doomedraven commented Aug 18, 2026

Uh oh!

rkoumis commented Aug 18, 2026

Uh oh!

kevoreilly commented Aug 18, 2026

Uh oh!

doomedraven commented Aug 18, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

doomedraven left a comment

Choose a reason for hiding this comment

Uh oh!

doomedraven commented Sep 16, 2026

Uh oh!

doomedraven commented Sep 26, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

doomedraven commented Aug 17, 2026 •

edited

Loading

doomedraven commented Aug 18, 2026 •

edited

Loading