Hi Volkan,
Sorry I haven’t found time to look into this. Let me spend some time
tomorrow and get back to you
On Thu, Dec 17, 2020 at 2:22 AM Volkan Yazıcı <volkan.yaz...@gmail.com>
wrote:
> Hey Varun! Were you able to figure out the problem? Did you have any
> progress?
>
> On Sun, Dec 13, 2020 at 9:47 PM Volkan Yazıcı <volkan.yaz...@gmail.com>
> wrote:
>
> > Varun, would you mind sharing the logger line causing this
> > problem, please? That is, is it *logger.error("foo", exception)* or
> > *logger.error(exception)*? Would you share the "exception" too?
> >
> > Assuming you can reproduce this locally, the best way to debug this is to
> > put a breakpoint into both of the following methods in
> > *JsonTemplateLayout* class:
> >
> > public String toSerializable(final LogEvent event)
> >
> > public void encode(final LogEvent event, final ByteBufferDestination
> destination)
> >
> > And step into *eventResolver.resolve(event, jsonWriter)* calls over
> there.
> >
> > I can think of two ways to approach this. 1) You either provide us
> > sufficient materials to reproduce the case on our end. 2) Or I can
> schedule
> > a video call with you and there we try to debug it together. As you might
> > imagine, my preference would be the first option. Let me know which suits
> > you best.
> >
> > On Fri, Dec 11, 2020 at 10:17 PM Varun Thacker <va...@vthacker.in>
> wrote:
> >
> >> Hello Volkan,
> >>
> >> Thanks for writing the test case.
> >>
> >> So when I run the test case I am seeing what you see as well.
> Additionally
> >> I checked out the `rel/2.14.0` tag and still wasn't able to reproduce
> the
> >> problem.
> >>
> >> I then thought of simplifying my log4j2.xml file and removed some
> Rewrite
> >> filters, changed async logging to sync logging and still see the same
> >> thing
> >> - the whole stack trace in the "message" field.
> >>
> >> Next thing I tried was making sure all the remaining log4j2 dependencies
> >> are on 2.14 - ( log4j-1.2-api , log4j-api , log4j-core and
> >> log4j-slf4j-impl ) . They were on 2.11 - Still saw the same problem
> >>
> >> I then tried using the default layout that comes packaged with the JAR (
> >> file
> >> <
> >>
> https://github.com/apache/logging-log4j2/blob/rel/2.14.0/log4j-layout-template-json/src/main/resources/LogstashJsonEventLayoutV1.json
> >> >
> >> ) by configuring the template to be *( <JsonTemplateLayout
> >> eventTemplateUri="classpath:LogstashJsonEventLayoutV1.json"/> )* and
> still
> >> hit the same issue
> >>
> >> Not sure how to debug next. I could have sworn I had gotten it to work
> >> with
> >> your https://github.com/vy/log4j2-logstash-layout project and only
> when I
> >> saw the notice on the github repo that the project moved to apache that
> I
> >> started to try JsonTemplateLayout
> >>
> >> The fact that in the log lines I am not seeing the `root_cause` key not
> >> even show up even with null means something is still broken with the
> >> setup.
> >> I'd previosuly see it being populated with root_cause:null with your
> >> logstash layout project when I had it configured via
> *"error.root_cause":
> >> "${json:exceptionRootCause:message}"*
> >>
> >>
> >>
> >>
> >>
> >> On Fri, Dec 11, 2020 at 4:43 AM Volkan Yazıcı <volkan.yaz...@gmail.com>
> >> wrote:
> >>
> >> > 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 <va...@vthacker.in>
> >> 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
> >> > >
> >> >
> >>
> >
>
