Re: Stack Traces in JSON Template Layout

Hello Varun,

Thanks for the detailed report. Though I still fail to reproduce the issue.

"message" resolver doesn't have an "includeStackTrace" configuration
option, though I can see where you are coming from. It is unfortunately a
leftover in the documentation. I will fix it in the manual. Your usage
of stackTraceEnabled="true" is correct.

To reproduce your case, I have implemented a test as follows:

@Test
void varun() {

    // Create the layout.
    JsonTemplateLayout layout = JsonTemplateLayout
            .newBuilder()
            .setConfiguration(new DefaultConfiguration())
            .setEventTemplateUri("classpath:varun.json")
            .setStackTraceEnabled(true)
            .build();

    // Create the log event.
    SimpleMessage message = new SimpleMessage("foo");
    Exception thrown = new RuntimeException("bar");
    LogEvent logEvent = Log4jLogEvent
            .newBuilder()
            .setLoggerName("org.apache.logging.log4j.layout.template.json.JsonTemplateLayoutTest")
            .setMessage(message)
            .setThrown(thrown)
            .build();

    String serializedLogEvent = layout.toSerializable(logEvent);

}

where varun.json is the template I have copied from your Gist. When I put a
breakpoint at the method closing curly brace, my IDE debugger shows the
following content for "serializedLogEvent":

{
  "@timestamp": "2020-12-11T12:27:13.599Z",
  "level": "OFF",
  "message": "foo",
  "thread": "ForkJoinPool-1-worker-1",
  "stack": null,
  "error.type": "java.lang.RuntimeException",
  "error.message": "bar",
  "root_cause": "java.lang.RuntimeException: bar\n\tat
org.apache.logging.log4j.layout.template.json.JsonTemplateLayoutTest.varun(JsonTemplateLayoutTest.java:2131)\n\tat
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat
java.lang.reflect.Method.invoke(Method.java:498)\n\tat
org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)\n\tat
org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)\n\tat
org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)\n\tat
org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)\n\tat
org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)\n\tat
org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)\n\tat
org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)\n\tat
org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)\n\tat
org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)\n\tat
org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)\n\tat
org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)\n\tat
org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)\n\tat
org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)\n\tat
org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)\n\tat
org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:210)\n\tat
org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)\n\tat
org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:206)\n\tat
org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:131)\n\tat
org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:65)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)\n\tat
org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)\n\tat
org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)\n\tat
org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)\n\tat
org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:185)\n\tat
org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService.invokeAll(ForkJoinPoolHierarchicalTestExecutorService.java:129)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)\n\tat
org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)\n\tat
org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)\n\tat
org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)\n\tat
org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:185)\n\tat
org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService.invokeAll(ForkJoinPoolHierarchicalTestExecutorService.java:129)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)\n\tat
org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)\n\tat
org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)\n\tat
org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)\n\tat
org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)\n\tat
org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:185)\n\tat
java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:189)\n\tat
java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)\n\tat
java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)\n\tat
java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)\n\tat
java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)\n"
}

Hence, this looks pretty legitimate to me.

Would you mind sharing the updated version of the JUnit test I showed above
to reproduce your case, please? If not, would you at least show me the line
where/how you call the logger?

Kind regards.

On Fri, Dec 11, 2020 at 3:09 AM Varun Thacker <[email protected]> wrote:

> I'm trying to use JSON Template Layout and can't figure out why is the
> "message" field contain the full stack trace and why aren't some exception
> resolvers working. They are probably connected. Adding
> "includeStackTrace": false to the message resolver didn't help.
>
> I've attached my log output, the layout config and the JSON Template Layout
> from the log4j2 file here -
> https://gist.github.com/vthacker/1e129b739f171ac277926f3f62e4d559
>
> What I was trying to achieve was
>
>    1. Don't log the entire stack trace in the "message" field
>    2. Populate the message with with just the exception message. Right now
>    it's part of "exception.message" but still not getting populated
>    3. Log only the "root_cause" part of the exception in a separate field
>
>
> My primary motivation for this is stack traces get quite large and
> downstream systems that ingest these logs try to cap the log size and some
> stack traces get truncated . Hence only log the root cause and the error
> message
>