关于springboot:在-Java-Spring-Boot-项目中使用结构化日志节省时间

40次阅读

共计 8450 个字符，预计需要花费 22 分钟才能阅读完成。

【注】本文译自：[Saving Time with Structured Logging – Reflectoring](
https://reflectoring.io/struc…)

日志记录是考察事件和理解应用程序中产生的事件的终极资源。每个应用程序都有某种类型的日志。

然而，这些日志通常很凌乱，剖析它们须要付出很多致力。在本文中，咱们将钻研如何利用结构化日志来大大增加日志的价值。

咱们将通过一些十分实用的技巧来进步应用程序日志数据的价值，并应用 Logz.io 作为日志平台来查问日志。

代码示例

本文附有 [GitHub 上](
https://github.com/thombergs/…)的工作代码示例。

什么是结构化日志？

“失常”日志是非结构化的。它们通常蕴含一个音讯字符串：

2021-08-08 18:04:14.721 INFO 12402 --- [main] i.r.s.StructuredLoggingApplication : Started StructuredLoggingApplication in 0.395 seconds (JVM running for 0.552)

此音讯蕴含咱们在考察事件或剖析问题时心愿取得的所有信息：

  • 日志事件的日期
  • 创立日志事件的记录器的名称，以及
  • 日志音讯自身。
    所有信息都在该日志音讯中，但很难查问这些信息！因为所有信息都在一个字符串中，如果咱们想从日志中获取特定信息，就必须解析和搜寻这个字符串。

例如，如果咱们只想查看特定记录器的日志，则日志服务器必须解析所有日志音讯，查看它们是否具备辨认记录器的特定模式，而后依据所需的记录器过滤日志音讯。

结构化日志蕴含雷同的信息，但采纳结构化模式而不是非结构化字符串。通常，结构化日志以 JSON 格局出现：

{
    "timestamp": "2021-08-08 18:04:14.721",
    "level": "INFO",
    "logger": "io.reflectoring....StructuredLoggingApplication",
    "thread": "main",
    "message": "Started StructuredLoggingApplication ..."
}

这种 JSON 构造容许日志服务器无效地存储，更重要的是检索日志。

例如，当初能够通过 timestamp 或 logger 轻松过滤日志，而且搜寻比解析特定模式的字符串更无效。

然而结构化日志的价值并不止于此：咱们能够依据须要向结构化日志事件中增加任何自定义字段！ 咱们能够增加上下文信息来帮忙咱们辨认问题，或者咱们能够向日志增加指标。

凭借咱们当初触手可及的所有数据，咱们能够创立弱小的日志查问和仪表板，即便咱们刚在中午醒来考察事件，咱们也能找到所需的信息。

当初让咱们看几个用例，它们展现了结构化日志记录的弱小性能。

为所有日志事件增加代码门路

咱们首先要看的是代码门路。每个应用程序通常有几个不同的门路，传入申请能够通过应用程序。思考这个图：

Java Spring Boot 我的项目中应用结构化日志节省时间
此示例具备（至多）三种不同的代码门路，传入申请能够采纳这些门路：

  • 用户代码门路：用户正在从他们的浏览器应用应用程序。浏览器向 Web 控制器发送申请，控制器调用畛域代码。
  • 第三方零碎代码门路：应用程序的 HTTP API 也从第三方零碎调用。在这个例子中，第三方零碎调用与用户浏览器雷同的 web 控制器。
  • 计时器代码门路 ：与许多应用程序一样，此应用程序有一些由计时器触发的打算工作。
    这些代码门路中的每一个都能够具备不同的特色。域服务波及所有三个代码门路。在波及域服务谬误的事件期间，理解导致谬误的代码门路将大有帮忙！

如果咱们不晓得代码门路，咱们很容易在事件调查期间做出毫无结果的猜想。

所以，咱们应该将代码门路增加到日志中！以下是咱们如何应用 Spring Boot 做到这一点。

为传入的 Web 申请增加代码门路

在 Java 中，SLF4J 日志库提供了 MDC 类（音讯诊断上下文）。这个类容许咱们向在同一线程中收回的所有日志事件增加自定义字段。

要为每个传入的 Web 申请增加自定义字段，咱们须要构建一个拦截器，在每个申请的结尾增加 codePath 字段，甚至在咱们的 Web 控制器代码执行之前。

咱们能够通过实现 HandlerInterceptor 接口来做到这一点：

public class LoggingInterceptor implements HandlerInterceptor {


    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
            throws Exception {if (request.getHeader("X-CUSTOM-HEADER") != null) {MDC.put("codePath", "3rdParty");
        } else {MDC.put("codePath", "user");
        }


        return true;
    }


    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
            ModelAndView modelAndView) {MDC.remove("codePath");
    }
}

在 preHandle() 办法中，咱们调用 MDC.put() 将 codePath 字段增加到所有日志事件中。如果申请蕴含标识申请来自第三方方零碎的标头，咱们将代码门路设置为 3rdParty，否则，咱们假如申请来自用户的浏览器。

依据利用的不同，这里的逻辑可能会有很大的不同，当然，这只是一个例子。

在 postHandle() 办法中，咱们不应该遗记调用 MDC.remove() 再次删除所有先前设置的字段，否则线程仍会保留这些字段，即便它返回到线程池，以及下一个申请 由该线程提供服务的那些字段可能依然设置为谬误的值。

要激活拦截器，咱们须要将其增加到 InterceptorRegistry 中：

@Componentpublic
class WebConfigurer implements WebMvcConfigurer {


    @Override
    public void addInterceptors(InterceptorRegistry registry) {registry.addInterceptor(new LoggingInterceptor());
    }
}

就是这样。在传入日志事件的线程中收回的所有日志事件当初都具备 codePath 字段。

如果任何申请创立并启动子线程，请确保在新线程生命周期开始时调用 MDC.put()。

在打算作业中增加代码门路

在 Spring Boot 中，咱们能够通过应用 @Scheduled 和 @EnableScheduling 注解轻松创立打算作业。

要将代码门路增加到日志中，咱们须要确保调用 MDC.put() 作为调度办法中的第一件事：

@Componentpublic
class Timer {


    private final DomainService domainService;


    private static final Logger logger = LoggerFactory.getLogger(Timer.class);


    public Timer(DomainService domainService) {this.domainService = domainService;}


    @Scheduled(fixedDelay = 5000)
    void scheduledHello() {MDC.put("codePath", "timer");
        logger.info("log event from timer");
        // do some actual work
        MDC.remove("codePath");
    }


}

这样，从执行调度办法的线程收回的所有日志事件都将蕴含字段 codePath。咱们也能够创立咱们本人的 @Job 注解或相似的注解来为咱们实现这项工作，但这超出了本文的范畴。

为了使预约作业的日志更有价值，咱们能够增加其余字段：

  • job_status：批示作业是否胜利的状态。
  • job_id：已执行作业的 ID。
  • job_records_processed：如果作业进行一些批处理，它能够记录解决的记录数。
  • ……
    通过日志中的这些字段，咱们能够在日志服务器获取到很多有用的信息！

将用户 ID 增加到用户启动的日志事件

典型 Web 应用程序中的大部分工作是在来自用户浏览器的 Web 申请中实现的，这些申请会触发应用程序中的线程，为浏览器创立响应。

设想一下产生了一些谬误，日志中的堆栈跟踪显示它与特定的用户配置无关。然而咱们不晓得申请来自哪个用户！

为了缓解这种状况，在用户触发的所有日志事件中蕴含某种用户 ID 是十分有帮忙的。

因为咱们晓得传入的 Web 申请大多间接来自用户的浏览器，因而咱们能够在创立的同一个 LoggingInterceptor 中增加 username 字段以增加 codePath 字段：

public class LoggingInterceptor implements HandlerInterceptor {


    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
            throws Exception {Object principal = SecurityContextHolder.getContext().getAuthentication().getPrincipal();


        if (principal instanceof UserDetails) {String username = ((UserDetails) principal).getUsername();
            MDC.put("username", username);
        } else {String username = principal.toString();
            MDC.put("username", username);
        }


        return true;
    }


    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
            ModelAndView modelAndView) {MDC.remove("username");
    }
}

