[
https://issues.apache.org/jira/browse/LOG4J2-3165?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17431058#comment-17431058
]
Volkan Yazici edited comment on LOG4J2-3165 at 10/20/21, 8:38 AM:
------------------------------------------------------------------
I see that you have changed the separator from //{{r}} in my example to /{{r}}
(sorry, Jira messes up backslashes) and consequently you have reproduced the
problem. To investigate it in more detail, I have created the following test:
{code:java}
LogEvent event = Log4jLogEvent
.newBuilder()
.setThrown(new IllegalArgumentException("foo"))
.build();
for (String pattern : new String[]{
"%m%throwable%n",
"%m%throwable{separator(\r)}%n",
"%m%throwable{separator(\\r)}%n"}) {
System.out.format(
"-----------%npattern: %s%n",
pattern.replace("\\", "\\\\").replace("\r", "\\r"));
String serializedEvent = PatternLayout
.newBuilder()
.withConfiguration(new DefaultConfiguration())
.withCharset(StandardCharsets.UTF_8)
.withPattern(pattern)
.build()
.toSerializable(event);
System.out.print(serializedEvent);
}
{code}
I ran it against 2.13.3, 2.14.1, and 2.15.0-SNAPSHOT versions and the outputs
are as follows:
*2.15.0-SNAPSHOT:*
{noformat}
pattern: %m%throwable%n
java.lang.IllegalArgumentException: foo
at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...
-----------
pattern: %m%throwable{separator(\r)}%n
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)
-----------
pattern: %m%throwable{separator(\\r)}%n
java.lang.IllegalArgumentException: foo\r at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)\r
at sun.reflect...
{noformat}
*2.14.1:*
{noformat}
pattern: %m%throwable%n
java.lang.IllegalArgumentException: foo
at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...
-----------
pattern: %m%throwable{separator(\r)}%n
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)
-----------
pattern: %m%throwable{separator(\\r)}%n
java.lang.IllegalArgumentException: foo\r at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)\r
at sun.reflect...
{noformat}
*2.13.3:*
{noformat}
pattern: %m%throwable%n
java.lang.IllegalArgumentException: foo
at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...
-----------
pattern: %m%throwable{separator(\r)}%n
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)
-----------
pattern: %m%throwable{separator(\\r)}%n
java.lang.IllegalArgumentException: foo\r at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)\r
at sun.reflect...
{noformat}
AFAIC, there are no changes in the behavior. I guess the only thing I can
suspect is how {{ThrowableFormatOptions#separator}} is populated. Mind putting
a breakpoint into {{ThrowableFormatOptions.java:260}} and see if there is
difference in the way {{ThrowableFormatOptions#separator}} is populated between
different versions, please?
was (Author: vy):
I see that you have changed the separator from {{\\r}} in my example to \{{r}}
and consequently you have reproduced the problem. To investigate it in more
detail, I have created the following test:
{code:java}
LogEvent event = Log4jLogEvent
.newBuilder()
.setThrown(new IllegalArgumentException("foo"))
.build();
for (String pattern : new String[]{
"%m%throwable%n",
"%m%throwable{separator(\r)}%n",
"%m%throwable{separator(\\r)}%n"}) {
System.out.format(
"-----------%npattern: %s%n",
pattern.replace("\\", "\\\\").replace("\r", "\\r"));
String serializedEvent = PatternLayout
.newBuilder()
.withConfiguration(new DefaultConfiguration())
.withCharset(StandardCharsets.UTF_8)
.withPattern(pattern)
.build()
.toSerializable(event);
System.out.print(serializedEvent);
}
{code}
I ran it against 2.13.3, 2.14.1, and 2.15.0-SNAPSHOT versions and the outputs
are as follows:
*2.15.0-SNAPSHOT:*
{noformat}
pattern: %m%throwable%n
java.lang.IllegalArgumentException: foo
at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...
-----------
pattern: %m%throwable{separator(\r)}%n
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)
-----------
pattern: %m%throwable{separator(\\r)}%n
java.lang.IllegalArgumentException: foo\r at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)\r
at sun.reflect...
{noformat}
*2.14.1:*
{noformat}
pattern: %m%throwable%n
java.lang.IllegalArgumentException: foo
at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...
-----------
pattern: %m%throwable{separator(\r)}%n
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)
-----------
pattern: %m%throwable{separator(\\r)}%n
java.lang.IllegalArgumentException: foo\r at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)\r
at sun.reflect...
{noformat}
*2.13.3:*
{noformat}
pattern: %m%throwable%n
java.lang.IllegalArgumentException: foo
at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...
-----------
pattern: %m%throwable{separator(\r)}%n
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)
-----------
pattern: %m%throwable{separator(\\r)}%n
java.lang.IllegalArgumentException: foo\r at
org.apache.logging.log4j.core.pattern.LOG4J2_3165_Test.LOG4J2_3165(LOG4J2_3165_Test.java:16)\r
at sun.reflect...
{noformat}
AFAIC, there are no changes in the behavior. I guess the only thing I can
suspect is how {{ThrowableFormatOptions#separator}} is populated. Mind putting
a breakpoint into {{ThrowableFormatOptions.java:260}} and see if there is
difference in the way {{ThrowableFormatOptions#separator}} is populated between
different versions, please?
> Custom line separator for throwable breaks formatting
> -----------------------------------------------------
>
> Key: LOG4J2-3165
> URL: https://issues.apache.org/jira/browse/LOG4J2-3165
> Project: Log4j 2
> Issue Type: Bug
> Components: Configuration, Core, Pattern Converters
> Affects Versions: 2.14.1
> Environment: Spring Boot 2.5.4
> Log4j2 2.14.1
> Reporter: Mikhail Dobrinin
> Assignee: Volkan Yazici
> Priority: Critical
>
> The following log pattern used to work great for rewriting exception stack
> traces.
> {code:java}
> %m%throwable{separator(\r)}%n
> {code}
> I am configuring it in Spring Boot 2 using application.yaml.
> {code:java}
> logging:
> pattern:
> console: "%m%throwable{separator(\r)}%n"
> {code}
> And the exception is being logged like this -
> {code:java}
> log.error("Error message: []", ex);
> {code}
> h2. Expected Behavior (worked in 2.13.3)
> The full exception should be logged. Or at least most of the exception
> according to default limits present in ThrowableFormatOptions.
> The exception should look like this
> {code:java}
> Error message: []
> org.springframework.web.client.HttpClientErrorException$NotFound: 404 : []
> at
> org.springframework.web.client.HttpClientErrorException.create(HttpClientErrorException.java:113)
> at
> org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:186)
> at
> org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:125)
> at
> org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)
> at
> org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:819)
> at
> org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:777)
> at
> org.springframework.web.client.RestTemplate.execute(RestTemplate.java:732)
> at
> org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:612)
> at
> com.company.utils.AttachmentDownloader.findFileMetadata(AttachmentDownloader.java:152)
> at
> com.company.utils.AttachmentDownloader.downloadAttachments(AttachmentDownloader.java:85)
> at
> com.company.services.ServiceRequestService.downloadAndGetAttachments(ServiceRequestService.java:164)
> at
> com.company.services.ServiceRequestService.lambda$submitRequest$1(ServiceRequestService.java:159)
> at com.company.models.ServiceRequest.also(ServiceRequest.java:113)
> at
> com.company.services.ServiceRequestService.submitRequest(ServiceRequestService.java:147)
> at
> com.company.services.ServiceRequestService$$FastClassBySpringCGLIB$$d0dcd3fb.invoke(<generated>)
> at
> org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
> at
> org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:779)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
> at
> org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
> at
> org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123)
> at
> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388)
> at
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
> at
> org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
> at
> org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
> at
> com.company.services.ServiceRequestService$$EnhancerBySpringCGLIB$$b01821d0.submitRequest(<generated>)
> at
> com.company.api.ServiceRequestsController.submit(ServiceRequestsController.java:76)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at
> org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197)
> at
> org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141)
> at
> org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
> 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:1064)
> 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.doPost(FrameworkServlet.java:909)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:681)
> at
> org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
> at
> org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
> at
> com.company.common.CommonHeadersFilter.doFilterInternal(CommonHeadersFilter.java:47)
> at
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
> at
> org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
> at
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
> at
> org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
> at
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
> at
> org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:96)
> at
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
> at
> org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
> at
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
> at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
> at
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
> at
> org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
> at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
> at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
> at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
> at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
> at
> org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
> at
> org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
> at
> org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1726)
> at
> org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.base/java.lang.Thread.run(Thread.java:834)
> {code}
> h2. Current Behavior (broken in 2.14.1)
> The exception is truncated to a single line in my environment.
> {code:java}
> at java.base/java.lang.Thread.run(Thread.java:834)
> {code}
> h2. Theory
> I think it has something to do with the custom separator being set to \r in
> version 2.14.1. If I remove that part then the exception is logged as
> expected again.
> {code}
> logging:
> pattern:
> console: "%m%throwable{}%n"
> {code}
> I stepped through some of the Log4j2 code and I can see that the full stack
> trace is present through most of the processing.
> * Full exception printed to buffer in
> org.apache.logging.log4j.core.pattern.Throwable
> * PatternConverter#formatOption().
> * Full exception still in buffer after next and final formatter runs
> (LineSeparatorPatternConverter) in file PatternLayout.
> * Then some kind of encoding logic happens and what is printed to Console is
> the truncated exception.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
