Loading...

Details

Type: Bug
Resolution: Unresolved
Priority: Major
Fix Version/s: None
Affects Version/s: 1.1.6, 1.2.1
Component/s: logback-access
Labels:
Environment:

Hide

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)

Show
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)

Description

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) &amp;&amp; (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) &amp;&amp; (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.

java.io.IOException: Stream closed in EvaluatorFilter

Details

Description

Attachments

Activity

People

Dates