这段代码假如咱们应用 Spring Security 来治理对 Web 应用程序的拜访。咱们应用 SecurityContextHolder 来获取 Principal 并从中提取用户名以将其传递给 MDC.put()。

从服务申请的线程收回的每个日志事件当初都将蕴含用户名字段和用户名。

有了这个字段，咱们当初能够过滤特定用户申请的日志。如果用户报告了问题，咱们能够依据他们的姓名过滤日志，并极大地缩小咱们必须查看的日志。

依据规定，您可能心愿记录更不通明的用户 ID 而不是用户名。

为谬误日志事件增加根本原因

当咱们的应用程序呈现谬误时，咱们通常会记录堆栈跟踪。堆栈跟踪帮忙咱们确定谬误的根本原因。如果没有堆栈跟踪，咱们将不晓得是哪个代码导致了谬误！

然而，如果咱们想在应用程序中运行谬误统计信息，堆栈跟踪是十分蠢笨的。假如咱们想晓得咱们的应用程序每天总共记录了多少谬误，以及其中有多少是由哪个根本原因异样引起的。咱们必须从日志中导出所有堆栈跟踪，并对它们进行一些手动过滤，能力失去该问题的答案！

然而，如果咱们将自定义字段 rootCause 增加到每个谬误日志事件，咱们能够通过该字段过滤日志事件，而后在日志服务器的 UI 中创立不同根本原因的直方图或饼图，甚至无需导出数据。

