您的当前位置:首页正文

ActiveMQ由于Session is closed错误导致发

来源:华拓网

天黑请闭眼 : 问题背景

在这样一个难得阳光灿烂的上午,大家都沐浴在清晨的清爽之中的时候……
好吧,我编不下去了,其实就是大清早被通知说我们的消息显示的不正确,然后开始排查问题,经由定位之后发现问题在于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;     
        // 以下省略若干行
        ...

请投票 : 问题解决

那么问题清楚了之后,还是不明确为什么会导致这种异常释放,突然小伙伴们想起了之前收到的一封邮件,于是成功发现了凶手(核对日志时间和机器,完全一致)……
这个故事告诉我们一定要注意看邮件啊,以及阿里的监控系统好犀利啊!


凶手

当然我们自身的代码中,对这方面理解也不够深入,主要在于:

  1. 捕获这种异常之后,仅仅是简单的记录了相关的log,其实更优雅的方式是针对这种错误作出健壮性的反馈(当如具体的方式和策略还得再深入理解相关的机制和相关实现)
  2. 单例模式,有自身的好处,但是Session固定之后是否合适,还需要结合第1点来具体给出策略

结局 : 写在最后

仅以此记录一下的问题,防止之后忘记了。
也希望能给有类似问题发生的小伙伴们一些线索。
have fun~ :)