This is an automated email from the ASF dual-hosted git repository. FreeAndNil pushed a commit to branch Feature/security-audit-hardening in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
commit 1786b139aad01148120f981cba80336c2c505f6e Author: Jan Friedrich <[email protected]> AuthorDate: Mon Aug 17 23:06:40 2026 +0200 keep the impersonated user name when a logging event is fixed UserName resolved the identity of whichever thread read it, so with a buffering appender the buffered events were attributed to the thread flushing the buffer rather than the one that logged them. Only impersonation makes that wrong. Without it the name is the process identity, which is the same on every thread and stays resolvable, so it is still resolved lazily and nothing changes for those applications. An event logged while impersonating now takes its user name with it when it is fixed, because that is the last point at which the identity is known. This happens whatever Fix asks for, and outside the block that fixes the requested fields, since that block is skipped when there is nothing to fix while the cache is locked all the same. FixFlags.UserName stays unset, so the flags keep reporting what the caller requested. Reading the property on a thread that is impersonating no longer reports that thread's user; the not available text is used instead. The impersonation check only queries the thread token. Resolving the name behind it is the expensive part and is unchanged. Also renames FixingTest.All_ShouldContainAllFlags and documents its members. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]> --- .../3.4.0/309-username-honours-the-fix-gate.xml | 16 ++++ src/log4net.Tests/Core/FixingTest.cs | 99 +++++++++++++++++++++- src/log4net.Tests/Core/UserNameFixingTest.cs | 43 ++++++++++ src/log4net/Core/LoggingEvent.cs | 68 ++++++++++++++- 4 files changed, 222 insertions(+), 4 deletions(-) diff --git a/src/changelog/3.4.0/309-username-honours-the-fix-gate.xml b/src/changelog/3.4.0/309-username-honours-the-fix-gate.xml new file mode 100644 index 00000000..ceffb9e1 --- /dev/null +++ b/src/changelog/3.4.0/309-username-honours-the-fix-gate.xml @@ -0,0 +1,16 @@ +<?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="309" link="https://github.com/apache/logging-log4net/pull/309"/> + <description format="asciidoc"> + stop `LoggingEvent.UserName` reporting the wrong user for an event logged while impersonating. + The property resolved the identity of whichever thread read it, so with a buffering appender the + buffered events were attributed to the thread flushing the buffer rather than the one that logged + them (CWE-282). An event logged while impersonating now takes its user name with it when it is + fixed, and an event read on an impersonating thread reports the not available text instead of that + thread's user. Without impersonation the name is the process identity, which is the same on every + thread, so it is still resolved lazily and nothing changes (audit 1231d72-f014) + </description> +</entry> diff --git a/src/log4net.Tests/Core/FixingTest.cs b/src/log4net.Tests/Core/FixingTest.cs index 3efe326b..840431fc 100644 --- a/src/log4net.Tests/Core/FixingTest.cs +++ b/src/log4net.Tests/Core/FixingTest.cs @@ -22,17 +22,28 @@ using System.Threading; using log4net.Core; +using log4net.Util; using NUnit.Framework; namespace log4net.Tests.Core; +/// <summary> +/// Tests for <see cref="LoggingEvent.Fix"/> and the fields it captures. +/// </summary> [TestFixture] [System.Diagnostics.CodeAnalysis.SuppressMessage("Usage", "CA2201:Do not raise reserved exception types")] public class FixingTest { - const string TestRepository = "Test Repository"; + /// <summary> + /// The name of the repository the events under test belong to. + /// </summary> + private const string TestRepository = "Test Repository"; + /// <summary> + /// Creates the repository the events under test belong to, and names the thread, so that + /// <see cref="LoggingEvent.ThreadName"/> has something stable to capture. + /// </summary> [OneTimeSetUp] public void CreateRepository() { @@ -61,8 +72,12 @@ public void CreateRepository() } } + /// <summary> + /// <see cref="FixFlags.All"/> has to contain every other flag, so that fixing everything does not + /// quietly leave a field out when a new flag is added. + /// </summary> [Test] - public void All_ShouldContainAllFlags() + public void AllContainsEveryFlag() { // Arrange // Act @@ -76,6 +91,9 @@ public void All_ShouldContainAllFlags() } } + /// <summary> + /// A newly created event has nothing fixed yet. + /// </summary> [Test] public void TestUnfixedValues() { @@ -95,6 +113,9 @@ public void TestUnfixedValues() Assert.That(loggingEvent.Fix, Is.EqualTo(FixFlags.None), "Fixed Fields is incorrect"); } + /// <summary> + /// Fixing with <see cref="FixFlags.All"/> reports every field as fixed. + /// </summary> [Test] public void TestAllFixedValues() { @@ -116,6 +137,9 @@ public void TestAllFixedValues() Assert.That(loggingEvent.Fix, Is.EqualTo(FixFlags.LocationInfo | FixFlags.UserName | FixFlags.Identity | FixFlags.Partial | FixFlags.Message | FixFlags.ThreadName | FixFlags.Exception | FixFlags.Domain | FixFlags.Properties), "Fixed Fields is incorrect"); } + /// <summary> + /// Fixing with <see cref="FixFlags.None"/> leaves the event unfixed. + /// </summary> [Test] public void TestNoFixedValues() { @@ -137,6 +161,71 @@ public void TestNoFixedValues() Assert.That(loggingEvent.Fix, Is.EqualTo(FixFlags.None), "Fixed Fields is incorrect"); } + /// <summary> + /// Without impersonation the user name is the process identity, which is the same whichever + /// thread asks, so resolving it after the event has been fixed still gives the right answer. An + /// event fixed without <see cref="FixFlags.UserName"/> must therefore keep reporting it. + /// </summary> + [Test] + public void UserNameIsStillResolvedAfterFixingWithoutImpersonation() + { + string expected = CreateEvent().UserName; + LoggingEvent loggingEvent = CreateEvent(); + + // Partial deliberately leaves UserName out, being the documented setting for avoiding its cost. + loggingEvent.Fix = FixFlags.Partial; + + Assert.That(loggingEvent.Fix & FixFlags.UserName, Is.EqualTo(FixFlags.None)); + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + Assert.That(loggingEvent.UserName, Is.Not.EqualTo(SystemInfo.NotAvailableText)); + } + + /// <summary> + /// Fixing with <see cref="FixFlags.None"/> skips the whole of FixVolatileData but still locks the + /// cache, so the user name has to survive that path too. + /// </summary> + [Test] + public void UserNameIsStillResolvedAfterFixingNothing() + { + string expected = CreateEvent().UserName; + LoggingEvent loggingEvent = CreateEvent(); + + loggingEvent.Fix = FixFlags.None; + + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + } + + /// <summary> + /// Fixing an event with UserName still has to capture it, on the thread that logged the event. + /// </summary> + [Test] + public void UserNameIsCapturedWhenItIsFixed() + { + LoggingEvent loggingEvent = CreateEvent(); + + string expected = loggingEvent.UserName; + loggingEvent.Fix = FixFlags.All; + + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + Assert.That(loggingEvent.UserName, Is.Not.EqualTo(SystemInfo.NotAvailableText)); + } + + /// <summary> + /// Creates an event in the test repository. + /// </summary> + /// <returns>A new, unfixed event.</returns> + private static LoggingEvent CreateEvent() + => new(typeof(FixingTest), + LogManager.GetRepository(TestRepository), + typeof(FixingTest).FullName, + Level.Warn, + "Logging event works", + null); + + /// <summary> + /// Builds the event data the tests compare against. + /// </summary> + /// <returns>Event data with every field set to a known value.</returns> private static LoggingEventData BuildStandardEventData() { LoggingEventData loggingEventData = new() @@ -154,6 +243,12 @@ private static LoggingEventData BuildStandardEventData() return loggingEventData; } + /// <summary> + /// Asserts that <paramref name="loggingEvent"/> carries the values of + /// <paramref name="loggingEventData"/>. + /// </summary> + /// <param name="loggingEvent">The event to check.</param> + /// <param name="loggingEventData">The expected values.</param> private static void AssertExpectedLoggingEvent(LoggingEvent loggingEvent, LoggingEventData loggingEventData) { Assert.That(loggingEventData.Domain, Is.EqualTo("ReallySimpleApp"), "Domain is incorrect"); diff --git a/src/log4net.Tests/Core/UserNameFixingTest.cs b/src/log4net.Tests/Core/UserNameFixingTest.cs index 25dfe1ec..50536c5d 100644 --- a/src/log4net.Tests/Core/UserNameFixingTest.cs +++ b/src/log4net.Tests/Core/UserNameFixingTest.cs @@ -95,6 +95,49 @@ public void UserNameIsResolvedWhileImpersonating() Assert.That(actual, Is.EqualTo(expected)); } + /// <summary> + /// An event logged while impersonating takes the user name with it when it is fixed, even though + /// <see cref="FixFlags.Partial"/> does not ask for it. Fixing is the last point at which the + /// identity that logged the event is known: a buffering appender reads the property later, from + /// the thread flushing the buffer. + /// </summary> + [Test] + public void UserNameIsCapturedWhenFixingAnImpersonatedEvent() + { + using WindowsIdentity identity = WindowsIdentity.GetCurrent(); + string expected = identity.Name; + + LoggingEvent loggingEvent = WindowsIdentity.RunImpersonated(identity.AccessToken, () => + { + LoggingEvent impersonatedEvent = CreateEvent(); + impersonatedEvent.Fix = FixFlags.Partial; + return impersonatedEvent; + }); + + // Read outside the impersonation, as a buffering appender would. + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + } + + /// <summary> + /// The same holds when nothing at all is fixed, which skips most of FixVolatileData but still + /// locks the cache. + /// </summary> + [Test] + public void UserNameIsCapturedWhenFixingNothingOnAnImpersonatedEvent() + { + using WindowsIdentity identity = WindowsIdentity.GetCurrent(); + string expected = identity.Name; + + LoggingEvent loggingEvent = WindowsIdentity.RunImpersonated(identity.AccessToken, () => + { + LoggingEvent impersonatedEvent = CreateEvent(); + impersonatedEvent.Fix = FixFlags.None; + return impersonatedEvent; + }); + + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + } + /// <summary> /// The process identity name may only be resolved on a thread that is not impersonating. /// Seeding it from an impersonating thread would report that user for every later event in diff --git a/src/log4net/Core/LoggingEvent.cs b/src/log4net/Core/LoggingEvent.cs index 016473fa..4f7c852e 100644 --- a/src/log4net/Core/LoggingEvent.cs +++ b/src/log4net/Core/LoggingEvent.cs @@ -735,8 +735,63 @@ private static string ReviseThreadName(string? threadName) /// rather than the Windows account the request happens to run as. /// </para> /// </remarks> - public string UserName => - _data.UserName ??= TryGetCurrentUserName() ?? SystemInfo.NotAvailableText; + public string UserName + { + get + { + if (_data.UserName is null) + { + // Resolving late gives the process identity, which is the same on every thread. On an + // impersonating thread it would give whoever is reading the event instead, so nothing is + // reported; FixVolatileData captures that case up front. + if (_cacheUpdatable || !IsImpersonating()) + { + _data.UserName = TryGetCurrentUserName() ?? SystemInfo.NotAvailableText; + } + } + + return _data.UserName ?? SystemInfo.NotAvailableText; + } + } + + /// <summary> + /// Whether the calling thread is impersonating another identity. + /// </summary> + /// <returns> + /// <see langword="true"/> when the thread runs as an impersonated identity rather than as the + /// process identity, and <see langword="false"/> when it does not or when that cannot be known. + /// </returns> + /// <remarks> + /// <para> + /// Only queries the thread token. Resolving the name behind it is the expensive part and is left + /// to <see cref="TryGetCurrentUserName"/>. + /// </para> + /// </remarks> + private static bool IsImpersonating() + { + try + { + if (_windowsIdentityUnavailable) + { + return false; + } + + if (!IsWindowsIdentitySupported()) + { + _windowsIdentityUnavailable = true; + return false; + } + + using WindowsIdentity? impersonated = WindowsIdentity.GetCurrent(ifImpersonating: true); + return impersonated is not null; + } + catch (Exception e) when (!e.IsFatal()) + { + // As in TryGetCurrentUserName: an unreadable identity must not break logging. + _windowsIdentityUnavailable = true; + return false; + } + } private static string? TryGetCurrentUserName() { @@ -1156,6 +1211,15 @@ protected virtual void FixVolatileData(FixFlags flags) } } + // Last point at which the identity that logged the event is known, so grab it even when it was + // not asked for. Outside the block above, which is skipped when there is nothing to fix while + // the cache is locked all the same. FixFlags.UserName stays unset: the flags report what the + // caller requested. + if (_data.UserName is null && IsImpersonating()) + { + _data.UserName = TryGetCurrentUserName() ?? SystemInfo.NotAvailableText; + } + // Finally lock everything we've cached. _cacheUpdatable = false; }
