diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index 2599ffcd0..af5b33599 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -72,4 +72,20 @@ jobs: dotnet publish ./src/log4net.Tests.Aot/log4net.Tests.Aot.csproj -c Release -o ./aot-probes if ($LASTEXITCODE -ne 0) { exit $LASTEXITCODE } & "./aot-probes/log4net.Tests.Aot$($IsWindows ? '.exe' : '')" + if ($LASTEXITCODE -ne 0) { exit $LASTEXITCODE } + + # A process that hosts the runtime natively has no entry assembly, so the configuration + # system cannot work out where the config file is (issue #162). The check owns the process + # from its first statement, because the configuration system caches its initialization and + # log4net reads its first setting from a static constructor, so it cannot be one of the + # probes above. + # + # JIT only, deliberately: under Native AOT the configuration system is trimmed away, so the + # first setting read fails as a missing constructor long before it can fail for want of an + # entry assembly. The published executable passes this check with the fix reverted, which + # makes it a green that cannot fail for the reason the check exists. + - name: AOT probes, no entry assembly + shell: pwsh + run: | + dotnet run --project ./src/log4net.Tests.Aot/log4net.Tests.Aot.csproj -c Release -- --no-entry-assembly if ($LASTEXITCODE -ne 0) { exit $LASTEXITCODE } \ No newline at end of file diff --git a/src/changelog/3.4.1/162-quiet-app-settings-in-a-native-host.xml b/src/changelog/3.4.1/162-quiet-app-settings-in-a-native-host.xml new file mode 100644 index 000000000..c16a8eadf --- /dev/null +++ b/src/changelog/3.4.1/162-quiet-app-settings-in-a-native-host.xml @@ -0,0 +1,15 @@ + + + + Stop reporting `log4net:ERROR Exception while reading ConfigurationSettings` + in a process that hosts the runtime natively, such as `powershell.exe` or a C++ host of the CoreCLR. + There is no entry assembly there for the configuration system to derive the config file path from, so + it fails with `PlatformNotSupportedException` before any config file is read. That is now recognised + as an absent configuration system, the same as under Native AOT: it is logged once at debug level and + application settings are read from environment variables instead + (reported by @viktorgobbi, + fixed by @FreeAndNil in https://github.com/apache/logging-log4net/pull/311[#311]) + diff --git a/src/log4net.Tests.Aot/NativeHostCheck.cs b/src/log4net.Tests.Aot/NativeHostCheck.cs new file mode 100644 index 000000000..d799ffeaa --- /dev/null +++ b/src/log4net.Tests.Aot/NativeHostCheck.cs @@ -0,0 +1,189 @@ +#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.Collections.Generic; +using System.IO; +using System.Reflection; + +using log4net.Appender; +using log4net.Config; +using log4net.Core; +using log4net.Layout; +using log4net.Util; + +namespace log4net.Tests.Aot; + +/// +/// Records what log4net does in a process that hosts the runtime natively, where there is no entry +/// assembly for the configuration system to derive the config file path from (issue #162). +/// +/// +/// +/// This cannot be one of : the configuration system caches its initialization, +/// and log4net reads its first application setting from a static constructor, so by the time any +/// probe runs the outcome is already decided. The check therefore owns the process from its first +/// statement, which is why the runner invokes it instead of the probe list. +/// +/// +/// Removing the entry assembly is what a native host does to the process, and reflecting onto +/// Assembly.SetEntryAssembly is the only way to arrive there without one. It is a CoreCLR +/// internal, so the check reports itself as not applicable rather than failing where it is absent. +/// +/// +/// The build runs this JIT compiled only. Native AOT trims the configuration system away, so there +/// the first setting read fails as a missing constructor before it can fail for want of an entry +/// assembly: the published executable passes this check even with the fix for #162 reverted, which +/// would be a green that cannot fail for the reason the check exists. +/// +/// +internal static class NativeHostCheck +{ + /// + /// The argument that selects this check instead of the probe list. + /// + internal const string Argument = "--no-entry-assembly"; + + /// + /// A setting that only app.config carries, so reading it proves whether the configuration system + /// was really bypassed rather than answering from a cache. + /// + private const string ConfigOnlyKey = "log4net.AotProbe"; + + /// + /// Removes the entry assembly, starts log4net, and reports what it wrote while doing so. + /// + /// 0 if log4net started without reporting an error, otherwise 1 + internal static int Run() + { + Console.WriteLine("log4net probes, no entry assembly"); + Console.WriteLine(new string('-', 100)); + + if (RemoveTheEntryAssembly() is string unavailable) + { + Console.WriteLine($" {"n/a",-6} settings/no error without an entry assembly"); + Console.WriteLine($" {unavailable}"); + Console.WriteLine(new string('-', 100)); + Console.WriteLine("no entry assembly: not applicable here"); + return 0; + } + + // log4net reports an unreadable configuration system on Console.Error, from a static + // constructor, so the writer has to be in place before anything touches log4net at all. + TextWriter console = Console.Error; + using StringWriter emitted = new(); + Console.SetError(emitted); + List failures = []; + try + { + Environment.SetEnvironmentVariable(Program.EnvironmentProbeKey, "from-environment"); + Check(failures, SystemInfo.GetAppSetting(Program.EnvironmentProbeKey) == "from-environment", + "an application setting was not read from the environment"); + Check(failures, SystemInfo.GetAppSetting(ConfigOnlyKey) is null, + $"{ConfigOnlyKey} was answered from app.config, so this check exercised nothing"); + Check(failures, Log() == 1, "the event did not reach the appender"); + } + catch (Exception e) when (e is not (OutOfMemoryException or StackOverflowException)) + { + failures.Add($"{e.GetType().Name}: {e.Message}"); + } + finally + { + Console.SetError(console); + } + + // The symptom of #162 is a stack trace for every setting log4net reads, in an application whose + // configuration is fine. An absent configuration system is a property of the host, so it + // belongs at debug level, and nothing here turns internal debugging on. + string output = emitted.ToString(); + Check(failures, !output.Contains("log4net:ERROR", StringComparison.Ordinal), + "log4net reported an error while reading its application settings"); + + foreach (string failure in failures) + { + Console.WriteLine($" {"FAIL",-6} settings/no error without an entry assembly"); + Console.WriteLine($" {failure}"); + } + if (failures.Count == 0) + { + Console.WriteLine($" {"ok",-6} settings/no error without an entry assembly"); + } + else if (output.Length > 0) + { + Console.WriteLine("what log4net wrote:"); + Console.WriteLine(output); + } + + Console.WriteLine(new string('-', 100)); + Console.WriteLine(failures.Count == 0 + ? "no entry assembly: log4net started without reporting an error" + : $"no entry assembly: {failures.Count} check(s) did not match expectations"); + return failures.Count == 0 ? 0 : 1; + } + + /// + /// Makes this process look like a natively hosted one. + /// + /// null once there is no entry assembly, otherwise why that cannot be arranged + private static string? RemoveTheEntryAssembly() + { + MethodInfo? setEntryAssembly = typeof(Assembly) + .GetMethod("SetEntryAssembly", BindingFlags.Static | BindingFlags.Public | BindingFlags.NonPublic); + if (setEntryAssembly is null) + { + return "Assembly.SetEntryAssembly is not available, so the entry assembly cannot be removed"; + } + try + { + setEntryAssembly.Invoke(null, [null]); + } + catch (Exception e) when (e is not (OutOfMemoryException or StackOverflowException)) + { + return $"Assembly.SetEntryAssembly rejected the call: {e.InnerException?.Message ?? e.Message}"; + } + return Assembly.GetEntryAssembly() is null + ? null + : "Assembly.SetEntryAssembly left an entry assembly in place"; + } + + /// + /// Starts log4net the way an application would, which is what reads the application settings. + /// + /// the number of events that reached the appender + private static int Log() + { + MemoryAppender memory = new() + { + Layout = new PatternLayout("%level %logger %message"), + Threshold = Level.All, + }; + memory.ActivateOptions(); + BasicConfigurator.Configure(memory); + LogManager.GetLogger(typeof(NativeHostCheck)).Info("hello from a host without an entry assembly"); + return memory.GetEvents().Length; + } + + private static void Check(List failures, bool condition, string message) + { + if (!condition) + { + failures.Add(message); + } + } +} diff --git a/src/log4net.Tests.Aot/Program.cs b/src/log4net.Tests.Aot/Program.cs index 5f484cb4a..bbe262cb5 100644 --- a/src/log4net.Tests.Aot/Program.cs +++ b/src/log4net.Tests.Aot/Program.cs @@ -19,6 +19,7 @@ using System; using System.Collections.Generic; +using System.Linq; using System.Reflection; using log4net.Util; @@ -42,8 +43,15 @@ internal static class Program /// internal const string EnvironmentProbeKey = "log4net.AotEnvironmentProbe"; - private static int Main() + private static int Main(string[] args) { + if (args.Contains(NativeHostCheck.Argument)) + { + // Owns the process from here: it has to remove the entry assembly before anything reads a + // setting, so it cannot share a run with the probes. + return NativeHostCheck.Run(); + } + // The probes report their own failures, so log4net's internal error reporting is only noise // here, and a passing run that prints errors reads as a broken one. LogLog.EmitInternalMessages = false; diff --git a/src/log4net.Tests/Layout/PatternLayoutTest.cs b/src/log4net.Tests/Layout/PatternLayoutTest.cs index 81e15d6de..da7cc6e5e 100644 --- a/src/log4net.Tests/Layout/PatternLayoutTest.cs +++ b/src/log4net.Tests/Layout/PatternLayoutTest.cs @@ -21,7 +21,9 @@ using System.Diagnostics.CodeAnalysis; using System.Globalization; using System.IO; +#if NET8_0_OR_GREATER using System.Linq; +#endif using System.Threading; using log4net.Config; using log4net.Core; @@ -37,15 +39,16 @@ namespace log4net.Tests.Layout; /// /// Used for internal unit testing the class. /// -/// -/// Used for internal unit testing the class. -/// [TestFixture] public class PatternLayoutTest { private CultureInfo? _currentCulture; private CultureInfo? _currentUiCulture; + /// + /// Renders in the invariant culture, so that the dates and numbers the tests assert on do not + /// depend on the machine's locale. + /// [SetUp] public void SetUp() { @@ -54,6 +57,10 @@ public void SetUp() _currentUiCulture = Thread.CurrentThread.CurrentUICulture; Thread.CurrentThread.CurrentCulture = Thread.CurrentThread.CurrentUICulture = CultureInfo.InvariantCulture; } + + /// + /// Removes the context property the tests set and restores the culture replaced. + /// [TearDown] public void TearDown() { @@ -63,10 +70,23 @@ public void TearDown() Thread.CurrentThread.CurrentUICulture = _currentUiCulture!; } + /// + /// Creates the layout every test in this fixture renders with. + /// + /// the layout under test protected virtual PatternLayout NewPatternLayout() => new(); + /// + /// Creates the layout every test in this fixture renders with, from a conversion pattern. + /// + /// the conversion pattern + /// the layout under test protected virtual PatternLayout NewPatternLayout(string pattern) => new(pattern); + /// + /// %property{key} renders a value taken from , and the null text while + /// the property is unset or has been removed again. + /// [Test] public void TestThreadPropertiesPattern() { @@ -97,6 +117,9 @@ public void TestThreadPropertiesPattern() stringAppender.Reset(); } + /// + /// %stacktrace{2} names the method that logged the event. + /// [Test] public void TestStackTracePattern() { @@ -115,6 +138,10 @@ public void TestStackTracePattern() stringAppender.Reset(); } + /// + /// %property{key} renders a value taken from , and the null text while + /// the property is unset or has been removed again. + /// [Test] public void TestGlobalPropertiesPattern() { @@ -145,6 +172,10 @@ public void TestGlobalPropertiesPattern() stringAppender.Reset(); } + /// + /// A converter registered with AddConverter is picked up by its name in the conversion + /// pattern. + /// [Test] public void TestAddingCustomPattern() { @@ -167,6 +198,11 @@ public void TestAddingCustomPattern() stringAppender.Reset(); } + /// + /// A without a precision renders the whole name, dots and all. + /// The empty string, a bare dot and a leading or trailing dot are covered, because those are where + /// an off by one in the index arithmetic would show. + /// [Test] public void NamedPatternConverterWithoutPrecisionShouldReturnFullName() { @@ -214,6 +250,10 @@ public void NamedPatternConverterWithoutPrecisionShouldReturnFullName() stringAppender.Reset(); } + /// + /// A precision of 1 keeps the last dot separated component, and leaves a name that ends in a dot, + /// or has no dot at all, as it is. + /// [Test] public void NamedPatternConverterWithPrecision1ShouldStripLeadingStuffIfPresent() { @@ -261,6 +301,9 @@ public void NamedPatternConverterWithPrecision1ShouldStripLeadingStuffIfPresent( stringAppender.Reset(); } + /// + /// A precision of 2 keeps the last two dot separated components. + /// [Test] public void NamedPatternConverterWithPrecision2ShouldStripLessLeadingStuffIfPresent() { @@ -323,6 +366,9 @@ private sealed class TestMessagePatternConverter : PatternLayoutConverter protected override void Convert(TextWriter writer, LoggingEvent loggingEvent) => loggingEvent.WriteRenderedMessage(writer); } + /// + /// %exception{stacktrace} renders the null text rather than the stack trace of the logged exception. + /// [Test] public void TestExceptionPattern() { @@ -343,6 +389,10 @@ public void TestExceptionPattern() stringAppender.Reset(); } + /// + /// Two %utcdate converters in one pattern each render in their own format, and both follow the + /// timestamp of the event rather than reusing what they rendered for the previous one. + /// [Test] public void ConvertMultipleDatePatternsTest() { @@ -364,6 +414,9 @@ public void ConvertMultipleDatePatternsTest() } #if NET8_0_OR_GREATER + /// + /// A date format with microsecond precision renders all six fractional digits. + /// [Test] public void ConvertMicrosecondsPatternTest() { @@ -381,6 +434,10 @@ public void ConvertMicrosecondsPatternTest() Assert.That(stringAppender.GetString(), Is.EqualTo("20250210 13:01:02.123456")); } + /// + /// Microsecond timestamps stay distinct across events logged in a tight loop, so no part of the + /// rendered date is cached between events. + /// [Test] public void ConvertMultipleMicrosecondsPatternTest() { @@ -404,9 +461,14 @@ public void ConvertMultipleMicrosecondsPatternTest() } #endif + /// + /// Converter that treats the message of an event as the name a + /// works on, so that the precision handling can be exercised with arbitrary input. + /// [SuppressMessage("Microsoft.Performance", "CA1812:AvoidUninstantiatedInternalClasses", Justification = "Reflection")] private sealed class MessageAsNamePatternConverter : NamedPatternConverter { + /// protected override string GetFullyQualifiedName(LoggingEvent loggingEvent) => loggingEvent.MessageObject?.ToString() ?? string.Empty; } } \ No newline at end of file diff --git a/src/log4net.Tests/Util/SystemInfoTest.cs b/src/log4net.Tests/Util/SystemInfoTest.cs index fbf544bdc..ebf3a72f3 100644 --- a/src/log4net.Tests/Util/SystemInfoTest.cs +++ b/src/log4net.Tests/Util/SystemInfoTest.cs @@ -274,6 +274,19 @@ public void MissingApplicationAssemblyIsNotTreatedAsAMissingConfigurationSystem( new ConfigurationErrorsException("An error occurred creating the configuration section handler", new FileNotFoundException("Could not load file or assembly", "Contoso.SectionHandlers"))), Is.False); + /// + /// A process that hosts the runtime natively has no entry assembly for the configuration system + /// to derive the config file path from, so it cannot read a config file whatever state that file + /// is in. That is recognised and the environment stands in, rather than being reported as a + /// malformed file on every setting log4net reads. + /// + [Test] + public void NativeHostExceptionIsRecognised() + => Assert.That(IsMissingConfigurationSystem( + new ConfigurationErrorsException("Configuration system failed to initialize", + new PlatformNotSupportedException("Operation is not supported on this platform."))), + Is.True); + private static bool IsMissingConfigurationSystem(Exception exception) { MethodInfo method = typeof(SystemInfo).GetMethod("IsMissingConfigurationSystem", BindingFlags.Static | BindingFlags.NonPublic) diff --git a/src/log4net/Util/SystemInfo.cs b/src/log4net/Util/SystemInfo.cs index eb3c656b1..f71876d7b 100644 --- a/src/log4net/Util/SystemInfo.cs +++ b/src/log4net/Util/SystemInfo.cs @@ -721,12 +721,13 @@ public static bool TryParse(string s, out short val) { if (IsMissingConfigurationSystem(e)) { - // There is no configuration system to read - Native AOT trims System.Configuration away. - // That is a property of the runtime rather than a fault, so it is not reported as an - // error, and the environment stands in for the config file as it does on Android. + // There is no configuration system to read - Native AOT trims System.Configuration away, + // and a native process hosting the runtime has no entry assembly for it to derive the + // config file path from. That is a property of the host rather than a fault, so it is not + // reported as an error, and the environment stands in for the config file as on Android. _configurationSystemUnavailable = true; LogLog.Debug(_declaringType, - "No configuration system on this runtime. Using environment variables for application settings.", e); + "No configuration system on this host. Using environment variables for application settings.", e); return Environment.GetEnvironmentVariable(key); } @@ -746,10 +747,12 @@ public static bool TryParse(string s, out short val) /// if the configuration system itself is unavailable /// /// - /// The inner exceptions have to be walked, because Native AOT surfaces this as a + /// The inner exceptions have to be walked, because the runtime surfaces both cases as a /// - the very type a malformed file produces. What - /// distinguishes it is further down the chain: a for - /// ClientConfigurationHost, whose constructor the trimmer removed. + /// distinguishes them is further down the chain: under Native AOT a + /// for ClientConfigurationHost, whose constructor the + /// trimmer removed, and in a native process hosting the runtime a + /// from ClientConfigPaths. /// /// /// An unrecognized failure is treated as a configuration file problem, which is the safer way @@ -773,6 +776,11 @@ private static bool IsMissingConfigurationSystem(Exception? exception) { switch (exception) { + // The configuration system cannot work out where the config file is, because there is no + // entry assembly to derive its path from. That is what a native process hosting the runtime + // looks like, and no config file can be read there however well formed it is. A malformed + // file never produces this, so it needs no check on which assembly it came from. + case PlatformNotSupportedException: case FileNotFoundException { FileName: string fileName } when IsConfigurationSystem(fileName): case TypeLoadException { TypeName: string typeName }