This is an automated email from the ASF dual-hosted git repository.
FreeAndNil pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
The following commit(s) were added to refs/heads/master by this push:
new 29a21046 Fix `LoggingEvent.UserName` resolving the Windows identity
for every event (#304)
29a21046 is described below
commit 29a21046be37ce8b912237bac70d46c785de4e69
Author: Jan Friedrich <[email protected]>
AuthorDate: Tue Aug 4 20:49:30 2026 +0200
Fix `LoggingEvent.UserName` resolving the Windows identity for every event
(#304)
The cache added in 2.0.15 (commit 9305ea9b) was declared as an instance
field
on `LoggingEvent`. Since every event is a fresh instance the guard was
always
false, so the `??=` never hit and each event ran a full
`WindowsIdentity.GetCurrent().Name` - measured at 79.6 us on the machine
used
here. The same commit had changed `TryGetCurrentUserName` from static to
instance, so the caching it introduced has never taken effect.
The doc comment above the property already described the intended design and
the reason it was abandoned: the name should be cached "as long as the
identity
stayed constant", but `WindowsIdentity.GetCurrent()` "seems to return
different
objects every time". Object identity was the wrong comparison. The security
identifier is stable, and obtaining the identity is far cheaper than
resolving
its name - the timing table in that same comment puts the two at roughly 20
ns
against 804 ns.
So the name is now cached without changing what the property reports:
- A thread that is not impersonating runs as the process identity, so its
name
is resolved once per process. `WindowsIdentity.GetCurrent(ifImpersonating:
true)` answers that question for 249 ns against 78 us for a name, making
this
the fast path for services, console applications and ASP.NET Core.
- A thread that is impersonating - classic ASP.NET with
`<identity impersonate="true"/>`, or `RunImpersonated` - has its name
resolved once per distinct user, keyed by security identifier and capped
at
`MaxCachedUserNames` entries so that a site in front of a large directory
cannot accumulate one entry per visitor.
The process-identity value is assigned in exactly one place, inside the
branch
that has already established the thread is not impersonating. Seeding it
from
an impersonating thread would report that user for the rest of the process,
which `ImpersonationDoesNotSeedTheProcessUserName` guards against.
A buffered `FixFlags.All` event goes from 192,937 to 17,578 ns on this
machine,
both sides built as netstandard2.0. The remainder is
`FixFlags.LocationInfo`,
which is untouched here.
Two related changes in the same method:
- `Environment.UserName`, the fallback when `WindowsIdentity` is unusable,
is
also cached; it measured 33.8 us per call. Impersonation does not apply on
that path.
- The `SecurityException` handler now sets the unavailable flag, as the
`PlatformNotSupportedException` handler already did. Under partial trust
the
old code threw, caught and logged once per event forever.
Documentation: the `%username` pattern entry now explains the caching and
points ASP.NET users at `%identity`, which is both cheaper and usually what
is
wanted because it reports the authenticated application user. The
`BufferingForwardingAppender` manual page recommends `Partial` in its
example
instead of `All`; the surrounding comment already warned that the `All`
default
"may negatively impact performance enough to warrant changing it", and
`LocationInfo` costs 6.9 us and 14 kB per event.
`LogicalThreadContextProperties` no longer stores an empty dictionary just
to
replace it on the next line, and no longer clones on removal of an absent
key.
Both are cleanups; neither changes the allocation profile of the common
set/remove pattern.
---
.../304-fix-username-resolved-for-every-event.xml | 13 ++
src/log4net.Tests/Core/UserNameFixingTest.cs | 128 +++++++++++++++
src/log4net/Core/LoggingEvent.cs | 173 +++++++++++++--------
src/log4net/Layout/PatternLayout.cs | 14 +-
src/log4net/Util/LogicalThreadContextProperties.cs | 18 ++-
src/log4net/Util/SystemInfo.cs | 5 +
.../appenders/bufferingforwardingappender.adoc | 4 +-
7 files changed, 280 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..25dfe1ec
--- /dev/null
+++ b/src/log4net.Tests/Core/UserNameFixingTest.cs
@@ -0,0 +1,128 @@
+#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);
+ }
+
+ /// <summary>
+ /// The UserName property matches the current Windows identity.
+ /// </summary>
+ [Test]
+ public void UserNameMatchesTheCurrentWindowsIdentity()
+ {
+ using WindowsIdentity identity = WindowsIdentity.GetCurrent();
+
+ Assert.That(CreateEvent().UserName, Is.EqualTo(identity.Name));
+ }
+
+ /// <summary>
+ /// The UserName is stable across multiple events (cached, not resolved each
time).
+ /// </summary>
+ [Test]
+ public void UserNameIsStableAcrossEvents()
+ {
+ string first = CreateEvent().UserName;
+
+ Assert.That(CreateEvent().UserName, Is.EqualTo(first));
+ }
+
+ /// <summary>
+ /// While impersonating, the UserName is correctly resolved to the
impersonated user's identity.
+ /// </summary>
+ [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..42aae569 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,47 @@ 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()
+ /// <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 !SystemInfo.IsMono;
#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 +1313,33 @@ 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;
+
+ private static string? _cachedEnvironmentUserName;
+
+ /// <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 =>
_cachedEnvironmentUserName ??= Environment.UserName;
+
+ /// <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/log4net/Util/SystemInfo.cs b/src/log4net/Util/SystemInfo.cs
index 74f0f6be..d5b9f9d3 100644
--- a/src/log4net/Util/SystemInfo.cs
+++ b/src/log4net/Util/SystemInfo.cs
@@ -41,6 +41,11 @@ public static class SystemInfo
/// </summary>
internal static bool IsAndroid { get; } = IsAndroidCore();
+ /// <summary>
+ /// Is the mono runtime used
+ /// </summary>
+ internal static bool IsMono { get; } = Type.GetType("Mono.Runtime") is not
null;
+
/// <summary>
/// Initialize default values for private static fields.
/// </summary>
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>
----
