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 <[email protected]> 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> ----
