Skip to content

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

Draft
doomedraven wants to merge 18 commits into
kevoreilly:capemonfrom
doomedraven:opt/spsc-engine-drain
Draft

Feature: SPSC Lock-Free Log Engine (Phases 1, 2, 4)#204
doomedraven wants to merge 18 commits into
kevoreilly:capemonfrom
doomedraven:opt/spsc-engine-drain

Conversation

@doomedraven

Copy link
Copy Markdown
Contributor

Overhauls the BSON logging engine loop entirely for wait-free throughput. Replaces g_mutex across all loq calls. Routes encoding bytes to a 512KB thread-local SPSC ring array inside thread_log_context_t. _send_log opportunistically drains all rings using contiguous chunk writes. Relies on the TEB cache hooks established in PR #203.

doomedraven and others added 16 commits August 19, 2026 12:36
…(SBO-Decoupling)

Implements completely concurrent and thread-local log serialization inside loq. Makes g_bson and g_istr thread-local variables using __declspec(thread), allowing multiple monitored threads to format their API arguments lock-free. Holds the global g_mutex strictly during the actual BSON buffer flush/cache operations, dropping lock-hold times from milliseconds to microseconds.
…2 Fix)

Surgically fixes the fatal crash bug caused by illegal static TLS usage (__declspec(thread)) inside the dynamically injected capemon.dll:
1. Replaces the unsupported static TLS variables g_bson and g_istr with safe, dynamic Windows Thread Local Storage (TLS) API (TlsAlloc, TlsGetValue, TlsSetValue, TlsFree).
2. Maps g_bson and g_istr through preprocessor macros to dynamic, auto-allocated thread contexts (thread_log_context_t) on-the-fly, retaining 100% compatibility with all 50+ logging helper functions.
3. Automatically frees thread-local log contexts during DLL_THREAD_DETACH inside DllMain to guarantee absolute zero memory leaks.
…zation

Addresses three critical defects in the concurrent logging implementation:

1. NULL Pointer Dereference Protection:
   - Added null check when calloc() fails in GetThreadLogContext()
   - Added null-safe accessor macros for g_bson and g_istr
   - Added early TLS validation in loq() before any logging operations
   - Prevents crashes when TLS allocation fails

2. Race Condition Fix in logtbl_explained:
   - Fixed broken double-checked locking with volatile cast
   - Added proper memory ordering: *(volatile char*)&logtbl_explained[index]
   - Replaced unsafe goto skip_explain with early return + cleanup
   - Ensures thread-safe initialization of log table explanations

3. Performance Optimization with __declspec(thread):
   - Added g_tls_ctx_cache using __declspec(thread) as described in PR
   - GetThreadLogContext() now returns cached value after first lookup
   - Eliminates repeated expensive TlsGetValue() calls on hot path
   - Cache cleared properly in TlsThreadCleanup()

The hybrid TLS approach (TLS API + __declspec(thread) cache) provides:
- Cross-DLL thread tracking compatibility
- Fast repeated access within same thread
- Proper cleanup on thread detach

All changes maintain 100% backward compatibility.
Test coverage:
- Concurrent logging from 16 threads (80,000 log operations)
- Rapid thread creation/destruction (TLS stress test)
- logtbl_explained race condition test (32 threads, same index)

Verifies all three critical fixes:
1. NULL pointer protection (TLS allocation failures)
2. Race condition fix (volatile + double-checked locking)
3. Performance optimization (__declspec(thread) cache)

Run with: cd tests && make test-tls-logging.exe && ./test-tls-logging.exe
…obuf)

Introduces a highly flexible, pluggable logging interface (g_active_serializer Strategy Pattern) supporting both BSON and Protocol Buffers dynamically:
1. Retains BSON as the 100% backward-compatible default serializer (preserving full compatibility for custom agents and result servers).
2. Adds high-performance, robust, and safe Protocol Buffers logging (via nanopb) which can be enabled dynamically at runtime using the config option "log-format = 1".
3. Fully resolves the critical UAF memory lifecycles bug on wide strings inside protobuf_wrapper.c by implementing a fast, zero-allocation, thread-local string and binary scratch-pad bump allocator.
4. Increases the nanopb serialization buffer size from 4KB to 64KB (allocated on static thread-local context structures) to safely prevent large payloads and decrypted config drops.
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
…efault_serializer and including log_serializer.h
The pluggable-serializer refactor introduced several regressions on the
default BSON path and left the protobuf backend unable to represent the
call model. This restores BSON wire compatibility, fixes the string
length handling, tightens the locking, and gates protobuf as explicitly
experimental.

