天黑请闭眼 : 问题背景
在这样一个难得阳光灿烂的上午,大家都沐浴在清晨的清爽之中的时候……
好吧,我编不下去了,其实就是大清早被通知说我们的消息显示的不正确,然后开始排查问题,经由定位之后发现问题在于MQ消息没有发送成功,导致生成的信息有缺失,然而悲剧的是祸不单行,由于之前配置日志的问题导致了历史日志的丢失。唯一的线索就是当时的一个同事给另一个同事的错误信息截图,如下:
于是就此,我们展开了调查……
狼人请杀人 : 错误位置
首先我们开始对可疑的问题点开始反推,鉴于存在错误信息的线索,我们分析了MQ Client的源码,发现了抛出这个异常的位置:
/**
* Check if the session is closed. It is used for ensuring that the session
* is open before performing various operations.
*
* @throws IllegalStateException if the Session is closed
*/
protected void checkClosed() throws IllegalStateException {
if (closed) {
throw new IllegalStateException("The Session is closed");
}
}
结合我们具体的业务日志代码,以及数据库记录,反推具体的问题发生点应该在于我们对MQ发送消息的功能封装类位置:
/**
* 注意提交事务 方法commit()
*
* queueName此处用于初始化,防止static对象先初始化时候出现空指针的问题
*
* @param queueName
* @param msg
* @throws JMSException
*/
public void sendMsg(String queueName, JSONObject messageJson) {
try {
if (null == producer) {
init(queueName);// 每一个queue分别实例化自己的参数
}
if (null != producer) {
//统一增加queueName
messageJson.put("queueName", queueName);
String msg = messageJson.toString();
// **警察叔叔,就是这里**
message = session.createTextMessage(msg);
if (null != message) {
producer.send(message);
mqLog.info("MQProducer, sendMsg succ, queueName:" + queueName + ", msg:" + msg);
} else {
throw new JMSException(" 消息未成功发送: " + msg);
}
} else {
throw new JMSException(" 消息未成功发送: " + messageJson.toString());
}
} catch (Exception exp) {
exp.printStackTrace();
Log4jUtil.exception(exp);
mqLog.error(messageJson.toString());
}
}
预言家请验人 : 错误原因
鉴于这里就明确了是Session的调用时,由于内部的closed值为TRUE导致了这个异常信息的打印,因此我们继续通过源码排查了这个值会被写为TRUE的情况,发现是在于如下释放(类似于析构的情况)的时候才会导致这个值的变化:
public synchronized void dispose() throws JMSException {
if (!closed) {
try {
executor.close();
for (Iterator<ActiveMQMessageConsumer> iter = consumers.iterator(); iter.hasNext();) {
ActiveMQMessageConsumer consumer = iter.next();
consumer.setFailureError(connection.getFirstFailureError());
consumer.dispose();
lastDeliveredSequenceId = Math.max(lastDeliveredSequenceId, consumer.getLastDeliveredSequenceId());
}
consumers.clear();
for (Iterator<ActiveMQMessageProducer> iter = producers.iterator(); iter.hasNext();) {
ActiveMQMessageProducer producer = iter.next();
producer.dispose();
}
producers.clear();
try {
if (getTransactionContext().isInLocalTransaction()) {
rollback();
}
} catch (JMSException e) {
}
} finally {
connection.removeSession(this);
this.transactionContext = null;
// ** 警察叔叔,就是这个人! **
closed = true;
}
}
}
因此想到可能是由于链接被释放了才导致了这个问题,开始在MQ Server端找对应日志,于是发现了如下错误信息,由于心跳(或其它)的超时,导致服务器端主动释放了相关的链接:
天亮了 : 根因分析
由此我们得到大致的结论,由于我们本身的代码里面采用的是单例模式,造成了Session值只会在一开始创建Producer之后就保持住。因此虽然服务器端释放后,我们Client端的Session值还是使用了之前的值,导致了这个异常被抛出。
也就是说MQ本身的程序在发现异常之后开始清理相关的数据,并设置相关的状态(把Closed变量置为TRUE)。而我们的程序由于还是引用到了之前的对象上,因此在访问Closed变量时发现出错了,因此抛出异常,导致我们之后的发送失败
Session在Producer中的声明如下:
// 这里的Producer是单例模式的
// Session一旦创建之后是不会更新的
protected class MQProducer {
private ActiveMQConnectionFactory factory = null;
private Connection connection = null;
private Session session = null;
// 以下省略若干行
...
请投票 : 问题解决
那么问题清楚了之后,还是不明确为什么会导致这种异常释放,突然小伙伴们想起了之前收到的一封邮件,于是成功发现了凶手(核对日志时间和机器,完全一致)……
这个故事告诉我们一定要注意看邮件啊,以及阿里的监控系统好犀利啊!
当然我们自身的代码中,对这方面理解也不够深入,主要在于:
- 捕获这种异常之后,仅仅是简单的记录了相关的log,其实更优雅的方式是针对这种错误作出健壮性的反馈(当如具体的方式和策略还得再深入理解相关的机制和相关实现)
- 单例模式,有自身的好处,但是Session固定之后是否合适,还需要结合第1点来具体给出策略
结局 : 写在最后
仅以此记录一下的问题,防止之后忘记了。
也希望能给有类似问题发生的小伙伴们一些线索。
have fun~ :)