Support logging exception stack traces when the last argument is Throwable #3960

raccoonback · 2025-01-02T15:49:34Z

Motivation

Hello,

Reactor Core supports SLF4J, Console Logger, and JDK Logger.
In SLF4J implementations (e.g., Logback), when the last argument is of type Throwable, the exception stack trace is automatically logged, as shown below.
(ref. SLF4J FAQ)
(ref: Logback implementation)

log.info("An error occurred: {}", "details", new Exception("Sample exception"));

However, the Console Logger and JDK Logger supported by Reactor Core do not provide this functionality, and users must manually check for Throwable and handle it accordingly in their code.

	@Test
	void useVerboseConsoleLoggers() throws Exception {
		try {
			Loggers.useVerboseConsoleLoggers();
			Logger l = Loggers.getLogger("test");

			l.debug("Processing data for user: {}", "user123", new Exception("Sample exception"));
		}
		finally {
			Loggers.resetLoggerFactory();
		        ReactorLauncherSessionListener.resetLoggersFactory();
		}
	}

[DEBUG] (Test worker) Processing data for user: user123

This results in unnecessary branching in user code and decreases consistency across logging mechanisms.

Therefore, in this change, we have modified the ConsoleLogger and JdkLogger to detect if the last argument is of type Throwable and automatically log the exception stack trace.

Description

This PR enhances the logging functionality in Reactor Core to check if the last argument in logger methods is of type Throwable. If a Throwable is detected, the exception stack trace is included in the log output.

Key Changes

Added logic to inspect the last argument in logger method calls.
Automatically handles Throwable instances for improved debugging.
Ensures compatibility with existing SLF4J-style message formatting for consistency across logging frameworks.

Example Usage

log.info("Processing data for user: {}", "user123", new Exception("Sample exception"));

Before

INFO: Processing data for user: user123

After

INFO: Processing data for user: user123
java.lang.Exception: Sample exception
    at ...

Benefits

Aligns Reactor's logging capabilities with familiar SLF4J-style formatting.
Simplifies exception handling for developers using JDK or Console Loggers.
Improves traceability and debugging in complex systems.

Testing

	@Test
	void useVerboseConsoleLoggers() throws Exception {
		try {
			Loggers.useVerboseConsoleLoggers();
			Logger l = Loggers.getLogger("test");

			l.debug("Processing data for user: {}", "user123", new Exception("Sample exception"));
		}
		finally {
			Loggers.resetLoggerFactory();
		        ReactorLauncherSessionListener.resetLoggersFactory();
		}
	}

	@Test
	void useJdkLoggers() throws Exception {
		try {
			Loggers.useJdkLoggers();
			Logger l = Loggers.getLogger("test");

			l.debug("Processing data for user: {}", "user123", new Exception("Sample exception"));
		}
		finally {
			Loggers.resetLoggerFactory();
		        ReactorLauncherSessionListener.resetLoggersFactory();
		}
	}

raccoonback · 2025-01-02T23:41:17Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		private boolean isLastElementThrowable(Object... arguments) {
+			int length = arguments.length;
+			return length > 0 && arguments[length - 1] instanceof Throwable;
+		}


Checks whether the last argements are of type Throwable.

raccoonback · 2025-01-02T23:43:06Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		private void logWithOptionalThrowable(Level level, String format, Object... arguments) {
+			if(isLastElementThrowable(arguments)) {
+				int lastIndex = arguments.length - 1;
+				Object[] args = Arrays.copyOfRange(arguments, 0, lastIndex);
+				Throwable t = (Throwable) arguments[lastIndex];
+
+				logger.log(level, format(format, args), t);
+				return;
+			}
+
+			logger.log(level, format(format, arguments));
+		}


In JdkLogger, if the last arguments are Throwable type, stacktrace is also logged.

I'd love to see a test for this.

raccoonback · 2025-01-02T23:43:22Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		private boolean isLastElementThrowable(Object... arguments) {
+			int length = arguments.length;
+			return length > 0 && arguments[length - 1] instanceof Throwable;
+		}


Checks whether the last argements are of type Throwable.

raccoonback · 2025-01-02T23:45:53Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		private synchronized void logWithOptionalThrowable(String level, String format, Object... arguments) {
+			if(isLastElementThrowable(arguments)) {
+				int lastIndex = arguments.length - 1;
+				Object[] args = Arrays.copyOfRange(arguments, 0, lastIndex);
+				Throwable t = (Throwable) arguments[lastIndex];
+
+				this.log.format("[%s] (%s) %s\n", level.toUpperCase(), Thread.currentThread().getName(), format(format, args));
+				t.printStackTrace(this.log);
+				return;
+			}
+
+			this.log.format("[%s] (%s) %s\n", level.toUpperCase(), Thread.currentThread().getName(), format(format, arguments));
+		}


