You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Arthur Gavlyukovskiy (Jira)" <ji...@apache.org> on 2022/07/20 09:16:00 UTC
[jira] [Comment Edited] (LOG4J2-3556) JsonTemplateLayout truncation ignores exception cause
[ https://issues.apache.org/jira/browse/LOG4J2-3556?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17568953#comment-17568953 ]
Arthur Gavlyukovskiy edited comment on LOG4J2-3556 at 7/20/22 9:15 AM:
-----------------------------------------------------------------------
[~vy] do you mean something like [this|https://github.com/gavlyukovskiy/log4j-json-template-reproducer/commit/bee83ed33b76a4ce02eb0730ddec3ec7799aed8e]? I first thought that we might need to process every "Caused by" separately, but JVM does that for me by not rendering matching frames, so finding first "Caused by" seems to be producing desirable stacktrace:
{code:java}
java.lang.IllegalArgumentException: StackTraceController.exception
at reproducer.log4jjsontemplate.StackTraceController.testMulti(StackTraceController.java:37)
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.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
at javax.servlet.http.HttpServlet.service
<skipped internal frames>
Caused by: java.lang.IllegalStateException: ServiceLayer.exception
at reproducer.log4jjsontemplate.ServiceLayer.doSomething(ServiceLayer.java:18)
at reproducer.log4jjsontemplate.StackTraceController.test(StackTraceController.java:22)
... 50 more
Caused by: java.lang.NullPointerException: RepositoryLayer.exception
at reproducer.log4jjsontemplate.RepositoryLayer.doSomething(RepositoryLayer.java:9)
at reproducer.log4jjsontemplate.ServiceLayer.doSomething(ServiceLayer.java:16)
... 51 more
{code}
Not sure if there are different cases when you have completely different stacktraces, maybe something like storing exception from one frame and using it as a cause for another exception, or if having multuple pointMatcherStrings|pointMatcherRegexes it might be useful to go over all Caused by stacktraces anyway. I'd be happy to make PR for that if it helps :)
was (Author: agavlyukovskiy):
[~vy] do you mean something like [this|https://github.com/gavlyukovskiy/log4j-json-template-reproducer/commit/bee83ed33b76a4ce02eb0730ddec3ec7799aed8e]? I first thought that we might need to process every "Caused by" separately, but JVM does that for me by not rendering matching frames, so finding first "Caused by" seems to be producing desirable stacktrace:
{code:java}
java.lang.IllegalArgumentException: StackTraceController.exception
at reproducer.log4jjsontemplate.StackTraceController.testMulti(StackTraceController.java:37)
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.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
at javax.servlet.http.HttpServlet.service
<skipped internal frames>
Caused by: java.lang.IllegalStateException: ServiceLayer.exception
at reproducer.log4jjsontemplate.ServiceLayer.doSomething(ServiceLayer.java:18)
at reproducer.log4jjsontemplate.StackTraceController.test(StackTraceController.java:22)
... 50 more
Caused by: java.lang.NullPointerException: RepositoryLayer.exception
at reproducer.log4jjsontemplate.RepositoryLayer.doSomething(RepositoryLayer.java:9)
at reproducer.log4jjsontemplate.ServiceLayer.doSomething(ServiceLayer.java:16)
... 51 more
{code}
Not sure if there are different cases when you have completely different stacktraces, maybe something like storing exception from one frame and using it as a cause for another exception, or if having multuple pointMatcherStrings|truncationPointMatcherRegexes it might be useful to go over all Caused by stacktraces anyway. I'd be happy to make PR for that if it helps :)
> JsonTemplateLayout truncation ignores exception cause
> -----------------------------------------------------
>
> Key: LOG4J2-3556
> URL: https://issues.apache.org/jira/browse/LOG4J2-3556
> Project: Log4j 2
> Issue Type: Bug
> Components: JsonTemplateLayout
> Reporter: Arthur Gavlyukovskiy
> Assignee: Volkan Yazici
> Priority: Minor
>
> Stacktrace truncation is helpful to reduce the size of the event, but current approach implemented in LOG4J2-2993 completely removes any "Caused by:" that might be in the stacktrace, while those are the most useful parts of stacktrace.
> I'm using the modified EcsLayout.json with suggested truncation point
> {code:java}
> "error.stack_trace": {
> "$resolver": "exception",
> "field": "stackTrace",
> "stackTrace": {
> "stringified": {
> "truncation": {
> "pointMatcherStrings": ["at javax.servlet.http.HttpServlet.service"],
> "suffix": "\n\t<skipped internal frames>"
> }
> }
> }
> } {code}
> and the stacktrace I saw on a real production server was rendered as
> {code:java}
> org.springframework.web.util.NestedServletException: Request processing failed; nested exception is java.lang.NullPointerException
> at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014)
> at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
> at javax.servlet.http.HttpServlet.service
> <skipped internal frames> {code}
> which doesn't show anything about origin of the error.
>
> The fix should be relatively simple - change StackTraceStringResolver.truncate method to
> {code:java}
> private void truncate(
> final TruncatingBufferedPrintWriter writer,
> final int index) {
> int causedByIndex = writer.indexOf("Caused by:");
> CharSequence causedBy = null;
> if (causedByIndex != -1) {
> causedBy = writer.subSequence(causedByIndex - 1, writer.position());
> }
> writer.position(index);
> writer.print(truncationSuffix);
> if (causedByIndex != -1) {
> writer.print(causedBy);
> }
> }
> {code}
> and it correctly displays the stack trace:
> {code:java}
> java.lang.IllegalArgumentException: wrapper error
> at reproducer.log4jjsontemplate.StackTraceController.test(StackTraceController.java:18)
> 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.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
> at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
> at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
> at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
> at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
> at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
> at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
> at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
> at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
> at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
> at javax.servlet.http.HttpServlet.service
> <skipped internal frames>
> Caused by: java.lang.NullPointerException: original error
> at reproducer.log4jjsontemplate.StackTraceController.test(StackTraceController.java:16)
> ... 50 more {code}
>
> I have created an MRE [here|https://github.com/gavlyukovskiy/log4j-json-template-reproducer] where you can find more details and monkey patch on a [separate branch|https://github.com/gavlyukovskiy/log4j-json-template-reproducer/tree/monkey-patch].
--
This message was sent by Atlassian Jira
(v8.20.10#820010)