log_serializer.h / log.c / protobuf_wrapper.*:
- append_string/append_wstring regain an explicit `length` parameter.
  Callers pass counted, non-NUL-terminated buffers (%S, %U, %o, registry
  values); the previous signatures forced strlen()/lstrlenW() on the raw
  input, over-reading process memory (crash or disclosure into the log).
- BSON string append restored to the historical encoding: every unit
  through utf8_do_encode() then stored as BSON_BIN_BINARY, with the
  stack-buffer fast path and the ""-on-OOM/error fallback. The interim
  code emitted a raw bson_append_string() that truncated at embedded NULs
  and could be rejected by the result-server parser as invalid UTF-8.
- serializer_append_ptr() helper replaces the open-coded C/R/P/return
  handling: int32 on 32-bit, int64 on 64-bit, one width for every pointer
  field (the interim code emitted C as int32 but R/P as int64 on x86).
- special_api_triggered / last_api_logged / delete_last_log are consumed
  in a short critical section BEFORE serialization again. Serialization
  now runs unlocked into thread-local buffers, so consuming this shared
  state at the tail let a concurrent loq() see stale values or free
  lastlog.buf out from under the API set_special_api() targeted.
- The per-index BSON "explain" frame and the residual
  bson_append_binary(g_bson,...) calls in the %r/%R/buffer_log paths now
  route through the active serializer, so protobuf mode no longer
  interleaves BSON frames into its output stream.
- protobuf_context_t (~100 KB: encode buffer + string scratch) is now a
  lazily-allocated pointer in thread_log_context_t, allocated only on a
  thread's first protobuf log. Default BSON mode allocates nothing extra
  (previously every logging thread paid ~100 KB of zeroed memory).
- g_bson / g_istr / g_active_serializer are single-lookup __inline
  accessors (were two TLS lookups per macro expansion); loq() caches the
  serializer in a local for the hot path.
- protobuf T no longer overwrites call->t (thread id has no schema field
  and is dropped explicitly); scratch-copy honours the length; both
  serializer tables use designated initializers.
- log_init() emits a CRITICAL warning when log-format=1 is selected:
  protobuf output is experimental and lossy and has no host-side parser.

Builds clean on Release|Win32 and Release|x64 (MSVC v143), no warnings
in log.c / protobuf_wrapper.c.

Next:
- Protobuf as a real BSON replacement is a separate effort: redesign
  schema.proto to carry the full call model (heterogeneous indexed args,
  nested %a arrays, caller address, thread id), regenerate schema.pb.*
  with the nanopb generator (not available in this env), grow/size the
  protobuf scratch arena to large_buffer_log_max, give the netlog
  transport its own protocol header, and add a matching parser on the
  CAPE result-server side. Only then drop the experimental banner.
- Benchmark protobuf vs BSON encode cost + wire size before switching any
  default; this BSON writer is a trivial TLV appender and nanopb's
  callback-per-field model may not be faster.
- test-pluggable-serialization.c is still a smoke test (the format is
  process-global, latched at log_init; it cannot switch at runtime).
  A real test needs a full monitor build to assert on emitted bytes and
  to exercise the counted-string / no-over-read paths.
@doomedraven

Copy link
Copy Markdown
Contributor Author

Depends on the #164 and #203

Architectural Execution:

• Phase 1 (Atomic Identifiers): Replaced g_mutex explanation blocking with InterlockedCompareExchange on an array of LONG.
• Phase 2 (SPSC Rings & Thread-Locals):
• Purged all g_mutex lock loops inside loq.
• Eradicated static lastlog_t lastlog completely. Duplicate tracking is now memory-mapped strictly inside the TEB pointers ctx->last_buf and ctx->last_api_logged.
• Re-routed log_raw_direct to bypass g_buffer appending entirely. Serialization dumps straight into your thread's pre-allocated 512KB Ring using monotonic write_idx tracking.
• Phase 4 (Opportunistic Drain): Hard-refactored _send_log(). Only the flushing pipe-writer uses TryEnterCriticalSection(&g_writing_log_buffer_mutex). We iterate through pItem = (entry_t *)g_log_contexts.root;, chunk out the length deltas via read_idx, and commit WriteFile flushes concurrently.

@doomedraven
doomedraven marked this pull request as draft September 11, 2026 16:48
Addresses review findings on the lock-free logging engine.

Compile/link:
- loq() referenced a ctx local that was never declared
- g_mutex definition was removed while capemon.c still externed
  and initialised it

