Mikhail Dobrinin created LOG4J2-3165:
----------------------------------------
Summary: 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, Pattern Converters
Affects Versions: 2.14.1
Environment: Spring Boot 2.5.4
Log4j2 2.14.1
Reporter: Mikhail Dobrinin
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: []", errorMessage, ex);
{code}
h2. Expected Behavior
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
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)
