RestController方法返回Boolean对象时SpringFramework报告HTTP Status 406 – Not Acceptable

图片来自pixabay.com的mrgajowy3会员

1. 问题描述

一个简单的spring mvc样例,spring-webmvc框架版本为5.1.5.RELEASE,里面定义了两个RestController接口方法,

@RestController
@RequestMapping(value = "/api", produces = "application/json; charset=utf-8")
public class SimpleController {

    @RequestMapping(value = "test", method = RequestMethod.GET)
    public String test() {
        return "hello,world";
    }

      @RequestMapping(value = "test2", method = RequestMethod.GET)
    public Boolean test2() {
        return Boolean.TRUE;
    }

}

通过http客户端工具调用/api/test接口能够正常返回信息,但是调用/api/test2时,报如下错误信息,

<body><h1>HTTP Status 406 – Not Acceptable</h1><hr class="line" /><p><b>Type</b> Status Report</p><p><b>Description</b> The target resource does not have a current representation that would be acceptable to the user agent, according to the proactive negotiation header fields received in the request, and the server is unwilling to supply a default representation.</p><hr class="line" /><h3>Apache Tomcat/8.5.37</h3></body>

后端日志报如下HttpMediaTypeNotAcceptableException异常信息,

org.springframework.web.HttpMediaTypeNotAcceptableException: Could not find acceptable representation

2. 问题调查

问题奇怪在于,接口api/test能正常返回信息,但接口api/test2报错。比较下两个接口,都差不多,区别在于:前者返回String,后者返回Boolean对象。

调试跟踪api/test2的接口,发现异常HttpMediaTypeNotAcceptableException在如下位置被抛出,

/** 调用栈
 * DispatcherServlet.doDispatch()
 * AbstractHandlerMethodAdapter.handle()
 * RequestMappingHandlerAdapter.invokeHandlerMethod()
 * ServletInvocableHandlerMethod.invokeAndHandle(webRequest, mavContainer, providedArgs)
 * this.returnValueHandlers.handleReturnValue(returnValue, this.getReturnValueType(returnValue), mavContainer, webRequest);
 * AbstractMessageConverterMethodProcessor.handleReturnValue()
 * this.writeWithMessageConverters(returnValue, returnType, inputMessage, outputMessage);
 *
 * 到达类AbstractMessageConverterMethodProcessor中的如下方法,
 * 注:如下为反编译代码,非源码,仅供问题调查
 */

protected <T> void writeWithMessageConverters(...){
    ...
    HttpMessageConverter converter;
    GenericHttpMessageConverter genericConverter;
    label138: {
        if(selectedMediaType != null) {
            selectedMediaType = selectedMediaType.removeQualityValue();
            var21 = this.messageConverters.iterator();

            while(var21.hasNext()) {
                converter = (HttpMessageConverter)var21.next();
                genericConverter = converter instanceof GenericHttpMessageConverter?(GenericHttpMessageConverter)converter:null;
                if(genericConverter != null) {
                    if(((GenericHttpMessageConverter)converter).canWrite((Type)declaredType, valueType, selectedMediaType)) {
                        break label138;
                    }
                } else if(converter.canWrite(valueType, selectedMediaType)) {
                    break label138;
                }
            }
        }

        if(outputValue != null) {
            // 异常抛出点
            throw new HttpMediaTypeNotAcceptableException(this.allSupportedMediaTypes);
        }

        return;
   }
   ...
}

查看上传代码,可以了解异常抛出的原因,是因为没有找到合适HttpMessageConverter,无法转换返回的消息。

调试查看this.messageConverters对象,发现有converters列表如下,

this.messageConverters ( ArrayList size = 7)
[0] ByteArrayHttpMessageConverter
[1] StringHttpMessageConverter
[2] ResourceHttpMessageConverter
[3] ResourceRegionHttpMessageConverter
[4] SourceHttpMessageConverter
[5] AllEncompassingFormHttpMessageConverter
[6] Jaxb2CollectionHttpMessageConverter

这个列表没有发现我们熟悉的Json Converter,于是接下来开始追查messageConverters的列表初始化,为什么没有Json converter?

查看spring mvc源码可以看到如下的convert初始化过程,
1. 在类RequestMappingHandlerAdapter中创建this.messageConverters列表对象,并加载各个缺省convert。
2. 其中AllEncompassingFormHttpMessageConverter被创建,在这个类中,其会检查当前JVM中是否加载了Jackson/Gson相关类,若有,则加载json converter。

