You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by fr...@apache.org on 2026/08/03 20:20:00 UTC
(logging-log4net) branch Feature/304-username-identity-lookup created (now 0007db4c)
This is an automated email from the ASF dual-hosted git repository.
FreeAndNil pushed a change to branch Feature/304-username-identity-lookup
in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
at 0007db4c Fix `LoggingEvent.UserName` resolving the Windows identity for every event
This branch includes the following new commits:
new 0007db4c Fix `LoggingEvent.UserName` resolving the Windows identity for every event
The 1 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
(logging-log4net) 01/01: Fix `LoggingEvent.UserName` resolving the Windows identity for every event
Posted by fr...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
FreeAndNil pushed a commit to branch Feature/304-username-identity-lookup
in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
commit 0007db4c2738b23e7f35a5e7046455504602e1b7
Author: Jan Friedrich <fr...@apache.org>
AuthorDate: Mon Aug 3 22:16:43 2026 +0200
Fix `LoggingEvent.UserName` resolving the Windows identity for every event
---
.../304-fix-username-resolved-for-every-event.xml | 13 ++
src/log4net.Tests/Core/UserNameFixingTest.cs | 119 ++++++++++++++
src/log4net/Core/LoggingEvent.cs | 171 +++++++++++++--------
src/log4net/Layout/PatternLayout.cs | 14 +-
src/log4net/Util/LogicalThreadContextProperties.cs | 18 ++-
.../appenders/bufferingforwardingappender.adoc | 4 +-
6 files changed, 264 insertions(+), 75 deletions(-)
diff --git a/src/changelog/3.3.3/304-fix-username-resolved-for-every-event.xml b/src/changelog/3.3.3/304-fix-username-resolved-for-every-event.xml
new file mode 100644
index 00000000..c9253cf6
--- /dev/null
+++ b/src/changelog/3.3.3/304-fix-username-resolved-for-every-event.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="304" link="https://github.com/apache/logging-log4net/pull/304"/>
+ <description format="asciidoc">
+ fix `LoggingEvent.UserName` resolving the Windows identity for every event, because the cache
+ added in 2.0.15 was held in an instance field and so never applied. The process identity is now
+ resolved once, and impersonated identities once per user, cutting a buffered `FixFlags.All` event
+ from about 193 us to 17.5 us on the machine measured
+ </description>
+</entry>
diff --git a/src/log4net.Tests/Core/UserNameFixingTest.cs b/src/log4net.Tests/Core/UserNameFixingTest.cs
new file mode 100644
index 00000000..517c4e31
--- /dev/null
+++ b/src/log4net.Tests/Core/UserNameFixingTest.cs
@@ -0,0 +1,119 @@
+#region Apache License
+//
+// Licensed to the Apache Software Foundation (ASF) under one or more
+// contributor license agreements. See the NOTICE file distributed with
+// this work for additional information regarding copyright ownership.
+// The ASF licenses this file to you under the Apache License, Version 2.0
+// (the "License"); you may not use this file except in compliance with
+// the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+//
+#endregion
+
+using System;
+using System.Reflection;
+using System.Security.Principal;
+
+using log4net.Core;
+
+using NUnit.Framework;
+
+namespace log4net.Tests.Core;
+
+/// <summary>
+/// Tests for <see cref="LoggingEvent.UserName"/>, whose name is resolved once for the process
+/// identity and once per impersonated user rather than once per logging event.
+/// </summary>
+[TestFixture]
+[Platform("Win")]
+[NonParallelizable]
+#if NET8_0_OR_GREATER
+[System.Runtime.Versioning.SupportedOSPlatform("windows")]
+#endif
+public class UserNameFixingTest
+{
+ /// <summary>
+ /// The assumption the impersonation tests below rest on: running under a token - even the
+ /// process's own - is observable as impersonation.
+ /// </summary>
+ [Test]
+ public void RunImpersonatedIsObservableAsImpersonation()
+ {
+ using WindowsIdentity identity = WindowsIdentity.GetCurrent();
+
+ bool impersonating = WindowsIdentity.RunImpersonated(identity.AccessToken, () =>
+ {
+ using WindowsIdentity? current = WindowsIdentity.GetCurrent(ifImpersonating: true);
+ return current is not null;
+ });
+
+ Assert.That(impersonating, Is.True);
+ }
+
+ [Test]
+ public void UserNameMatchesTheCurrentWindowsIdentity()
+ {
+ using WindowsIdentity identity = WindowsIdentity.GetCurrent();
+
+ Assert.That(CreateEvent().UserName, Is.EqualTo(identity.Name));
+ }
+
+ [Test]
+ public void UserNameIsStableAcrossEvents()
+ {
+ string first = CreateEvent().UserName;
+
+ Assert.That(CreateEvent().UserName, Is.EqualTo(first));
+ }
+
+ [Test]
+ public void UserNameIsResolvedWhileImpersonating()
+ {
+ using WindowsIdentity identity = WindowsIdentity.GetCurrent();
+ string expected = identity.Name;
+
+ string actual = WindowsIdentity.RunImpersonated(
+ identity.AccessToken,
+ () => CreateEvent().UserName);
+
+ Assert.That(actual, 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
+ /// the process, including events raised on threads that impersonate nobody.
+ /// </summary>
+ [Test]
+ public void ImpersonationDoesNotSeedTheProcessUserName()
+ {
+ FieldInfo field = typeof(LoggingEvent).GetField(
+ "_processUserName",
+ BindingFlags.Static | BindingFlags.NonPublic)
+ ?? throw new InvalidOperationException("LoggingEvent._processUserName is missing");
+ object? saved = field.GetValue(null);
+ try
+ {
+ field.SetValue(null, null);
+ using WindowsIdentity identity = WindowsIdentity.GetCurrent();
+
+ WindowsIdentity.RunImpersonated(identity.AccessToken, () => CreateEvent().UserName);
+
+ Assert.That(field.GetValue(null), Is.Null);
+ }
+ finally
+ {
+ field.SetValue(null, saved);
+ }
+ }
+
+ private static LoggingEvent CreateEvent()
+ => new(typeof(UserNameFixingTest), null, "UserNameFixingTest", Level.Info, "message", null);
+}
diff --git a/src/log4net/Core/LoggingEvent.cs b/src/log4net/Core/LoggingEvent.cs
index d915f69c..695cfc80 100644
--- a/src/log4net/Core/LoggingEvent.cs
+++ b/src/log4net/Core/LoggingEvent.cs
@@ -1,4 +1,4 @@
-#region Apache License
+#region Apache License
//
// Licensed to the Apache Software Foundation (ASF) under one or more
// contributor license agreements. See the NOTICE file distributed with
@@ -18,6 +18,7 @@
#endregion
using System;
+using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Globalization;
using System.IO;
@@ -701,83 +702,84 @@ private static string ReviseThreadName(string? threadName)
/// </value>
/// <remarks>
/// <para>
- /// On Windows it calls <c>WindowsIdentity.GetCurrent().Name</c> to get the name of
- /// the current windows user. On other OSes it calls Environment.UserName.
+ /// On Windows this resolves the name from <see cref="WindowsIdentity"/>, on other platforms
+ /// from <see cref="Environment.UserName"/>.
/// </para>
/// <para>
- /// To improve performance, we could cache the string representation of
- /// the name, and reuse that as long as the identity stayed constant.
- /// Once the identity changed, we would need to re-assign and re-render
- /// the string.
+ /// Resolving the name is by far the most expensive part: obtaining the identity costs a few
+ /// hundred nanoseconds, while translating it into a <c>DOMAIN\user</c> string is a local
+ /// security authority lookup costing tens of microseconds. The name is therefore cached, in a
+ /// way that still reports the right user in a process which switches users:
/// </para>
- /// <para>
- /// However, the <c>WindowsIdentity.GetCurrent()</c> call seems to
- /// return different objects every time, so the current implementation
- /// doesn't do this type of caching.
- /// </para>
- /// <para>
- /// Timing for these operations:
- /// </para>
- /// <list type="table">
- /// <listheader>
- /// <term>Method</term>
- /// <description>Results</description>
- /// </listheader>
- /// <item>
- /// <term><c>WindowsIdentity.GetCurrent()</c></term>
- /// <description>10000 loops, 00:00:00.2031250 seconds</description>
- /// </item>
- /// <item>
- /// <term><c>WindowsIdentity.GetCurrent().Name</c></term>
- /// <description>10000 loops, 00:00:08.0468750 seconds</description>
- /// </item>
+ /// <list type="bullet">
+ /// <item><description>
+ /// A thread that is not impersonating runs as the process identity, so its name is
+ /// resolved once per process. Asking whether the thread impersonates, via
+ /// <see cref="WindowsIdentity.GetCurrent(bool)"/>, is around 300 times cheaper than
+ /// resolving a name, so this is the fast path for services, console applications and
+ /// ASP.NET Core.
+ /// </description></item>
+ /// <item><description>
+ /// A thread that is impersonating - classic ASP.NET with
+ /// <c><identity impersonate="true"/></c>, or <c>WindowsIdentity.RunImpersonated</c> -
+ /// has its name resolved once per distinct user and cached by security identifier, for up
+ /// to <see cref="MaxCachedUserNames"/> users. Past that bound the name is resolved per
+ /// event rather than letting the cache grow without limit.
+ /// </description></item>
/// </list>
/// <para>
- /// This means we could speed things up almost 40 times by caching the
- /// value of the <c>WindowsIdentity.GetCurrent().Name</c> property, since
- /// this takes (8.04-0.20) = 7.84375 seconds.
+ /// In classic ASP.NET, <see cref="Identity"/> is both cheaper than this property and usually
+ /// what the application actually wants, because it reports the authenticated application user
+ /// rather than the Windows account the request happens to run as.
/// </para>
/// </remarks>
public string UserName =>
_data.UserName ??= TryGetCurrentUserName() ?? SystemInfo.NotAvailableText;
- private string? TryGetCurrentUserName()
+ private static string? TryGetCurrentUserName()
{
try
{
- if (_platformDoesNotSupportWindowsIdentity)
+ if (_windowsIdentityUnavailable)
{
- // we've already received one PlatformNotSupportedException or null from TryReadWindowsIdentityUserName
- // and it's highly unlikely that will change
- return Environment.UserName;
+ // we've already seen a PlatformNotSupportedException, a SecurityException or a
+ // non-Windows platform, and it's highly unlikely that will change
+ return CachedEnvironmentUserName;
}
-
- if (_cachedWindowsIdentityUserName is not null)
+
+ if (!IsWindowsIdentitySupported())
{
- return _cachedWindowsIdentityUserName;
+ _windowsIdentityUnavailable = true;
+ return CachedEnvironmentUserName;
}
- if (TryReadWindowsIdentityUserName() is string userName)
+
+ using WindowsIdentity? impersonated = WindowsIdentity.GetCurrent(ifImpersonating: true);
+ if (impersonated is null)
{
- _cachedWindowsIdentityUserName = userName;
- return _cachedWindowsIdentityUserName;
+ // Not impersonating, so this thread runs as the process identity. Reading it through
+ // GetCurrent() is only correct here, which is why the field is assigned nowhere else:
+ // seeding it from an impersonating thread would report that user for the whole process.
+ return _processUserName ??= ReadProcessUserName();
}
- _platformDoesNotSupportWindowsIdentity = true;
- return Environment.UserName;
+
+ return ReadImpersonatedUserName(impersonated);
}
catch (PlatformNotSupportedException)
{
- _platformDoesNotSupportWindowsIdentity = true;
- return Environment.UserName;
+ _windowsIdentityUnavailable = true;
+ return CachedEnvironmentUserName;
}
catch (SecurityException)
{
- // This security exception will occur if the caller does not have
- // some undefined set of SecurityPermission flags.
+ // This security exception will occur if the caller does not have
+ // some undefined set of SecurityPermission flags. It will keep happening, so remember it
+ // instead of throwing and catching once per logging event.
+ _windowsIdentityUnavailable = true;
LogLog.Debug(
_declaringType,
"Security exception while trying to get current windows identity. Error Ignored."
);
- return Environment.UserName;
+ return CachedEnvironmentUserName;
}
catch (Exception e) when (!e.IsFatal())
{
@@ -785,29 +787,53 @@ private static string ReviseThreadName(string? threadName)
}
}
- private string? _cachedWindowsIdentityUserName;
-
- /// <returns>
- /// On Windows: UserName in case of success, empty string for unexpected null in identity or Name
- /// <para/>
- /// On other OSes: null
- /// </returns>
- /// <exception cref="PlatformNotSupportedException">Thrown on non-Windows platforms on net462</exception>
- private static string? TryReadWindowsIdentityUserName()
+ /// <summary>
+ /// <see cref="Environment.UserName"/>, resolved once per process. Only reached when
+ /// <see cref="WindowsIdentity"/> is unusable, where thread level impersonation does not apply.
+ /// </summary>
+ private static string CachedEnvironmentUserName => field ??= Environment.UserName;
+
+ /// <returns><see langword="false"/> on platforms where <see cref="WindowsIdentity"/> cannot be used</returns>
+ private static bool IsWindowsIdentitySupported()
{
// According to docs RuntimeInformation.IsOSPlatform is supported from netstandard1.1,
// but it's erroring in runtime on < net471
#if NET471_OR_GREATER || NETSTANDARD2_0_OR_GREATER
- if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
- {
- return null;
- }
+ return RuntimeInformation.IsOSPlatform(OSPlatform.Windows);
+#else
+ return true;
#endif
+ }
+
+ /// <returns>UserName of the process identity, empty string for an unexpected null in identity or Name</returns>
+ /// <exception cref="PlatformNotSupportedException">Thrown on non-Windows platforms on net462</exception>
+ private static string ReadProcessUserName()
+ {
using WindowsIdentity identity = WindowsIdentity.GetCurrent();
return identity?.Name ?? string.Empty;
}
- private static bool _platformDoesNotSupportWindowsIdentity;
+ /// <returns>UserName of <paramref name="identity"/>, resolved once per security identifier</returns>
+ private static string ReadImpersonatedUserName(WindowsIdentity identity)
+ {
+ if (identity.User is not SecurityIdentifier sid)
+ {
+ return identity.Name ?? string.Empty;
+ }
+
+ if (_userNamesBySid.TryGetValue(sid, out string? cached))
+ {
+ return cached;
+ }
+
+ string userName = identity.Name ?? string.Empty;
+ if (_userNamesBySid.Count < MaxCachedUserNames)
+ {
+ _userNamesBySid[sid] = userName;
+ }
+
+ return userName;
+ }
/// <summary>
/// Gets the identity of the current thread principal.
@@ -1293,6 +1319,25 @@ public PropertiesDictionary GetProperties()
return _compositeProperties!.Flatten();
}
+ /// <summary>
+ /// Upper bound on <see cref="_userNamesBySid"/>, so that a process impersonating an unbounded
+ /// set of users - an intranet site in front of a large directory - does not accumulate one
+ /// cache entry per visitor.
+ /// </summary>
+ private const int MaxCachedUserNames = 64;
+
+ /// <summary>
+ /// Name of the process identity, resolved once on a thread that is not impersonating.
+ /// </summary>
+ private static string? _processUserName;
+
+ /// <summary>
+ /// Names of impersonated users, keyed by security identifier.
+ /// </summary>
+ private static readonly ConcurrentDictionary<SecurityIdentifier, string> _userNamesBySid = new();
+
+ private static bool _windowsIdentityUnavailable;
+
/// <summary>
/// The internal logging event data.
/// </summary>
diff --git a/src/log4net/Layout/PatternLayout.cs b/src/log4net/Layout/PatternLayout.cs
index 7f8b2dca..29e64746 100644
--- a/src/log4net/Layout/PatternLayout.cs
+++ b/src/log4net/Layout/PatternLayout.cs
@@ -556,13 +556,21 @@ namespace log4net.Layout;
/// </para>
/// <para>
/// <b>WARNING</b> Generating caller WindowsIdentity information is
-/// extremely slow. Its use should be avoided unless execution speed
-/// is not an issue.
+/// slow. The name is cached per identity, so a process that does not
+/// impersonate pays for it once, and one that impersonates pays once
+/// per distinct user - but the first event for each user is expensive.
+/// </para>
+/// <para>
+/// In classic ASP.NET with <c><identity impersonate="true"/></c> this reports the
+/// Windows account the request runs as. <b>identity</b> is both cheaper and usually what
+/// is wanted there, because it reports the authenticated application user. On ASP.NET Core
+/// there is no impersonation by default, so this reports the application pool identity
+/// rather than the request user.
/// </para>
/// </description>
/// </item>
/// <item>
-/// <term>utcdate</term>
+/// <term>utcdate</term>
/// <description>
/// <para>
/// Used to output the date of the logging event in universal time.
diff --git a/src/log4net/Util/LogicalThreadContextProperties.cs b/src/log4net/Util/LogicalThreadContextProperties.cs
index 7b4081c3..4e089178 100644
--- a/src/log4net/Util/LogicalThreadContextProperties.cs
+++ b/src/log4net/Util/LogicalThreadContextProperties.cs
@@ -78,14 +78,14 @@ internal LogicalThreadContextProperties()
}
set
{
- // Force the dictionary to be created
- PropertiesDictionary props = GetProperties(true)!;
// Reason for cloning the dictionary below: object instances set on the CallContext
- // need to be immutable to correctly flow through async/await
- PropertiesDictionary immutableProps = new(props)
- {
- [key] = value
- };
+ // need to be immutable to correctly flow through async/await.
+ // The existing dictionary is read without creating one, because the clone replaces it
+ // anyway - asking for creation would store an empty dictionary just to overwrite it.
+ PropertiesDictionary immutableProps = GetProperties(false) is PropertiesDictionary props
+ ? new(props)
+ : [];
+ immutableProps[key] = value;
SetLogicalProperties(immutableProps);
}
}
@@ -101,7 +101,9 @@ internal LogicalThreadContextProperties()
/// </remarks>
public void Remove(string key)
{
- if (GetProperties(false) is PropertiesDictionary dictionary)
+ // Cloning is only worthwhile when the key is actually present - otherwise the clone would
+ // replace the stored dictionary with an equal one.
+ if (GetProperties(false) is PropertiesDictionary dictionary && dictionary.Contains(key))
{
PropertiesDictionary immutableProps = new(dictionary);
immutableProps.Remove(key);
diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/bufferingforwardingappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/bufferingforwardingappender.adoc
index 6775c917..f46c981a 100644
--- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/bufferingforwardingappender.adoc
+++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/bufferingforwardingappender.adoc
@@ -31,9 +31,11 @@ The following example shows how to configure the `BufferingForwardingAppender` t
<!--
The value configures what gets fixed immediately when calling logger.Log().
The default value is All, which may negatively impact performance enough to warrant changing it to fix less data.
+ Partial is the recommended starting point: it fixes the message, thread name, exception, domain
+ and properties, and leaves out LocationInfo, which has to walk the call stack for every event.
More information can be found at https://github.com/apache/logging-log4net/blob/master/src/log4net/Core/FixFlags.cs
-->
- <fix value="All"/>
+ <fix value="Partial"/>
<appender-ref ref="ConsoleAppender" />
</appender>
----