记一次线上排查异步任务失败问题

Z时代
2024-01-10
分类：综合

问题描述

今天有客服反馈说，从某一天开始到现在有很一些订单属于没有代买状态（可以理解为没有创建订单的意思）。

然后我就登上线上机器查看相关方法的调用日志。从日志中看出，发现了SQL异常日志，没有调用到其他系统的创建订单方法。

异常日志如下：

2020-05-10 16:43:05,721 ERROR ThreadPoolTaskExecutor-82 interceptor.SimpleAsyncUncaughtExceptionHandler:39 - Unexpected exception occurred invoking async method: public void xxx.xxx.xxxServiceImpl.placeOrder(java.lang.String) throws xxx.xxx.ServerException
org.springframework.jdbc.BadSqlGrammarException: StatementCallback; bad SQL grammar [...省略...错误的sql]; nested exception is java.sql.SQLSyntaxErrorException: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near "xxxxxxsql" at line 1
	at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:234)
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
	at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1442)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:387)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:451)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:461)
	at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:472)
	at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:479)
	at com.xeshop.dao.db.impl.OrderDaoImpl.countOrder(OrderDaoImpl.java:78)
	...省略...

现象

系统分为两个web模块，API 和 ADMIN 模块，线上订单自动下单是 API 模块。ADMIN 模块用于后台管理。

我通过 admin 模块手动触发创建订单接口，发现了只打印了创建订单的日志，然后过了一段时间（大概 10 分钟）才在工作日志中发现下单失败。

工日日志记录了失败的原因，原因是最新上线的一个功能因为某个特殊参数导致的 SQL 错误，从而导致的下单方法失败。

这里有几个问题：

为什么线上触发自动异步下单时，只是打了一行日志以及相关的错误日志，没有记录工作日志？

为什么现在手动调用异步下单，过了一段时间才出现工作日志？

分析

仔细看下代码的异步信息和重试配置相关的代码。

admin 模块配置

@EnableWebSecurity
@EnableRetry
@EnableEurekaClient
@EnableCircuitBreaker
@EnableAspectJAutoProxy(proxyTargetClass = true, exposeProxy = true)
public class AdminStartupApplication {
  public static void main(String[] args) {
    SpringApplication app = new SpringApplication(AdminStartupApplication.class);
    app.run(args);
  }
}

api 模块配置

@EnableEurekaClient
@EnableCircuitBreaker
@EnableAspectJAutoProxy(proxyTargetClass = true, exposeProxy = true)
public class ApiStartupApplication {
  public static void main(String[] args) {
    SpringApplication app = new SpringApplication(ApiStartupApplication.class);
    app.run(args);
  }
}

执行创建订单的方法如下


  // 创建订单方法，异步+重试
  @Override
  @Async
  @Retryable(value = Exception.class, backoff = @Backoff(delay = 180 * 1000, maxDelay = 600 * 1000, multiplier = 2))
  public void createOrder(String orderSn) throws ServerException {
    log.info("create order, orderSn:{}", orderSn);
    // do something...
  }
  // 重试失败调用的方法
  @Recover
  private void recordCreateOrderFailedLog(Exception e, String orderSn) throws ServerException {
    log.info("create order failed, error msg: {} ", e.getMessage());
    // 添加工作日志
  }

异步任务线程池的配置信息

@Configuration
@EnableAsync
@EnableScheduling
public class ServiceConfig implements AsyncConfigurer, SchedulingConfigurer {
  @Override
  public Executor getAsyncExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    // 核心线程数是 100
    executor.setCorePoolSize(100);
    // 最大线程数 500
    executor.setMaxPoolSize(500);
    // 任务队列容量 500
    executor.setQueueCapacity(500);
    /*
    线程池拒绝策略：
    ABORT（缺省）：抛出TaskRejectedException异常，然后不执行
    DISCARD：不执行，也不抛出异常即放弃该线程
    DISCARD_OLDEST：丢弃queue中最旧的那个任务
    CALLER_RUNS：不在新线程中执行任务，而是由调用者所在的线程来执行(不再异步)，但是如果主线程已经结束，则任务会被拒绝
    */
    executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
    executor.initialize();
    return executor;
  }
  // 其他配置
 }

分析下代码：

创建订单的方法是异步方法，通过配置的异步任务线程池，来执行该方法。

线程池的核心大小是 100 个线程，最大线程数 500，任务队列容量是 500 ，采用的任务拒绝策略是 CallerRunsPolicy 主线程执行。