public class RequestMappingHandlerAdapter {

  public RequestMappingHandlerAdapter() {
      StringHttpMessageConverter stringHttpMessageConverter = new StringHttpMessageConverter();
      stringHttpMessageConverter.setWriteAcceptCharset(false);
      this.messageConverters = new ArrayList(4);
      this.messageConverters.add(new ByteArrayHttpMessageConverter());
      this.messageConverters.add(stringHttpMessageConverter);
      this.messageConverters.add(new SourceHttpMessageConverter());
      this.messageConverters.add(new AllEncompassingFormHttpMessageConverter());
  }

}

public class AllEncompassingFormHttpMessageConverter {

    private static final boolean jackson2Present = ClassUtils.isPresent("com.fasterxml.jackson.databind.ObjectMapper", ...);
    private static final boolean gsonPresent = ClassUtils.isPresent("com.google.gson.Gson", ...);

    public AllEncompassingFormHttpMessageConverter() {
      ...
      if(jackson2Present) {
        this.addPartConverter(new MappingJackson2HttpMessageConverter());
      } else if(gsonPresent) {
        this.addPartConverter(new GsonHttpMessageConverter());
      } else if(jsonbPresent) {
        this.addPartConverter(new JsonbHttpMessageConverter());
      }
      ...
    }
}

由此可以看到,缺少json converter的原因就是缺少相应的Jackson/Gson类库,而默认的converter无法对Boolean对象转换,从而产生HttpMediaTypeNotAcceptableException异常,接而导致HTTP 406的返回消息。

3. 问题解决

在项目中添加如下依赖,加载MappingJackson2HttpMessageConverter到this.messageConverters列表中,问题得到解决。

<dependency>
    <groupId>com.fasterxml.jackson.core</groupId>
    <artifactId>jackson-databind</artifactId>
    <version>${fasterxml.version}</version>
</dependency>

JVM 8的启动参数

图片来自pixabay.com的Myriams-Fotos会员

1. JVM版本

本文所描述的启动参数在如下JVM版本测试通过,

java version "1.8.0_172"
Java(TM) SE Runtime Environment (build 1.8.0_172-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.172-b11, mixed mode)

启动参数的推荐值主要针对的场景为:4核CPU + 4G内存的机器配置,部署单应用,应用的堆内存使用量在1-2GB。

2. 服务器配置

参数名 说明 默认值 推荐值 备注
server Java Hotsport Server VM 64位机器默认为server选项 启用 -

3. 堆大小

参数名 说明 默认值 推荐值 备注
Xms 堆空间初始大小 若没有设置,则根据old+young计算得出 Xms2G 堆的大小根据物理内存配置,不大于所能提供的物理内存
Xmx 堆空间最大值 根据系统配置 Xmx3G
XX:NewRatio Old/Young的空间比例 2 XX:NewRatio=2
XX:SurvivorRatio Eden/Survivor的空间比例 8 XX:SurvivorRatio=8
XX:+UseAdaptiveSizePolicy 分代空间动态调整 启用 启用 年轻代占整个堆内存三分之一,Survivor区占整个年轻代十分之一。(为推荐值,实际JVM会动态进行调优)

4. 元空间和线程栈大小

参数名 说明 默认值 推荐值 备注
XX:MaxMetaspaceSize 元数据空间大小 无上限 XX:MaxMetaspaceSize=256M
Xss 线程栈空间大小 根据virtual memory计算而定 Xss256K 栈的大小根据应用所需并发线程数决定,1000线程*256KB = 256 MB。若线程数大于2000,可以考虑配置为128KB。

5. GC回收器选择

5.1 串行GC回收器

不推荐为生产环境的配置,主要是由于无法利用现代计算机的多核优势。

适合的应用场景,
1. 对性能要求不要高的简单客户端应用,开发环境
2. 堆内存设置不大(<200MB)
3. 物理机器是单核CPU

5.2 并行GC回收器

此为JVM 8默认GC回收器。

适合的应用场景,
1. 生产环境的后台应用服务器
2. 系统配置较高,通常情况下至少四核(以目前的硬件水平为准)
3. 应用程序运行时间较长,对吞吐量要求较高,应用程序使用的堆内存大于1G

5.3 并发GC回收器(年轻代Parallel GC, 老年代CMS GC)

不推荐,JDK9已经移除对CMS GC的支持

5.4 G1回收器

此为JVM 9默认GC回收器。

