getOutputStream() has already been called for this response 从了解到解决

Posted 2020-11-23 qingmuchuanqi48

一、背景说明
        在tomcat的localhost.log日志中时长见到 getOutputStream() has already been called for this response 异常的身影，一直不知由于哪里原因导致异常的产生，此异常并不会影响前端客户正常使用。

二、认识异常
        异常详情如下所示(部分代码)：

org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [springServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.IllegalStateException: getOutputStream() has already been called for this response] with root cause
 java.lang.IllegalStateException: getOutputStream() has already been called for this response
    at org.apache.catalina.connector.Response.getWriter(Response.java:579)
    at org.apache.catalina.connector.ResponseFacade.getWriter(ResponseFacade.java:212)
    at org.springframework.web.servlet.view.velocity.VelocityView.mergeTemplate(VelocityView.java:519)
    at org.springframework.web.servlet.view.velocity.VelocityLayoutView.doRender(VelocityLayoutView.java:169)
    at org.springframework.web.servlet.view.velocity.VelocityView.renderMergedTemplateModel(VelocityView.java:294)
    at org.springframework.web.servlet.view.AbstractTemplateView.renderMergedOutputModel(AbstractTemplateView.java:167)
    at org.springframework.web.servlet.view.AbstractView.render(AbstractView.java:303)
    at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1257)
    at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1037)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:980)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)

getOutputStream() has already been called for this response  翻译过来是“getOutputStream 已经被要求做出这种回应”，普通话说就是response.getOutputStream()  已经用过了不能再次使用。
具体模拟此异常的伪代码如下所示(请自行忽略流关闭等相关代码)：

@Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        ServletOutputStream output= response.getOutputStream();
        response.getWriter().print("timerbin");
        return true;
    }

注：问题扩展
getWriter() has already been called for this response  此异常具体原因同上，区别在于，如下所示：
具体模拟此异常的伪代码如下所示(请自行忽略流关闭等相关代码)：

@Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        response.getWriter().print("timerbin");
    ServletOutputStream output= response.getOutputStream();
        return true;
}

没错你没有看错，只要是将response.getOutputStream()和 response.getWriter() 位置调换就会出现不同异常信息

三、了解异常

想要了解它就直接去看源码：
直接查看Response源码，其中核心代码如下所示

protected boolean usingOutputStream = false;
protected boolean usingWriter = false;
@Override
public ServletOutputStream getOutputStream()
    throws IOException {
    if (usingWriter) {
        throw new IllegalStateException
            (sm.getString("coyoteResponse.getOutputStream.ise"));
    }
    usingOutputStream = true;
    if (outputStream == null) {
        outputStream = new CoyoteOutputStream(outputBuffer);
    }
    return outputStream;
 
}
@Override
public PrintWriter getWriter()
    throws IOException {
    if (usingOutputStream) {
        throw new IllegalStateException
            (sm.getString("coyoteResponse.getWriter.ise"));
    }
    if (ENFORCE_ENCODING_IN_GET_WRITER) {
        setCharacterEncoding(getCharacterEncoding());
    }
    usingWriter = true;
    outputBuffer.checkConverter();
    if (writer == null) {
        writer = new CoyoteWriter(outputBuffer);
    }
    return writer;
}

一目了然，在Response中有两个Boolean类型的标usingOutputStream 和 usingWriter，哪个被用过就会被标为true，同一个请求，另一个就会报错。
继续查看Response源码发现一个重置方法，代码如下所示：

@Override
public void reset() {
    if (included) { //忽略servlet调用
        return;
    }
    getCoyoteResponse().reset();
    outputBuffer.reset();
    usingOutputStream = false;
    usingWriter = false;
    isCharacterEncodingSet = false;
}

通过这里可以找到一个此问题的解决方式，如果在代码中确实存在同时调用了response.getOutputStream()和 response.getWriter() 的话，可以在两个方法中间加上response.reset()代码，解决以上报错。

四、解决异常
        非常幸运的是，我们项目中的问题有两个特性：
         1、在我们项目中并没有找到可能存在连续调用response.getOutputStream() 和 response.getWriter() 代码的地方
         2、getOutputStream() has already been called for this response 异常在我们项目中是偶现的，同样的功能时好时坏。
        由于以上二个特性导致我定位到我们项目中问题耗时了2天。

