rabbitmq异步处理的bug

上周在完成利用rabbitmq异步发送邮件的需求中，意外发现了一个很微妙的bug，在此记录一下。本篇文章中的具体业务实现，读者可以忽略，主要看问题产生的缘由以及解决方法。

公司需求，JavaMail发送邮件进行异步处理，邮件在发送后的一分钟之内可以撤回。

我的方案：前台提交发送邮件请求，后台定时任务扫描，比对发送邮件的创建时间，如果已经超过一分钟，则生产MQ消息，消息消费进行实际的邮件发送操作。

生产者（定时任务）和消费者（发送邮件）相关代码如下。

/**
 * 生产者：定时任务
 * @param outbox
 */
@XxlJob(value = "mailSentTask")
@Transactional(rollbackFor = Exception.class)
public ReturnT<String> MailSentTask(String param){
    ImmutableMap<String, Object> params = ImmutableMap.of("boxType", MailCenterConstant.BoxType.OUTBOX,
            "sentStatus",MailCenterConstant.SentStatus.WAITING, "drawbackTime",MailCenterConstant.DRAW_BACK_TIME);
    //查询出可以发送的邮件
    List<MailCenterOutboxDTO> outboxs = outboxMapper.outboxToMq(params);
    if(CollectionUtils.isEmpty(outboxs)){
        return ReturnT.SUCCESS;
    }

    for(MailCenterOutboxDTO outbox : outboxs){
        //修改邮件的状态为发送中，避免因邮件过大，发送时长超过1分钟时的重复发送
        this.updSending(outbox, MailCenterConstant.SentStatus.SENDING);
        MailOutboxMsg mailOutboxMsg = new MailOutboxMsg();
        BeanUtils.copyProperties(outbox, mailOutboxMsg);
        ImmutableMap<String, Object> attachParams = ImmutableMap.of("mailId", mailOutboxMsg.getId(), "boxType", mailOutboxMsg.getBoxType());
        List<MailAttachMsg> attachList = attachMapper.getAttachList(attachParams);
        mailOutboxMsg.setAttaches(attachList);
        amqpTemplate.convertAndSend(TaskQueueConstant.MAIL_CENTER_OUTBOX_QUEUE, mailOutboxMsg);
        log.info("推送发件至消息队列,时间：{} ,发件: {} ,收件{}", DateUtil.getDateTimeString1(new Date()), mailOutboxMsg.getSentEmail(), mailOutboxMsg.getToEmail());
    }
    return ReturnT.SUCCESS;
}

/**
 * 消费者：发送邮件
 * @param outbox
 */
@RabbitListener(queuesToDeclare = @Queue(TaskQueueConstant.MAIL_CENTER_OUTBOX_QUEUE))
public void sendMail(MailOutboxMsg outbox) throws Exception {
	log.info("发送邮件消息消费，outboxId:" + outbox.getId() + ",sentEmail:" + outbox.getSentEmail() + ",toEmail:" + outbox.getToEmail());
	MailCenterOutbox _outbox = outboxMapper.selectByPrimaryKey(outbox.getId());
	log.info("发送邮件消息消费:" + outbox.toString());
	log.info("发送邮件消息消费:" + _outbox.toString());

	if(_outbox == null){
		log.error("发送邮件消息消费：找不到id为{}对应的发件邮件！", outbox.getId());
		return;
	}
	//防止重复消费
	if(_outbox != null && !MailServerConstant.SentStatus.SENDING.equals(_outbox.getSentStatus())){
		log.error("发送邮件消息消费：id为{}的邮件状态不为8！", outbox.getId());
		return;
	}
	//发送邮件
	outbox = sentService.sendEmail(outbox);
}

一个发送消息，一个消费消息，消费端还做了去重判断，看起来很完美，没什么问题。开发服测试，邮件发送也无误，所以就提测了。

然后测试的时候发现，偶尔会有一两封邮件无法发送，一直停留在“发送中”的状态。

我直接拉出后台打印的日志，一看才发现，卡在“发送中”的邮件，在消费端的状态为“待发送”，说明生产端的DB操作尚未完成，消费端就已经开始进行状态判断了。但是生产端的代码分明就是同步的，为什么会产生异步的效果呢？

原来是因为我的这个事物注解导致的。