适合的应用场景,
1. 生产环境的后台应用服务器
2. 系统配置较高,通常情况下至少四核(以目前的硬件水平为准)
3. 应用程序运行时间较长,对吞吐量要求较高,应用程序使用的堆内存大于4G

6. 日志和诊断信息

参数名 说明 默认值 推荐值 备注
XX:+PrintGCDetails
XX:+PrintGCDateStamps
Xloggc:./gc.log
XX:+PrintHeapAtGC
XX:+PrintTenuringDistribution
输出GC日志,以便监控查看 未开启 启用
XX:+HeapDumpOnOutOfMemoryError
XX:HeapDumpPath=./dump.hprof
在OOM时输出内存快照,以便后续问题调查 未开启 启用 相比PrintGCTimeStamps,使用PrintGCDateStamps会更加清晰易懂

7. 启动参数推荐样例

7.1 普通应用

  • 服务器配置:4核CPU + 4G内存,单应用部署。
  • 应用:堆内存使用量在500MB到1GB左右
java -server -Xms2G -Xmx2G -XX:MaxMetaspaceSize=256M -Xss256K -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseAdaptiveSizePolicy -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:../logs/gc.log -XX:+PrintTenuringDistribution  -XX:+PrintHeapAtGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=../logs/dump.hprof -jar pphh.jar

7.2 大内存堆的应用

  • 服务器配置:4核CPU + 16G内存,单应用部署,有足够的物理内存
  • 应用:堆内存使用量在2GB左右
java -server -Xms4G -Xmx4G -XX:MaxMetaspaceSize=256M -Xss256K -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseAdaptiveSizePolicy -XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:../logs/gc.log -XX:+PrintTenuringDistribution  -XX:+PrintHeapAtGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=../logs/dump.hprof -jar pphh.jar

7.3 大内存堆的应用(物理内存出现瓶颈)

  • 服务器配置:4核CPU + 4G内存,部署单应用,
  • 应用:堆内存使用量在2GB左右
  • 物理内存只有4G,应用的堆内存无法设置为4G,并启用JVM的UseStringDeduplication
java -server -Xms3G -Xmx3G -XX:MaxMetaspaceSize=256M -Xss256K -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseAdaptiveSizePolicy -XX:+UseG1GC -XX:+UseStringDeduplication -XX:+PrintStringDeduplicationStatistics -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:../logs/gc.log -XX:+PrintTenuringDistribution  -XX:+PrintHeapAtGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=../logs/dump.hprof -jar pphh.jar

7.4 JVM7的普通应用配置

  • 服务器配置:4核CPU + 4G内存,单应用部署
  • 应用:堆内存使用量在500MB到1GB左右
java -server -Xms2G -Xmx2G -XX:MaxPermSize=256M -Xss256K -XX:NewRatio=2 -XX:SurvivorRatio=8 -XX:+UseAdaptiveSizePolicy -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:../logs/gc.log -XX:+PrintTenuringDistribution  -XX:+PrintHeapAtGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=../logs/dump.hprof -jar pphh.jar

8. 参考资料

一个JedisConnectionException的异常跟踪调查

图片来自pixabay.com的spencerlikestorun会员

1. 问题缘起

有一个web服务应用一直在稳定运行,直到最近一个月,陆续三次在晚上出现了JedisConnectionException的异常,服务集群几乎在同一时间段都报同一错误,无法正常运行,重启后一切正常。

redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool
   at redis.clients.util.Pool.getResource(Pool.java:50)
   at redis.clients.jedis.JedisPool.getResource(JedisPool.java:86)
    …
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
    at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:449)

2. 现场处理和初步调查结论

  • JedisConnectionException异常所报告的问题是,无法正常获取连接,通过查看redis连接池配置(maxTotal=200)和当时的并发流量(并发数小于5),没有发现不对和特别的地方。
  • 通过netstat查看网络TCP连接,redis连接数也不多(小于20),正常连接中,在redis服务器端可以观察到有连接正在陆续正常地新建和关闭,网络没有问题。
  • 查看zabbix和pinpoint监控,主站应用的CPU使用率有升高,不过在正常范围内,但响应时间有飙高(长达6秒),预计是获取redis连接阻塞的原因(在redis客户端设置阻塞时间为6秒)。
  • 为了能够保证主站恢复使用,调查一段时间后,决定重启应用,然后检查所有服务,一切恢复正常使用。

3. 调查方向

