问题出现&解决
在我们的系统中对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