这个注解是在方法执行完，并且无异常的时候才会commit到DB，而这个时候消息早就发送出去了，所以可能会导致时间差的出现，这也解释了为什么这个bug是偶发性的。

于是，我把生产端和消费端的代码稍作修改，bug解决。生产端去掉了事物，并增加了发送消息的异常处理；消费端消费消息前，睡眠等待3秒（实际没必要，但我被这个bug整的心有余悸了），增加了更新重置状态的操作。

/**
 * 生产者：定时任务
 * @param outbox
 */
@XxlJob(value = "mailSentTask")
public ReturnT<String> MailSentTask(String param){
    ImmutableMap<String, Object> params = ImmutableMap.of("boxType", MailCenterConstant.BoxType.OUTBOX,
            "sentStatus",MailCenterConstant.SentStatus.WAITING, "drawbackTime",MailCenterConstant.DRAW_BACK_TIME);
    //查询出可以发送的邮件
    List<MailCenterOutboxDTO> outboxs = outboxMapper.outboxToMq(params);
    if(CollectionUtils.isEmpty(outboxs)){
        return ReturnT.SUCCESS;
    }

    for(MailCenterOutboxDTO outbox : outboxs){
        //修改邮件的状态为发送中，避免因邮件过大，发送时长超过1分钟时的重复发送
        this.updSending(outbox, MailCenterConstant.SentStatus.SENDING);
        MailOutboxMsg mailOutboxMsg = new MailOutboxMsg();
        BeanUtils.copyProperties(outbox, mailOutboxMsg);
        ImmutableMap<String, Object> attachParams = ImmutableMap.of("mailId", mailOutboxMsg.getId(), "boxType", mailOutboxMsg.getBoxType());
        List<MailAttachMsg> attachList = attachMapper.getAttachList(attachParams);
        mailOutboxMsg.setAttaches(attachList);
        try {
            amqpTemplate.convertAndSend(TaskQueueConstant.MAIL_CENTER_OUTBOX_QUEUE, mailOutboxMsg);
        }catch (Exception e){
            //发送消息出现异常的话，需要重置发件状态，等待下一分钟重新发送
            this.updSending(outbox, MailCenterConstant.SentStatus.WAITING);
        }
        log.info("推送发件至消息队列,时间：{} ,发件: {} ,收件{}", DateUtil.getDateTimeString1(new Date()), mailOutboxMsg.getSentEmail(), mailOutboxMsg.getToEmail());
    }
    return ReturnT.SUCCESS;
}

/**
 * 消费者：发送邮件
 * @param outbox
 */
@RabbitListener(queuesToDeclare = @Queue(TaskQueueConstant.MAIL_CENTER_OUTBOX_QUEUE))
public void sendMail(MailOutboxMsg outbox) throws Exception {
    Thread.sleep(3000);
	log.info("发送邮件消息消费，outboxId:" + outbox.getId() + ",sentEmail:" + outbox.getSentEmail() + ",toEmail:" + outbox.getToEmail());
	MailCenterOutbox _outbox = outboxMapper.selectByPrimaryKey(outbox.getId());
	log.info("发送邮件消息消费:" + outbox.toString());
	log.info("发送邮件消息消费:" + _outbox.toString());

	if(_outbox == null){
		log.error("发送邮件消息消费：找不到id为{}对应的发件邮件！", outbox.getId());
		return;
	}
	//防止重复消费
	if(_outbox != null && !MailServerConstant.SentStatus.SENDING.equals(_outbox.getSentStatus())){
		log.error("发送邮件消息消费：id为{}的邮件状态不为8！", outbox.getId());
        if(MailServerConstant.SentStatus.WAITING.equals(_outbox.getSentStatus())){
            //如果生产端DB操作还未完成，直接更新会“待发送”，等待下一次发送
            Thread.sleep(3000);
            outboxMapper.updateByPrimaryKey(_outbox);
		}
		return;
	}
	//发送邮件
	outbox = sentService.sendEmail(outbox);
}

我以前写代码很喜欢用事物，觉得这就是万能的，发生异常也不会污染数据。这个bug让我认识到，对事物的使用，也要分具体业务情况。不合理的滥用，可能会导致一些莫名其妙的bug。。。