springboot升级过程中踩坑定位分析记录 | 京东云技术团队

京东云开发者
• 阅读 335

作者:京东零售 李文龙

1.背景

俗话说:为了修复一个小bug而引入了一个更大bug

因所负责的系统使用的spring框架版本5.1.5.RELEASE在线上出过一个偶发的小事故,最后定位为spring-context中的一个bug导致的。

为了修复此bug进行了spring版本的升级,最终定的版本为收银台团队使用的版本5.2.12.RELEASE,对应的springboot版本为2.2.12.RELEASE。

选择这个版本的原因是:

1.有团队经过了长时间的线上验证

2.修复了5.1.5.RELEASE对应的bug

2.升级上线

升级相关版本后在预发环境进行了验证,暂未遇到关于框架的问题。本以为安全升级完成,在上线过程中发现在APP中无法访问,此时还未挂载流量。

日志中分析是某些参数未解析到,后在nginx日志中查到相关请求,使用postman模拟请求可以正常使用

3.分析验证定位原因

1.临时修复

在代码一致的情况下,唯一的可能就只能是线上与预发配置不同,经对比分析得出是某个过滤器的顺序在线上未配置,按照预发的配置后可正常使用。我们暂且称修改的这两个过滤器为MA,

其中默认情况下执行顺序为M->A,顺序修改为A->M后正常,其两者作用大致为:

M : 通用过滤器,解析url中的参数至parameterMap中,并初始化读取了body中的inputstream进行了byte数组的缓存,用于解决重复读取流问题 A: 特定处理器,先是查询parameter中的参数,然后逻辑处理后再设置一些特殊参数。

2.为何需要改过滤器顺序

经查未升级前过滤器的顺序与升级后过滤器顺序一致,为何升级spring框架后需要修改配置。此时猜测可能是spring在升级过程中修改了一部分代码,

但未有头绪,只能先调转方向分析为什么postman和浏览器中的swagger可以正常使用

3.分析nginx日志

前端请求与postman请求的nginx日志进行了分析得出了原因,对比日志如下:

postman POST /shop/bpaas/floor?client&clientVersion&ip=111.202.149.19&gfid=getShopMainFloor&body= 前端 : POST /shop/bpaas/floor HTTP/1.0" 200 634 "-" "api" "0.94" 0.008 0.007 client&clientVersion&ip=111.202.149.17&gfid=getShopMainFloor&body=

经过以上对比发现虽然postman使用了post请求,但数据还是放置在url中,在经过系统的一个内置过滤器M时将url中的参数解析到了parameterMap中,后续过滤器可以使用

request.getParameter获取到,注意此方法是解决问题的关键,此时还未意识到。

4.升级前后框架是否有大的修改

因升级的版本是升级了一个小版本号,所以不好对比升级的buglist,只能慢慢进行分析,后在分析过滤器时发现升级spring后过滤器个数由11个减少到了10个,减少了那一个为:

org.springframework.web.filter.HiddenHttpMethodFilter

此过虑器的作用是在浏览器不支持PUT、DELETE、PATCH等method时,可以在form表单中使用隐藏的_method参数支持这几种method。好像跟参数解析没有任何关系,

继续分析升级版本中 (由2.1.3.RELEASE->2.2.12.RELEASE)是否修改了此过滤器的一些内容,后在2.2.0.M5的release notes中发现HiddenHttpMethodFilter相关的:

Disable auto-configuration of HiddenHttpMethodFilter by default github上对应的版本release notes: https://github.com/spring-projects/spring-boot/releases/tag/v2.2.0.M5

也就是说升级后HiddenHttpMethodFilter默认配置由enable修改为了disable,如果再修改回去是不是可以修复参数解析的问题呢?

5.添加过滤器enable配置

因bug修复列表中有对应的issues,所以找到了此过滤器对应的配置:

-Dspring.mvc.hiddenmethod.filter.enabled=true

添加后可以正常使用,证明是此过滤器中在某种条件下不可缺少。

6.未升级spring版本时disable验证

在确认未升级版本的spring支持此参数的情况下,添加了以上参数,将默认的启动修改成了禁用,经验证:在不代码修改的情况下,无此过滤器时参数无法解析。证明了上步的猜测。

7.深入源码分析

此时需要分析HiddenHttpMethodFilter过滤器中是否有特殊操作,源码如下:

protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
            throws ServletException, IOException {

        HttpServletRequest requestToUse = request;

        if ("POST".equals(request.getMethod()) && request.getAttribute(WebUtils.ERROR_EXCEPTION_ATTRIBUTE) == null) {
            String paramValue = request.getParameter(this.methodParam);
            if (StringUtils.hasLength(paramValue)) {
                String method = paramValue.toUpperCase(Locale.ENGLISH);
                if (ALLOWED_METHODS.contains(method)) {
                    requestToUse = new HttpMethodRequestWrapper(request, method);
                }
            }
        }

        filterChain.doFilter(requestToUse, response);
    }

分析以上源码可以发现,有且只有一种可能,就是request.getParameter可能是解决问题的是关键。

8.大胆猜测

分析后源码猜测,第一步中的修改顺序有可能是A中有调用getParameter,所以顺序调整为A->M后,相当于间接使用了HiddenHttpMethodFilter。

9.开始验证

