一次产品需求愉快的上线后，翌日下午有用户反馈，工单流程状态不对，为何不对呢？经过跟用户微信电话沟通，工单提交后，流程子状态应该展示
转存量。是的，没有错，业务流程
没有问题，应该是我的程序出现bug了。恰巧上线后翌日，北京气象局多次短信通知，有大暴雨，注意防涝。尽管如此，当日我依然来到公司，排查一些其他反馈问题。室外开始大雨来临，
我收拾电脑准备回家，到家后准备吃饭，微信群又反馈出现几单状态不正确，我回复"刚到家，吃饭后立即排查"。吃饭后，经过电脑前一系列排查最终找到问题，当时已经晚上22点多了。
1.业务概述
如上图业务逻辑是这么处理的：
-
1.提交工单时，用户可以选择转存，输入一个天数，然后提交成功。这时候单子需要变成
转存量。 -
2.技术方案中是这么处理，对于转存的订单，通过redis设置key的失效时间（这里的时间就是转存天数换算成的秒）。
-
3.客户端通过订阅Key失效事件，判断是转存订单，然后会通过redis zset对象入队；同时，把转存队列的该工单出队，实现工单队列从转存队列转移到正式队列。
-
4.正式队列的工单系统会定时轮询去派单。
-
工单队列示例
2.排查过程
服务是基于容器构建部署，线上初步上线经过评估，仅发布了两个实例节点。我依次打开两个
webshell窗口，根据我编写的代码业务逻辑排查输出的日志。
- 应用实例服务器1关键日志截图：
从上图截图，可以看到一次完成的工单提交操作，包括表单提交的数据，delayDays=3。但是，在正式队列入队前构建上下文对象时，expireSeconds=10800。
日志的输出的时间是：2020-08-12 15:16:03.591。
- 应用实例服务器2关键日志截图：
另一台服务器收到该工单（通过Redis存储并设置key失效时间）的失效事件，发生的时间2020-08-12 18:16:05.373。相当于当天该工单就失效了，转存才6个小时就失效了。
- RedisKeyExpirationListener
监听Key失效事件
@Component
@Slf4j
public class RedisKeyExpirationListener extends KeyExpirationEventMessageListener {
final static String STORED_CACHE_KEY_PREFIX = WorkOrderCacheManager.CacheType.stored_cache.getKey();
final static String SUSPENDED_CACHE_KEY_PREFIX = WorkOrderCacheManager.CacheType.suspended_cache.getKey();
@Autowired
TraceLogService traceLogService;
@Autowired
RedisService redisService;
@Autowired
WorkOrderService workOrderService;
@Autowired
DelayedScheduledOperateBridge delayedScheduledOperateBridge;
public RedisKeyExpirationListener(RedisMessageListenerContainer listenerContainer) {
super(listenerContainer);
}
@Override
public void onMessage(Message message, byte[] pattern) {
Date startTime = TimeTools.createNowTime();
String expiredKey = message.toString();
String bizPrefix = redisService.getKeyPrefix().getName();
if(!expiredKey.startsWith(bizPrefix)){
return;
}
String caseOfStored = redisService.getKey(STORED_CACHE_KEY_PREFIX);
String caseOfSuspended = redisService.getKey(SUSPENDED_CACHE_KEY_PREFIX);
WorkOrderCacheManager.CacheType cacheType;
WorkOrderContext.QueueType queueType;
if(expiredKey.startsWith(caseOfStored)){
queueType = WorkOrderContext.QueueType.stored;
cacheType = WorkOrderCacheManager.CacheType.stored_cache;
}else if(expiredKey.startsWith(caseOfSuspended)){
queueType = WorkOrderContext.QueueType.suspended;
cacheType = WorkOrderCacheManager.CacheType.suspended_cache;
}else{
return;
}
String workCode = getWorkCode(expiredKey);
log.info("监听到 redis key=[{}] 已过期",expiredKey);
if(Objects.nonNull(workCode)){
log.info("监听到 redis key=[{}],挂起|转存工单开始处理，workCode={}",expiredKey,workCode);
WorkOrder workOrder = workOrderService.queryOne(workCode);
if(Objects.isNull(workOrder)){
log.info("监听到 redis key=[{}],挂起|转存工单开始处理，未找到工单，workCode={}",expiredKey,workCode);
return;
}
WorkOrderContext delayedContext = WorkOrderContext.builder()
.worOrder(WorkOrderContext.WorkOrder.builder().delayedTime(5).priority(workOrder.getCasePriority()).workCode(workOrder.getWorkCode()).build())
.queueType(queueType). build();
Boolean done = delayedScheduledOperateBridge.transferImmediateQueue(cacheType,delayedContext);
saveTraceLog(delayedContext,done,traceLog -> {
JSONObject requestBody = new JSONObject();
requestBody.put("expiredKey",expiredKey);
requestBody.put("workCode",workCode);
traceLog.setRequestBody(requestBody.toJSONString());
traceLog.setRequestTime(startTime);
});
}
}
/**
* traceLog入库
* @param context
* @param done
* @param consumer
*/
void saveTraceLog(WorkOrderContext context, Boolean done, Consumer<TraceLog> consumer){
try {
String hostAddress = InetAddress.getLocalHost().getHostAddress();
JSONObject responseBody = new JSONObject();
responseBody.put("workOrderContext",context);
responseBody.put("transferImmediateQueue",done);
TraceLog traceLog = TraceLog.builder()
.appCode(context.getWorOrder().getWorkCode())
.url("["+hostAddress+"]redisKeyExpirationListener.onMessage")
.target(this.getClass().getPackage().getName() + "." + this.getClass().getSimpleName())
.responseBody(responseBody.toJSONString())
.responseTime(TimeTools.createNowTime())
.traceType(TraceTypeEnum.REDIS_KEY_EXPIRE.getIndex())
.build();
consumer.accept(traceLog);
traceLogService.insertRecord(traceLog);
} catch (Exception e) {
log.error("saveTraceLog exception,[context={}]",JSONObject.toJSONString(context),e);
}
}
/**
* 从字符串截取制定的工单号
* @param value
* @return
*/
String getWorkCode(String value){
return value.substring(value.lastIndexOf("_") + 1);
}
}
带着诡异的表情，打开转存的类SubmitWithStoreOperateStrategy源代码，找到最关键设置延迟秒的代码如下
@Slf4j
@Component
public class SubmitWithStoreOperateStrategy extends AbstractSubmitOperateStrategy{
@Override
public void prepare(OperateContext context) {
ATTENTION_EVENT_CONTEXT.set(AttentionEventEnum.STORE_ORDER);
context.setAttentionEvent(AttentionEventEnum.STORE_ORDER);
super.prepare(context);
}
@Override
public boolean paramCheck(OperateContext context) {
if(Objects.isNull(context.getSurveyResult().getDelayedDays())){
context.buildExecuteResultWithFailure("[surveyResult.delayedDays]为空！");
}
if(context.getSurveyResult().getDelayedDays() == 0){
context.buildExecuteResultWithFailure("等待天数[delayedDays]必须大于0！");
}
return super.paramCheck(context);
}
@Override
WorkOrder buildWorkOrder(OperateContext context){
WorkOrder workOrder = super.buildWorkOrder(context);
workOrder.setMainStatus(WorkOrderStatusEnum.PENDING.getIndex());
workOrder.setSubStatus(WorkOrderStatusEnum.SubStatusEnum.STORED.getIndex());
workOrder.setIsFinished(Const.NON_INDEX);
workOrder.setIsStore(Const.YES_INDEX);
//setSuspendedCount 这里需要重置为0，转存后派单流程状态依赖该字段
workOrder.setSuspendedCount(0);
workOrder.setDelayedTime(context.getOperateParam().getDelayedTime());
return workOrder;
}
@Override
void operationExtend(OperateContext context) {
long delayedTime = context.getOperateParam().getDelayedTime().getTime();
int delayedSeconds = context.getOperateParam().getDelayedSeconds();
WorkOrder workOrder = context.getWorkOrder();
WorkOrderContext cxt = WorkOrderContext.buildStored(workOrder.getWorkCode(),workOrder.getCasePriority(),delayedTime);
workOrderQueueManager.leftPush(cxt);
WorkOrderCacheManager.CacheValue cacheValue = WorkOrderCacheManager.CacheValue.
buildStored(workOrder.getWorkCode(),workOrder.getCasePriority(),delayedTime,delayedSeconds);
workOrderCacheManager.setCacheInExpire(cacheValue);
super.operationExtend(context);
}
@Override
public void setDelayedTime(OperateContext context) {
int delayedDays = context.getSurveyResult().getDelayedDays();
Date delayedTime = TimeTools.createNowTime();
TimeTools.addTimeField(delayedTime, Calendar.DAY_OF_YEAR,delayedDays);
context.getOperateParam().setDelayedTime(delayedTime);
context.getOperateParam().setDelayedSeconds(delayedDays * 3600);
}
}
这里有一句关键代码 context.getOperateParam().setDelayedSeconds(delayedDays * 3600);，逗比了吧，换算秒错了。看来是粘贴代码导致的，
由于在测试时，转存的订单最低等一天（转存按照天）之后才能看到测试用例结果，所以跟测试沟通，我手动调整key的失效时间，这样及时看到问题。但恰巧测不到这次发生问题。
所以有了今日微信朋友圈的上线感慨Often what you think is impossible is likely to be possible.
代码修复完毕并本地验证一下，没问题，然后发布补丁修复了。
修复代码：
/**
* 转存天数 换算 秒数
*/
static final int DAY_TO_SECONDS = 24 * 60 * 60;
///省略中间若干代码
context.getOperateParam().setDelayedSeconds(delayedDays * DAY_TO_SECONDS);
对于通过Redis设置Key失效时间，既然缩小了24倍，那么直接把这些Key失效时间再扩大24倍即可。顺着这条思路，由于客户端以及相关平台没法操作Redis相关命令，只好
联系DBA同事，诉说缘由并协助。
- 查找相关命令
报备使用的database以及port，dba开始操作如下命令
keys 'carCarthage:stored_cache_*'
得到如下keys结果如下（忽略图不对）
然后通过 expireat key 命令重新设置key失效时间（我跟DBA说只要失效时间即便多个几秒也行）。
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120215"
(integer) 902268
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120238"
(integer) 39364
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120216"
(integer) 720777
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120237"
(integer) 23332
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120313"
(integer) 4839
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120045"
(integer) 51896
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120189"
(integer) 208902
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120199"
(integer) 330349
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120111"
(integer) 944431
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120319"
(integer) 10129
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120208"
(integer) 520908
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120266"
(integer) 401959
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120131"
(integer) 302309
127.0.0.1:6676[6]> ttl "carCarthage:stored_cache_S202008120177"
(integer) 100336
设置完毕之后，延迟没有问题，故事尾声。
3.问题总结
“通常你认为的不可能往往很容易称为可能（
Often what you think is impossible is likely to be possible.）”。
所以代码review还是很重要的，测试的忽略点也很容易成为漏网之鱼。
下面的是我的公众号二维码图片，欢迎关注，或公众号搜索【秋夜无霜】。
1756
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
