EsAppender代码不当导致队列Mq队列停止消费的问题

问题出现&解决

在我们的系统中对MQ消息的消费代码类似如下：

private void consumer2Xxx() {
        EXECUTOR_SERVICE.submit(() -> {
            try {  //mq队列监听
                   new xxxListener(){
                        void onMessage(){
                            //业务处理操作
                        }
                    }                     
            } catch (Exception e) {
               //记录日志
               logger.error(消费失败....)
            }
        });
    }

上述代码我们通过try{}catch()捕获了任何可能出现在业务处理中的异常，防止mq队列消费停止。然后神奇的事情是在未来的某一刻我们的开发人员说推送服务停了，打开mq的控制台看到队列也阻塞了，然后查看了日志内容如下：

[ERROR]:2019-11-02 13:12:11 [MsgPushListener]:消费失败.....
         at org.elaENOealsticsearch.client.transport.TransportClientNodesService.execute
         ............
         at org.elasticsearch.action.ActionRequestHandler.execute(ActionRequestBuilder.java:46)
        at org.elasticsearch.action.ActionRequestHandler.get(ActionRequestBuilder.java:53)
        at com.gysoft.utils.log4j.EsAppender.flushBuffer(EsAppender.java:163)
        at com.gysoft.utils.log4j.EsAppender.append(EsAppender.java:121)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppendSkeleton.java:251)
        .............
        at com.gysoft.rabbitmq.listener.onmessage(PushMsgListener$Listener.java:272)
        at com.gysoft.rabbitmq.listener.onmessage(PushMsgListener$Listener.java:43)
        .............
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)  

可以看到报错是由于EsAppender.flushBuffer方法抛出了异常，而报错原因可能就是由于网络连接抖动导致TransportClient连接不稳定导致写入数据到es报错，所以我们通过给flushBuffer添加try{}catch解决该问题

修改前

/**
     * 将数据写入到ES中
     */
    private void flushBuffer() {
        if (EmptyUtils.isNotEmpty(buffers)) {
            BulkRequestBuilder bulkRequestBuilder = getClient().prepareBulk();
            for (XContentBuilder xContentBuilder : buffers) {
                bulkRequestBuilder.add(getClient().prepareIndex(index, type).setSource(xContentBuilder));
                removes.add(xContentBuilder);
            }
            bulkRequestBuilder.get();
            buffers.removeAll(removes);
            removes.clear();
        }
    }

修改后

private void flushBuffer() {
        try {
            if (EmptyUtils.isNotEmpty(buffers)) {
                BulkRequestBuilder bulkRequestBuilder = getClient().prepareBulk();
                for (XContentBuilder xContentBuilder : buffers) {
                    bulkRequestBuilder.add(getClient().prepareIndex(index, type).setSource(xContentBuilder));
                    removes.add(xContentBuilder);
                }
                bulkRequestBuilder.get();
                buffers.removeAll(removes);
                removes.clear();
            }
        } catch (Exception e) {
            errorHandler.error("Error flushBuffer", e, ErrorCode.GENERIC_FAILURE);
        }
    }

分析&思考

上面程序出现错误我们不难分析得出结论：我们的org.slf4j.Logger.error方法和EsAppender.flushBuffer记录日志在同一个线程中，由于EsAppender.flushBuffer记录写入日志到es报错导致org.slf4j.Logger.error报错，最后导致consumer2Xxx方法中的消费线程停止，进而导致消息队列阻塞；

为了更具有说服力，我们来看下log4j实现的源码：

Log4jLoggerAdapter.error(String format, Object[] argArray)

public void error(String format, Object[] argArray) {
    if (logger.isEnabledFor(Level.ERROR)) {
      FormattingTuple ft = MessageFormatter.arrayFormat(format, argArray);
      logger.log(FQCN, Level.ERROR, ft.getMessage(), ft.getThrowable());
    }
  }

该方法委托记录日志给Category.log方法

Category.log(String callerFQCN, Priority level, Object message, Throwable t)

public
  void log(String callerFQCN, Priority level, Object message, Throwable t) {
    if(repository.isDisabled(level.level)) {
      return;
    }
    if(level.isGreaterOrEqual(this.getEffectiveLevel())) {
      forcedLog(callerFQCN, level, message, t);
    }
  }

protected
  void forcedLog(String fqcn, Priority level, Object message, Throwable t) {
    callAppenders(new LoggingEvent(fqcn, this, level, message, t));
  }

Category.callAppenders(LoggingEvent event)

