概述

本文记录使用fastjson时遇到的一个问题。两个不同的应用，相同的代码片段，报错日志却不一致。

getOutputStream() has already been called for this response

生产环境下，EFK日志查询平台记录到如下更详细的报错信息：

write javaBean error, fastjson version 1.2.68, class org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryResponseWrapper, fieldName : 2, getOutputStream() has already been called for this response
at com.aba.open.merchant.aop.ControllerLogAop.doBefore(ControllerLogAop.java:45)
at com.aba.open.merchant.aop.ControllerLogAop.doAround(ControllerLogAop.java:68)
at com.aba.open.merchant.controller.MerchantLoginController$$EnhancerBySpringCGLIB$$420d319e.login(<generated>)

既然已经打印出报错的代码具体行数，那就首先去看代码：

@Aspect
@Component
@Slf4j
public class ControllerLogAop {

    @Pointcut("execution(public * com.aba.open.merchant.controller..*.*(..))")
    public void webLog() {
    }

    /**
     * 在切点之前织入
     */
    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) throws Throwable {
        // 打印请求相关参数
        log.info("===== Start =====");
        // 打印请求入参
        Object[] args = joinPoint.getArgs();
        Object[] arguments = new Object[args.length];
        for (int i = 0; i < args.length; i++) {
            if (args[i] instanceof ServletRequest || args[0] instanceof ServletResponse || args[0] instanceof MultipartFile) {
                continue;
            }
            arguments[i] = args[i];
        }
        log.info("类{}方法{}，请求参数= {}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(), JSON.toJSONString(arguments));
    }

    /**
     * 在切点之后织入
     */
    @After("webLog()")
    public void doAfter() throws Throwable {
        log.info("===== End =====");
    }

    /**
     * 环绕
     */
    @Around("webLog()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        Object result = proceedingJoinPoint.proceed();
        // 打印出参    
        log.info("返回参数= {}", JSON.toJSONString(result));
        // 执行耗时    
        log.info("耗时{} ms", System.currentTimeMillis() - startTime);
        return result;
    }
}

代码分析：很常见的AOP编程，目的是记录controller接口的请求体和响应体，方便问题排查。

报错原因【应该】是fastjson序列化某个请求体或响应体参数。

与此同时，根据被省略的日志，可以知道是在请求如下接口时打印的报错信息：

@PostMapping("/login")
@ApiOperation(value = "手机验证码登录", produces = "application/json", consumes="application/json")
public Response<String> login(@RequestBody @Valid MerchantLoginDTO loginDTO, HttpServletRequest request, HttpServletResponse response) {
}

报错是发生在生产，首先会想到如何在本地复现问题，上面也知道是具体哪个接口报错，那就在本地通过postman调试，尝试复现问题。

结合报错代码行，不难知道报错原因：fastjson序列化HttpServletResponse失败导致这个报错。

解决报错的方案自然也就很简单：修改for循环里面的if条件判断语句里面的args[0]，明显是敲代码或复制代码时的小错误，应该为args[i]。

事实上，这样修改后，报错消失。

UT010034: Stream not in async mode

值得一提的是，在修复上面这个merchant应用的报错日志后，过一段时间，另一个服务user也爆出fastjson序列化问题，具体的报错信息如下：

write javaBean error, fastjson version 1.2.83, class io.undertow.servlet.spec.HttpServletResponseImpl, fieldName : 1,
write javaBean error, fastjson version 1.2.83, class io.undertow.server.HttpServerExchange, 
fieldName : exchange, UT010034: Stream not in async mode
at com.aba.enduser.aop.ControllerLogAop.doBefore(ControllerLogAop.java:45)

具体的报错代码片段：

@Before("webLog()")
public void doBefore(JoinPoint joinPoint) throws Throwable {
    // 打印请求相关参数
    log.info("===== Start =====");
    // 打印请求入参
    Object[] args = joinPoint.getArgs();
    Object[] arguments = new Object[args.length];
    for (int i = 0; i < args.length; i++) {
        if (args[i] instanceof ServletRequest || args[0] instanceof ServletResponse || args[0] instanceof MultipartFile) {
            continue;
        }
        arguments[i] = args[i];
    }
    // 45行
    log.info("类{}方法{}，请求参数= {}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(), JSON.toJSONString(arguments));
}

两个服务，AOP配置类是copy过去的！

此时我们轻车熟路，看一下controller接口层代码：

@GetMapping(value = "/excelUser")
public void excelUser(String channel, HttpServletResponse response, String startTime, String endTime) {
}

也是有一个HttpServletResponse。

解决方法：还是把AOP编程类，for循环里面if条件判断语句中的args[0]换成args[i]。

问题是得到解决，为啥啊？

分析

根据上面的描述，两个应用都有相同的ControllerLogAop，即AOP编程，目的不言而喻，自然是为了记录controller接口的requestBody和responseBody。

其次两个应用的controller层接口非常相似，不关心其他String类型或POJO实体类型请求参数，两个接口都有HttpServletResponse。

为啥相同的代码片段，在不同的应用，报错日志却不一样？

考虑到merchant服务使用的fastjson版本为1.2.68，和fastjson版本有关？

那就升级merchant服务所使用的fastjson版本到1.2.83，但是仍然报错：

aba-merchant-provider | [http-nio-8849-exec-2] |  | ERROR | o.a.c.c.C.[Tomcat].[localhost].[/].[dispatcherServlet] | log | 175 | - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is com.alibaba.fastjson.JSONException: write javaBean error, fastjson version 1.2.83, class org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryResponseWrapper, fieldName : 2, getOutputStream() has already been called for this response] with root cause
java.lang.IllegalStateException: getOutputStream() has already been called for this response

由此可见，不同的报错日志和fastjson版本无关。

Stream not in async mode

报错堆栈日志：

at io.undertow.servlet.spec.ServletOutputStreamImpl.isReady(ServletOutputStreamImpl.java:757)

源码如下：

@Override
public boolean isReady() {
    if (listener == null) {
        // TODO: is this the correct behaviour?
        throw UndertowServletMessages.MESSAGES.streamNotInAsyncMode();
    }
    if (!anyAreSet(state, FLAG_READY)) {
        if (channel != null) {
            channel.resumeWrites();
        }
        return false;
    }
    return true;
}