龙腾CMS演示站02

sve141a笔记本多少钱（让异常无处遁形）

发布者：金悦华 2022-03-26 11:42

导读大部分时候，发现问题通常比解决问题更加重要。异常是我们在开发和运维过程中频繁会遇到的东西，通过异常我们可以知道程序中发生了一些非正常的事件，进而排查原因、解决问题。能够有效的对异常进行收集分析，及时发

大部分时候，发现问题通常比解决问题更加重要。

异常是我们在开发和运维过程中频繁会遇到的东西，通过异常我们可以知道程序中发生了一些非正常的事件，进而排查原因、解决问题。能够有效的对异常进行收集分析，及时发现异常报告异常，对于我们提高系统的稳定性和可用性都具有很大的现实意义。

本文介绍了我们在分布式系统异常日志收集与分析方面的实践过程，文中提出了一种对异常日志分类的算法，可以相对有效的分析海量异常日志。

一、背景

首先，我们先来讨论下为什么要做这件事情。

一般在开发过程中出现的异常大部分都能被大家及时发现并解决，但是通常在系统上线之后，由于大家不会实时查看日志，我们的异常信息可能会被淹没在大量应用系统日志中。

如果没有将异常信息及时收集并暴露出来，可能某些异常便会被忽略或造成很大影响之后才被发现。大家也可能经历过如下类似的场景：

场景一：某些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、定义异常分析算法

知道了异常日志的基本格式，接下来我们就需要找到一个方法对异常日志进行分析了。

日志分析最重要的一个问题就是如何对海量的异常日志做分类，我们知道如果仅仅是把异常上报上来，可能每天会出现几千几万条异常我们是没办法逐条进行处理的，所以我们需要定义一个算法对异常进行分类。

算法定义如下：

对于每一个异常，我们计算一个签名代表异常的分类
同类的异常具有相同的签名
签名信息十一个md5值，便于后续的数据分析
取原始签名的前256个字符作为异常的别名，用户展示

所以现在的问题是如何找到异常的签名，我们继续分析。

一个异常出现一次，那么就有可能出现多次，这些异常应该归属为同一类，我们可以简单地认为在同一个位置出现的异常是同一类。对其中某个异常结构分析如下所示：

同一个位置这里包含两个部分：

一个是代码行数，这个其实是有日志框架提供的，代表这行日志是在哪个类哪一行打印的
第二是具体的执行方法，这个信息是隐含在具体的异常堆栈里面的

所以只要我们成功提取出这两个信息，使用他们就可以计算签名了。

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 提取执行方法信息

提取执行方法则需要一些技巧。从上面的分析我们可以知道我们系统中的异常大体分为了三类：

应用中通过logger.error()打印的异常带堆栈
应用中通过logger.error()打印的异常不带堆栈
框架统一打印的异常

前两种其实只要提取出异常打印的具体类就可以定位位置了，但是第三种也只使用位置信息的话则无法区分具体的异常，如下所示：

所以针对于这种框架打印的异常，我们最好要分析出异常堆栈中最接近案发现场的信息作为签名，我们实现了如下算法：

遍历每一行堆栈信息，提取出全限定名
对于每一行计算一个分数，分数高的代表信息更重要，最终找到分数最高的获得签名


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等。

免责声明：本文章由会员“金悦华”发布如果文章侵权，请联系我们处理，本站仅提供信息存储空间服务如因作品内容、版权和其他问题请于本站联系

标签：科技