[logback-dev] [JIRA] (LOGBACK-1262) java.io.IOException: Stream closed in EvaluatorFilter

QOS.CH (JIRA) noreply-jira at qos.ch
Thu Feb 16 08:38:00 CET 2017 

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)

More information about the logback-dev mailing list