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 000000000..c9253cf62 --- /dev/null +++ b/src/changelog/3.3.3/304-fix-username-resolved-for-every-event.xml @@ -0,0 +1,13 @@ + + + + + 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 + + diff --git a/src/log4net.Tests/Core/UserNameFixingTest.cs b/src/log4net.Tests/Core/UserNameFixingTest.cs new file mode 100644 index 000000000..25dfe1ec7 --- /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; + +/// +/// Tests for , whose name is resolved once for the process +/// identity and once per impersonated user rather than once per logging event. +/// +[TestFixture] +[Platform("Win")] +[NonParallelizable] +#if NET8_0_OR_GREATER +[System.Runtime.Versioning.SupportedOSPlatform("windows")] +#endif +public class UserNameFixingTest +{ + /// + /// The assumption the impersonation tests below rest on: running under a token - even the + /// process's own - is observable as impersonation. + /// + [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); + } + + /// + /// The UserName property matches the current Windows identity. + /// + [Test] + public void UserNameMatchesTheCurrentWindowsIdentity() + { + using WindowsIdentity identity = WindowsIdentity.GetCurrent(); + + Assert.That(CreateEvent().UserName, Is.EqualTo(identity.Name)); + } + + /// + /// The UserName is stable across multiple events (cached, not resolved each time). + /// + [Test] + public void UserNameIsStableAcrossEvents() + { + string first = CreateEvent().UserName; + + Assert.That(CreateEvent().UserName, Is.EqualTo(first)); + } + + /// + /// While impersonating, the UserName is correctly resolved to the impersonated user's identity. + /// + [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)); + } + + /// + /// 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. + /// + [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 d915f69cc..42aae5696 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) /// /// /// - /// On Windows it calls WindowsIdentity.GetCurrent().Name to get the name of - /// the current windows user. On other OSes it calls Environment.UserName. + /// On Windows this resolves the name from , on other platforms + /// from . /// /// - /// 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 DOMAIN\user 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: /// - /// - /// However, the WindowsIdentity.GetCurrent() call seems to - /// return different objects every time, so the current implementation - /// doesn't do this type of caching. - /// - /// - /// Timing for these operations: - /// - /// - /// - /// Method - /// Results - /// - /// - /// WindowsIdentity.GetCurrent() - /// 10000 loops, 00:00:00.2031250 seconds - /// - /// - /// WindowsIdentity.GetCurrent().Name - /// 10000 loops, 00:00:08.0468750 seconds - /// + /// + /// + /// 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 + /// , is around 300 times cheaper than + /// resolving a name, so this is the fast path for services, console applications and + /// ASP.NET Core. + /// + /// + /// A thread that is impersonating - classic ASP.NET with + /// <identity impersonate="true"/>, or WindowsIdentity.RunImpersonated - + /// has its name resolved once per distinct user and cached by security identifier, for up + /// to users. Past that bound the name is resolved per + /// event rather than letting the cache grow without limit. + /// /// /// - /// This means we could speed things up almost 40 times by caching the - /// value of the WindowsIdentity.GetCurrent().Name property, since - /// this takes (8.04-0.20) = 7.84375 seconds. + /// In classic ASP.NET, 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. /// /// 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; - - /// - /// On Windows: UserName in case of success, empty string for unexpected null in identity or Name - /// - /// On other OSes: null - /// - /// Thrown on non-Windows platforms on net462 - private static string? TryReadWindowsIdentityUserName() + /// on platforms where cannot be used + 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 + } + + /// UserName of the process identity, empty string for an unexpected null in identity or Name + /// Thrown on non-Windows platforms on net462 + private static string ReadProcessUserName() + { using WindowsIdentity identity = WindowsIdentity.GetCurrent(); return identity?.Name ?? string.Empty; } - private static bool _platformDoesNotSupportWindowsIdentity; + /// UserName of , resolved once per security identifier + 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; + } /// /// Gets the identity of the current thread principal. @@ -1293,6 +1313,33 @@ public PropertiesDictionary GetProperties() return _compositeProperties!.Flatten(); } + /// + /// Upper bound on , 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. + /// + private const int MaxCachedUserNames = 64; + + private static string? _cachedEnvironmentUserName; + + /// + /// , resolved once per process. Only reached when + /// is unusable, where thread level impersonation does not apply. + /// + private static string CachedEnvironmentUserName => _cachedEnvironmentUserName ??= Environment.UserName; + + /// + /// Name of the process identity, resolved once on a thread that is not impersonating. + /// + private static string? _processUserName; + + /// + /// Names of impersonated users, keyed by security identifier. + /// + private static readonly ConcurrentDictionary _userNamesBySid = new(); + + private static bool _windowsIdentityUnavailable; + /// /// The internal logging event data. /// diff --git a/src/log4net/Layout/PatternLayout.cs b/src/log4net/Layout/PatternLayout.cs index 7f8b2dca4..29e64746a 100644 --- a/src/log4net/Layout/PatternLayout.cs +++ b/src/log4net/Layout/PatternLayout.cs @@ -556,13 +556,21 @@ namespace log4net.Layout; /// /// /// WARNING 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. +/// +/// +/// In classic ASP.NET with <identity impersonate="true"/> this reports the +/// Windows account the request runs as. identity 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. /// /// /// /// -/// utcdate +/// utcdate /// /// /// 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 7b4081c31..4e0891785 100644 --- a/src/log4net/Util/LogicalThreadContextProperties.cs +++ b/src/log4net/Util/LogicalThreadContextProperties.cs @@ -78,14 +78,14 @@ public override object? this[string key] } 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 @@ public override object? this[string key] /// 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 74f0f6be3..d5b9f9d39 100644 --- a/src/log4net/Util/SystemInfo.cs +++ b/src/log4net/Util/SystemInfo.cs @@ -41,6 +41,11 @@ public static class SystemInfo /// internal static bool IsAndroid { get; } = IsAndroidCore(); + /// + /// Is the mono runtime used + /// + internal static bool IsMono { get; } = Type.GetType("Mono.Runtime") is not null; + /// /// Initialize default values for private static fields. /// 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 6775c917f..f46c981a4 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 - + ----