Generate log message in advance

[raccoonback]

Add separate handling for Throwable when available.

Fixes: #3561

[violetagg]

@raccoonback Thanks for the PR!
I think we need more to this solution.
Can you try the test below and ensure that with the fix we will be able to see the exception?

@Test
void testLogFormat() {
	Channel channel = new EmbeddedChannel();
	useVerboseConsoleLoggers();
	try {
		InstrumentedPool<? extends Connection> pool = mock(InstrumentedPool.class);
		InstrumentedPool.PoolMetrics metrics = mock(InstrumentedPool.PoolMetrics.class);
		when(pool.metrics()).thenReturn(metrics);
		logPoolState(channel, pool, "log message");
		logPoolState(channel, pool, "log message", new Exception("test log format"));
	}
	finally {
		resetLoggerFactory();
		Connection.from(channel).dispose();
	}
}

[raccoonback]

@violetagg Yes, I'll check it out!

[raccoonback]

@violetagg
I have tested the provided code locally, and it seems to work as expected without any issues!

[violetagg]

@raccoonback That's interesting

When I'm using useVerboseConsoleLoggers();

I'm seeing

[DEBUG] (Test worker) Using Verbose Console logging
[DEBUG] (Test worker) [embedded, L:embedded - R:embedded] log message, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
[DEBUG] (Test worker) [embedded, L:embedded - R:embedded] log message, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.

When I'm using useSl4jLoggers();

I'm seeing also the exception

19:05:46.600 [Test worker] DEBUG r.n.r.PooledConnectionProvider - [embedded, L:embedded - R:embedded] log message, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
19:05:46.607 [Test worker] DEBUG r.n.r.PooledConnectionProvider - [embedded, L:embedded - R:embedded] log message, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
java.lang.Exception: test log format
	at reactor.netty.resources.DefaultPooledConnectionProviderTest.testLogFormat(DefaultPooledConnectionProviderTest.java:590)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:767)
	at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
...

Can you share the output that you are seeing?

[raccoonback]

@violetagg
Same thing happened to me..
I'll look into this more and share it with you!

when useing useVerboseConsoleLoggers();
There was no stacktrace in logPoolState(channel, pool, "log message", new Exception("test log format")).

[DEBUG] (Test worker) Using Verbose Console logging
[DEBUG] (Test worker) [embedded, L:embedded - R:embedded] log message, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
[DEBUG] (Test worker) [embedded, L:embedded - R:embedded] log message, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.

when useing useSl4jLoggers();

08:19:01.030 [Test worker] DEBUG r.n.r.PooledConnectionProvider - [embedded, L:embedded - R:embedded] log message, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
08:19:01.037 [Test worker] DEBUG r.n.r.PooledConnectionProvider - [embedded, L:embedded - R:embedded] log message, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
java.lang.Exception: test log format
	at reactor.netty.resources.DefaultPooledConnectionProviderTest.testLogFormat(DefaultPooledConnectionProviderTest.java:590)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:767)
	at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)

[raccoonback]

Here is what I’ve found so far:
It seems there are two issues at play.

1. Even when an Exception is thrown, debug(String format, Object... arguments) is invoked instead of debug(String msg, Throwable t).

2. While the SLF4J implementation (logback) handles cases where debug(String format, Object... arguments) is called with only a Throwable, the console logger does not handle this scenario.
   In console logger, it only prints in PrintStream.

public PrintStream format(String format, Object ... args) {
        try {
            synchronized (this) {
                ensureOpen();
                if ((formatter == null)
                    || (formatter.locale() != Locale.getDefault()))
                    formatter = new Formatter((Appendable) this);
                formatter.format(Locale.getDefault(), format, args);
            }
        } catch (InterruptedIOException x) {
            Thread.currentThread().interrupt();
        } catch (IOException x) {
            trouble = true;
        }
        return this;
    }

As a result, when useSl4jLoggers() is used, the stack trace is printed correctly, but this is not the case for the console logger.

[raccoonback]

@violetagg The above case appears to be a reactor-core issue, so I will also send a PR to reactor-core!

[violetagg]

@raccoonback Please wait, there is no issue with reactor-core, I just wanted to point that we provide 5 arguments for 4 placeholders. Depending on the different implementations this behaves differently - some may omit the Throwable, some may try to handle the Throwable and as in the reported issue, the logging implementation may even print bad pattern.
IMO we need to distinguish between two use cases - with/without Throwable and use the proper method - debug(String format, Object... arguments)/debug(String msg, Throwable t). We have to ensure that we have even arguments and placeholders.

[raccoonback]

@violetagg
Thanks for the great advice! 😃
I believe we have three possible solutions for this issue. Could you share your thoughts on which approach might be the best?

1. Add an additional log.debug("", t) call.

log.debug(
    format(channel, "{}, now: {} active connections, {} inactive connections and {} pending acquire requests."),
	msg,
	metrics.acquiredSize(),
	metrics.idleSize(),
	metrics.pendingAcquireSize()
);
if(t != null) {
     log.debug("", t);
}

2. Set the log message in advance before calling log.debug().
   (Since most of them are primitive types, it would be a good idea to create a string log message in advance.)

String message = new StringJoiner(", ")
			.add(msg)
			.add("now: " + metrics.acquiredSize() + " active connections")
			.add(metrics.idleSize() + " inactive connections and " + metrics.pendingAcquireSize() + " pending acquire requests.")
			.toString();
if(t != null) {
    log.debug(format(channel, message), t);
}

3. Create a logging utility to handle such cases separately.

class LogUtils {

  // ...

}

Do you think any of these approaches would work best? Or do you have any other suggestions we could consider?

[raccoonback]

@violetagg
First of all, I modified it using method 2.
(If it is a slf4j environment, there is a tradeoff of always trying string operations regardless of the log level.)

ref. https://www.slf4j.org/faq.html#logging_performance

[violetagg]

Thanks for the PR!

[violetagg]

I back ported the fix to 1.1.x branch.