下单方法的重试策略配置如下：

  @Retryable(value = Exception.class, backoff = @Backoff(delay = 180 * 1000, maxDelay = 600 * 1000, multiplier = 2))

介绍一下几个注解

@EnableRetry能否重试。当proxyTargetClass属性为true时，使用CGLIB代理。默认使用标准JAVA注解。在spring Boot中此参数写在程序入口即可。

@Retryable 标注此注解的方法在发生异常时会进行重试
- value：指定处理的异常类
- include：指定处理的异常类和value一样，默认为空，当exclude也为空时，默认所有异常
- exclude：指定异常不处理，默认空，当include也为空时，默认所有异常
- maxAttempts：最大重试次数。默认3次
- backoff：重试等待策略。默认使用@Backoff注解

@Backoff 重试等待策略
- 不设置参数时，默认使用FixedBackOffPolicy（指定等待时间），重试等待1000ms
- 设置delay,使用FixedBackOffPolicy（指定等待时间），重试等待填写的时间
- 设置delay和maxDealy时，重试等待在这两个值之间均态分布
- 设置delay、maxDealy、multiplier，使用 ExponentialBackOffPolicy（指数级重试间隔的实现），multiplier即指定延迟倍数，比如delay=5000l,multiplier=2,则第一次重试为5秒，第二次为10秒，第三次为20秒……

@Recover 用于@Retryable重试失败后处理方法，此注解注释的方法参数一定要是@Retryable抛出的异常，否则无法识别，可以在该方法中进行日志处理。

value 是 Exception.class，backoff 是重试失败回退策略，delay 参数表示延迟执行的时间，单位毫秒，maxDelay 参数表示最大延迟执行的时间，单位毫秒，multiplier 参数下一次回退乘法倍率。

上面的配置的意思是说，这个方法执行时遇到 Exception 类型的异常可以进行重试，默认的重试次数是 3 次。并且是以重试回退策略的方式执行重试。重试回退策略是：以 180 秒的延迟时间，每次重试延迟时间以二倍倍率增长，最大延迟时间是 600 秒，即，第一次重试时间是 180 秒，第二次是 180 * 2 = 360 秒，第三次是（360 * 2 = 640 秒）< 600 秒，是 600 秒，也就是 10 分钟。

三次重试失败后，执行 recordCreateOrderFailedLog 方法，打印错误日志，记录工作日志数据。

那么，我们解决下上面提到的问题：

为什么线上触发自动异步下单时，只是打了一行日志，没有记录到工作日志？

答：

线上触发自动异步下单的代码是在 api 模块中，API 模块中的 springboot 启动类上没有增加 @EnableRetry 注解，所以下单方法先执行打印日志代码那进行日志打印，然后执行逻辑操作，此时发生了 SQL异常，不会执行重试操作，当然也不会执行到带有 @Recover 注解的方法，自然也不会记录工作日志了。

刚开始找问题的思路，一直围绕着线程池队列满的情况下任务被拒绝策略方向上，后来想了想那时候订单量并不是很多，线程池中的核心线程数很充裕，不会出现任务被拒绝的情况，并且任务已经被执行，哪怕是重试也不会出现被线程池拒绝的情况。

为什么现在手动调用异步下单，过了一段时间才出现工作日志？

答：

手动调用异步下单功能是在 admin 模块中，改模块使用 @EnableRetry 启动了重试功能，所以该下单方法在出现了 BadSqlGrammarException 异常（属于 Exception 异常），触发了重试，并且按照重试失败回退策略重试执行了三次，一共 600 秒，然后三次重试都失败，最后被 @Recover 注解标记的方法 recordCreateOrderFailedLog 方法 cover 住，记录工作日志。

解决

修复特殊参数导致 SQL 的错误的 BUG；

在 api 模块的 springboot 启动类上加入 @EnableRetry 注解，开启支持重试操作功能；

重新上线，解决问题。

总结

开发完毕业务除了测试一些基本 case，边缘的 case 也要考虑到；

平时自己开发代码时，遇到别人写的代码不懂的需要及时查阅资料，不能一知半解；

项目中用到相关的框架 API 技术需要充分的学习它的文档，了解各个参数说明和应用场景，不能为了用而用；

遇到问题先解决，事后及时做总结。

参考

在Spring Boot中使用Spring Retry

以上是记一次线上排查异步任务失败问题的全部内容，来源链接： utcz.com/z/516395.html

记一次线上排查异步任务失败问题

问题描述

现象

分析

解决

总结

参考

其他人也看了：