记一次生产事故排查

背景：刚接手一个新工程，是一个给国内top级医院开发的老项目，因为历史原因，代码质量略低，测试难度略高。

上线很久的功能，最近一直频繁的爆发各种问题，经排查发现都是因为在业务过程中im聊天账号绑定异常所致。

修复方案一：

因为im工程比较老，日志打印不完善，因此从日志看初步分析业务dubbo接口未调用到im服务因此导致了绑定失败，此时我开始在工程里设置dubbo接口该方法的重试机制，retries设置为2，timeout设置为3000，由于本身既有的一次rpc调用，因此实际在调用失败的情况下业务会对im接口进行3次rpc的调用。

鉴于项目的各种难度和稳定性要求，另在业务代码侧再次进行了三次递归重试（客户端超时30s，正常情况不会因为重试而超时，慢是肯定的）。

同时因为服务此时并没有打印traceId进行链路跟踪机制的拓展，因此另开发traceId写入MDC并通过log4j2打印到cosole并通过钉钉表达式进行采集汇总输出，针对dubbo接口也通过扩展spi进行了traceId的透传。

服务消费者端代码如下：

import org.apache.commons.lang3.StringUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.core.Ordered;
import org.springframework.core.annotation.Order;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;

import javax.servlet.FilterChain;
import javax.servlet.annotation.WebFilter;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

/**
 * MDC属性设置  日志用
 * 方法屏蔽actuator接口
 */
@Order(Ordered.HIGHEST_PRECEDENCE)
@WebFilter(urlPatterns = {"/*"})
public class MDCFilter extends OncePerRequestFilter {

    private  Logger LOGGER = LoggerFactory.getLogger(MDCFilter.class);

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain chain) {
        if(request.getRequestURI().contains("/actuator/health")){
            return;
        }
        try {
            String traceId = request.getHeader("traceId");
            if(StringUtils.isNotBlank(traceId)) {
                TraceIdUtil.create(traceId);
            } else {
                TraceIdUtil.create();
            }
            TraceContext.addAttachment("traceId",MDC.get("traceId"));
            chain.doFilter(new ContentCachingRequestWrapper(request), response);
        } catch (Exception exception) {
            LOGGER.error("Web端traceId处理异常", exception);
        } finally {
            TraceContext.clear();
            TraceIdUtil.clear();
        }
    }

}

import java.util.UUID;
import org.slf4j.MDC;

public class TraceIdUtil {
    public static final String TRACE_ID = "traceId";

    public TraceIdUtil() {
    }

    public static void create() {
        create(UUID.randomUUID().toString().replace("-", ""));
    }

    public static void create(String traceId) {
        MDC.put("traceId", traceId);
    }

    public static String get() {
        return MDC.get("traceId");
    }

    public static void clear() {
        MDC.clear();
    }
}

import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.*;

@Activate(group = {"consumer"})
public class DubboTraceFilter implements Filter {

    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        RpcContext rpcContext = RpcContext.getContext();
        if (rpcContext.isConsumerSide()) {
            rpcContext.setAttachment("traceId", TraceContext.getTraceId());
        }
        return invoker.invoke(invocation);
    }
}

public class TraceContext {

    private static ThreadLocal<Map<String,Object>> threadLocal = new ThreadLocal<Map<String, Object>>(){
        @Override
        protected Map<String, Object> initialValue() {
            return new LinkedHashMap<String, Object>();
        }
    };

    public static void addAttachment(String key, Object value){
        threadLocal.get().put(key,value);
    }

    public static void addAttachments(Map<String, Object> map){
        threadLocal.get().putAll(map);
    }

    public static Map<String, Object> getAttachments(){
        return threadLocal.get();
    }

    public static  void clear(){
        threadLocal.remove();
    }

    public static String getTraceId(){
        return String.valueOf(threadLocal.get().get("traceId"));
    }

}

启动类添加注解：@ServletComponentScan

resource目录新建文件com.alibaba.dubbo.rpc.Filter

文件内容

dubboTraceFilter=com.xxx.filter.DubboTraceFilter（文件路径）

文件结构如下

服务提供者端代码如下：

import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.*;
import org.apache.commons.lang.StringUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

@Activate(group = {"provider","consumer"})
public class TraceIdFilter implements Filter {

	private static final Logger LOGGER = LoggerFactory.getLogger(TraceIdFilter.class);

	@Override
	public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
		try{
			String traceId = RpcContext.getContext().getAttachment("traceId");
			if ( !StringUtils.isEmpty(traceId) ) {
				// *) 从RpcContext里获取traceId并保存
				MDC.put("traceId", traceId);
			} else {
				// *) 交互前重新设置traceId, 避免信息丢失
				TraceIdUtil.create();
				RpcContext.getContext().setAttachment("traceId", MDC.get("traceId"));
			}
			// *) 实际的rpc调用
			return invoker.invoke(invocation);
		}catch (Exception e){
			LOGGER.error("rpcContext get traceId exception:",e);
			return null;
		}finally {
			TraceIdUtil.clear();
		}
	}
}

提供者端SPI扩展相同

此外：1、Log4j2需要解析自定义的traceId标签，可以用%X{traceId}打印

? ? ? ? ? ?2、resources目录下文件路径注意com.alibaba还是apache dubbo，请与依赖保持一致

?至此，问题修复完成。

代码上线后，发现问题依然存在。（上述方案仅可在一定程度上避免，并不能完全修复）

修复方案二：

再次排查发现，原来是im接口有另一个实现也在提供服务，此时找到了问题的元凶，摘除该无用实现问题解决。（也可考虑group隔离，因为另一实现无用，因此摘除）

经验总结：im的另一实现是前几天上线一新功能随之发布的，因为dubbo接口默认路由的随机性及测试账号的历史原因，导致该问题在测试过程未被发现。实际上当我们上线任何新功能，都应该全面进行评估上线代码是否会对老功能造成影响，而不应该只局限在眼前的需求，从而造成更大的损失。