From d4895f2e4d4775426d168ff12aa7f6850e5d48c5 Mon Sep 17 00:00:00 2001 From: Marko Lahma Date: Wed, 4 Nov 2026 00:04:03 +0200 Subject: [PATCH 1/3] Packet L1: make LogExceptionHandler log again Since the move to Microsoft.Extensions.Logging the handler built the SpEL text "#log.(, #e)" and evaluated it against an ILogger, which has no such instance methods. The evaluation threw, the catch swallowed it with a warning, and nothing was logged. ActionExpressionText is now the message expression. HandleException evaluates it against the call context and logs the result directly with the constant "{Message}" template at LogLevel, in the LogName category, attaching the exception from #e unless LogMessageOnly is set. A failing expression still logs a warning through the handler's own logger and the handler still returns "logged". The set-once guard is gone, the getter returns the expression as assigned, and the "log" context variable is assigned rather than added so several log handlers can share a context. Adds LogExceptionHandlerTests (direct and through ExceptionHandlerAdvice) and replaces the legacy #log.Fatal(...) action in an existing test. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01LGkLQuAuUjvRjrU1AcTsmk Signed-off-by: Marko Lahma --- .../Aspects/Exceptions/LogExceptionHandler.cs | 70 +++-- .../ExceptionHandlerAspectIntegrationTests.cs | 2 +- .../Exception/LogExceptionHandlerTests.cs | 295 ++++++++++++++++++ 3 files changed, 336 insertions(+), 31 deletions(-) create mode 100644 test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs diff --git a/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs b/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs index 2bc123931..01eddcc34 100644 --- a/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs +++ b/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs @@ -20,8 +20,23 @@ namespace Spring.Aspects.Exceptions; /// -/// Log the exceptions. Default log nameis "LogExceptionHandler" and log level is Debug +/// Logs the exceptions that this handler is configured for. +/// Default log name is "LogExceptionHandler" and default log level is . /// +/// +/// +/// The is the Spring expression (SpEL) that produces the log message. It is +/// evaluated against the call context, which provides #method, #args, #target and +/// #e, and the resulting text is written to the logger named at . +/// The exception is attached to the entry unless is set. +/// +/// +/// Earlier versions required the expression to be a call on #log, for example +/// #log.Fatal('message', #e). That form no longer works, because Microsoft.Extensions.Logging's +/// has no such instance methods. Give the message expression only, +/// for example 'message'. +/// +/// /// Mark Pollack public class LogExceptionHandler : AbstractExceptionHandler { @@ -31,10 +46,6 @@ public class LogExceptionHandler : AbstractExceptionHandler private bool logMessageOnly = false; - private bool first = true; - - private string actionExpressionText; - /// /// Initializes a new instance of the class. /// @@ -84,35 +95,23 @@ public bool LogMessageOnly } /// - /// Gets the action translation expression text. Overridden to add approprate settings to - /// the SpEL expression that does the logging so that it depends on the values of LogLevel and - /// LogMessageOnly. Those properties must be set to the desired values before calling this method. - /// + /// Gets or sets the Spring expression (SpEL) that produces the message to log. /// - /// The action translation expression. + /// + /// The getter returns the expression as it was set. Earlier versions returned the expression wrapped in + /// a call on #log, which depended on and having been + /// set first, and ignored every assignment after the first. The level and the message-only setting are now + /// applied when the exception is handled, so the order of property assignments no longer matters. + /// + /// The message expression. public override string ActionExpressionText { - get { return actionExpressionText; } - set - { - if (first) - { - first = false; - string textPart1 = "#log." + LogLevel.ToString() + "(" + value; - if (logMessageOnly) - { - actionExpressionText = textPart1 + ")"; - } - else - { - actionExpressionText = textPart1 + ", #e)"; - } - } - } + get { return base.ActionExpressionText; } + set { base.ActionExpressionText = value; } } /// - /// Handles the exception. + /// Handles the exception by logging the message that evaluates to. /// /// the calling context dictionary /// @@ -122,11 +121,22 @@ public override object HandleException(IDictionary callContextDi { //TODO log name is targettype. ILogger adviceLogger = LogManager.GetLogger(logName); - callContextDictionary.Add("log", adviceLogger); + + // Stays available to user expressions that reference #log; the handler itself does not call it. + // Assigned rather than added, because several log handlers can run against the same call context. + callContextDictionary["log"] = adviceLogger; try { IExpression expression = Expression.Parse(ActionExpressionText); - expression.GetValue(null, callContextDictionary); + object message = expression.GetValue(null, callContextDictionary); + + Exception exception = null; + if (!logMessageOnly && callContextDictionary.TryGetValue("e", out object thrown)) + { + exception = thrown as Exception; + } + + adviceLogger.Log(logLevel, exception, "{Message}", message?.ToString()); } catch (Exception e) { diff --git a/test/Spring/Spring.Aop.Tests/Aspects/Exception/ExceptionHandlerAspectIntegrationTests.cs b/test/Spring/Spring.Aop.Tests/Aspects/Exception/ExceptionHandlerAspectIntegrationTests.cs index 5e4403e4f..a7ccf2145 100644 --- a/test/Spring/Spring.Aop.Tests/Aspects/Exception/ExceptionHandlerAspectIntegrationTests.cs +++ b/test/Spring/Spring.Aop.Tests/Aspects/Exception/ExceptionHandlerAspectIntegrationTests.cs @@ -182,7 +182,7 @@ public void LoggingTestWithConstraintExpressionWithExceptionHandlerInList() LogExceptionHandler exHandler = new LogExceptionHandler(); exHandler.ConstraintExpressionText = "#e is T(System.ArithmeticException)"; exHandler.LogName = "adviceHandler"; - exHandler.ActionExpressionText = "#log.Fatal('Request Timeout occured', #e)"; + exHandler.ActionExpressionText = "'Request Timeout occured'"; ExecuteLoggingHandlerInList(exHandler, "Request Timeout"); } diff --git a/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs b/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs new file mode 100644 index 000000000..eebfde115 --- /dev/null +++ b/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs @@ -0,0 +1,295 @@ +using Microsoft.Extensions.Logging; +using NUnit.Framework; +using Spring.Aop.Framework; +using Spring.Core.TypeConversion; +using Spring.Objects; + +namespace Spring.Aspects.Exceptions; + +/// +/// Tests that writes the entry it is configured for, +/// directly and through . +/// +[TestFixture] +public class LogExceptionHandlerTests +{ + private sealed class LogEntry(string category, LogLevel level, string message, Exception exception) + { + public string Category { get; } = category; + + public LogLevel Level { get; } = level; + + public string Message { get; } = message; + + public Exception Exception { get; } = exception; + } + + private sealed class RecordingLoggerFactory : ILoggerFactory + { + public List Entries { get; } = []; + + public ILogger CreateLogger(string categoryName) => new RecordingLogger(categoryName, Entries); + + public void AddProvider(ILoggerProvider provider) + { + } + + public void Dispose() + { + } + + private sealed class RecordingLogger(string category, List entries) : ILogger + { + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + entries.Add(new LogEntry(category, logLevel, formatter(state, exception), exception)); + } + + public bool IsEnabled(LogLevel logLevel) => true; + + public IDisposable BeginScope(TState state) => null; + } + } + + private ILoggerFactory originalFactory; + private RecordingLoggerFactory loggerFactory; + + [SetUp] + public void SetUp() + { + originalFactory = LogManager.LoggerFactory; + loggerFactory = new RecordingLoggerFactory(); + LogManager.LoggerFactory = loggerFactory; + } + + [TearDown] + public void TearDown() + { + LogManager.LoggerFactory = originalFactory; + loggerFactory.Dispose(); + } + + private static Dictionary CreateCallContext(Exception exception) + { + return new Dictionary + { + ["method"] = typeof(TestObject).GetMethod(nameof(TestObject.Exceptional)), + ["args"] = new object[] { exception }, + ["target"] = new TestObject(), + ["e"] = exception + }; + } + + private static ITestObject CreateProxy(ExceptionHandlerAdvice advice) + { + advice.AfterPropertiesSet(); + ProxyFactory pf = new ProxyFactory(new TestObject()); + pf.AddAdvice(advice); + return (ITestObject) pf.GetProxy(); + } + + [Test] + public void LogsEvaluatedMessageAtConfiguredLevelAndCategoryWithException() + { + var thrown = new ArithmeticException("Bad Math"); + var handler = new LogExceptionHandler + { + LogName = "my.category", + LogLevel = LogLevel.Error, + ActionExpressionText = "'Failed in ' + #method.Name + ': ' + #e.Message" + }; + + object result = handler.HandleException(CreateCallContext(thrown)); + + Assert.That(result, Is.EqualTo("logged")); + Assert.That(loggerFactory.Entries, Has.Count.EqualTo(1)); + LogEntry entry = loggerFactory.Entries[0]; + Assert.That(entry.Category, Is.EqualTo("my.category")); + Assert.That(entry.Level, Is.EqualTo(LogLevel.Error)); + Assert.That(entry.Message, Is.EqualTo("Failed in Exceptional: Bad Math")); + Assert.That(entry.Exception, Is.SameAs(thrown)); + } + + [Test] + public void DefaultsToTraceLevelAndLogExceptionHandlerCategory() + { + var handler = new LogExceptionHandler { ActionExpressionText = "'hello'" }; + + handler.HandleException(CreateCallContext(new InvalidOperationException())); + + Assert.That(loggerFactory.Entries, Has.Count.EqualTo(1)); + Assert.That(loggerFactory.Entries[0].Category, Is.EqualTo("LogExceptionHandler")); + Assert.That(loggerFactory.Entries[0].Level, Is.EqualTo(LogLevel.Trace)); + } + + [Test] + public void LogMessageOnlyDoesNotAttachTheException() + { + var handler = new LogExceptionHandler + { + LogName = "my.category", + LogLevel = LogLevel.Warning, + LogMessageOnly = true, + ActionExpressionText = "'only the message'" + }; + + handler.HandleException(CreateCallContext(new ArithmeticException("Bad Math"))); + + Assert.That(loggerFactory.Entries, Has.Count.EqualTo(1)); + Assert.That(loggerFactory.Entries[0].Message, Is.EqualTo("only the message")); + Assert.That(loggerFactory.Entries[0].Level, Is.EqualTo(LogLevel.Warning)); + Assert.That(loggerFactory.Entries[0].Exception, Is.Null); + } + + [TestCase("Info", LogLevel.Information)] + [TestCase("Warn", LogLevel.Warning)] + [TestCase("Fatal", LogLevel.Critical)] + [TestCase("Debug", LogLevel.Debug)] + public void LegacyLevelNamesConvertedByLogLevelConverterAreHonoured(string levelName, LogLevel expected) + { + var level = (LogLevel) TypeConverterRegistry.GetConverter(typeof(LogLevel)).ConvertFromInvariantString(levelName); + var handler = new LogExceptionHandler + { + LogName = "my.category", + LogLevel = level, + ActionExpressionText = "'legacy level'" + }; + + handler.HandleException(CreateCallContext(new ArithmeticException())); + + Assert.That(loggerFactory.Entries, Has.Count.EqualTo(1)); + Assert.That(loggerFactory.Entries[0].Level, Is.EqualTo(expected)); + Assert.That(loggerFactory.Entries[0].Message, Is.EqualTo("legacy level")); + } + + [Test] + public void PropertyOrderAndRepeatedAssignmentDoNotMatter() + { + var handler = new LogExceptionHandler(); + handler.ActionExpressionText = "'first'"; + handler.LogName = "my.category"; + handler.LogLevel = LogLevel.Critical; + handler.ActionExpressionText = "'second'"; + + Assert.That(handler.ActionExpressionText, Is.EqualTo("'second'")); + handler.HandleException(CreateCallContext(new ArithmeticException())); + + Assert.That(loggerFactory.Entries, Has.Count.EqualTo(1)); + Assert.That(loggerFactory.Entries[0].Message, Is.EqualTo("second")); + Assert.That(loggerFactory.Entries[0].Level, Is.EqualTo(LogLevel.Critical)); + } + + [Test] + public void InvalidMessageExpressionLogsWarningAndDoesNotThrow() + { + var handler = new LogExceptionHandler + { + LogName = "my.category", + LogLevel = LogLevel.Error, + ActionExpressionText = "#e.NoSuchProperty.Foo" + }; + + object result = null; + Assert.DoesNotThrow(() => result = handler.HandleException(CreateCallContext(new ArithmeticException()))); + + Assert.That(result, Is.EqualTo("logged")); + Assert.That(loggerFactory.Entries.Where(e => e.Category == "my.category"), Is.Empty); + LogEntry warning = loggerFactory.Entries.Single(); + Assert.That(warning.Level, Is.EqualTo(LogLevel.Warning)); + Assert.That(warning.Category, Does.Contain(nameof(LogExceptionHandler))); + Assert.That(warning.Message, Does.Contain("Was not able to evaluate action expression [#e.NoSuchProperty.Foo]")); + Assert.That(warning.Exception, Is.Not.Null); + } + + [Test] + public void SeveralLogHandlersCanShareACallContext() + { + var context = CreateCallContext(new ArithmeticException()); + var first = new LogExceptionHandler { LogName = "first", ActionExpressionText = "'one'" }; + var second = new LogExceptionHandler { LogName = "second", ActionExpressionText = "'two'" }; + + first.HandleException(context); + second.HandleException(context); + + Assert.That(loggerFactory.Entries.Select(e => e.Category + "=" + e.Message), Is.EqualTo(new[] { "first=one", "second=two" })); + } + + [Test] + public void DslLogActionThroughAdviceLogsMessageForProxiedMethodThatThrows() + { + var advice = new ExceptionHandlerAdvice(); + advice.ExceptionHandlers.Add("on exception name ArithmeticException log 'Hello ' + #method.Name"); + ITestObject proxy = CreateProxy(advice); + var thrown = new ArithmeticException("Bad Math"); + + var rethrown = Assert.Throws(() => proxy.Exceptional(thrown)); + + Assert.That(rethrown, Is.SameAs(thrown)); + + Assert.That(loggerFactory.Entries, Has.Count.EqualTo(1)); + LogEntry entry = loggerFactory.Entries[0]; + Assert.That(entry.Category, Is.EqualTo("LogExceptionHandler")); + Assert.That(entry.Level, Is.EqualTo(LogLevel.Trace)); + Assert.That(entry.Message, Is.EqualTo("Hello Exceptional")); + Assert.That(entry.Exception, Is.SameAs(thrown)); + } + + [Test] + public void DslLogActionWithConstraintExpressionThroughAdviceLogsMessage() + { + var advice = new ExceptionHandlerAdvice(); + advice.ExceptionHandlers.Add("on exception (#e is T(System.ArithmeticException)) log 'Constrained ' + #e.Message"); + ITestObject proxy = CreateProxy(advice); + + Assert.Throws(() => proxy.Exceptional(new ArithmeticException("Bad Math"))); + + Assert.That(loggerFactory.Entries.Single().Message, Is.EqualTo("Constrained Bad Math")); + } + + [Test] + public void ConfiguredHandlerTemplateKeyedAsLogSuppliesLevelCategoryAndMessageOnlyToDslAction() + { + var template = new LogExceptionHandler + { + LogName = "configured.category", + LogLevel = LogLevel.Warning, + LogMessageOnly = true + }; + var advice = new ExceptionHandlerAdvice(); + advice.ExceptionHandlerDictionary.Add("log", template); + advice.ExceptionHandlers.Add("on exception name ArithmeticException log 'Template ' + #method.Name"); + ITestObject proxy = CreateProxy(advice); + + Assert.Throws(() => proxy.Exceptional(new ArithmeticException())); + + LogEntry entry = loggerFactory.Entries.Single(); + Assert.That(entry.Category, Is.EqualTo("configured.category")); + Assert.That(entry.Level, Is.EqualTo(LogLevel.Warning)); + Assert.That(entry.Message, Is.EqualTo("Template Exceptional")); + Assert.That(entry.Exception, Is.Null); + } + + [Test] + public void ExplicitHandlerInAdviceListLogsAndLetsLaterHandlersRun() + { + var handler = new LogExceptionHandler + { + LogName = "my.category", + LogLevel = LogLevel.Error, + ActionExpressionText = "'Logged ' + #e.Message" + }; + handler.SourceExceptionNames.Add("ArithmeticException"); + var advice = new ExceptionHandlerAdvice(); + advice.ExceptionHandlers.Add(handler); + advice.ExceptionHandlers.Add("on exception name ArithmeticException wrap System.InvalidOperationException 'Wrapped'"); + ITestObject proxy = CreateProxy(advice); + + var wrapped = Assert.Throws(() => proxy.Exceptional(new ArithmeticException("Bad Math"))); + + Assert.That(wrapped.Message, Is.EqualTo("Wrapped")); + LogEntry entry = loggerFactory.Entries.Single(); + Assert.That(entry.Category, Is.EqualTo("my.category")); + Assert.That(entry.Level, Is.EqualTo(LogLevel.Error)); + Assert.That(entry.Message, Is.EqualTo("Logged Bad Math")); + } +} From 69614e7d0e818e8077667434f09cdb7635addd04 Mon Sep 17 00:00:00 2001 From: Marko Lahma Date: Wed, 4 Nov 2026 00:12:28 +0200 Subject: [PATCH 2/3] Packet L1 follow-ups: breaking-change note, #log. hint, honest tests - BreakingChanges.txt item 10: LogExceptionHandler.ActionExpressionText is now the message expression only. - Fix the history note in the XML doc. - When the expression fails and starts with "#log.", warn that the form is no longer supported instead of the generic message. - Log the message outside the try, so a failing logging provider is not reported as an expression failure; test a null-valued expression. - ExceptionHandlerAspectIntegrationTests: assert exact message, level and category instead of substrings that the failure warning could satisfy, and use Assert.Throws instead of try/catch helpers that asserted nothing when no exception was thrown. This also exposed that ExecuteSpelAction never executed its action (unresolvable type name); it now uses T(type, assembly). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01LGkLQuAuUjvRjrU1AcTsmk Signed-off-by: Marko Lahma --- BreakingChanges.txt | 9 ++ .../Aspects/Exceptions/LogExceptionHandler.cs | 37 +++-- .../ExceptionHandlerAspectIntegrationTests.cs | 146 ++++++++---------- .../Exception/LogExceptionHandlerTests.cs | 76 +++++++++ 4 files changed, 172 insertions(+), 96 deletions(-) diff --git a/BreakingChanges.txt b/BreakingChanges.txt index 15e641bc1..dc201a68d 100644 --- a/BreakingChanges.txt +++ b/BreakingChanges.txt @@ -110,6 +110,15 @@ Changes (3.1 to 4.0) - Spring.Testing.Microsoft requires MSTest.TestFramework 4.5.2 or later (was 3.4.3). The base classes are source compatible with it, and build for netstandard2.0, net472 and net10.0. +10. LogExceptionHandler.ActionExpressionText is now the message expression only. The level and the + exception come from LogLevel and LogMessageOnly, and the getter returns the expression as set, + not the #log.(...) wrapper it used to return. A handler configured with + #log.Fatal('msg', #e) no longer logs: that form worked on 3.0.2 and earlier only by accident of + nesting, and nothing has been logged by it since 3.0.3, when logging moved to + Microsoft.Extensions.Logging. It now writes a warning that says so. To migrate: + - Before: ActionExpressionText="#log.Fatal('msg', #e)" + - After: ActionExpressionText="'msg'" LogLevel="Critical" + Changes (3.0.x to 3.1) ======================== diff --git a/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs b/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs index 01eddcc34..2705428d7 100644 --- a/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs +++ b/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs @@ -31,10 +31,11 @@ namespace Spring.Aspects.Exceptions; /// The exception is attached to the entry unless is set. /// /// -/// Earlier versions required the expression to be a call on #log, for example -/// #log.Fatal('message', #e). That form no longer works, because Microsoft.Extensions.Logging's -/// has no such instance methods. Give the message expression only, -/// for example 'message'. +/// Before 3.0.3 an expression such as #log.Fatal('message', #e) also worked, by accident of nesting; +/// it has not since the switch to Microsoft.Extensions.Logging, whose +/// has no such instance methods. Give the message expression +/// only, for example 'message'. A failing expression that starts with #log. is reported with a +/// warning that names this form. /// /// /// Mark Pollack @@ -125,24 +126,36 @@ public override object HandleException(IDictionary callContextDi // Stays available to user expressions that reference #log; the handler itself does not call it. // Assigned rather than added, because several log handlers can run against the same call context. callContextDictionary["log"] = adviceLogger; + object message; try { IExpression expression = Expression.Parse(ActionExpressionText); - object message = expression.GetValue(null, callContextDictionary); - - Exception exception = null; - if (!logMessageOnly && callContextDictionary.TryGetValue("e", out object thrown)) + message = expression.GetValue(null, callContextDictionary); + } + catch (Exception e) + { + if (ActionExpressionText != null && ActionExpressionText.StartsWith("#log.", StringComparison.Ordinal)) { - exception = thrown as Exception; + log.LogWarning( + e, + "The '#log.(...)' form is no longer supported; set ActionExpressionText to the message expression and LogLevel to the level. Was not able to evaluate action expression [{ActionExpression}]", + ActionExpressionText); + } + else + { + log.LogWarning(e, "Was not able to evaluate action expression [{ActionExpression}]", ActionExpressionText); } - adviceLogger.Log(logLevel, exception, "{Message}", message?.ToString()); + return "logged"; } - catch (Exception e) + + Exception exception = null; + if (!logMessageOnly && callContextDictionary.TryGetValue("e", out object thrown)) { - log.LogWarning(e, "Was not able to evaluate action expression [{ActionExpression}]", ActionExpressionText); + exception = thrown as Exception; } + adviceLogger.Log(logLevel, exception, "{Message}", message?.ToString()); return "logged"; } } diff --git a/test/Spring/Spring.Aop.Tests/Aspects/Exception/ExceptionHandlerAspectIntegrationTests.cs b/test/Spring/Spring.Aop.Tests/Aspects/Exception/ExceptionHandlerAspectIntegrationTests.cs index a7ccf2145..bf61090e8 100644 --- a/test/Spring/Spring.Aop.Tests/Aspects/Exception/ExceptionHandlerAspectIntegrationTests.cs +++ b/test/Spring/Spring.Aop.Tests/Aspects/Exception/ExceptionHandlerAspectIntegrationTests.cs @@ -44,9 +44,20 @@ public void Setup() exceptionHandlerAdvice = new ExceptionHandlerAdvice(); } + public sealed class CapturedEvent(string category, LogLevel level, string message) + { + public string Category { get; } = category; + + public LogLevel Level { get; } = level; + + public string Message { get; } = message; + + public override string ToString() => $"{Level} {Category}: {Message}"; + } + public class CapturingLoggerFactory : ILoggerFactory { - public List LoggerEvents { get; set; } = []; + public List LoggerEvents { get; set; } = []; public void Dispose() { @@ -54,15 +65,15 @@ public void Dispose() public ILogger CreateLogger(string categoryName) { - return new CapturingLogger(LoggerEvents); + return new CapturingLogger(categoryName, LoggerEvents); } - public class CapturingLogger(List loggedEvents) : ILogger + public class CapturingLogger(string category, List loggedEvents) : ILogger { public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { var message = formatter(state, exception); - loggedEvents.Add(message); + loggedEvents.Add(new CapturedEvent(category, logLevel, message)); } public bool IsEnabled(LogLevel logLevel) @@ -96,17 +107,14 @@ public void TearDown() public void ExecuteSpelAction() { string executeHandlerText = - "on exception name ArithmeticException execute Spring.Aspects.Exceptions.ExceptionHandlerAspectIntegrationTests.Executed(true)"; + "on exception name ArithmeticException execute T(Spring.Aspects.Exceptions.ExceptionHandlerAspectIntegrationTests, Spring.Aop.Tests).Executed(true)"; ITestObject to = CreateTestObjectProxy(executeHandlerText); + spelActionExecuted = false; - try - { - to.Exceptional(new ArithmeticException()); - } - catch (ArithmeticException) - { - Assert.That(spelActionExecuted, Is.True); - } + // The execute action returns null, which the advice treats as handled: the exception is not rethrown. + Assert.DoesNotThrow(() => to.Exceptional(new ArithmeticException())); + + Assert.That(spelActionExecuted, Is.True, "Logged: " + string.Join("; ", loggerFactory.LoggerEvents)); } public static void Executed(bool val) @@ -132,24 +140,10 @@ public void LoggingTest() pf.AddAdvice(exceptionHandlerAdvice); ITestObject to = (ITestObject) pf.GetProxy(); - try - { - to.Exceptional(new ArithmeticException()); - Assert.Fail("Should have thrown exception when only logging"); - } - catch (ArithmeticException) - { - bool found = false; - foreach (var loggerEvent in loggerFactory.LoggerEvents) - { - if (loggerEvent.IndexOf("Hello World") >= 0) - { - found = true; - } - } + var thrown = new ArithmeticException("Bad Math"); + Assert.Throws(() => to.Exceptional(thrown), "Should have thrown exception when only logging"); - Assert.That(found, Is.True, "did not find logging output"); - } + AssertLogged("Hello World, exception message = Bad Math, target method = Exceptional", LogLevel.Trace, "adviceHandler"); } [Test] @@ -157,7 +151,7 @@ public void LoggingTestWithString() { string logHandlerText = "on exception name ArithmeticException log 'My Message, Method Name ' + #method.Name"; - ExecuteLoggingHandler(logHandlerText, "My Message"); + ExecuteLoggingHandler(logHandlerText, "My Message, Method Name Exceptional", LogLevel.Trace, "LogExceptionHandler"); } [Test] @@ -165,7 +159,7 @@ public void LoggingTestWithStringExplicitHandler() { string logHandlerText = "on exception name ArithmeticException log 'My Message, Method Name ' + #method.Name"; - ExecuteLoggingHandler(logHandlerText, "My Message"); + ExecuteLoggingHandler(logHandlerText, "My Message, Method Name Exceptional", LogLevel.Trace, "LogExceptionHandler"); } [Test] @@ -173,7 +167,7 @@ public void LoggingTestWithConstraintExpression() { string logHandlerText = "on exception (#e is T(System.ArithmeticException)) log 'My Message, Method Name ' + #method.Name"; - ExecuteLoggingHandler(logHandlerText, "My Message"); + ExecuteLoggingHandler(logHandlerText, "My Message, Method Name Exceptional", LogLevel.Trace, "LogExceptionHandler"); } [Test] @@ -182,17 +176,26 @@ public void LoggingTestWithConstraintExpressionWithExceptionHandlerInList() LogExceptionHandler exHandler = new LogExceptionHandler(); exHandler.ConstraintExpressionText = "#e is T(System.ArithmeticException)"; exHandler.LogName = "adviceHandler"; + exHandler.LogLevel = LogLevel.Critical; exHandler.ActionExpressionText = "'Request Timeout occured'"; - ExecuteLoggingHandlerInList(exHandler, "Request Timeout"); + ITestObject to = CreateTestObjectProxyInList(exHandler); + + Assert.Throws(() => to.Exceptional(new ArithmeticException())); + + AssertLogged("Request Timeout occured", LogLevel.Critical, "adviceHandler"); } [Test] public void LoggingTestWithConstraintExpressionWithKeyedExceptionHandler() { LogExceptionHandler exHandler = new LogExceptionHandler(); - ExecuteLoggingHandlerWithKeyedLogHandler(exHandler, - @"on exception (#e is T(System.ArithmeticException)) log 'Request Timeout occured'", "Request Timeout"); + ITestObject to = CreateTestObjectProxyWithKeyedHandler(exHandler, + @"on exception (#e is T(System.ArithmeticException)) log 'Request Timeout occured'"); + + Assert.Throws(() => to.Exceptional(new ArithmeticException())); + + AssertLogged("Request Timeout occured", LogLevel.Trace, "LogExceptionHandler"); } [Test] @@ -200,7 +203,7 @@ public void LoggingTestWithBadString() { string logHandlerText = "on foobar name ArithmeticException log 'My Message, Method Name ' + #method.Name"; - Assert.Throws(() => ExecuteLoggingHandler(logHandlerText, "My Message")); + Assert.Throws(() => CreateTestObjectProxy(logHandlerText)); } [Test] @@ -208,7 +211,7 @@ public void LoggingTestWithInvalidConstraintExpression() { string logHandlerText = "on exception (#e is System.FooBar) log 'My Message, Method Name ' + #method.Name"; - ExecuteLoggingHandler(logHandlerText, "Was not able to evaluate constraint expression [#e is System.FooBar]"); + ExecuteLoggingHandler(logHandlerText, "Was not able to evaluate constraint expression [#e is System.FooBar]", LogLevel.Warning, typeof(LogExceptionHandler).FullName, expectMessageLogged: false); } [Test] @@ -216,48 +219,24 @@ public void LoggingTestWithNonBooleanConstraintExpression() { string logHandlerText = "on exception (1+1) log 'My Message, Method Name ' + #method.Name"; - ExecuteLoggingHandler(logHandlerText, "Was not able to unbox constraint expression to boolean [1+1]"); + ExecuteLoggingHandler(logHandlerText, "Was not able to unbox constraint expression to boolean [1+1]", LogLevel.Warning, typeof(LogExceptionHandler).FullName, expectMessageLogged: false); } - private void ExecuteLoggingHandler(string logHandlerText, string searchString) + /// + /// Runs a proxied method that throws and checks that exactly the expected entry was written. + /// A handler whose constraint can't be evaluated reports a warning and logs no message, + /// which false checks for. + /// + private void ExecuteLoggingHandler(string logHandlerText, string expectedMessage, LogLevel expectedLevel, string expectedCategory, bool expectMessageLogged = true) { ITestObject to = CreateTestObjectProxy(logHandlerText); - try - { - to.Exceptional(new ArithmeticException()); - } - catch (ArithmeticException) - { - AssertSearchString(searchString); - } - } - - private void ExecuteLoggingHandlerInList(IExceptionHandler handler, string searchString) - { - ITestObject to = CreateTestObjectProxyInList(handler); + Assert.Throws(() => to.Exceptional(new ArithmeticException())); - try - { - to.Exceptional(new ArithmeticException()); - } - catch (ArithmeticException) + AssertLogged(expectedMessage, expectedLevel, expectedCategory); + if (!expectMessageLogged) { - AssertSearchString(searchString); - } - } - - private void ExecuteLoggingHandlerWithKeyedLogHandler(IExceptionHandler handler, string handlerText, string searchString) - { - ITestObject to = CreateTestObjectProxyWithKeyedHandler(handler, handlerText); - - try - { - to.Exceptional(new ArithmeticException()); - } - catch (ArithmeticException) - { - AssertSearchString(searchString); + Assert.That(loggerFactory.LoggerEvents.Where(e => e.Message.StartsWith("My Message")), Is.Empty); } } @@ -501,18 +480,17 @@ private ITestObject CreateProxy() return (ITestObject) pf.GetProxy(); } - private void AssertSearchString(string searchString) + /// + /// Asserts that exactly one entry was written with this message, level and category. + /// The message must match exactly, so the warning that a failed expression produces can't stand in for it. + /// + private void AssertLogged(string expectedMessage, LogLevel expectedLevel, string expectedCategory) { - bool found = false; - foreach (var loggerEvent in loggerFactory.LoggerEvents) - { - if (loggerEvent.IndexOf(searchString) >= 0) - { - found = true; - } - } + var matches = loggerFactory.LoggerEvents + .Where(e => e.Message == expectedMessage && e.Level == expectedLevel && e.Category == expectedCategory) + .ToList(); - Assert.That(found, Is.True, "did not find logging output [" + searchString + "] Logging values = " - + StringUtils.CollectionToCommaDelimitedString(loggerFactory.LoggerEvents)); + Assert.That(matches, Has.Count.EqualTo(1), "did not find logging output [" + expectedMessage + "] Logging values = " + + StringUtils.CollectionToCommaDelimitedString(loggerFactory.LoggerEvents)); } } diff --git a/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs b/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs index eebfde115..64d07279e 100644 --- a/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs +++ b/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs @@ -201,6 +201,82 @@ public void InvalidMessageExpressionLogsWarningAndDoesNotThrow() Assert.That(warning.Exception, Is.Not.Null); } + [Test] + public void LegacyLogCallFormLogsSpecificWarningAndDoesNotThrow() + { + var handler = new LogExceptionHandler + { + LogName = "my.category", + ActionExpressionText = "#log.Fatal('msg', #e)" + }; + + object result = null; + Assert.DoesNotThrow(() => result = handler.HandleException(CreateCallContext(new ArithmeticException()))); + + Assert.That(result, Is.EqualTo("logged")); + LogEntry warning = loggerFactory.Entries.Single(); + Assert.That(warning.Level, Is.EqualTo(LogLevel.Warning)); + Assert.That(warning.Category, Does.Contain(nameof(LogExceptionHandler))); + Assert.That(warning.Message, Does.Contain("The '#log.(...)' form is no longer supported")); + Assert.That(warning.Message, Does.Contain("[#log.Fatal('msg', #e)]")); + Assert.That(warning.Exception, Is.Not.Null); + } + + [Test] + public void MessageExpressionEvaluatingToNullLogsWithoutThrowing() + { + var thrown = new ArithmeticException(); + var handler = new LogExceptionHandler + { + LogName = "my.category", + LogLevel = LogLevel.Error, + ActionExpressionText = "null" + }; + + object result = null; + Assert.DoesNotThrow(() => result = handler.HandleException(CreateCallContext(thrown))); + + Assert.That(result, Is.EqualTo("logged")); + LogEntry entry = loggerFactory.Entries.Single(); + Assert.That(entry.Category, Is.EqualTo("my.category")); + Assert.That(entry.Level, Is.EqualTo(LogLevel.Error)); + Assert.That(entry.Exception, Is.SameAs(thrown)); + } + + [Test] + public void FailureOfTheLoggingProviderIsNotReportedAsAnExpressionFailure() + { + LogManager.LoggerFactory = new ThrowingLoggerFactory(); + var handler = new LogExceptionHandler { LogName = "my.category", ActionExpressionText = "'msg'" }; + + Assert.Throws(() => handler.HandleException(CreateCallContext(new ArithmeticException()))); + } + + private sealed class ThrowingLoggerFactory : ILoggerFactory + { + public ILogger CreateLogger(string categoryName) => new ThrowingLogger(); + + public void AddProvider(ILoggerProvider provider) + { + } + + public void Dispose() + { + } + + private sealed class ThrowingLogger : ILogger + { + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + throw new InvalidOperationException("provider failure"); + } + + public bool IsEnabled(LogLevel logLevel) => true; + + public IDisposable BeginScope(TState state) => null; + } + } + [Test] public void SeveralLogHandlersCanShareACallContext() { From eaa5b86bfba32b3bd8b9e9f206ea8662dbd0b771 Mon Sep 17 00:00:00 2001 From: Marko Lahma Date: Wed, 4 Nov 2026 00:14:30 +0200 Subject: [PATCH 3/3] Don't let a failing logging provider replace the advised method's exception Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01LGkLQuAuUjvRjrU1AcTsmk Signed-off-by: Marko Lahma --- .../Aspects/Exceptions/LogExceptionHandler.cs | 11 ++++++++++- .../Aspects/Exception/LogExceptionHandlerTests.cs | 15 ++++++++++++--- 2 files changed, 22 insertions(+), 4 deletions(-) diff --git a/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs b/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs index 2705428d7..774479269 100644 --- a/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs +++ b/src/Spring/Spring.Aop/Aspects/Exceptions/LogExceptionHandler.cs @@ -155,7 +155,16 @@ public override object HandleException(IDictionary callContextDi exception = thrown as Exception; } - adviceLogger.Log(logLevel, exception, "{Message}", message?.ToString()); + // A failing logging provider must not replace the exception the advised method threw. + try + { + adviceLogger.Log(logLevel, exception, "{Message}", message?.ToString()); + } + catch (Exception e) + { + log.LogWarning(e, "Was not able to write the log entry for action expression [{ActionExpression}]", ActionExpressionText); + } + return "logged"; } } diff --git a/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs b/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs index 64d07279e..37e897e94 100644 --- a/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs +++ b/test/Spring/Spring.Aop.Tests/Aspects/Exception/LogExceptionHandlerTests.cs @@ -244,12 +244,21 @@ public void MessageExpressionEvaluatingToNullLogsWithoutThrowing() } [Test] - public void FailureOfTheLoggingProviderIsNotReportedAsAnExpressionFailure() + public void FailureOfTheLoggingProviderIsReportedAndDoesNotReplaceTheException() { - LogManager.LoggerFactory = new ThrowingLoggerFactory(); + // The handler's own logger comes from the recording factory; only the advice logger, + // resolved per call, comes from the failing one. var handler = new LogExceptionHandler { LogName = "my.category", ActionExpressionText = "'msg'" }; + LogManager.LoggerFactory = new ThrowingLoggerFactory(); + + object result = null; + Assert.DoesNotThrow(() => result = handler.HandleException(CreateCallContext(new ArithmeticException()))); - Assert.Throws(() => handler.HandleException(CreateCallContext(new ArithmeticException()))); + Assert.That(result, Is.EqualTo("logged")); + LogEntry warning = loggerFactory.Entries.Single(); + Assert.That(warning.Level, Is.EqualTo(LogLevel.Warning)); + Assert.That(warning.Message, Is.EqualTo("Was not able to write the log entry for action expression ['msg']")); + Assert.That(warning.Exception, Is.TypeOf()); } private sealed class ThrowingLoggerFactory : ILoggerFactory