refactor: Logging infrastructure thread-safety and modernization (#1812)

[thomhurst]

Summary

This PR addresses several items from issue #1812:

• Add thread-safety to AfterPipelineLogger - Multiple modules can call LogOnPipelineEnd() concurrently
• Replace legacy MethodImplOptions.Synchronized with modern lock pattern in ModuleLoggerProvider

Changes

1. Thread-Safety Gap - AfterPipelineLogger (Fixed)

Added thread-safety using explicit lock synchronization:

• LogOnPipelineEnd(): Protected _values.Add() with lock
• GetOutput(): Protected entire method body with lock
• WriteLogs(): Created a copy of _values under lock before iterating

2. Legacy Synchronization Pattern (Fixed)

Replaced [MethodImpl(MethodImplOptions.Synchronized)] in ModuleLoggerProvider with explicit lock statement:

• Removed legacy System.Runtime.CompilerServices usage
• Added private _lock object for better encapsulation
• The legacy pattern locks on this which can cause deadlocks if external code acquires the same lock

3. DRY Investigation (No changes needed)

Investigated duration formatting - the codebase already consistently uses TimeSpanFormatter.ToDisplayString().

Test plan

• Build passes
• Existing tests pass
• Verify thread-safety under concurrent access

🤖 Generated with Claude Code

[thomhurst]

Summary

This PR adds thread-safety to AfterPipelineLogger and modernizes ModuleLoggerProvider synchronization.

Critical Issues

1. Race Condition in AfterPipelineLogger.GetOutput() (Line 35-51)

The cached output in _stringBuilder can become stale if LogOnPipelineEnd() is called after the first GetOutput() call. Scenario: Thread A calls GetOutput() and builds cache, Thread B calls LogOnPipelineEnd() adding new value, Thread A calls GetOutput() again and gets stale cached output missing the new message.

Fix: Either clear the cache in LogOnPipelineEnd() when adding new values, or rebuild the output every time.

2. ModuleLoggerProvider.MakeLogger() Not Thread-Safe (Line 74-80)

MakeLogger() modifies shared state (_moduleLogger) but is NOT protected by the lock. Can be called from both GetLogger() (locked) and GetLogger(Type type) (NOT locked). If both are called concurrently, they can both execute the assignment to _moduleLogger without synchronization.

Fix: Either protect MakeLogger() with the lock, or protect GetLogger(Type type) with the lock.

Suggestions

The copy-then-iterate pattern in WriteLogs() is good - it prevents holding the lock during I/O.

Verdict

REQUEST CHANGES - Critical thread-safety bugs found. Both issues must be resolved before merging.

[Copilot]

Pull request overview

This PR modernizes the logging infrastructure's thread-safety mechanisms by replacing legacy synchronization patterns and adding explicit locking to address concurrent access scenarios.

Key changes:

• Replaced MethodImplOptions.Synchronized with explicit lock pattern in ModuleLoggerProvider
• Added thread-safety to AfterPipelineLogger methods to handle concurrent calls to LogOnPipelineEnd()

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 3 comments.

File	Description
src/ModularPipelines/Logging/ModuleLoggerProvider.cs	Modernized synchronization from MethodImplOptions.Synchronized to explicit lock with dedicated lock object for better encapsulation
src/ModularPipelines/Logging/AfterPipelineLogger.cs	Added thread-safety using lock synchronization for concurrent access to log buffer across multiple modules

[Copilot]

The PR description states this change adds thread-safety to handle concurrent calls to LogOnPipelineEnd, but the existing tests don't verify concurrent access behavior. Consider adding a test that calls LogOnPipelineEnd from multiple threads simultaneously to validate the thread-safety guarantees, especially given the race condition in GetOutput that needs to be fixed.

[Copilot]

Race condition: If LogOnPipelineEnd is called after the StringBuilder length check (line 40) but before the foreach loop completes (lines 46-49), the newly added value won't be included in the cached StringBuilder, but it will be present in _values. This creates an inconsistency where subsequent calls to GetOutput will return stale data missing the new value.

To fix this, the caching logic should be removed entirely, or _values should be copied to a local list inside the lock and then processed. The simplest solution is to build the string from _values each time, or clear both _values and _stringBuilder together once the string is built to make the cache immutable.

[thomhurst]

Fixes Applied

Addressed both critical thread-safety issues from the review:

1. AfterPipelineLogger.GetOutput() Race Condition

• Added _stringBuilder.Clear() in LogOnPipelineEnd() when adding new values
• This invalidates the cache so GetOutput() will rebuild with the new value

2. ModuleLoggerProvider.MakeLogger() Not Thread-Safe

• Wrapped the GetLogger(Type type) method body with the existing _lock
• Now both GetLogger() overloads are protected by the same lock

Commit: 590443f

[thomhurst]

Summary

Adds thread-safety to AfterPipelineLogger and ModuleLoggerProvider using lock-based synchronization.

Critical Issues

1. AfterPipelineLogger: Broken caching logic in GetOutput()

Location: src/ModularPipelines/Logging/AfterPipelineLogger.cs:37-53

Issue: The caching mechanism is broken. The PR clears _stringBuilder in LogOnPipelineEnd() to invalidate the cache, but the logic doesn't work correctly:

• GetOutput() is called → builds string, _stringBuilder.Length is now > 0
• LogOnPipelineEnd() is called → clears _stringBuilder, length is now 0
• GetOutput() is called again → sees length == 0, rebuilds ✅
• GetOutput() is called again (no new values) → sees length == 0, rebuilds again ❌

The cache only works for the first call after a build, then breaks permanently.

Suggested fix: Use a boolean flag instead:

private bool _isCacheValid;

public void LogOnPipelineEnd(string value)
{
    lock (_lock)
    {
        _values.Add(value);
        _isCacheValid = false;
    }
}

public string GetOutput()
{
    lock (_lock)
    {
        if (_isCacheValid)
        {
            return _stringBuilder.ToString();
        }

        _stringBuilder.Clear();
        foreach (var value in _values)
        {
            _stringBuilder.AppendLine(value);
        }
        _isCacheValid = true;
        return _stringBuilder.ToString();
    }
}

2. ModuleLoggerProvider: Incorrect locking in GetLogger(Type type)

Location: src/ModularPipelines/Logging/ModuleLoggerProvider.cs:35-39

Issue: The lock was added to GetLogger(Type type) but this method shouldn't be modifying or using the instance field _moduleLogger. That field is specifically for caching the result of the parameterless GetLogger() method.

Looking at MakeLogger(Type module) (line 86), it uses _moduleLogger ??= which means:

• GetLogger(Type type) can overwrite the cached logger from GetLogger() if called with a different type
• This breaks the intended caching behavior where each method has separate semantics

Suggested fix: Either:

1. Use separate fields: _parameterlessLogger for GetLogger() and don't cache in GetLogger(Type)
2. Or remove the lock from GetLogger(Type type) if it's always called with the same type

The original code didn't lock GetLogger(Type type), suggesting it may not need synchronization. Please verify the usage pattern.

3. ModuleLoggerProvider: Potential deadlock concern

Location: src/ModularPipelines/Logging/ModuleLoggerProvider.cs:44-73

Issue: The GetLogger() method now holds a lock while calling MakeLogger() which:

• Calls _moduleLoggerContainer.GetLogger()
• Calls _serviceProvider.GetRequiredService()

If either of these methods try to resolve services that depend on IModuleLoggerProvider (directly or indirectly), this could cause a deadlock. Review the dependency graph to ensure this isn't possible.

Suggestions

None - please address the critical issues above first.

Previous Review Status

Unable to retrieve previous comments due to GitHub token permissions. If there were prior reviews, please check if those concerns were addressed.

Verdict

⚠️ REQUEST CHANGES - Critical issues found with caching logic and locking strategy

[thomhurst]

Additional Fixes Applied (Commit 949233f)

Addressed the issues from the second review:

1. AfterPipelineLogger: Fixed caching logic

• Now uses a boolean _isCacheValid flag instead of relying on StringBuilder.Length
• LogOnPipelineEnd() sets _isCacheValid = false
• GetOutput() checks the flag, clears StringBuilder and rebuilds if invalid, then sets flag to true
• Prevents unnecessary rebuilds when GetOutput() is called multiple times with no new values

2. ModuleLoggerProvider: Fixed caching separation

• GetLogger(Type type) no longer uses or modifies _moduleLogger
• Removed lock from GetLogger(Type type) since it doesn't share the cache
• Only parameterless GetLogger() caches to _moduleLogger (with lock protection)
• Avoids potential deadlock - GetLogger(Type type) doesn't hold lock during DI resolution
• Renamed MakeLogger to CreateLogger for clarity

[thomhurst]

Summary

This PR adds thread-safety to AfterPipelineLogger and ModuleLoggerProvider to handle concurrent access from parallel module execution.

Critical Issues

1. Unnecessary _stringBuilder.Clear() defeats caching purpose

Location: src/ModularPipelines/Logging/AfterPipelineLogger.cs:47

Issue: You clear the StringBuilder every time, which means you're rebuilding the entire string on every GetOutput() call after a new log is added. This defeats the purpose of caching.

The old code built the string once and never cleared it. The new code rebuilds from scratch every time after any LogOnPipelineEnd() call.

Impact: Performance regression - repeatedly rebuilding strings from all values instead of appending new ones.

Better approach:

• Option A: Append new values to StringBuilder when they're added (in LogOnPipelineEnd)
• Option B: Don't cache at all if you're rebuilding anyway

2. ModuleLoggerProvider.GetLogger(Type) behavior change - BREAKING CHANGE

Location: src/ModularPipelines/Logging/ModuleLoggerProvider.cs:39-44

Issue: The old code cached the result in _moduleLogger (via MakeLogger), the new code doesn't. This changes behavior:

• Old: GetLogger(TypeA) then GetLogger(TypeB) - both cached in _moduleLogger (last one wins)
• New: GetLogger(TypeA) - not cached, GetLogger() - might cache

The comment says "Does not cache to _moduleLogger to avoid conflicts" but this is a behavioral change that could break existing code expecting caching.

Question: Is this intentional? If so, it should be documented in the commit message. If not, the internal method should still cache but perhaps use a different cache.

3. Lock contention concern in ModuleLoggerProvider.GetLogger()

Location: src/ModularPipelines/Logging/ModuleLoggerProvider.cs:47-76

Issue: Since ModuleLoggerProvider is registered as Scoped (src/ModularPipelines/DependencyInjection/DependencyInjectionSetup.cs:90), each module scope gets its own instance. However, PipelineContext is also scoped and contains a lazy logger.

Question: Is there actually concurrent access to the same ModuleLoggerProvider instance? If each module gets its own scope, the lock may be unnecessary. Please verify the actual concurrency scenario.

The old code used [MethodImpl(MethodImplOptions.Synchronized)] which is equivalent but less efficient. If locking is truly needed, the new approach is better. But verify it's needed at all.

Suggestions

4. Missing thread-safety in AfterPipelineLogger.WriteLogs() - potential issue

Location: src/ModularPipelines/Logging/AfterPipelineLogger.cs:63-72

The code copies the list before iterating, which is good. However, if LogOnPipelineEnd() is called during iteration, the log might be missed OR logged twice (depending on timing).

Suggestion: Document the expected usage pattern. Is WriteLogs() only called once at the end after all LogOnPipelineEnd() calls complete? If so, no issue. If concurrent access is expected, document the behavior.

Verdict

⚠️ REQUEST CHANGES - Critical issues found:

• Issue Feature/initial work #1: Performance regression in caching logic
• Issue Feedback/Ideas for Improvement #2: Undocumented behavior change in GetLogger(Type)
• Issue Feature/initial 2 #3: Need to verify lock is actually necessary given DI scoping

Please address these issues, particularly clarifying the DI scoping and concurrency scenarios that prompted these changes.

[thomhurst]

Fixes Applied (Commit bfdf153)

Addressed all review comments:

1. AfterPipelineLogger: Fixed Performance Regression

• Switched from invalidate-rebuild pattern to append-only strategy
• LogOnPipelineEnd() now appends directly to StringBuilder - no more clearing/rebuilding
• Removed the _isCacheValid flag as it's no longer needed with append-only approach

2. ModuleLoggerProvider: Documented Intentional Behavior Change

Added comprehensive XML documentation explaining:

• Why GetLogger(Type) doesn't cache to _moduleLogger: This is intentional to prevent type conflicts. If you call GetLogger(TypeA) then GetLogger(TypeB), caching to a shared field would return the wrong type. The IModuleLoggerContainer handles per-type caching properly.
• Why lock is still needed despite Scoped lifetime: Multiple async continuations within the same scope can race to initialize the cached logger. The lock prevents double-initialization.
• Detection priority order documented for GetLogger(): cached → AsyncLocal logger → AsyncLocal type → stack trace inspection

3. Thread-safety Documentation

Added detailed remarks to both classes explaining:

• Expected usage patterns (WriteLogs() called once at end)
• Thread-safety guarantees and limitations
• Caching strategy rationale