(logging-log4net) 05/05: unlock the event cache only while fixing #323

[fr...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

FreeAndNil pushed a commit to branch Feature/323-event-and-context-state
in repository https://gitbox.apache.org/repos/asf/logging-log4net.git

commit e123b497dd06b4875d1af9ebeb81aef64b62fbf5
Author: Jan Friedrich <fr...@apache.org>
AuthorDate: Sun Sep 20 21:15:35 2026 +0200

    unlock the event cache only while fixing #323
    
    - the cache was unlocked before the fields to fix were determined
    - a redundant Fix reopened it with nothing to do
    - a reader then cached its own identity, thread name or location
    - measured: a hit after 56000 to 63000 calls, five runs of five
    
    audit da18b6fd-f039.
---
 .../3.5.0/323-logging-event-fix-cache.xml          | 13 +++++++
 src/log4net.Tests/Core/FixingTest.cs               | 41 ++++++++++++++++++++++
 src/log4net/Core/LoggingEvent.cs                   | 10 +++---
 3 files changed, 58 insertions(+), 6 deletions(-)

diff --git a/src/changelog/3.5.0/323-logging-event-fix-cache.xml b/src/changelog/3.5.0/323-logging-event-fix-cache.xml
new file mode 100644
index 00000000..45b4939f
--- /dev/null
+++ b/src/changelog/3.5.0/323-logging-event-fix-cache.xml
@@ -0,0 +1,13 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+       xmlns="https://logging.apache.org/xml/ns"
+       xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
+       type="fixed">
+  <issue id="323" link="https://github.com/apache/logging-log4net/pull/323"/>
+  <description format="asciidoc">Stop a repeated `LoggingEvent.Fix` from reopening the value cache of an
+  already fixed event. The cache was unlocked before the fields still to fix were determined, so a
+  redundant call reopened it even when there was nothing to do, and another thread reading a field
+  the event never captured stored its own thread name, identity or location in it. It is now
+  unlocked only while fields are actually being fixed (audit da18b6fd-f039, fixed by
+  @FreeAndNil)</description>
+</entry>
diff --git a/src/log4net.Tests/Core/FixingTest.cs b/src/log4net.Tests/Core/FixingTest.cs
index 840431fc..4e7c474a 100644
--- a/src/log4net.Tests/Core/FixingTest.cs
+++ b/src/log4net.Tests/Core/FixingTest.cs
@@ -19,7 +19,9 @@
 
 using System;
 using System.Linq;
+using System.Security.Principal;
 using System.Threading;
+using System.Threading.Tasks;
 
 using log4net.Core;
 using log4net.Util;
@@ -210,6 +212,45 @@ public void UserNameIsCapturedWhenItIsFixed()
     Assert.That(loggingEvent.UserName, Is.Not.EqualTo(SystemInfo.NotAvailableText));
   }
 
+  /// <summary>
+  /// A redundant Fix must not reopen the cache: a thread reading a field the event never captured
+  /// would otherwise store its own principal in it. 500000 calls, the defect hit within 63000.
+  /// </summary>
+  [Test]
+  public void ARedundantFixDoesNotLetAnotherThreadCacheItsIdentity()
+  {
+    LoggingEvent loggingEvent = CreateEvent();
+    // Partial leaves Identity out, so it stays null unless the cache reopens.
+    loggingEvent.Fix = FixFlags.Partial;
+
+    bool stop = false;
+    long spins = 0;
+    TaskCompletionSource<bool> running = new();
+    Thread reader = new(() =>
+    {
+      Thread.CurrentPrincipal = new GenericPrincipal(new GenericIdentity("Intruder"), null);
+      running.TrySetResult(true);
+      while (!Volatile.Read(ref stop) && loggingEvent.Identity is null)
+      {
+        Interlocked.Increment(ref spins);
+      }
+    })
+    { IsBackground = true };
+    reader.Start();
+    Assert.That(running.Task.Wait(TimeSpan.FromSeconds(10)), Is.True);
+
+    for (int i = 0; i < 500_000; i++)
+    {
+      loggingEvent.Fix = FixFlags.Partial;
+    }
+    Volatile.Write(ref stop, true);
+    Assert.That(reader.Join(TimeSpan.FromSeconds(10)), Is.True);
+
+    // A reader that never got scheduled would pass the identity assertion for the wrong reason.
+    Assert.That(Interlocked.Read(ref spins), Is.GreaterThan(0));
+    Assert.That(loggingEvent.Identity, Is.Null);
+  }
+
   /// <summary>
   /// Creates an event in the test repository.
   /// </summary>
diff --git a/src/log4net/Core/LoggingEvent.cs b/src/log4net/Core/LoggingEvent.cs
index 4f7c852e..b5a8790d 100644
--- a/src/log4net/Core/LoggingEvent.cs
+++ b/src/log4net/Core/LoggingEvent.cs
@@ -1137,16 +1137,14 @@ public LoggingEventData GetLoggingEventData(FixFlags fixFlags)
   /// </remarks>
   protected virtual void FixVolatileData(FixFlags flags)
   {
-    // Unlock the cache so that new values can be stored
-    // This may not be ideal if we are no longer in the correct context
-    // and someone calls fix. 
-    _cacheUpdatable = true;
-
     // determine the flags that we are actually fixing
     FixFlags updateFlags = (flags ^ _fixFlags) & flags;
 
     if (updateFlags > 0)
     {
+      // Unlocked only while there is something to fix, so a redundant call cannot reopen the cache.
+      _cacheUpdatable = true;
+
       if ((updateFlags & FixFlags.Message) != 0)
       {
         // Force the message to be rendered
@@ -1448,7 +1446,7 @@ public PropertiesDictionary GetProperties()
   /// This is a separate flag to fixFlags as it allows incremental fixing and simpler
   /// changes in the caching strategy.
   /// </remarks>
-  private bool _cacheUpdatable = true;
+  private volatile bool _cacheUpdatable = true;
 
   /// <summary>
   /// The key into the Properties map for the host name value.