Mikhail Chinkov created LOGBACK-1262:
----------------------------------------
Summary: java.io.IOException: Stream closed in EvaluatorFilter
Key: LOGBACK-1262
URL: https://jira.qos.ch/browse/LOGBACK-1262
Project: logback
Issue Type: Bug
Components: logback-access
Affects Versions: 1.2.1, 1.1.6
Environment: OS: Alpine Linux v3.4 (application under Docker)
Kernel: 3.10.0-327.10.1.el7.x86_64 (CentOS 7 host)
Tomcat version: 7.0.73
Logback-access/core/classic version: 1.1.6 (tried to upgrade to 1.2.1, but it
didn't work out)
Reporter: Mikhail Chinkov
Assignee: Logback dev list
I changed my filter configuration in logback-access to log HTTP requests with
full response/request to console instead of file.
Configuration that works properly in file:
{{<statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener"
/>}}{{<appender name="FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">}}
{{ <filter class="ch.qos.logback.core.filter.EvaluatorFilter">}}
{{ <evaluator>}}
{{ <expression>(event.getStatusCode() == 500 || event.getStatusCode() == 400)
&& (event.getLocalPort() == 8080)</expression>}}
{{ </evaluator>}}
{{ <onMismatch>DENY</onMismatch>}}
{{ <onMatch>NEUTRAL</onMatch>}}
{{ </filter>}}
{{ <file>$\{catalina.base}/logs/data-api-requests.log</file>}}
{{ <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">}}
{{
<fileNamePattern>$\{catalina.base}/logs/data-api-requests-%d\{yyyy-MM-dd}.log.%i</fileNamePattern>}}
{{ <maxHistory>10</maxHistory>}}
{{ <timeBasedFileNamingAndTriggeringPolicy
class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">}}
{{ <maxFileSize>500mb</maxFileSize>}}
{{ </timeBasedFileNamingAndTriggeringPolicy>}}
{{ </rollingPolicy>}}
{{ <encoder>}}
{{ <pattern>%a %t\{dd MMM yyyy ;HH:mm:ss,SSS}
%fullRequest%n%n%fullResponse</pattern>}}
{{ </encoder>}}
{{ </appender>}}
New configuration which breaks:
{{<statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener"
/>}}{{<appender name="HTTP" class="ch.qos.logback.core.ConsoleAppender">}}
{{ <filter class="ch.qos.logback.core.filter.EvaluatorFilter">}}
{{ <evaluator>}}
{{ <expression>(event.getStatusCode() == 500 || event.getStatusCode() ==
400)</expression>}}
{{ </evaluator>}}
{{ <onMismatch>DENY</onMismatch>}}
{{ <onMatch>NEUTRAL</onMatch>}}
{{ </filter>}}
{{ <encoder>}}
{{ <pattern>%h %l %u %user %date "%r" %s
%b%n%n%fullRequest%n%n%fullResponse</pattern>}}
{{ </encoder>}}
{{ </appender>}}
How breaks? When trying to log event by filter it throws IOException.
{{java.io.IOException: Stream closed}}
{{ at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:312)}}
{{ at
org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:200)}}
{{ at
ch.qos.logback.access.servlet.TeeServletInputStream.consumeBufferAndReturnAsByteArray(TeeServletInputStream.java:56)}}
{{ at
ch.qos.logback.access.servlet.TeeServletInputStream.duplicateInputStream(TeeServletInputStream.java:42)}}
{{ at
ch.qos.logback.access.servlet.TeeServletInputStream.<init>(TeeServletInputStream.java:30)}}
{{ at
ch.qos.logback.access.servlet.TeeHttpServletRequest.<init>(TeeHttpServletRequest.java:44)}}
{{ at ch.qos.logback.access.servlet.TeeFilter.doFilter(TeeFilter.java:49)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at com.skybonds.data.filter.CORSFilter.doFilter(CORSFilter.java:30)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)}}
{{ at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)}}
{{ at
org.springframework.boot.context.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:113)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:748)}}
{{ at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:486)}}
{{ at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:411)}}
{{ at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:338)}}
{{ at
org.springframework.boot.context.web.ErrorPageFilter.handleErrorStatus(ErrorPageFilter.java:154)}}
{{ at
org.springframework.boot.context.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:122)}}
{{ at
org.springframework.boot.context.web.ErrorPageFilter.access$000(ErrorPageFilter.java:61)}}
{{ at
org.springframework.boot.context.web.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:95)}}
{{ at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)}}
{{ at
org.springframework.boot.context.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:113)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)}}
{{ at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)}}
{{ at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)}}
{{ at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)}}
{{ at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)}}
{{ at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)}}
{{ at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)}}
{{ at ch.qos.logback.access.tomcat.LogbackValve.invoke(LogbackValve.java:254)}}
{{ at
org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)}}
{{ at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)}}
{{ at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)}}
{{ at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1074)}}
{{ at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)}}
{{ at
org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)}}
{{ at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)}}
{{ at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)}}
{{ at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)}}
{{ at java.lang.Thread.run(Thread.java:745)}}
When I removed filter, the problem was gone. Also I tried to reconfigure filter.
{{<statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener"
/>}}{{<appender name="HTTP" class="ch.qos.logback.core.ConsoleAppender">}}
{{ <filter class="ch.qos.logback.core.filter.EvaluatorFilter">}}
{{ <evaluator>}}
{{ <expression>(event.getStatusCode() != 200) && (event.getStatusCode()
!= 303)</expression>}}
{{ </evaluator>}}
{{ <onMismatch>DENY</onMismatch>}}
{{ </filter>}}
{{ <encoder>}}
{{ <pattern>%h %l %u %user %date "%r" %s
%b%n%n%fullRequest%n%n%fullResponse</pattern>}}
{{ </encoder>}}
{{ </appender>}}
This one started to throw events and IOExceptions simultaneously.
So, looking for your docs, I configured logback-access to console as mentioned
there, but I still get the same exception. Probably, there must be my mistake,
but after few-hours debugging still can't get where. So, please, help me to
find the problem at this filter.
--
This message was sent by Atlassian JIRA
(v7.3.1#73012)
_______________________________________________
logback-dev mailing list
logback-dev@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-dev