在 Spring Boot 中执行此操作的一种办法是创立一个 @ExceptionHandle：

@ControllerAdvicepublic
class WebExceptionHandler {private static final Logger logger = LoggerFactory.getLogger(WebExceptionHandler.class);


    @ExceptionHandler(Exception.class)
    @ResponseStatus(HttpStatus.INTERNAL_SERVER_ERROR)
    public void internalServerError(Exception e) {MDC.put("rootCause", getRootCause(e).getClass().getName());
        logger.error("returning 500 (internal server error).", e);
        MDC.remove("rootCause");
    }


    private Throwable getRootCause(Exception e) {
        Throwable rootCause = e;
        while (e.getCause() != null && rootCause.getCause() != rootCause) {rootCause = e.getCause();
        }
        return rootCause;
    }


}

咱们创立了一个用 @ControllerAdvice 注解的类，这意味着它在咱们所有的 web 控制器中都是无效的。

在类中，咱们创立了一个用 @ExceptionHandler 注解的办法。对于任何 Web 控制器中呈现的异样，都会调用此办法。它将 rootCause MDC 字段设置为导致谬误的异样类的齐全限定名称，而后记录异样的堆栈跟踪。

就是这样。所有打印堆栈跟踪的日志事件当初都有一个字段 rootCause，咱们能够通过这个字段进行过滤以理解咱们应用程序中的谬误散布。

向所有日志事件增加跟踪 ID

如果咱们运行多个服务，例如在微服务环境中，剖析谬误时事件会很快变得复杂。一个服务调用另一个服务，另一个服务调用再一个服务，并且很难（如果可能的话）跟踪一个服务中的谬误到另一个服务中的谬误。

跟踪 ID 有助于连贯一个服务中的日志事件和另一个服务中的日志事件：

在下面的示例图中，服务 1 被调用并生成跟踪 ID“1234”。而后它调用服务 2 和 3，将雷同的跟踪 ID 流传给它们，以便它们能够将雷同的跟踪 ID 增加到其日志事件中，从而能够通过搜寻特定的跟踪 ID 来连贯所有服务的日志事件。

对于每个传出申请，服务 1 还会创立一个惟一的“跨度 ID”。尽管跟踪逾越服务 1 的整个申请 / 响应周期，但跨度仅逾越一个服务和另一个服务之间的申请 / 响应周期。

咱们能够本人实现这样的跟踪机制，然而有一些跟踪规范和工具能够应用这些规范集成到跟踪零碎中，例如 Logz.io 的分布式跟踪性能。

咱们还是应用规范工具吧。在 Spring Boot 世界中，这就是 Spring Cloud Sleuth，咱们能够通过简略地将它增加到咱们的 pom.xml，从而把该性能集成到咱们的应用程序中：

<dependencyManagement>
  <dependencies>
    <dependency>
      <groupId>org.springframework.cloud</groupId>
      <artifactId>spring-cloud-dependencies</artifactId>
      <version>2020.0.3</version>
      <type>pom</type>
      <scope>import</scope>
    </dependency>
  </dependencies>
</dependencyManagement><dependencies>
  <dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-starter-sleuth</artifactId>
  </dependency>
</dependencies>