public
  void callAppenders(LoggingEvent event) {
    int writes = 0;

    for(Category c = this; c != null; c=c.parent) {
      // Protected against simultaneous call to addAppender, removeAppender,...
      synchronized(c) {
	if(c.aai != null) {
	  writes += c.aai.appendLoopOnAppenders(event);
	}
	if(!c.additive) {
	  break;
	}
      }
    }

    if(writes == 0) {
      repository.emitNoAppenderWarning(this);
    }
  }

通过debug可以看到c.aai（AppenderAttachableImpl）中有如下三个appender

AppenderAttachableImpl.appendLoopOnAppenders(LoggingEvent event)

public
  int appendLoopOnAppenders(LoggingEvent event) {
    int size = 0;
    Appender appender;

    if(appenderList != null) {
      size = appenderList.size();
      for(int i = 0; i < size; i++) {
	appender = (Appender) appenderList.elementAt(i);
	appender.doAppend(event);
      }
    }    
    return size;
  }

该方法遍历ConsoleAppender、DailyRollingAppender、EsAppender分别记录不同的日志；所以不难得知,logger.error方法和EsAppender的flushBuffer处于同一个线程中，所以EsAppender.flushBuffer()异常，导致logger.error异常，进而导致消费者线程停止。

思考&思维发散

由于logger.error()和EsAppender.flushBuffer()方法的处理同属于一个线程（这样子是合理的，如果业务线程和logger.error线程不在一个线程，肯定会出现内存不可见问题），所以对于一个request请求，经过filter->controller->logger.error()->EsAppender.flushBuffer()我们是不是可以通过ThreadLocal变量来保存一些信息，比如登录的产品编号、用户的sessoin、其他信息到通过ThreadLocal传递到EsAppender.flushBuffer();

编写一个filter，该filter用于记录session中的产品编号到ThreadLocal

/**
 * 记录当前线程操作的产品编号
 * @author 周宁
 * @Date 2019-10-23 16:51
 */
public class CurrentThreadProductNumFilter implements Filter {
    @Override
    public void init(FilterConfig filterConfig) throws ServletException {

    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        HttpServletRequest req = (HttpServletRequest) request;
        HttpServletResponse res = (HttpServletResponse) response;
        LoginInfo result = (LoginInfo) req.getSession().getAttribute(LOGIN_INFO);
        if (result != null) {
            EsAppender.setProductNum(result.getProductNum());
        }
        chain.doFilter(req, res);
    }

    @Override
    public void destroy() {

    }
}

EsAppender记录日志的错误日志中添加productNum实现

public class EsAppender extends AppenderSkeleton {
    private static ThreadLocal<String> PRODUCT_NUM_HOLDER = new ThreadLocal();

    @Override
    protected void append(LoggingEvent event) {
        parseLog(event);
        if (buffers.size() >= (bufferSize == 0 ? DEFAULT_BUFFER_SIZE : bufferSize)) {
            flushBuffer();
        }
    }

    private void parseLog(LoggingEvent event) {
        ThrowableInformation throwableInformation = event.getThrowableInformation();
        if (throwableInformation != null) {
            LocationInfo locationInfo = event.getLocationInformation();
            Throwable throwable = throwableInformation.getThrowable();
            try {
                String productNum = PRODUCT_NUM_HOLDER.get();
                if (null != productNum) {
                    PRODUCT_NUM_HOLDER.remove();
                }
                StringBuilder throwStackTrace = new StringBuilder();
                String[] s = event.getThrowableStrRep();
                if (s != null) {
                    int len = s.length;
                    for (int i = 0; i < len; i++) {
                        throwStackTrace.append(s[i]);
                        throwStackTrace.append(Layout.LINE_SEP);
                    }
                }
                buffers.add(jsonBuilder()
                        .startObject()
                        .field("className", locationInfo.getClassName())
                        .field("productNum", productNum)
                        .field("fileName", locationInfo.getFileName())
                        .field("lineNumber", locationInfo.getLineNumber())
                        .field("methodName", locationInfo.getMethodName())
                        .field("serverIp", getIp())
                        .field("logName", event.getLogger().getName())
                        .field("logLevel", event.getLevel())
                        .field("logThread", event.getThreadName())
                        .field("logMills", new Date(event.getTimeStamp()))
                        .field("logMessage", event.getMessage().toString())
                        .field("throwMessage", throwable.getMessage())
                        .field("throwDetailMessage", throwable.toString())
                        .field("throwStackTrace", throwStackTrace)
                        .endObject());
            } catch (IOException e) {
                errorHandler.error("Error parseLog", e, ErrorCode.GENERIC_FAILURE);
            }
        }
    }

    public static void setProductNum(String productNum) {
        PRODUCT_NUM_HOLDER.set(productNum);
    }

EsAppender.java代码可以参考：https://blog.csdn.net/qq_23536449/article/details/89876514