Optimize concurrent logging via decoupled thread-local serialization …

.github/workflows/msbuild.yml

@@ -5,6 +5,7 @@ on:
     branches: [ "capemon" ]
   pull_request:
     branches: [ "capemon" ]
+  workflow_dispatch:  # Allow manual trigger
 
 env:  
   BUILD_CONFIGURATION: Release

.github/workflows/pr-build-test.yml

@@ -0,0 +1,74 @@
+name: PR Build Test
+
+on:
+  workflow_dispatch:  # Manual trigger
+    inputs:
+      pr_number:
+        description: 'PR number to test'
+        required: true
+        type: number
+  pull_request:
+    branches: [ "capemon" ]
+
+env:
+  BUILD_CONFIGURATION: Release
+  SOLUTION_FILE_PATH: capemon.sln
+
+jobs:
+  build:
+    runs-on: windows-2019
+    strategy:
+      fail-fast: false
+      matrix:
+        include:
+          - arch: x86
+            platform: Win32
+          - arch: x64
+            platform: x64
+
+    steps:
+    - uses: actions/checkout@v3
+
+    - name: Add MSBuild to PATH
+      uses: microsoft/setup-msbuild@v1.1
+      with:
+       msbuild-architecture: ${{ matrix.arch }}
+
+    - name: Restore NuGet packages
+      working-directory: ${{env.GITHUB_WORKSPACE}}
+      run: nuget restore ${{env.SOLUTION_FILE_PATH}}
+
+    - name: Build
+      working-directory: ${{env.GITHUB_WORKSPACE}}
+      run: msbuild /m /p:Configuration=${{env.BUILD_CONFIGURATION}} /p:Platform=${{ matrix.platform }} ${{env.SOLUTION_FILE_PATH}}
+
+    - name: Build Tests
+      working-directory: ${{env.GITHUB_WORKSPACE}}
+      run: |
+        cd tests
+        make test-tls-logging.exe
+        make test-pluggable-serialization.exe
+      shell: bash
+      continue-on-error: true
+
+    - uses: actions/upload-artifact@v3
+      with:
+        name: capemon_test_${{ matrix.arch }}_pr${{ github.event.inputs.pr_number || github.event.pull_request.number }}
+        path: |
+          Release/capemon.dll
+          x64/Release/capemon_x64.dll
+          tests/*.exe
+        if-no-files-found: ignore
+
+    - name: Comment Build Status
+      if: github.event.pull_request.number
+      uses: actions/github-script@v6
+      with:
+        script: |
+          github.rest.issues.createComment({
+            issue_number: context.issue.number,
+            owner: context.repo.owner,
+            repo: context.repo.name,
+            body: '✅ Build succeeded for ${{ matrix.platform }}! Artifacts available in workflow run.'
+          })
+      continue-on-error: true

capemon.c

@@ -690,6 +690,10 @@ BOOL APIENTRY DllMain(HANDLE hModule, DWORD dwReason, LPVOID lpReserved)
 		if (!g_config.tlsdump && !g_config.interactive)
 			notify_successful_load();
 	}
+	else if (dwReason == DLL_THREAD_DETACH) {
+		extern void TlsThreadCleanup(void);
+		TlsThreadCleanup();
+	}
 	else if(dwReason == DLL_PROCESS_DETACH) {
 		// in production, we shouldn't ever get called in this way since we
 		// unlink ourselves from the module list in the PEB

log.c

@@ -52,8 +52,52 @@ static BOOLEAN delete_last_log;
 HANDLE g_log_handle;
 
 // current to-be-logged API call
-static bson g_bson[1];
-static char g_istr[4];
+typedef struct {
+	bson g_bson[1];
+	char g_istr[4];
+} thread_log_context_t;
+
+DWORD g_bson_tls_index = TLS_OUT_OF_INDEXES;
+
+// Thread-local storage with caching to avoid repeated TLS lookups
+static __declspec(thread) thread_log_context_t* g_tls_ctx_cache = NULL;
+
+static thread_log_context_t* GetThreadLogContext(void) {
+	// Use cached value if available to avoid TLS overhead
+	if (g_tls_ctx_cache)
+		return g_tls_ctx_cache;
+
+	thread_log_context_t* pCtx = NULL;
+	if (g_bson_tls_index != TLS_OUT_OF_INDEXES) {
+		pCtx = (thread_log_context_t*)TlsGetValue(g_bson_tls_index);
+		if (!pCtx) {
+			pCtx = (thread_log_context_t*)calloc(1, sizeof(thread_log_context_t));
+			if (pCtx) {
+				TlsSetValue(g_bson_tls_index, pCtx);
+				g_tls_ctx_cache = pCtx; // Cache for this thread
+			}
+		} else {
+			g_tls_ctx_cache = pCtx; // Cache for this thread
+		}
+	}
+	return pCtx;
+}
+
+// Safe accessor macros with NULL check
+// Note: These will return NULL if TLS allocation failed, callers must check
+#define g_bson ({ thread_log_context_t *_ctx = GetThreadLogContext(); _ctx ? _ctx->g_bson : NULL; })
+#define g_istr ({ thread_log_context_t *_ctx = GetThreadLogContext(); _ctx ? _ctx->g_istr : NULL; })
+
+void TlsThreadCleanup(void) {
+	if (g_bson_tls_index != TLS_OUT_OF_INDEXES) {
+		thread_log_context_t* pCtx = (thread_log_context_t*)TlsGetValue(g_bson_tls_index);
+		if (pCtx) {
+			free(pCtx);
+			TlsSetValue(g_bson_tls_index, NULL);
+			g_tls_ctx_cache = NULL; // Clear cache
+		}
+	}
+}
 
 static char logtbl_explained[256] = {0};
 
@@ -559,40 +603,45 @@ void loq(int index, const char *category, const char *name,
 
 	hook_disable();
 
-	{
-		int retries = 100;
-		BOOL acquired = FALSE;
-
-		while (retries-- > 0) {
-			if (TryEnterCriticalSection(&g_mutex)) {
-				acquired = TRUE;
-				break;
-			}
-			SwitchToThread();
-		}
-
-		if (!acquired) {
-			goto exit;
-		}
-	}
-
-	if (!special_api_triggered)
-		last_api_logged = API_OTHER;
-	else {
-		special_api_triggered = FALSE;
-		if (delete_last_log) {
-			free(lastlog.buf);
-			lastlog.buf = NULL;
-		}
+	// Verify TLS context is available before proceeding
+	if (!GetThreadLogContext()) {
+		// TLS allocation failed - cannot log, exit gracefully
+		hook_enable();
+		set_lasterrors(&lasterror);
+		return;
 	}
 
-	if (logtbl_explained[index] == 0) {
+	// Use volatile to ensure proper memory ordering for logtbl_explained
+	// This fixes the race condition in double-checked locking
+	if (*(volatile char*)&logtbl_explained[index] == 0) {
 		const char * pname;
 		bson b[1];
 
-		logtbl_explained[index] = 1;
+		{
+			int retries = 100;
+			BOOL acquired = FALSE;
 
-		va_start(args, fmt);
+			while (retries-- > 0) {
+				if (TryEnterCriticalSection(&g_mutex)) {
+					acquired = TRUE;
+					break;
+				}
+				SwitchToThread();
+			}
+
+			if (!acquired) {
+				// Failed to acquire lock - skip explanation and return
+				hook_enable();
+				set_lasterrors(&lasterror);
+				return;
+			}
+		}
+
+		// Double-check inside the lock (proper double-checked locking pattern)
+		if (logtbl_explained[index] == 0) {
+			logtbl_explained[index] = 1;
+
+			va_start(args, fmt);
 
 		bson_init( b );
 		bson_append_int( b, "I", index );
@@ -723,12 +772,14 @@ void loq(int index, const char *category, const char *name,
 			}
 
 		}
-		bson_append_finish_array( b );
-		bson_finish( b );
-		log_raw_direct(bson_data( b ), bson_size( b ));
-		bson_destroy( b );
-		// log_flush();
-		va_end(args);
+			bson_append_finish_array( b );
+			bson_finish( b );
+			log_raw_direct(bson_data( b ), bson_size( b ));
+			bson_destroy( b );
+			// log_flush();
+			va_end(args);
+		}
+		LeaveCriticalSection(&g_mutex);
 	}
 
 	fmt = fmtbak;
@@ -1133,6 +1184,34 @@ void loq(int index, const char *category, const char *name,
 	bson_append_finish_array( g_bson );
 	bson_finish( g_bson );
 
+	{
+		int retries = 100;
+		BOOL acquired = FALSE;
+
+		while (retries-- > 0) {
+			if (TryEnterCriticalSection(&g_mutex)) {
+				acquired = TRUE;
+				break;
+			}
+			SwitchToThread();
+		}
+
+		if (!acquired) {
+			bson_destroy( g_bson );
+			goto exit;
+		}
+	}
+
+	if (!special_api_triggered)
+		last_api_logged = API_OTHER;
+	else {
+		special_api_triggered = FALSE;
+		if (delete_last_log) {
+			free(lastlog.buf);
+			lastlog.buf = NULL;
+		}
+	}
+
 	if (index == LOG_ID_PROCESS || index == LOG_ID_THREAD || index == LOG_ID_ENVIRON) {
 		// don't hold back any of our critical notifications -- these *must* be flushed in log_init()
 		log_raw_direct(bson_data(g_bson), bson_size(g_bson));
@@ -1447,6 +1526,8 @@ DWORD g_logwatcher_thread_id;
 
 void log_init(int debug)
 {
+	g_bson_tls_index = TlsAlloc();
+
 	g_buffer = calloc(1, BUFFERSIZE);
 
 	g_log_flush = CreateEvent(NULL, FALSE, FALSE, NULL);
@@ -1489,6 +1570,11 @@ void log_init(int debug)
 void log_free()
 {
 	log_flush();
+	if (g_bson_tls_index != TLS_OUT_OF_INDEXES) {
+		TlsThreadCleanup();
+		TlsFree(g_bson_tls_index);
+		g_bson_tls_index = TLS_OUT_OF_INDEXES;
+	}
 	if (g_sock == DEBUG_SOCKET) {
 		g_sock = INVALID_SOCKET;
 	}