这会主动将跟踪和跨度 ID 增加到咱们的日志中，并在应用反对的 HTTP 客户端时通过申请标头将它们从一个服务流传到下一个服务。您能够在“应用 Spring Cloud Sleuth 在分布式系统中进行跟踪”一文中浏览无关 Spring Cloud Sleuth 的更多信息。

增加某些代码门路的持续时间

咱们的应用程序响应申请所需的总持续时间是一个重要的指标。如果速度太慢，用户会感到丧气。

通常，将申请持续时间作为指标公开并创立显示申请持续时间的直方图和百分位数的仪表板是一个好主见，这样咱们就能够高深莫测地理解应用程序的健康状况，甚至可能在违反某个阈值时收到警报。

然而，咱们并不是始终在查看仪表板，咱们可能不仅对总申请持续时间感兴趣，而且对某些代码门路的持续时间感兴趣。在剖析日志以考察问题时，理解代码中特定门路执行所需的工夫可能是一个重要线索。

在 Java 中，咱们可能会这样做：

void callThirdPartyService() throws InterruptedException {logger.info("log event from the domain service");
    Instant start=Instant.now();
    Thread.sleep(2000); // simulating an expensive operation
    Duration duration=Duration.between(start,Instant.now());
    MDC.put("thirdPartyCallDuration",String.valueOf(duration.getNano()));
    logger.info("call to third-party service successful!");
    MDC.remove("thirdPartyCallDuration");
}

假如咱们正在调用第三方服务并心愿将持续时间增加到日志中。应用 Instant.now() 和 Duration.between()，咱们计算持续时间，将其增加到 MDC，而后创立日志事件。

这个日志事件当初将蕴含字段 thirdPartyCallDuration，咱们能够在日志中过滤和搜寻该字段。例如，咱们可能会搜寻这个调用耗时过长的实例。而后，咱们能够应用用户 ID 或跟踪 ID，当这须要特地长的工夫时，咱们也能够将它们作为日志事件的字段来找出模式。

在 Logz.io 中查问结构化日志

如果咱们依照对于 per-environment logging 的文章中的形容设置了日志记录到 Logz.io，咱们当初能够在 Logz.io 提供的 Kibana UI 中查问日志。

谬误散布

例如，咱们能够查问在 rootCause 字段中具备值的所有日志事件：

__exists__: "rootCause"

这将显示具备根本原因的谬误事件列表。

咱们还能够在 Logz.io UI 中创立一个可视化来显示给定工夫范畴内的谬误散布：

此图表显示简直一半的谬误是由 ThingyException 引起的，因而查看是否能够以某种形式防止此异样可能是个好主见。如果无奈防止，咱们应该将其记录在 WARN 而不是 ERROR 上，以放弃谬误日志的清洁。

跨代码门路的谬误散布

例如，假如用户埋怨预约的作业没有失常工作。如果咱们在调度办法代码中增加了一个 job_status 字段，咱们能够通过那些失败的作业来过滤日志：

job_status: "ERROR"

为了取得更高级的视图，咱们能够创立另一个饼图可视化，显示 job_status 和 rootCause 的散布：

咱们当初能够看到大部分预约的作业都失败了！咱们应该为此增加一些警报！咱们还能够查看哪些异样是大多数打算作业的根本原因并开始考察。

检查用户的谬误

或者，假如用户名为“user”的用户提出了一个反对申请，指定了它产生的大抵日期和工夫。咱们能够应用查问 username: user 过滤日志以仅显示该用户的日志，并且能够疾速将用户问题的起因归零。

咱们还能够扩大查问以仅显示具备 rootCause 的该用户的日志事件，以间接理解何时出了什么问题。

username: "user" AND _exists_: "rootCause"

结构化您的日志

本文仅展现了几个示例，阐明咱们如何向日志事件增加构造并在查问日志时应用该构造。当前能够在日志中搜寻的任何内容都应该是日志事件中的自定义字段。增加到日志事件中的字段在很大水平上取决于咱们正在构建的应用程序，所以在编写代码时，肯定要思考哪些信息能够帮忙您剖析日志。

您能够在 [GitHub 上](
https://github.com/thombergs/…)找到本文中探讨的代码示例。

正文完
springboot
发表至： springboot
2021-11-10
 0
springcloud项目优雅重启六解决方案
关于springboot:SpringBoot与Mybatis整合day04
关于springboot:09springboot工程中的热部署实现
关于springboot:activiti-添加流程模型并返回-modelId