In ConsoleLogger, if the last argument is of type Throwable, it also prints a stack trace.
(only use for TRACE, DEBUG, INFO level)

Can we have tests to validate this?

I have added test code!

raccoonback · 2025-01-02T23:48:31Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		private synchronized void logErrorWithOptionalThrowable(String level, String format, Object... arguments) {
+			if(isLastElementThrowable(arguments)) {
+				int lastIndex = arguments.length - 1;
+				Object[] args = Arrays.copyOfRange(arguments, 0, lastIndex);
+				Throwable t = (Throwable) arguments[lastIndex];
+
+				this.err.format("[%s] (%s) %s\n", level.toUpperCase(), Thread.currentThread().getName(), format(format, args));
+				t.printStackTrace(this.err);
+				return;
+			}
+
+			this.err.format("[%s] (%s) %s\n", level.toUpperCase(), Thread.currentThread().getName(), format(format, arguments));
+		}


In ConsoleLogger, if the last arguments are Throwable type, it also prints a stack trace with the err PrintStream.
(only use for WARN, ERROR level)

raccoonback · 2025-01-22T16:25:52Z

@chemicL
Hello!
Could you please take a look at this PR?
The review seems to be delayed, so I would greatly appreciate your confirmation.
Thank you!

chemicL

Thank you for the proposal. I've been occupied with other priority subjects and now found the time to review the PR. I think it is a useful utility. I left some comments, please address them if you'd like to integrate this change. Most importantly, I look forward to tests validating the change has some meaningful effect.

