科技改變生活 · 科技引領未來
科技改變生活 · 科技引領未來
大部分時候，發現問題通常比解決問題更加重要。異常是我們在開發和運維過程中頻繁會遇到的東西，通過異常我們可以知道程序中發生了一些非正常的事件，進而排查原因、解決問題。能夠有效的對異常進行收集分析，及時發現異常報告異常，對于我們提高系統的穩定性
大部分時候，發現問題通常比解決問題更加重要。
異常是我們在開發和運維過程中頻繁會遇到的東西，通過異常我們可以知道程序中發生了一些非正常的事件，進而排查原因、解決問題。能夠有效的對異常進行收集分析，及時發現異常報告異常，對于我們提高系統的穩定性和可用性都具有很大的現實意義。
本文介紹了我們在分布式系統異常日志收集與分析方面的實踐過程，文中提出了一種對異常日志分類的算法，可以相對有效的分析海量異常日志。
一、背景
首先，我們先來討論下為什么要做這件事情。
一般在開發過程中出現的異常大部分都能被大家及時發現并解決，但是通常在系統上線之后，由于大家不會實時查看日志，我們的異常信息可能會被淹沒在大量應用系統日志中。
如果沒有將異常信息及時收集并暴露出來，可能某些異常便會被忽略或造成很大影響之后才被發現。大家也可能經歷過如下類似的場景：
場景一：某些leader和運維同學在看線上日志的時候發現了異常日志，于是便截圖或將異常信息拷貝出來貼到溝通群里，@某個同學排查，這種方式通常是隨機的，很容易漏掉了某些重要異常，或者是不能及時發現異常。
場景二：某一天突然接到運營或客服同學反饋某個問題，經過排查發現系統bug，但是其實異常早就打印出來了，只不過一直沒有發現，不得不緊急修復bug，上線，更麻煩的是可能還需要修復異常數據。
所以，我們一直想找一種方法可以對異常日志進行分析處理，但是僅僅是將異常日志收集上來報告給各業務系統研發同學效果并不會很好。
其實在之前的工作中我們已經把項目的異常日志統一收集起來了，大家可以看到自己項目的異常，也可以看到每天異常數量的趨勢，如下圖所示：
上面的圖中明顯的有兩個點開始異常數變多了，為什么變多了呢？是哪些項目變多了，哪些異常變多了，我們目前很難給出準確的答案，所以需要我們對現有的異常做數據分析，以便可以更好的分析問題。
那需要做哪些分析呢？我們希望通過分析可以知道如下信息：
如下是我們最終實現的一個效果圖：
在上圖中可以看到，針對于每一個項目，在異常日志分析tab中，可以看到這個項目今天、昨天以及所有異常日志的分類信息。針對于每一個異常，點擊畫像分析，可以看到這個異常的具體詳細信息，標識了一個異常發生的位置，出現的頻率，發生的具體時間等，如下圖所示。
下面帶著這些目標我們來一步一步分析該如何實現這些需求。
二、技術實現
1、已知信息
假如我們把這個問題看成一個數學題，第一步當然是先要搞清楚我們當前已知的信息。
通過我們的集中日志收集系統，我們已經把所有的異常信息統一收集到了 kafka 的 p_error_log 這個topic中，其中某一行的日志格式如下：
{ "env": "docker", "hostAddress": "x.x.72.x-192.x.x.x", "hostName": "yxy-ody-bridge-ody-bridge-api-dev-bbbb99cb5-8q825", "level": "ERROR", "log": "[2019-12-17 11:49:18.803 ERROR] [http-nio-8080-exec-75] (WebExceptionHandle:56) 服務內部錯誤ncom.yxy.ody.api.exception.ServiceException: 訂單號：1908xxxxxx052沒有查到交易信息，請檢查參數！ntat com.yxy.ody.api.handler.CustomsPayHandler.getTradeFlowByOrderCode(CustomsPayHandler.java:146) ~[classes/:?]ntat com.yxy.ody.api.handler.CustomsPayHandler.GetCreateDeliveryOrderArgs(CustomsPayHandler.java:93) ~[classes/:?]ntat sun.reflect.GeneratedMethodAccessor118.invoke(Unknown Source) ~[?:?]ntat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_161]ntat java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_161]ntat org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:215) ~[spring-web-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132) ~[spring-web-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:781) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:721) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:83) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:943) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:877) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.servlet.frameworkServlet.processRequest(frameworkServlet.java:961) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.servlet.frameworkServlet.doPost(frameworkServlet.java:863) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat javax.servlet.http.HttpServlet.service(HttpServlet.java:648) ~[servlet-api.jar:?]ntat org.springframework.web.servlet.frameworkServlet.service(frameworkServlet.java:837) ~[spring-webmvc-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat javax.servlet.http.HttpServlet.service(HttpServlet.java:729) ~[servlet-api.jar:?]ntat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292) ~[catalina.jar:8.0.53]ntat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207) ~[catalina.jar:8.0.53]ntat org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.0.53]ntat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240) ~[catalina.jar:8.0.53]ntat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207) ~[catalina.jar:8.0.53]ntat org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88) ~[spring-web-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.1.0.RELEASE.jar:4.1.0.RELEASE]ntat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240) ~[catalina.jar:8.0.53]ntat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207) ~[catalina.jar:8.0.53]ntat org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) ~[log4j-web-2.11.1.jar:2.11.1]ntat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240) ~[catalina.jar:8.0.53]ntat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207) ~[catalina.jar:8.0.53]ntat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212) ~[catalina.jar:8.0.53]ntat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:94) ~[catalina.jar:8.0.53]ntat org.apache.catalina.authenticator.Authenticatorbase.invoke(Authenticatorbase.java:492) ~[catalina.jar:8.0.53]ntat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141) ~[catalina.jar:8.0.53]ntat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80) ~[catalina.jar:8.0.53]ntat org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:620) ~[catalina.jar:8.0.53]ntat org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:684) ~[catalina.jar:8.0.53]ntat org.apache.catalina.core.StandardEnginevalve.invoke(StandardEnginevalve.java:88) ~[catalina.jar:8.0.53]ntat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:502) ~[catalina.jar:8.0.53]ntat org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1152) ~[tomcat-coyote.jar:8.0.53]ntat org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:684) ~[tomcat-coyote.jar:8.0.53]ntat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1539) ~[tomcat-coyote.jar:8.0.53]ntat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1495) ~[tomcat-coyote.jar:8.0.53]ntat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_161]ntat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_161]ntat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-util.jar:8.0.53]ntat java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]n", "serviceName": "ody-bridge-api", "threadName": "http-nio-8080-exec-75", "timeMillis": 1576554558803 }該日志格式描述了以下基本事實：什么時候哪臺機器哪個應用打印了什么日志。其中`log`字段標識了原始打印的日志內容，對應的log4j2的PatternLayout定義如下：
[%d{yyyy-MM-dd HH:mm:ss.SSS} %-5p] [%t] (%C{1}:%L) %m%n一個比較直觀的異常如下：
所以，其實我們能拿到所有的異常文本信息，只要我們能夠把異常數據結構化，然后抽取出特征信息，將相同的異常歸為同一類，那么我們就可以完成最基本也是最重要的分類任務。
在這之前我們深入剖析下Java異常日志。
2、java異常日志剖析
如果在代碼中出現異常，我們通常會使用如下方式打印日志，
logger.error("同步寶寶數據異常", e);打印到控制臺如下所示：
接下來我們通過源碼具體分析這上面這行代碼背后發生了什么事情：
1、調用logger.error() 最終會執行如下方法：
@Override public void logMessage(final String fqcn, final Level mgsLevel, final Marker marker, final Message msg, final Throwable throwable) { final StringBuilder sb = new StringBuilder(); // Append date-time if so configured if (showDateTime) { final Date now = new Date(); String dateText; synchronized (dateFormatter) { dateText = dateFormatter.format(now); } sb.append(dateText); sb.append(SPACE); } sb.append(mgsLevel.toString()); sb.append(SPACE); if (Strings.isNotEmpty(logName)) { sb.append(logName); sb.append(SPACE); } sb.append(msg.getFormattedMessage()); if (showContextMap) { final Map mdc = ThreadContext.getImmutableContext(); if (mdc.size() > 0) { sb.append(SPACE); sb.append(mdc.toString()); sb.append(SPACE); } } final Object[] params = msg.getParameters(); Throwable t; if (throwable == null && params != null && params.length > 0 && params[params.length - 1] instanceof Throwable) { t = (Throwable) params[params.length - 1]; } else { t = throwable; } stream.println(sb.toString()); if (t != null) { stream.print(SPACE); t.printStackTrace(stream); } } 可以看到logMessage方法最終執行了 t.printStackTrace 來打印異常信息，如下是printStackTrace方法體：
private void printStackTrace(PrintStreamOrWriter s) { // Guard against malicious overrides of Throwable.equals by // using a Set with identity equality semantics. Set dejaVu = Collections.newSetFromMap(new IdentityHashMap()); dejaVu.add(this); synchronized (s.lock()) { // Print our stack trace s.println(this); StackTraceElement[] trace = getOurStackTrace(); for (StackTraceElement traceElement : trace) s.println("tat " + traceElement); // Print suppressed exceptions, if any for (Throwable se : getSuppressed()) se.printEnclosedStackTrace(s, trace, SUPPRESSED_CAPTION, "t", dejaVu); // Print cause, if any Throwable ourCause = getCause(); if (ourCause != null) ourCause.printEnclosedStackTrace(s, trace, CAUSE_CAPTION, "", dejaVu); } } 在synchronized同步代碼塊中，我們看如下一行是將 Throwable 對象本身做了輸出，所以我們繼續看toString方法的實現。
s.println(this); public String toString() { String s = getClass().getName(); String message = getLocalizedMessage(); return (message != null) ? (s + ": " + message) : s; }toString方法依次輸出了className 和 message 信息。對應于異常日志的如下部分：
然后開始輸出堆棧信息
StackTraceElement[] trace = getOurStackTrace(); for (StackTraceElement traceElement : trace) s.println("tat " + traceElement); // Print suppressed exceptions, if any for (Throwable se : getSuppressed()) se.printEnclosedStackTrace(s, trace, SUPPRESSED_CAPTION, "t", dejaVu); // Print cause, if any Throwable ourCause = getCause(); if (ourCause != null) ourCause.printEnclosedStackTrace(s, trace, CAUSE_CAPTION, "", dejaVu);我們知道棧是先進后出的數據結構，所以我們在日志中看到的異常信息，越靠前的說明調用得越深，也最接近案發現場，所以看異常信息的時候尤其注意。
3、分析當前項目的異常日志
在實際的開發過程中，大家打印日志的方式是有一些差異的，所以會導致我們收集的異常日志也會存在多種格式，經過對當前項目異常日志的分析我們可以分為如下幾類：
1）異常帶堆棧
如果代碼中使用如下形式打印error日志：
logger.error("[TestCaseController] error={}",e);異常日志輸出類似于如下形式：
2）異常不帶堆棧信息
如果代碼中使用如下形式打印error日志：
logger.error("[viewErrorLog] request:{}", JSON.toJSonString(request));異常日志輸出類似于如下形式：
3）api-gateway 和 Rpcbase 統一打印的日志
還有一類異常，日志是在框架層統一打印的
public class RpcbaseService { Logger logger = LoggerFactory.getLogger(RpcbaseService.class); protected RpcbaseResponse handleException(Throwable e, RpcbaseResponse response) { if(e instanceof ServiceException) { ServiceException se = (ServiceException)e; response.setCode(se.getCode()); response.setMessage(se.getMessage()); } else if(e instanceof IllegalArgumentException) { response.setCode(ResponseStatus.FAILD.getCode()); response.setMessage(e.getMessage()); }else { logger.error("rpc handleException :",e); response.setCode(ResponseStatus.FAILD.getCode()); response.setMessage(ResponseStatus.FAILD.getMessage()); } return response; } }@Controller @RequestMapping("/api") public class APIController extends MultiActionController { private String handleException(Throwable e, AbstractProtocolPrint print){ if (e instanceof ServiceException) { ServiceException se = (ServiceException) e; String returnValue = null; if(se.getCode() == AuthTokenConstants.TOKEN_CODE_EMPTY || se.getCode() == AuthTokenConstants.TOKEN_CODE_BREAK || se.getCode() == AuthTokenConstants.TOKEN_CODE_RELOGIN) { // Token 異常 TokenRouters router = TokenSkipModel.loginTokenSkipModel(e.getMessage()); returnValue =print.error(ResponseStatus.OK.getCode(), se.getMsg(),router.getSkipModel()); }else { returnValue = print.error(se.getCode(), se.getMsg()); } return returnValue; } else if (e instanceof CallableException) { log.error("[api-callable CallableException] exception={}",e); CallableException ce = (CallableException) e; return print.error(ResponseStatus.FAILD.getCode(), ce.getMessage()); } else if (e instanceof SmartValidateException) { log.error("[api-callable SmartValidateException] exception={}",e); SmartValidateException sve = (SmartValidateException) e; return print.error(ResponseStatus.BIZ_FAILD.getCode(), sve.getMessage()); } else if (e instanceof InvocationTargetException) { InvocationTargetException ite = (InvocationTargetException) e; return handleException(ite.getTargetException(), print); } else { log.error("[api-callable] exception={}",e); e.printStackTrace(); return print.error(ResponseStatus.FAILD.getCode(), "服務器開小差兒了，請稍候重試"); } } }此種情況打印的異常，位置信息都會相同，所以可能會產生大量的相似的日志。
4、定義異常分析算法
知道了異常日志的基本格式，接下來我們就需要找到一個方法對異常日志進行分析了。
日志分析最重要的一個問題就是如何對海量的異常日志做分類，我們知道如果僅僅是把異常上報上來，可能每天會出現幾千幾萬條異常我們是沒辦法逐條進行處理的，所以我們需要定義一個算法對異常進行分類。
算法定義如下：
所以現在的問題是如何找到異常的簽名，我們繼續分析。
一個異常出現一次，那么就有可能出現多次，這些異常應該歸屬為同一類，我們可以簡單地認為在同一個位置出現的異常是同一類。對其中某個異常結構分析如下所示：
同一個位置這里包含兩個部分：
所以只要我們成功提取出這兩個信息，使用他們就可以計算簽名了。
4.1 提取異常位置信息
提取位置信息可以使用正則提取，如下所示：
Pattern logPattern = Pattern.compile("^[(d{4}-d{2}-d{2} d{2}:d{2}:d{2}.d{3})sERROR].*?((S+))s+(.*)"); String[] arr = logMessageVO.getString("log").split("n"); if(arr.length <=0) { return; } Matcher matcher = logPattern.matcher(arr[0]); matcher.find(); String logTime = matcher.group(1); String logLocation = matcher.group(2);4.2 提取執行方法信息
提取執行方法則需要一些技巧。從上面的分析我們可以知道我們系統中的異常大體分為了三類：
前兩種其實只要提取出異常打印的具體類就可以定位位置了，但是第三種也只使用位置信息的話則無法區分具體的異常，如下所示：
所以針對于這種框架打印的異常，我們最好要分析出異常堆棧中最接近案發現場的信息作為簽名，我們實現了如下算法：
private Tuple2 getSignature(String logLocation, String[] arr) { //簽名等于異常的位置 String signature = logLocation; //如果是公共類打印的異常，則繼續尋找具體打印異常信息的方法位置 if(logLocation.startsWith("RpcbaseService") || logLocation.startsWith("APIController") || logLocation.startsWith("LogAspect") || logLocation.startsWith("WebExceptionHandle") || logLocation.startsWith("baseController") || logLocation.startsWith("ExceptionUtil")){ if(arr.length>1){ Tuple2 temp = null; for(int i=1;im()); temp = processChange(a,temp); if(temp.getSecond()==3){ break; } } if(temp!=null){ signature = signature + "-" + temp.getFirst(); } } } String alias = signature.length()>=256? signature.substring(0,255) : signature; return new Tuple2(alias,MD5Util.md5(signature)); } 計算分數的代碼如下：
private Integer getScore(String newline) { if(newline.startsWith("at com.yxy") && !newline.startsWith("at com.yxy.framework")){ return 3; } if(newline.startsWith("at com.yxy") || newline.startsWith("at com.callable") ||newline.startsWith("at com.smart.validate") ){ return 2; } if(newline.startsWith("at ") ){ return 1; } return 0; }原則是，如果是堆棧是自己框架層的代碼則分數為2，如果是業務代碼則為3，如果是其它類庫或jdk代碼則為1，默認為0。這樣通過計算之后我們能拿到最接近業務代碼的堆棧信息作為簽名的一部分。
5、異常分析
一個異常經過分析之后，我們獲得了異常的基本信息：
然后我們將這些數據存儲到mysql或clickhouse類似的數據庫，執行具體的分析即可得到異常的統計數據和畫像信息。
三、結束語
本文只是簡述了Java異常的處理流程，其實將這種分類算法擴展，我們可以分析其它類型的異常日志，比如我們后續做了客戶端崩潰日志分析，針對于Android上報的ANR、Native和Java崩潰日志，使用類似分類方式，將異常信息分類統計展示，供客戶端同學排查問題。
本文沒有介紹異常日志收集的部分，這個地方可以有多種實現方式，我們是內部實現了一套集中式日志管理系統，所有的日志是通過KafkaAppender實時異步輸出到kafka的，大家也可以使用其他日志收集方式，比如filebeat、logstash等。
王同明