《关于一个方法命名搞崩业务链的那件事》BUG
# 场景还原
场景：RabbitMQ使用延迟队列处理30分钟超时订单
业务实现：因为考虑到RabbitMQ延迟消息插件内部会维护一个本地数据库表，同时使用Elang Timers功能实现计时。如果消息的延迟时间设置较长，可能会导致堆积的延迟消息非常多，会带来较大的CPU开销，同时延迟消息的时间会存在误差。所以我们的解决方案如下：
我们在用户下单后的第10秒、20秒、30秒、45秒、60秒、1分30秒、2分、...30分分别设置延迟消息，如果提前发现订单已经支付，则后续的检测取消即可。这样就可以有效避免对MQ资源的浪费了。
生产者业务代码
static Long[] delayTimes = new Long[]{10000L, 10000L, 10000L, 10000L, 10000L, 10000L};
@Test
public void test() {
rabbitTemplate.convertAndSend("delay.direct", "delay",
SpinDelayMessage.of(2L, delayTimes));
}
1
2
3
4
5
6
2
3
4
5
6
像这样传入一个SpinDelayMessage声明消息TTL队列，上面的话就是延迟每10s检查一次订单支付状态。
问题就出在这个SpinDelayMessage对象中：
@Data
public class SpinDelayMessage<T> implements Serializable {
/**
* 消息体
*/
private T data;
/**
* 延迟时间数组(ms)
*/
private List<Long> delayTimes;
public SpinDelayMessage() {
}
public SpinDelayMessage(T data, List<Long> delayTimes) {
this.data = data;
this.delayTimes = delayTimes;
}
public static <T> SpinDelayMessage<T> of(T data, Long... delayTimes) {
return new SpinDelayMessage<>(data, new ArrayList<>(Arrays.asList(delayTimes)));
}
/**
* 获取下一次延迟时间
* @return 下一次延迟时间
*/
public Long getNextDelay() {
return delayTimes.remove(0);
}
/**
* 是否还有下一个延迟时间
* @return 是否还有下一个延迟时间
*/
public boolean hasNextDelayTime() {
return !delayTimes.isEmpty();
}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
※※※ 重点关注getNextDelay()这个方法名，get开头，但是执行的内容是从List中移除一个元素。乍一看好像没什么问题，甚至觉得有点巧妙，但是这里就埋下伏笔了。
我们再来看一下消费者这边的处理逻辑：
@RabbitListener(bindings = @QueueBinding(
value = @Queue(name = "delay.queue", durable = "true"),
exchange = @Exchange(name = "delay.direct", delayed = "true"),
key = "delay"
))
public void listenDelayMessage(SpinDelayMessage<Long> msg) {
// TODO 业务判断，如订单是否支付
if (msg.getData().equals(1L)) {
logger.info("订单已完成支付...");
return;
}
// 判断是否还有剩余时间
if (msg.hasNextDelayTime()) {
logger.info("剩余时间：{}", msg.getDelayTimes());
int delay = msg.removeAndGetNextDelay().intValue();
// 有剩余，重新加入队列
rabbitTemplate.convertAndSend("delay.direct", "delay", msg,
new DelayMessagePostProcessor(delay));
return;
}
// TODO 没有剩余时间，取消订单
logger.info("订单已超时...");
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
就是获取到消息后判断订单是否支付，未支付则判断是否还有剩余时间，如果还有剩余时间则丢回到队列中，消费者这边并没有什么问题。
可以看到我们生产者和消费者的消息都是直接用对象实体接收的，因为我们做了消息JSON的序列化和反序列化，这里或许也是伏笔之一。
我们来看执行效果：
2024-03-01T17:41:34.803+08:00 INFO 34544 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000, 10000, 10000]
2024-03-01T17:41:44.828+08:00 INFO 34544 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000, 10000]
2024-03-01T17:41:54.834+08:00 INFO 34544 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000]
2024-03-01T17:42:04.840+08:00 INFO 34544 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000]
2024-03-01T17:42:14.844+08:00 INFO 34544 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000]
2024-03-01T17:42:24.848+08:00 INFO 34544 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000]
2024-03-01T17:42:25.852+08:00 INFO 34544 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000]
2024-03-01T17:42:26.854+08:00 INFO 34544 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000]
2024-03-01T17:42:26.865+08:00 WARN 34544 --- [ntContainer#0-1] o.s.a.r.r.RejectAndDontRequeueRecoverer : Retries exhausted for message (Body:'{"data":2,"delayTimes":[10000],"nextDelay":10000}' MessageProperties [headers={__TypeId__=cn.kk.mq.SpinDelayMessage}, contentType=application/json, contentEncoding=UTF-8, contentLength=0, receivedDeliveryMode=PERSISTENT, priority=0, redelivered=false, receivedExchange=delay.direct, receivedRoutingKey=delay, receivedDelay=10000, deliveryTag=6, consumerTag=amq.ctag-qfcSCkqPSWfK1vOXDLB-tg, consumerQueue=delay.queue])
....
Caused by: java.lang.IndexOutOfBoundsException: Index 0 out of bounds for length 0
at java.base/jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:64) ~[na:na]
at java.base/jdk.internal.util.Preconditions.outOfBoundsCheckIndex(Preconditions.java:70) ~[na:na]
at java.base/jdk.internal.util.Preconditions.checkIndex(Preconditions.java:266) ~[na:na]
at java.base/java.util.Objects.checkIndex(Objects.java:359) ~[na:na]
at java.base/java.util.ArrayList.remove(ArrayList.java:504) ~[na:na]
at cn.kk.mq.SpinDelayMessage.getNextDelay(SpinDelayMessage.java:40) ~[classes/:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:688) ~[jackson-databind-2.15.3.jar:2.15.3]
at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:772) ~[jackson-databind-2.15.3.jar:2.15.3]
... 49 common frames omitted
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
wdf？为什么在最后一次剩余时间时执行了三次？？？我们跟进越界异常：
/**
* 获取下一次延迟时间
* @return 下一次延迟时间
*/
public Long getNextDelay() {
return delayTimes.remove(0);
}
1
2
3
4
5
6
7
2
3
4
5
6
7
明显是这行代码，为什么呢？我外面不是做了判断剩余时间集合是否为空，为空按理不应该执行这个方法的，于是我在这行代码中增加一个打印：
/**
* 获取下一次延迟时间
* @return 下一次延迟时间
*/
public Long getNextDelay() {
System.out.println("getNextDelay()方法执行...");
return delayTimes.remove(0);
}
1
2
3
4
5
6
7
8
2
3
4
5
6
7
8
再试一下：
2024-03-01T17:48:46.550+08:00 INFO 32824 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000, 10000, 10000]
getNextDelay()方法执行...
getNextDelay()方法执行...
2024-03-01T17:48:56.578+08:00 INFO 32824 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000, 10000]
getNextDelay()方法执行...
getNextDelay()方法执行...
2024-03-01T17:49:06.583+08:00 INFO 32824 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000]
getNextDelay()方法执行...
getNextDelay()方法执行...
2024-03-01T17:49:16.587+08:00 INFO 32824 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000]
getNextDelay()方法执行...
getNextDelay()方法执行...
2024-03-01T17:49:26.592+08:00 INFO 32824 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000]
getNextDelay()方法执行...
getNextDelay()方法执行...
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
2
3
4
5
6
7
8
9
10
11
12
13
14
15
好好好，这么玩是吧，也就是说消费者在发送消息时执行了一次，然后MQ在发送消息时又执行了一次，为什么MQ发消息他会自动执行这个方法呢？
我们关注点再回到这个方法名，说到get set方法相必各位都有想法了，调用这两个开头方法的时机可太多了，序列化、反射、spring，大把场景都会涉及到get set方法，所以这里推测就是MQ在做消息的JSON序列化的时候读取了所有get开头的方法，尝试作为属性名，那么解决方案的思路就很明确了。
# 解决方案
将方法名改成非get开头：
/**
* 获取下一次延迟时间
* @return 下一次延迟时间
*/
public Long removeAndGetNextDelay() {
return delayTimes.remove(0);
}
1
2
3
4
5
6
7
2
3
4
5
6
7
再试一次：
2024-03-01T17:56:37.038+08:00 INFO 19908 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000, 10000, 10000]
2024-03-01T17:56:47.059+08:00 INFO 19908 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000, 10000]
2024-03-01T17:56:57.065+08:00 INFO 19908 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000, 10000]
2024-03-01T17:57:07.072+08:00 INFO 19908 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000, 10000]
2024-03-01T17:57:17.075+08:00 INFO 19908 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000, 10000]
2024-03-01T17:57:27.079+08:00 INFO 19908 --- [ntContainer#0-1] cn.kk.mq.MqListener : 剩余时间：[10000]
2024-03-01T17:57:37.096+08:00 INFO 19908 --- [ntContainer#0-1] cn.kk.mq.MqListener : 订单已超时...
1
2
3
4
5
6
7
2
3
4
5
6
7
OK，问题解决，所以各位在取方法名的时候，非单一取值逻辑的get set方法一定要慎重。
上次更新: 2024/03/02 22:02:56