在不使用HiddenHttpMethodFilter的情况下,如果在过滤器原有顺序不修改的情况下,只要在M执行前调用了request.getParameter,理论上可以正常为使用。所以在debug情况下

利用工具在M过滤器调用前先行执行request.getParameter,发现的确可以正常使用。

10.分析过滤器

先前简述了M的功能,主要是包装了request,后读源码时发现,如果是post请求,读取body体中的数据后并未解析body中的参数至parameterMap中,而代码中的其它过滤器都是

通过request.getParameter获取的数据,重写后的代码:

public String getParameter(String name) {
        if ( this.parameterMap.containsKey(name) )
            return this.parameterMap.get(name);
        else {
            return super.getParameter(name);
        }
    }

在经过request包装后,先是从paremeterMap中获取数据,此时map肯定是没有数据,只能从父类获取,而父类获取时会解析parameter,解析时使用到了inputStream,但M过滤器

的在初始化时解析了输入流,此时tomcat内部使用内部的request获取stream时将获取到空数据,即无法从parameter中获取到body体中的数据。

而如果在调用M前调用了request.getParameter,tomcat内部将提前于M解析parameter,可以保证后续可获取到相关参数。

4. 修复方案

既然得出了结论,那么升级spring版本后修复此bug可选择的方案就比较多了,主要有:

  1. 启用HiddenHttpMethodFilter,添加对应的参数,保证升级前后过滤器个数与顺序一致

  2. 调整理过滤器A与M的顺序,保证M在A之前执行即可。

  3. 修改过滤器M内部的逻辑,不在初始化的时候解析body,或是在解析body后将参数重新放置到parameterMap中。

此文是笔者按照分析流程进行简单验证,分析验证过程中难免有遗漏之处,如有错误遗漏还烦请各位指出共同进步。

点赞
收藏
评论区
推荐文章
blmius blmius
3年前
MySQL:[Err] 1292 - Incorrect datetime value: ‘0000-00-00 00:00:00‘ for column ‘CREATE_TIME‘ at row 1
文章目录问题用navicat导入数据时,报错:原因这是因为当前的MySQL不支持datetime为0的情况。解决修改sql\mode:sql\mode:SQLMode定义了MySQL应支持的SQL语法、数据校验等,这样可以更容易地在不同的环境中使用MySQL。全局s
Wesley13 Wesley13
3年前
PPDB:今晚老齐直播
【今晚老齐直播】今晚(本周三晚)20:0021:00小白开始“用”飞桨(https://www.oschina.net/action/visit/ad?id1185)由PPDE(飞桨(https://www.oschina.net/action/visit/ad?id1185)开发者专家计划)成员老齐,为深度学习小白指点迷津。
Wesley13 Wesley13
3年前
VBox 启动虚拟机失败
在Vbox(5.0.8版本)启动Ubuntu的虚拟机时,遇到错误信息:NtCreateFile(\\Device\\VBoxDrvStub)failed:0xc000000034STATUS\_OBJECT\_NAME\_NOT\_FOUND(0retries) (rc101)Makesurethekern
Wesley13 Wesley13
3年前
FLV文件格式
1.        FLV文件对齐方式FLV文件以大端对齐方式存放多字节整型。如存放数字无符号16位的数字300(0x012C),那么在FLV文件中存放的顺序是:|0x01|0x2C|。如果是无符号32位数字300(0x0000012C),那么在FLV文件中的存放顺序是:|0x00|0x00|0x00|0x01|0x2C。2.  
Stella981 Stella981
3年前
SpringBoot整合Redis乱码原因及解决方案
问题描述:springboot使用springdataredis存储数据时乱码rediskey/value出现\\xAC\\xED\\x00\\x05t\\x00\\x05问题分析:查看RedisTemplate类!(https://oscimg.oschina.net/oscnet/0a85565fa
Wesley13 Wesley13
3年前
mysql设置时区
mysql设置时区mysql\_query("SETtime\_zone'8:00'")ordie('时区设置失败,请联系管理员!');中国在东8区所以加8方法二:selectcount(user\_id)asdevice,CONVERT\_TZ(FROM\_UNIXTIME(reg\_time),'08:00','0
Wesley13 Wesley13
3年前
PHP创建多级树型结构
<!lang:php<?php$areaarray(array('id'1,'pid'0,'name''中国'),array('id'5,'pid'0,'name''美国'),array('id'2,'pid'1,'name''吉林'),array('id'4,'pid'2,'n
Easter79 Easter79
3年前
SpringBoot整合Redis乱码原因及解决方案
问题描述:springboot使用springdataredis存储数据时乱码rediskey/value出现\\xAC\\xED\\x00\\x05t\\x00\\x05问题分析:查看RedisTemplate类!(https://oscimg.oschina.net/oscnet/0a85565fa
Stella981 Stella981
3年前
Jenkins 插件开发之旅:两天内从 idea 到发布(上篇)
本文首发于:Jenkins中文社区(https://www.oschina.net/action/GoToLink?urlhttp%3A%2F%2Fjenkinszh.cn)!huashan(https://oscimg.oschina.net/oscnet/f499d5b4f76f20cf0bce2a00af236d10265.jpg)
Wesley13 Wesley13
3年前
MySQL部分从库上面因为大量的临时表tmp_table造成慢查询
背景描述Time:20190124T00:08:14.70572408:00User@Host:@Id:Schema:sentrymetaLast_errno:0Killed:0Query_time:0.315758Lock_