使用的手段：
        1.修改logback.xml配置文件，增加[%thread] 配置，在每一行日志中输出线程ID，并将日志级别调整为INFO级别
        2.增加全局拦截器输出所有请求路径
        3.排查代码中所有使用到response.getOutputStream() 和 response.getWriter() 的地方

了解到的知识点：
        SpringMVC 中所有Controller接口进行返回时底层都是用response.getOutputStream() 或 response.getWriter()进行输出的，同时又增加了排查问题的难度。

通过对线上环境中所有日志进行监控发现，在出现getOutputStream() has already been called for this response 异常之前都出现了java.io.IOException: Broken pipe 异常(日志中ThreadId相同)，由于tomcat日志和业务日志分开隔离存储，导致延后暴漏了问题的本质。

小知识：
       java.io.IOException: Broken pipe 翻译过来是 “断开的管道” ，具体异常详情如下所示：

org.apache.catalina.connector.ClientAbortException: java.io.IOException:  Broken pipe
at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:393)
at org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:426)
at org.apache.tomcat.util.buf.ByteChunk.append(ByteChunk.java:339)
at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:418)
at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:406)
at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:97)
at com.fasterxml.jackson.core.json.UTF8JsonGenerator._flushBuffer(UTF8JsonGenerator.java:2039)
at com.fasterxml.jackson.core.json.UTF8JsonGenerator.flush(UTF8JsonGenerator.java:1051)
at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:953)

首先Broken pipe 断开的管道这个异常是允许在程序中出现。因为该异常是在客户端浏览器向服务端发起请求后，未等到服务端进行正常响应就关闭浏览器或页面，可以通过优化服务端接口处理性能来减少此类问题的产生，也有前辈推荐修改tomcat配置文件来减少此问题出现(不建议这么做)。

我们项目中问题的第二个特性：问题偶现
       通过以上的代码分析，已经确认我们项目中问题偶现的原因是由于客户端向服务端发起请求后，不待服务端正常返回直接关闭浏览器或页面，从而出现Broken pipe 异常，最终导致getOutputStream() has already been called for this response  异常的产生。

我们项目中问题的第一个特性：未同时使用response.getOutputStream() 或 response.getWriter() 代码
        由于Broken pipe异常的存在，成功让我缩小了定位问题的范围，经过排查发现项目中使用了SpringMvc的统一错误处理器，具体代码如下所示：

import org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver;
public class ExceptionResolver extends AbstractHandlerExceptionResolver {
    @Override
    protected ModelAndView doResolveException(HttpServletRequest request, HttpServletResponse response, Object handler,
            Exception ex) {
        /**
         * 配置不同的异常白名单 -> 跳转到指定的错误页
         * java.lang.Exception ->  error/404
         * java.lang.Throwable -> error/404
         */
        String viewName = getErrorView(ex, request);
        if (viewName != null) {
             ModelAndView mav = new ModelAndView();
             mav.setViewName(viewName);
             return mav;
        }else {
            return null;
        }
    }
}

通过以上代码就可以明确的分析出，我们项目中问题特性一的原因，由于在服务端接口处理完成后已正常返回，但是不幸遭遇Broken pipe异常，同时由于Broken pipe异常被ExceptionResolver 统一异常处理器捕获，再次返回到了error/404 错误页，最终导致在程序中出现错误异常，由于进行了两次Response

解决方案(临时解决方案)：

import org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver;
public class ExceptionResolver extends AbstractHandlerExceptionResolver {
    @Override
    protected ModelAndView doResolveException(HttpServletRequest request, HttpServletResponse response, Object handler,
            Exception ex) {
        if ("org.apache.catalina.connector.ClientAbortException".equals(ex.getClass().getName())) {
            return null;
        }
        /**
         * 配置不同的异常白名单 -> 跳转到指定的错误页
         * java.lang.Exception ->  error/404
         * java.lang.Throwable -> error/404
         */
        String viewName = getErrorView(ex, request);
        if (viewName != null) {
             ModelAndView mav = new ModelAndView();
             mav.setViewName(viewName);
             return mav;
        }else {
            return null;
        }
    }
}

估计每个人都会发现，笔记写到这里，感觉并未把问题完全描述清楚，没错是这样的，你没有感觉错。

由于我依旧存在不确定因素，就是在SpringMVC中在Controller接口中进行返回ModelAndView和 @ResponseBody 时，到底哪个使用了response.getOutputStream() ，而又是哪个使用了response.getWriter() 。