根据现象,确定如下几个调查方向,

  1. 查看redis的访问代码实现,是否有redis连接泄漏?并尝试是否可以本地开发环境重现同样问题。
  2. 查看线上配置,是否配置不正确或者未加载的情况?
  3. 查看网络原因,是否由于因为防火墙导致单机连接有限制?
    • 查看iptables
    • 使用tcpdump查看TCP流量
  4. 查看主站应用的请求访问日志和运行日志,查看异常前后有无特别的请求访问?
    • 请求访问日志 localhost_access_log.2018-12-28
    • 运行日志 catalina.out-20181228

4. 定位问题

通过查看代码时,发现有段代码在获取redis连接后,没有在方法退出时执行close()方法,

public void leakRedisConn() {
  Jedis jedis = null;
    try {
        jedis = jedisPool.getResource();
        jedis.ping();
    } catch (Exception ignored) {
    } finally {
        // 没有归还redis连接到空闲资源池
        // if (jedis != null) jedis.close();
    }
}

查看服务集群的请求访问日志和运行日志,发现在JedisConnectionException异常出现前,都有对该方法的调用,印证此方法和异常的出现有强关联性,因此上述方法应该就是异常发生的罪魁祸首。

该方法在获取连接后,并没有执行close()方法,使得redis连接无法回收到空闲资源池,每一次调用,都会泄漏一个连接,直到整个连接池队列达到上限,从而出现异常。具体原因见对JedisPool的代码分析。

5. 异常出现的原因和JedisPool代码分析

通过分析JedisPool的实现代码,可以看到里面有两个内部对象allObjects和idleObjects,一个是保存着所有连接对象,一个是保存着所有空闲连接对象,

public class JedisPool extends Pool<Jedis> {
  protected GenericObjectPool<T> internalPool;
}

// JedisPool里通过GenericObjectPool维护着所创建的连接池对象,实现Jedis连接的创建、获取和回收,
class GenericObjectPool{
    private final Map<T, PooledObject<T>> allObjects; // 保存着所有连接对象,上限通过maxTotal控制
    private final LinkedBlockingDeque<PooledObject<T>> idleObjects; // 保存着所有空闲连接对象,上限通过maxIdle控制
}

每次创建时,新建的连接会放入allObjects列表中,在close()方法调用时,空闲的连接会存放入idleObjects,以待后续重复利用。

方法jedisPool.getResource()会先尝试从空闲队列中获取连接,若获取不到,则尝试新建一个连接。一旦获取到的连接没有执行close()方法,则无法被回收到空闲队列,于是每一次方法调用,allObjects连接池中会增加一个,一旦数量超过maxTotal,则不再允许创建,请见下面的代码,

class GenericObjectPool{

  public T borrowObject(long borrowMaxWaitMillis) throws Exception {
     ...
     boolean create;
     p = (PooledObject)this.idleObjects.pollFirst();
     if(p == null) {
         p = this.create();
         if(p != null) {
            create = true;
         }
     }
     ...
  }

  private PooledObject<T> create() throws Exception {
        int localMaxTotal = this.getMaxTotal();
        long newCreateCount = this.createCount.incrementAndGet();

        // 当创建的个数大于maxTotal时,则不再允许创建,直接返回null
        if((localMaxTotal <= -1 || newCreateCount <= (long)localMaxTotal) && newCreateCount <= 2147483647L) {
            PooledObject p;
            try {
                p = this.factory.makeObject();
            } catch (Exception var6) {
            }
            ...
            return p;
        } else {
            this.createCount.decrementAndGet();
            return null;
        }
  }

}

注意的是,泄漏的连接在redis服务器端在超时后会被关闭,但在客户端则一直占着位置不会被释放,从而报JedisConnectionException异常,直到重启。

5. 后记

对这个JedisConnectionException的异常泄漏问题解决后,后来想了想,还有两个事情可以总结下,以待未来改进。

5.1 保留问题第一现场

在发生问题时,可以通过如下jmap命令保存下Java内存快照,保留第一现场,这样能够为后续查看发生问题,分析JedisPool对象的内部数据提供方便。

jmap -dump:format=b,file=jmap.dump <pid>

下图是通过Eclipse的MemoryAnalyzer工具分析的JedisPool对象,

jedis连接池

若当时有上面的内存快照,可以看到minIdle/maxIdle的配置情况,也可以看到createCount的变量值,这样会更加容易发现redis泄漏问题。

5.2 一颗老鼠屎,坏了一锅粥

对于Jedis连接池这种全局有限资源,必须严控管理,规范使用,不然一个地方出现泄漏,就会导致整个应用崩溃,本案例是一个活生生的例子。