Dubbo全鏈路追蹤日誌的實現
微服務架構的專案,一次請求可能會呼叫多個微服務,這樣就會產生多個微服務的請求日誌,當我們想要檢視整個請求鏈路的日誌時,就會變得困難,所幸的是我們有一些集中日誌收集工具,比如很熱門的ELK,我們需要把這些日誌串聯起來,這是一個很關鍵的問題,如果沒有串聯起來,查詢起來很是很困難,我們的做法是在開始請求系統時生成一個全域性唯一的id,這個id伴隨這整個請求的呼叫週期,即當一個服務呼叫另外一個服務的時候,會往下傳遞,形成一條鏈路,當我們檢視日誌時,只需要搜尋這個id,整條鏈路的日誌都可以查出來了。
現在以dubbo微服務架構為背景,舉個栗子:
A -> B -> C
我們需要將A/B/C/三個微服務間的日誌按照鏈式列印,我們都知道Dubbo的RpcContext只能做到消費者和提供者共享同一個RpcContext,比如A->B,那麼A和B都可以獲取相同內容的RpcContext,但是B->C時,A和C就無法共享相同內容的RpcContext了,也就是無法做到鏈式列印日誌了。
那麼我們是如何做到呢?
我們可以用左手交換右手的思路來解決,假設左手是執行緒的ThreadLocal,右手是RpcContext,那麼在交換之前,我們首先將必要的日誌資訊儲存到ThreadLocal中。
在我們的專案微服務中大致分為兩種容器型別的微服務,一種是Dubbo容器,這種容器的特點是隻使用spring容器啟動,然後使用dubbo進行服務的暴露,然後將服務註冊到zookeeper,提供服務給消費者;另一種是SpringMVC容器,也即是我們常見的WEB容器,它是我們專案唯一可以對外開放介面的容器,也是充當專案的閘道器功能。
在瞭解了微服務容器之後,我們現在知道了呼叫鏈的第一層一定是在SpringMVC容器層中,那麼我們直接在這層寫個自定義攔截器就ojbk了,talk is cheap,show you the demo code:
舉例一個Demo程式碼,公共攔截器的前置攔截中程式碼如下:
public class CommonInterceptor implements HandlerInterceptor { @Override public boolean preHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object handler) throws Exception { // ... // 初始化全域性的Context容器 Request request = initRequest(httpServletRequest); // 新建一個全域性唯一的請求traceId,並set進request中 request.setTraceId(JrnGenerator.genTraceId()); // 將初始化的請求資訊放進ThreadLocal中 Context.initialLocal(request); // ... return true; } // ... }
系統內部上下文物件:
public class Context { // ... private static final ThreadLocal<Request> REQUEST_LOCAL = new ThreadLocal<>(); public final static void initialLocal(Request request) { if (null == request) { return; } REQUEST_LOCAL.set(request); } public static Request getCurrentRequest() { return REQUEST_LOCAL.get(); } // ... }
攔截器實現了org.springframework.web.servlet.HandlerInterceptor
介面,它的主要作用是用於攔截處理請求,可以在MVC層做一些日誌記錄與許可權檢查等操作,這相當於MVC層的AOP,即符合橫切關注點的所有功能都可以放入攔截器實現。
這裡的initRequest(httpServletRequest);
就是將請求資訊封裝成系統內容的請求物件Request
,並初始化一個全域性唯一的traceId放進Request中,然後再把它放進系統內部上下文ThreadLocal欄位中。
接下來講講如何將ThreadLocal中的內容放到RpcContext中,在講之前,我先來說說Dubbo基於spi擴充套件機制,官方文件對攔截器擴充套件解釋如下:
服務提供方和服務消費方呼叫過程攔截,Dubbo 本身的大多功能均基於此擴充套件點實現,每次遠端方法執行,該攔截都會被執行,請注意對效能的影響。
也就是說我們進行服務遠端呼叫前,攔截器會對此呼叫進行攔截處理,那麼就好辦了,在消費者呼叫遠端服務之前,我們可以偷偷把ThreadLocal的內容放進RpcContext容器中,我們可以基於dubbo的spi機制擴充套件兩個攔截器,一個在消費者端生效,另一個在提供者端生效:
在META-INF中加入com.alibaba.dubbo.rpc.Filter檔案,內容如下:
provider=com.objcoding.dubbo.filter.ProviderFilter consumer=com.objcoding.dubbo.filter.ConsumerFilter
消費者端攔截處理:
public class ConsumerFilter implements Filter { @Override public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException { //1.從ThreadLocal獲取請求資訊 Request request = Context.getCurrentRequest(); //2.將Context引數放到RpcContext RpcContext rpcCTX = RpcContext.getContext(); // 將初始化的請求資訊放進ThreadLocal中 Context.initialLocal(request); // ... } }
Context.getCurrentRequest();
就是從ThreadLocal中拿到Request請求內容,contextToDubboContext(request);
將Request內容放進當前執行緒的RpcContext容器中。
很容易聯想到提供者也就是把RpcContext中的內容拿出來放到ThreadLocal中:
public class ProviderFilter extends AbstractDubboFilter implements Filter{ @Override public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException { // 1.獲取RPC遠端呼叫上下文 RpcContext rpcCTX = RpcContext.getContext(); // 2.初始化請求資訊 Request request = dubboContextToContext(rpcCTX); // 3.將初始化的請求資訊放進ThreadLocal中 Context.initialLocal(request); // ... } }
接下來我們還要配置log4j2,使得我們同一條請求在關聯的每一個容器列印的訊息,都有一個共同的traceId,那麼我們在ELK想要查詢某個請求時,只需要搜尋traceId,就可以看到整條請求鏈路的日誌了。
我們在Context上下文物件的initialLocal(Request request)
方法中在log4j2的上下文中新增traceId資訊:
public class Context { // ... final public static String TRACEID = "_traceid"; public final static void initialLocal(Request request) { if (null == request) { return; } // 在log4j2的上下文中新增traceId ThreadContext.put(TRACEID, request.getTraceId()); REQUEST_LOCAL.set(request); } // ... }
接下來實現org.apache.logging.log4j.core.appender.rewrite.RewritePolicy
:
@Plugin(name = "Rewrite", category = "Core", elementType = "rewritePolicy", printObject = true) public final class MyRewritePolicy implements RewritePolicy { // ... @Override public LogEvent rewrite(final LogEvent source) { HashMap<String, String> contextMap = Maps.newHashMap(source.getContextMap()); contextMap.put(Context.TRACEID, contextMap.containsKey(Context.TRACEID) ? contextMap.get(Context.TRACEID) : NULL); return new Log4jLogEvent.Builder(source).setContextMap(contextMap).build(); } // ... }
RewritePolicy的作用是我們每次輸出日誌,log4j都會呼叫這個類進行一些處理的操作。
配置log4j2.xml:
<Configuration status="warn"> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="[%d{yyyy/MM/dd HH:mm:ss,SSS}][${ctx:_traceid}]%m%n" /> </Console> <!--定義一個Rewrite--> <Rewrite name="Rewrite"> <MyRewritePolicy/> <!--引用輸出模板--> <AppenderRef ref="Console"/> </Rewrite> </Appenders> <Loggers> <!--使用日誌模板--> <Logger name="com.objcoding.MyLogger" level="debug" additivity="false"> <!--引用Rewrite--> <AppenderRef ref="Rewrite"/> </Logger> </Loggers> </Configuration>
自定義日誌類:
public class MyLogger { private static final Logger logger = LoggerFactory.getLogger(MyLogger.class); public static void info(String msg, Object... args) { if (canLog() == 1 && logger.isInfoEnabled()) { logger.info(msg, args); } } public static void debug(String message, Object... args) { if (canLog() == 1 && logger.isDebugEnabled()) { logger.debug(message, args); } } // .. }