chemicL · 2025-01-30T10:41:48Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		private void logWithOptionalThrowable(Level level, String format, Object... arguments) {
+			if(isLastElementThrowable(arguments)) {
+				int lastIndex = arguments.length - 1;
+				Object[] args = Arrays.copyOfRange(arguments, 0, lastIndex);


Let's try to avoid copying the array, it isn't necessary.

chemicL · 2025-01-30T10:43:46Z

reactor-core/src/main/java/reactor/util/Loggers.java

+				Object[] args = Arrays.copyOfRange(arguments, 0, lastIndex);
+				Throwable t = (Throwable) arguments[lastIndex];
+
+				logger.log(level, format(format, args), t);


I'd suggest changing the way the format method works to optionally exclude the last element in case we know it's a Throwable. Pseudocode:

Throwable t = getPotentialThrowable(arguments); if (t != null) logger.log(level, format(format, arguments, true), t); else logger.log(level, format(format, arguments));

The existing format method would then delegate to the one with an optional boolean skipLast argument with false.

The getPotentialThrowable would be similar to isLastElementThrowable but would return the value or null.

I added the skipLast parameter to the format(...) method. Since Varargs must be placed at the end, I added skipLast as a middle parameter.
Additionally, I overloaded the existing method.

chemicL · 2025-01-31T10:28:31Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		private void logWithOptionalThrowable(Level level, String format, Object... arguments) {
+			if(isLastElementThrowable(arguments)) {
+				int lastIndex = arguments.length - 1;
+				Object[] args = Arrays.copyOfRange(arguments, 0, lastIndex);
+				Throwable t = (Throwable) arguments[lastIndex];
+
+				logger.log(level, format(format, args), t);
+				return;
+			}
+
+			logger.log(level, format(format, arguments));
+		}


I'd love to see a test for this.

chemicL · 2025-01-31T10:29:01Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		private synchronized void logWithOptionalThrowable(String level, String format, Object... arguments) {
+			if(isLastElementThrowable(arguments)) {
+				int lastIndex = arguments.length - 1;
+				Object[] args = Arrays.copyOfRange(arguments, 0, lastIndex);
+				Throwable t = (Throwable) arguments[lastIndex];
+
+				this.log.format("[%s] (%s) %s\n", level.toUpperCase(), Thread.currentThread().getName(), format(format, args));
+				t.printStackTrace(this.log);
+				return;
+			}
+
+			this.log.format("[%s] (%s) %s\n", level.toUpperCase(), Thread.currentThread().getName(), format(format, arguments));
+		}


Can we have tests to validate this?

chemicL · 2025-01-31T10:31:03Z

reactor-core/src/main/java/reactor/util/Loggers.java

@@ -507,6 +526,39 @@ final String format(@Nullable String from, @Nullable Object... arguments){
 			return null;
 		}

+		private synchronized void logWithOptionalThrowable(String level, String format, Object... arguments) {


Same comments as with the JdkLogger.

chemicL · 2025-01-31T10:31:59Z

reactor-core/src/main/java/reactor/util/Loggers.java

+			this.log.format("[%s] (%s) %s\n", level.toUpperCase(), Thread.currentThread().getName(), format(format, arguments));
+		}
+
+		private synchronized void logErrorWithOptionalThrowable(String level, String format, Object... arguments) {


This method is almost exactly the same as the one above, can you please unify them with a PrintStream as an argument?

I have merged the methods into one, and modified it to accept a PrintStream as a parameter.

chemicL · 2025-01-31T10:34:40Z

reactor-core/src/main/java/reactor/util/Loggers.java

-		public synchronized void info(String format, Object... arguments) {
-			this.log.format("[ INFO] (%s) %s\n", Thread.currentThread().getName(), format(format, arguments));
+		public void info(String format, Object... arguments) {
+			logWithOptionalThrowable("INFO", format, arguments);


I am guessing the space was to align INFO under DEBUG and such in a single column so the space was a filler. With the spaces all of (TRACE, DEBUG, INFO, WARN, ERROR) take up the same amount of horizontal space. Please roll back.

Thanks for detailed explanation!
I have reverted the code.

- Enhanced logger methods to check if the last argument is of type Throwable. - If Throwable is detected, its stack trace is included in the log output. - Improves debugging by seamlessly handling exception logging alongside message formatting. ref. https://www.slf4j.org/faq.html#paramException Signed-off-by: raccoonback <[email protected]>

Signed-off-by: raccoonback <[email protected]>

…rgument Signed-off-by: raccoonback <[email protected]>

Signed-off-by: raccoonback <[email protected]>

raccoonback · 2025-01-31T14:49:56Z

@chemicL
First of all, thanks for your review!
I have incorporated all of your suggestions.
Please let me know if there's anything else that needs adjustment!

raccoonback · 2025-01-31T14:57:49Z

reactor-core/src/main/java/reactor/util/Loggers.java

+					if (skipLast) --lastIndex;
+					for (int index = 0; index < lastIndex; ++index) {
+						computed = computed.replaceFirst("\\{\\}", Matcher.quoteReplacement(String.valueOf(arguments[index])));


Determines whether to replace the last factor depending on skipLast.

reactor-core/src/main/java/reactor/util/Loggers.java

chemicL

Thanks for the follow up. I added a few more comments, please apply them also to similar areas where appropriate. Please check the build results, they are failing with NPE. Before the next round please make sure the build is passing on your machine.

chemicL · 2025-01-31T17:51:07Z

reactor-core/src/main/java/reactor/util/Loggers.java

@@ -442,18 +442,45 @@ public void error(String msg, Throwable t) {
 		}

 		@Nullable
-		final String format(@Nullable String from, @Nullable Object... arguments){
-			if(from != null) {
+		String format(@Nullable String from, @Nullable Object... arguments) {


This one can also be private.

Changed to private accessor.

chemicL · 2025-01-31T17:53:21Z

reactor-core/src/main/java/reactor/util/Loggers.java

-					for (Object argument : arguments) {
-						computed = computed.replaceFirst("\\{\\}", Matcher.quoteReplacement(String.valueOf(argument)));
+					int lastIndex = arguments.length;
+					if (skipLast) --lastIndex;


Please make sure you use braces around the instructions following an if condition.

Reflect it!

chemicL · 2025-01-31T17:56:46Z

reactor-core/src/main/java/reactor/util/Loggers.java

+		}
+
+		@Nullable
+		private String format(@Nullable String from, boolean skipLast, @Nullable Object... arguments) {


I added the skipLast parameter to the format(...) method. Since Varargs must be placed at the end, I added skipLast as a middle parameter.
Additionally, I overloaded the existing method.

Would it work if instead of Object... you used Object[] ? Since this is an internal API it should be totally fine with the usages here. Then the order of arguments will be more appropriate IMO.

I have changed it to use Object[] instead.

Signed-off-by: raccoonback <[email protected]>

raccoonback · 2025-02-01T00:47:03Z

@chemicL
Hello.

Thank you for your detailed review!
I have addressed all the comments and also fixed the issue causing the NPE.

chemicL

Thank you for the follow up. The production code looks good. Regarding the tests, please refrain from using mocks when more end-to-end tests are possible. The existing tests allow validating the output. Check the use of ConsoleLoggerTest#outContent and JdkLoggerTest#nullFormatIsAcceptedByUnderlyingLogger. Also, please revert unrelated formatting changes so that the PR consists only of changes relevant to the problem that's being solved. Thanks.

Signed-off-by: raccoonback <[email protected]>

raccoonback · 2025-02-03T13:15:10Z

@chemicL

I have rolled back the unrelated formatting changes.

Additionally, since ConsoleLoggerTest already covers all cases for ConsoleLogger, I found the newly added test to be redundant and have therefore removed it.

chemicL · 2025-02-03T13:29:18Z

I have rolled back the unrelated formatting changes.

Additionally, since ConsoleLoggerTest already covers all cases for ConsoleLogger, I found the newly added test to be redundant and have therefore removed it.

I'm not sure I understand. Since the functionality of ConsoleLogger has been enhanced, there should be a need for more tests. Specifically, no test validates a vararg call that has a Throwable at the end, which is the entire purpose of this PR.

In JdkLoggerTest there is no validation of the stacktrace. Please thoroughly review the changes and expectations.

Also, make sure the test methods are descriptive as the existing methods are and capture the circumstance and expectation.

…gger Signed-off-by: raccoonback <[email protected]>

Signed-off-by: raccoonback <[email protected]>

raccoonback · 2025-02-03T14:38:22Z

@chemicL

I misunderstood;;
As you mentioned, I have added a test for the case where the last argument of varargs is a Throwable.
Additionally, I modified JdkLoggerTest to validate the stacktrace and extracted the duplicate code for creating JdkLogger into the getJdkLogger() method.

chemicL · 2025-02-04T11:58:33Z

@raccoonback thank you for the contribution! 🚀

raccoonback requested a review from a team as a code owner January 2, 2025 15:49

raccoonback force-pushed the log-with-optional-throable branch from e336792 to d946148 Compare January 2, 2025 15:51

raccoonback commented Jan 2, 2025

View reviewed changes

chemicL requested changes Jan 31, 2025

View reviewed changes

raccoonback added 4 commits January 31, 2025 23:40

Rollback removed space in console logger

9b8421e

Signed-off-by: raccoonback <[email protected]>

Modify format method to conditionally exclude Throwable as the last a…

c8d4680

…rgument Signed-off-by: raccoonback <[email protected]>

Add test code for logger

4dd4f62

Signed-off-by: raccoonback <[email protected]>

raccoonback force-pushed the log-with-optional-throable branch from 9df27da to 4dd4f62 Compare January 31, 2025 14:42

raccoonback requested a review from chemicL January 31, 2025 14:55

raccoonback commented Jan 31, 2025

View reviewed changes

chemicL requested changes Jan 31, 2025

View reviewed changes

raccoonback added 5 commits February 1, 2025 09:37

Replace varargs with an object array argument

a26af67

Signed-off-by: raccoonback <[email protected]>

Fix codestyle

669fe68

Signed-off-by: raccoonback <[email protected]>

Protects against null arguments in loggers

d7f149b

Signed-off-by: raccoonback <[email protected]>

Place test files appropriately according to their purpose

854c9d6

Signed-off-by: raccoonback <[email protected]>

Maintain LoggersTest format

487b467

Signed-off-by: raccoonback <[email protected]>

raccoonback requested a review from chemicL February 1, 2025 01:00

chemicL added the type/enhancement A general enhancement label Feb 3, 2025

chemicL added this to the 3.7.3 milestone Feb 3, 2025

chemicL requested changes Feb 3, 2025

View reviewed changes

raccoonback added 2 commits February 3, 2025 22:07

Change to an end-to-end test

37a844f

Signed-off-by: raccoonback <[email protected]>

Remove duplicated test

55858be

Signed-off-by: raccoonback <[email protected]>

raccoonback requested a review from chemicL February 3, 2025 13:10

Add test for varargs with Throwable as the last argument in ConsoleLo…

33ee6ce

…gger Signed-off-by: raccoonback <[email protected]>

Clarify test assertions for varargs ending with Throwable in JdkLogger

e7cf75c

Signed-off-by: raccoonback <[email protected]>

chemicL approved these changes Feb 4, 2025

View reviewed changes

chemicL merged commit fb3d31d into reactor:main Feb 4, 2025
7 checks passed

Support logging exception stack traces when the last argument is Throwable #3960

Support logging exception stack traces when the last argument is Throwable #3960

Conversation

raccoonback commented Jan 2, 2025 • edited Loading

Motivation

Description

Key Changes

Example Usage

Before

After

Benefits

Testing

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

raccoonback commented Jan 22, 2025

chemicL left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

raccoonback commented Jan 31, 2025

Choose a reason for hiding this comment

chemicL left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

raccoonback commented Feb 1, 2025

chemicL left a comment

Choose a reason for hiding this comment

raccoonback commented Feb 3, 2025

chemicL commented Feb 3, 2025 • edited Loading

raccoonback commented Feb 3, 2025

chemicL commented Feb 4, 2025

raccoonback commented Jan 2, 2025 •

edited

Loading

chemicL left a comment •

edited

Loading

chemicL commented Feb 3, 2025 •

edited

Loading