Ring memory safety:
- the wrap marker could be 1-3 bytes, so the drainer's 4-byte
  length read could run past the end of the buffer. Records are
  now 4-byte aligned, which keeps write_idx aligned and
  guarantees a full marker always fits
- wrap padding was not charged against free space, letting a
  write overrun read_idx and corrupt unread records
- partial WriteFile results were ignored, truncating records on
  the wire. write_all() now loops

Ordering (result-server protocol):
- the netlog 'BSON <pid>' header went through a per-thread ring,
  so another thread's ring could be drained ahead of it. It now
  goes straight to the pipe
- explain frames were gated by a global atomic, so the winning
  thread parked explain(id) in its own ring while other threads
  emitted record(id) into rings that could drain first. The gate
  is now per-thread, keeping explain and record in one FIFO

Loss:
- log_flush() could silently skip via TryEnterCriticalSection.
  It now blocks; only the periodic drain is best-effort
- rings were unlinked on thread exit without being drained
- dropped records are now reported on the command pipe
- ring reduced 512KB -> 256KB (allocated per thread, never freed)

Syntax-checked for x86 and x64 with mingw-w64.

TAG=agy
CONV=5cf1c128-6f21-4847-bb4a-e12c8c7c4ef9
@doomedraven

Copy link
Copy Markdown
Contributor Author

Pushed a round of fixes addressing correctness problems in the ring implementation. Summary of what changed and why.

Compile / link

  • loq() referenced a ctx local that was never declared.
  • The g_mutex definition had been removed from log.c while capemon.c still externed and initialised it. Both sites removed; no references remain.

Ring memory safety

  • The wrap marker could be 1-3 bytes, so the drainer's 4-byte length read could run past the end of the buffer. Records are now padded to a 4-byte boundary, which keeps write_idx aligned and guarantees a full marker always fits.
  • Wrap padding was not charged against free space, so a write could overrun read_idx and corrupt records the drainer had not consumed yet. It is now accounted for before a record is admitted.
  • Partial WriteFile results were ignored. The old global-buffer path handled short writes with a memmove; the ring now loops in write_all(). Without this a short write truncates a BSON document and desynchronises the stream permanently.
  • Records too large to ever fit the ring drain the thread's ring and then go straight to the pipe, preserving that thread's ordering, instead of being dropped.

Record ordering

This was the significant one. Per-thread rings broke two ordering guarantees the result server depends on, and neither was fixable by tightening the ring itself.

  1. Netlog header. announce_netlog() wrote the BSON <pid> header through a per-thread ring, making it just another record. The drain walks threads in lookup order, so another thread's ring could reach the pipe first and corrupt the stream from byte zero. The header now bypasses the rings and goes straight to the pipe.

  2. Explain frames. The per-index explain frame was gated by a global atomic. The thread that won the CAS parked explain(id) in its own ring while every other thread proceeded immediately and emitted record(id) into a different ring — which could drain first, leaving the parser with an unknown index.

    The gate is now per-thread, so explain(id) and the record that needs it always land in the same ring and drain in FIFO order. Cost is a duplicate explain frame per thread per id; the parser treats that as an idempotent map update. This also removes the InterlockedCompareExchange, which was the thing creating the split in the first place.

Record loss

  • log_flush() could silently skip the drain via TryEnterCriticalSection. It now blocks; only the periodic drain from the logging thread stays best-effort.
  • Rings were unlinked on thread exit without being drained. lookup_del() only unlinks, so anything still queued became unreachable for the rest of the process. Teardown now flushes and drains before unlinking.
  • Dropped records were counted into a field nothing read. Overflow is now reported on the command pipe with the owning thread ID, rearmed only when the count grows so a saturated ring cannot flood.

Cleanup

Removed the unreferenced exit: label, an empty block, and a stale comment describing the old cross-thread race.


Still open

Two things I have deliberately not addressed here, both worth resolving before this comes out of draft:

  • Per-thread ring memory. Reduced 512KB to 256KB, but it is still allocated per thread and never freed, since lookup_del() leaks by design. A thread-spamming sample grows memory without bound. Bounding it properly needs either a free list of retired contexts or a cap on tracked threads.

  • TEB slot choice (inherited from the context-caching change, not this one). NtTib.ArbitraryUserPointer is not a free slot — ntdll writes it during DLL and path-name resolution, e.g. LdrLoadDll stores the module name there. Clobbering it from a hook running underneath loader activity is a risk that should be either verified empirically under loader-heavy samples or avoided by moving to a TLS slot index reserved at load time.

Both x86 and x64 configurations were syntax-checked after the change.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant