[Java知识库]记一次SpringBean误用引起的线上并发问题

问题背景

之前和同事一起负责一个新上线产品登录模块，开始的时候处于小流量试运行，没有什么问题。突然从某天开始，部分用户报登录校验失败。该问题排查了很久，最终定位到是并发问题，这里回顾一下。

出现问题的关键代码

AuthParams

@Data
@Component
public class AuthParams {

    /**
     * 用户code
     */
    private String code;

    /**
     * 用户密码
     */
    private String pass;
}

由于该类并非简单的Java实体类，还需要依赖其他的SpringBean，所以将该类也标记了@Component注解。有经验的小伙伴可能已经猜出问题所在了。

AuthService

@Service
@Slf4j
public class AuthServiceImpl implements AuthService {

    /**
     * mock一下user信息
     */
    private static final Map<String, String> MOCK_USER = Maps.newHashMap();

    static {
        MOCK_USER.put("code1", "pass1");
        MOCK_USER.put("code2", "pass2");
    }

    @Override
    public boolean checkAuth(AuthParams authParams) {
        String code = authParams.getCode();
        String pass = authParams.getPass();
        boolean checkResult = MOCK_USER.containsKey(code) && MOCK_USER.get(code).equalsIgnoreCase(pass);
        if (!checkResult) {
            log.error("code:{}, pass:{}, result:{}", code, pass, checkResult);
        }
        return checkResult;
    }
}

这里采用Mock的方式，实际验证服务会依赖第三方统一登录，这里仅仅是为了验证问题。

AuthController

@RestController
@RequestMapping("/auth")
public class AuthController {

    @Resource
    private AuthService authService;

    @Resource
    private AuthParams authParams;

    @PostMapping(value = "/checkAuth")
    public boolean checkAuth(HttpServletRequest httpServletRequest) {
        String code = httpServletRequest.getParameter("code");
        String pass = httpServletRequest.getParameter("pass");
        authParams.setCode(code);
        authParams.setPass(pass);
        return authService.checkAuth(authParams);
    }
}

模拟对外权限认证的Rest服务接口，从Http请求中获取到code+pass，然后进行校验，返回校验结果。

AuthTest

@Slf4j
public class AuthTest {

    private static final ExecutorService EXECUTOR_SERVICE = Executors.newFixedThreadPool(100);

    private static final RestTemplate REST_TEMPLATE = new RestTemplate();

    private static final String URL = "http://127.0.0.1:8080/auth/checkAuth";


    public static void main(String[] args) {
        // 并发模拟用户登录
        for (int i = 0; i < 1; i++) {
            EXECUTOR_SERVICE.submit(new Runnable() {
                @Override
                public void run() {
                    int random = ThreadLocalRandom.current().nextInt(1, 3);
                    String code = "code" + random;
                    String pass = "pass" + random;
                    HttpHeaders headers = new HttpHeaders();
                    headers.setContentType(MediaType.APPLICATION_FORM_URLENCODED);

                    MultiValueMap<String, Object> map = new LinkedMultiValueMap<>();
                    // 将请求对象转为map，并添加到multiValueMap中
                    map.add("code", code);
                    map.add("pass", pass);
                    HttpEntity<MultiValueMap<String, Object>> httpEntity = new HttpEntity<>(map, headers);
                    boolean checkResult = REST_TEMPLATE.postForObject(URL, httpEntity, Boolean.class);
                    log.info("code:{}, pass:{}, checkResult:{}", code, pass, checkResult);
                }
            });
        }
    }
}

说明: 上述代码会模拟多线程并发访问，传入的code+pass，都是Service层Mock的数据。

问题复现

低并发场景

将AuthTest中的请求次数设置的低一些，比如10，看一下运行结果是正常的。

20:08:26.813 [pool-1-thread-7] INFO com.yichao.myblogs.controller.AuthTest - code:code2, pass:pass2, checkResult:true
20:08:26.813 [pool-1-thread-3] INFO com.yichao.myblogs.controller.AuthTest - code:code2, pass:pass2, checkResult:true
20:08:26.814 [pool-1-thread-1] INFO com.yichao.myblogs.controller.AuthTest - code:code1, pass:pass1, checkResult:true
20:08:26.817 [pool-1-thread-9] INFO com.yichao.myblogs.controller.AuthTest - code:code1, pass:pass1, checkResult:true
20:08:26.818 [pool-1-thread-6] INFO com.yichao.myblogs.controller.AuthTest - code:code1, pass:pass1, checkResult:true
20:08:26.820 [pool-1-thread-5] INFO com.yichao.myblogs.controller.AuthTest - code:code1, pass:pass1, checkResult:true
20:08:26.823 [pool-1-thread-4] INFO com.yichao.myblogs.controller.AuthTest - code:code2, pass:pass2, checkResult:true
20:08:26.824 [pool-1-thread-8] INFO com.yichao.myblogs.controller.AuthTest - code:code1, pass:pass1, checkResult:true
20:08:26.824 [pool-1-thread-2] INFO com.yichao.myblogs.controller.AuthTest - code:code2, pass:pass2, checkResult:true
20:08:26.827 [pool-1-thread-10] INFO com.yichao.myblogs.controller.AuthTest - code:code2, pass:pass2, checkResult:true

高并发场景

将AuthTest中的请求次数设置高一些，模拟高并发，这里设置1000，看一下运行结果。

20:11:05.829 [pool-1-thread-29] INFO com.yichao.myblogs.controller.AuthTest - code:code2, pass:pass2, checkResult:false
20:11:05.829 [pool-1-thread-92] INFO com.yichao.myblogs.controller.AuthTest - code:code2, pass:pass2, checkResult:true
20:11:05.829 [pool-1-thread-42] INFO com.yichao.myblogs.controller.AuthTest - code:code1, pass:pass1, checkResult:false
20:11:05.829 [pool-1-thread-69] INFO com.yichao.myblogs.controller.AuthTest - code:code2, pass:pass2, checkResult:true

可以看到这里就已经出现校验失败的了，明明传入的是正确的参数，为什么会失败了呢。

问题分析

我们都知道SpringBean默认是单例的，那么在线程并发的时候，如果在没有并发控制情况下，对Bean进行修改，势必会引发并发问题。

回到我们的代码

AuthParams通过@Component注解，被Spring管理。

@Component
public class AuthParams 

在AuthController中使用的时，直接利用@Resource使用了该Bean

@Resource
private AuthParams authParams;

那么当并发请求了"auth/checkAuth" Rest接口时，就会出现code和pass赋值错乱的问题。

我们在AuthServiceImpl中特意加了一些日志

if (!checkResult) {
  log.error("code:{}, pass:{}, result:{}", code, pass, checkResult);
}

2021-08-01 20:11:05.297 ERROR 24804 --- [nio-8080-exec-6] c.y.m.service.impl.AuthServiceImpl       : code:code1, pass:pass2, result:false
2021-08-01 20:11:05.297 ERROR 24804 --- [nio-8080-exec-4] c.y.m.service.impl.AuthServiceImpl       : code:code1, pass:pass2, result:false
2021-08-01 20:11:05.810 ERROR 24804 --- [io-8080-exec-20] c.y.m.service.impl.AuthServiceImpl       : code:code2, pass:pass1, result:false
2021-08-01 20:11:05.810 ERROR 24804 --- [nio-8080-exec-8] c.y.m.service.impl.AuthServiceImpl       : code:code2, pass:pass1, result:false
2021-08-01 20:11:06.146 ERROR 24804 --- [io-8080-exec-42] c.y.m.service.impl.AuthServiceImpl       : code:code2, pass:pass1, result:false
2021-08-01 20:11:06.146 ERROR 24804 --- [io-8080-exec-55] c.y.m.service.impl.AuthServiceImpl       : code:code2, pass:pass1, result:false
2021-08-01 20:11:06.156 ERROR 24804 --- [io-8080-exec-82] c.y.m.service.impl.AuthServiceImpl       : code:code1, pass:pass2, result:false
2021-08-01 20:11:06.156 ERROR 24804 --- [nio-8080-exec-1] c.y.m.service.impl.AuthServiceImpl       : code:code1, pass:pass2, result:false
2021-08-01 20:11:07.368 ERROR 24804 --- [io-8080-exec-59] c.y.m.service.impl.AuthServiceImpl       : code:code1, pass:pass2, result:false
2021-08-01 20:11:07.368 ERROR 24804 --- [io-8080-exec-63] c.y.m.service.impl.AuthServiceImpl       : code:code1, pass:pass2, result:false
2021-08-01 20:11:07.670 ERROR 24804 --- [io-8080-exec-36] c.y.m.service.impl.AuthServiceImpl       : code:code2, pass:pass1, result:false
2021-08-01 20:11:07.670 ERROR 24804 --- [io-8080-exec-77] c.y.m.service.impl.AuthServiceImpl       : code:code2, pass:pass1, result:false

通过上面的日志也看出了存在code和pass不匹配的情况。

问题解决

既然发现了问题，那就快速修复解决吧。我们知道SpringBean实际会有几种不同的scope。

这里着重介绍2类

• singleton(默认)
  • 此取值时表明容器中创建时只存在一个实例，所有引用此bean都是单一实例
• prototype
  • 允许创建任意多次实例，每个请求方可以得到自己对应的一个对象实例

可以看出，在我们场景中，需要的是prototype类型。那么直接修改AuthParams就可以了吗？

尝试一下吧！

在Controller中加了一条日志，看一下每次调用AuthServiceImpl前的authParams值，是不是每次都是单独的AuthParams

@PostMapping(value = "/checkAuth")
public boolean checkAuth(HttpServletRequest httpServletRequest) {
  String code = httpServletRequest.getParameter("code");
  String pass = httpServletRequest.getParameter("pass");
  log.info("before set,  code:{}, pass:{}", authParams.getCode(), authParams.getPass());
  authParams.setCode(code);
  authParams.setPass(pass);
  return authService.checkAuth(authParams);
}

同样以10000并发模拟

2021-08-01 20:31:23.262  INFO 25355 --- [o-8080-exec-229] c.y.myblogs.controller.AuthController    : before set,  code:code2, pass:pass2
2021-08-01 20:31:23.264  INFO 25355 --- [o-8080-exec-229] c.y.myblogs.controller.AuthController    : before set,  code:code1, pass:pass1
2021-08-01 20:31:23.267  INFO 25355 --- [o-8080-exec-146] c.y.myblogs.controller.AuthController    : before set,  code:code2, pass:pass2

奇怪，明明设置了prototype，那么日志打印的地方位于authParams赋值之前，怎么会有值呢。

这里需要特别强调的一点，由于AuthController是单例的，那么由它引入的AuthParams实际还是一个同一个实例，所以到这里还没有解决并发问题。

继续修改。不得不佩服强大的Spring。

@RestController
@RequestMapping("/auth")
@Slf4j
public class AuthController {

    @Resource
    private AuthService authService;

    @Resource
    private ApplicationContext applicationContext;

    @PostMapping(value = "/checkAuth")
    public boolean checkAuth(HttpServletRequest httpServletRequest) {
        String code = httpServletRequest.getParameter("code");
        String pass = httpServletRequest.getParameter("pass");
        AuthParams authParams = applicationContext.getBean(AuthParams.class);
        log.info("before set,  code:{}, pass:{}", authParams.getCode(), authParams.getPass());
        authParams.setCode(code);
        authParams.setPass(pass);
        return authService.checkAuth(authParams);
    }
}

改为直接使用ApplicationContext获取Bean。

这里说明一下，有的小伙伴可能会疑惑，为什么不直接new AuthParams。前面也提到过，由于实际场景中，AuthParams这个类还依赖其他SpringBean做一些处理，所以AuthParams这个类也需要交给Spring管理。直接new的话，就无法使用其他SpringBean了。

再次执行AuthTest

2021-08-01 20:38:54.675  INFO 25704 --- [io-8080-exec-61] c.y.myblogs.controller.AuthController    : before set,  code:null, pass:null
2021-08-01 20:38:54.675  INFO 25704 --- [io-8080-exec-32] c.y.myblogs.controller.AuthController    : before set,  code:null, pass:null
2021-08-01 20:38:54.676  INFO 25704 --- [io-8080-exec-22] c.y.myblogs.controller.AuthController    : before set,  code:null, pass:null
2021-08-01 20:38:54.677  INFO 25704 --- [io-8080-exec-95] c.y.myblogs.controller.AuthController    : before set,  code:null, pass:null

好开心，终于每次调用前，都是一个全新的AuthParams了，可以解决并发登录验证问题了。

接下来就是RCA(问题根源分析)，全组检讨😭。

问题总结

这个问题感觉还是比较普遍的，因为在我更换项目之后，在另外一个项目中有同学也犯了类似的错误。

总结一下这个case暴露的问题。

1. 对SpringBean的作用域和多线程并发问题认知不够。
2. 其实当时排查时还有一个问题，就是关键地方的日志不够，这也增加了我们排查定位问题的难度。
3. 对基础服务，尽可能提前做好压测，提前发现问题。实际上这段出问题的代码已经在线上环境跑了几个月了，如果不是用户访问增加，我们还是无法识别出问题。

每一次RCA都是宝贵的财富，共勉!