当前位置: 首页 > 后端技术 > Java

在JavaSpringBoot项目中使用结构化日志记录节省时间

时间:2023-04-02 09:09:39 Java

以及了解应用程序中发生的事情的终极资源。每个应用程序都有某种类型的日志。然而,这些日志通常是杂乱无章的,分析它们需要付出很多努力。在本文中,我们将了解如何利用结构化日志来大幅增加日志的价值。我们将通过一些非常实用的技巧来使用Logz.io作为日志记录平台来增加应用程序日志数据和查询日志的价值。?代码示例本文附带一个工作代码示例[在GitHub上](https://github.com/thombergs/…)。什么是结构化日志?“正常”日志是非结构化的。它们通常包含消息字符串:2021-08-0818:04:14.721INFO12402---[main]i.r.s.StructuredLoggingApplication:StartedStructuredLoggingApplicationin0.395seconds(JVMrunningfor0.552)您希望在记录时获得的所有信息事件:日志事件的日期、创建日志事件的记录器的名称以及日志消息本身。所有信息都在该日志消息中,但很难查找!由于所有的信息都在一个字符串中,如果我们想从日志中得到具体的信息,就必须解析和搜索这个字符串。例如,如果我们只想查看特定记录器的日志,则日志服务器必须解析所有日志消息,检查它们是否具有识别记录器的特定模式,然后根据所需记录器过滤日志消息。结构化日志包含相同的信息,但采用结构化形式而不是非结构化字符串。通常,结构化日志以JSON格式呈现:{"timestamp":"2021-08-0818:04:14.721","level":"INFO","logger":"io.reflectoring....StructuredLoggingApplication","thread":"main","message":"StartedStructuredLoggingApplication..."}这种JSON结构允许日志服务器有效地存储和更重要的是检索日志。例如,现在可以通过时间戳或记录器轻松过滤日志,并且搜索比针对特定模式解析字符串更有效。但结构化日志的价值并不止于此:我们可以根据需要向结构化日志事件添加任何自定义字段!我们可以添加上下文信息来帮助我们识别问题,或者我们可以将指标添加到日志中。有了我们现在触手可及的所有数据,我们可以创建强大的日志查询和仪表板,即使我们只是在半夜醒来调查一个事件,我们也可以找到我们需要的信息。现在让我们看一些展示结构化日志记录功能的用例。为所有日志事件添加代码路径我们首先要看的是代码路径。每个应用程序通常有几个不同的路径,传入请求可以通过这些路径传递到应用程序。考虑下图:在JavaSpringBoot项目中使用结构化日志记录节省时间此示例具有(至少)三个传入请求可以采用的不同代码路径:用户代码路径:用户正在使用其浏览器中的应用程序。浏览器向web控制器发送请求,控制器调用域代码。第三方系统代码路径:应用的HTTPAPI也是从第三方系统调用的。在这个例子中,第三方系统调用与用户浏览器相同的网络控制器。计时器代码路径:与许多应用程序一样,此应用程序有一些由计时器触发的计划任务。这些代码路径中的每一个都可以具有不同的特征。域服务涉及所有三个代码路径。在涉及域服务错误的事件中,了解导致错误的代码路径可以大有帮助!如果我们不知道代码路径,我们很容易在事件调查过程中做出毫无结果的猜测。所以,我们应该将代码路径添加到日志中!下面是我们如何使用SpringBoot来做到这一点。为传入的Web请求添加代码路径在Java中,SLF4J日志库提供了MDC类(消息诊断上下文)。此类允许我们将自定义字段添加到同一线程中发出的所有日志事件。要向每个传入的Web请求添加自定义字段,我们需要构建一个拦截器,在每个请求的开头添加codePath字段,甚至在我们的Web控制器代码执行之前。我们可以通过实现HandlerInterceptor接口来做到这一点:MDC.put("codePath","3rdParty");}else{MDC.put("codePath","user");}returntrue;}@OverridepublicvoidpostHandle(HttpServletRequest请求,HttpServletResponse响应,对象处理程序,ModelAndViewmodelAndView){MDC.remove("codePath");}}在preHandle()方法中,我们调用MDC.put()将codePath字段添加到所有日志事件。如果请求包含标识请求来自的标头第三方系统,我们设置代码路径为3rdParty,否则,我们假设请求来自用户的浏览器。根据不同的应用,这里的逻辑可能会有很大差异,当然,这只是一个例子。在postHandle()方法中,我们不要忘记再次调用MDC.remove(),将之前设置的所有字段全部移除,否则线程即使返回线程池,仍会保留这些字段,下次请求时由该线程提供服务这些字段可能仍被设置为错误的值。要激活一个拦截器,我们需要将它添加到InterceptorRegistry:@ComponentpublicclassWebConfigurerimplementsWebMvcConfigurer}}就是这样。在传递日志事件的线程中发出的所有日志事件现在都有一个codePath字段。如果发出任何创建和启动子线程的请求,请确保在新线程生命周期开始时调用MDC.put()。在计划作业中添加代码路径在SpringBoot中,我们可以使用@Scheduled和@EnableScheduling注解轻松创建计划作业。要将代码路径添加到日志中,我们需要确保在调度方法中首先调用MDC.put():privatestaticfinalLoggerlogger=LoggerFactory.getLogger(Timer.class);publicTimer(DomainServicedomainService){this.domainService=domainService;}@Scheduled(fixedDelay=5000)voidscheduledHello(){MDC.put("codePath","timer");logger.info("从计时器记录事件");//做一些实际的工作MDC.remove("codePath");这样,执行调度方法的线程发出的所有日志事件都将包含字段codePath。我们也可以创建自己的@Job注释或类似注释来为我们完成这项工作,但这超出了本文的范围。为了使计划作业的日志更有价值,我们可以添加额外的字段:job_status:指示作业是否成功的状态。job_id:已执行作业的ID。job_records_processed:如果作业做一些批处理,它可以记录处理的记录数。...通过日志中的这些字段,我们可以得到日志服务器中很多有用的信息!将用户ID添加到用户启动的日志事件中典型Web应用程序中的大部分工作都是在来自用户浏览器的Web请求中完成的,这会触发应用程序中的线程为浏览器创建响应。想象一下发生了一些错误,日志中的堆栈跟踪显示它与特定的用户配置有关。但是我们不知道请求来自哪个用户!为了缓解这种情况,在用户触发的所有日志事件中包含某种用户ID非常有帮助。因为我们知道传入的Web请求大多直接来自用户的浏览器,所以我们可以在我们创建的同一个LoggingInterceptor中添加用户名字段以添加代码路径字段:,对象处理程序)抛出异常{Objectprincipal=SecurityContextHolder.getContext().getAuthentication().getPrincipal();if(principalinstanceofUserDetails){Stringusername=((UserDetails)principal).getUsername();MDC.put("用户名",用户名);}else{字符串用户名=principal.toString();MDC.put("用户名",用户名);}返回真;}@OverridepublicvoidpostHandle(HttpServletRequestrequest,HttpServletResponseresponse,Objecthandler,ModelAndViewmodelAndView){MDC.remove("用户名");}}此代码假定我们使用SpringSecurity来管理对Web应用程序的访问。我们使用SecurityContextHolder获取Principal并从中提取用户名以将其传递给MDC.put()。从为请求提供服务的线程发出的每个日志事件现在都将包含一个用户名字段和用户名。有了这个字段,我们现在可以过滤特定用户请求的日志。如果用户报告问题,我们可以根据他们的名字过滤日志,大大减少我们必须查看的日志。根据法规,您可能希望记录更不透明的用户ID而不是用户名。将根本原因添加到错误日志事件中当我们的应用程序中发生错误时,我们通常会记录堆栈跟踪。堆栈跟踪帮助我们确定错误的根本原因。没有堆栈跟踪,我们就不知道是哪个代码导致了错误!但是,如果我们想在应用程序中运行错误统计信息,那么堆栈跟踪会非常笨拙。假设我们想知道我们的应用程序每天总共记录了多少错误,以及其中有多少是由哪个根本原因异常引起的。我们必须从日志中导出所有堆栈跟踪,并对它们进行一些手动过滤才能得到这个问题的答案!但是,如果我们为每个错误日志事件添加一个自定义字段roo??tCause,我们就可以通过该字段过滤日志事件,然后在日志服务器的UI中创建不同根本原因的直方图或饼图,甚至无需导出数据。在SpringBoot中执行此操作的一种方法是创建一个@ExceptionHandle:@ControllerAdvicepublicclassWebExceptionHandler{privatestaticfinalLoggerlogger=LoggerFactory.getLogger(WebExceptionHandler.class);@ExceptionHandler(Exception.class)@ResponseStatus(HttpStatus.INTERNAL_SERVER_publicvoidinternalServerError(Exceptione){MDC.put("rootCause",getRootCause(e).getClass().getName());logger.error("返回500(内部服务器错误).",e);MDC.remove("rootCause");}privateThrowablegetRootCause(Exceptione){ThrowablerootCause=e;while(e.getCause()!=null&&rootCause.getCause()!=rootCause){rootCause=e.getCause();}returnrootCause;}}我们创建了一个用@ControllerAdvice注解的类,这意味着它在我们所有的网络控制器中都可用。在这个类中,我们创建了一个用@注解的方法ExceptionHandler。在任何Web控制器中引发的异常都会调用此方法。它将rootCauseMDC字段设置为导致错误的异常类的完全限定名称,然后记录异常的堆栈跟踪。就是这样。所有打印堆栈跟踪的日志事件现在都有一个字段roo??tCause,我们可以通过该字段进行过滤以了解应用程序中错误的分布。向所有日志事件添加跟踪ID如果我们运行多个服务,例如在微服务环境中,分析错误时事情会很快变得复杂。一项服务调用另一项服务,另一项服务调用另一项服务,并且很难(如果可能的话)将一项服务中的错误跟踪到另一项服务中的错误。跟踪ID有助于将一项服务的日志事件连接到另一项服务的日志事件:在上面的示例图中,服务1被调用并生成了跟踪ID“1234”。然后它调用服务2和3,向它们传播相同的跟踪ID,以便它们可以将相同的跟踪ID添加到它们的日志事件中,允许它们通过搜索特定的跟踪ID来加入所有服务的日志事件。服务1还为每个传出请求创建一个唯一的“spanID”。虽然跟踪跨越服务1的整个请求/响应周期,但跨度仅跨越一个服务与另一个服务之间的请求/响应周期。我们可以自己实现这样的跟踪机制,但是有跟踪标准和工具可以集成到使用这些标准的跟踪系统中,例如Logz.io的分布式跟踪功能。让我们坚持使用标准工具。在SpringBoot世界中,这就是SpringCloudSleuth,我们只需将其添加到我们的pom.xml中即可将此功能集成到我们的应用程序中:groupId>spring-cloud-dependencies2020.0.3pomimportorg.springframework.cloudspring-cloud-starter-sleuth这会自动将跟踪和跨度ID添加到我们的日志并在使用支持的HTTP客户端时通过请求标头将它们从一个服务传播到下一个服务。您可以在“使用SpringCloudSleuth在分布式系统中进行跟踪”一文中阅读有关SpringCloudSleuth的更多信息。添加某些代码路径的持续时间我们的应用程序响应请求所需的总持续时间是一个重要指标。如果速度太慢,用户会感到沮丧。通常,将请求持续时间公开为指标并创建显示请求持续时间的直方图和百分位数的仪表板是个好主意,这样我们就可以一目了然地了解应用程序的健康状况,甚至可能在某个特定的时候达到阈值时收到警报。但是,我们可能不仅对总请求持续时间感兴趣,而且对某些代码路径的持续时间感兴趣,而不是一直查看仪表板。在分析日志以调查问题时,了解代码中特定路径的执行时间可能是一个重要线索。在Java中,我们可能会这样做:voidcallThirdPartyService()throwsInterruptedException{logger.info("logeventfromthedomainservice");即时启动=Instant.now();线程.睡眠(2000);//模拟一个昂贵的操作Durationduration=Duration.between(start,Instant.now());MDC.put("thirdPartyCallDuration",String.valueOf(duration.getNano()));logger.info("调用第三方服务成功!");MDC.remove("thirdPartyCallDuration");}假设我们正在调用第三方服务并希望将持续时间添加到日志中。使用Instant.now()和Duration.between(),我们计算持续时间,将其添加到MDC,然后创建日志事件。此日志事件现在将包含字段thirdPartyCallDuration,我们可以在日志中过滤和搜索该字段。例如,我们可能会搜索调用时间过长的实例。然后我们可以使用用户ID或者跟踪ID,当这需要特别长的时间时,我们也可以将它们作为日志事件的字段来查找模式。在Logz.io中查询结构化日志如果我们按照有关每个环境日志记录的文章中的描述将日志记录设置到Logz.io,我们现在可以在Logz.io提供的KibanaUI中查询日志。错误分布例如,我们可以查询在rootCause字段中具有值的所有日志事件:__exists__:"rootCause"这将显示带有根本原因的错误事件列表。我们还可以在Logz.ioUI中创建可视化,以显示给定时间范围内的错误分布:该图显示几乎一半的错误是由ThingyException引起的,因此最好检查一下是否可以避免此异常不知何故的想法。如果无法避免,我们应该将其记录在WARN而不是ERROR上,以保持错误日志的清洁。跨代码路径的错误分布例如,假设用户抱怨计划的作业无法正常工作。如果我们在调度方法代码中添加一个job_status字段,我们可以通过那些失败的作业过滤日志:大多数预定的工作都失败了!我们应该为此添加一些警报!我们还可以查看哪些异常是大多数计划作业的根本原因并开始调查。检查用户错误或者,假设用户名为“user”的用户提交了支持请求,并指定了错误发生的大致日期和时间。我们可以使用查询用户名:用户来过滤日志以仅显示该用户的日志,我们可以快速将用户问题的原因归零。我们还可以扩展查询以仅显示具有rootCause的该用户的日志事件,以直接查看什么时候出了什么问题。username:"user"AND_exists_:"rootCause"构造您的日志本文仅展示了几个示例,说明我们如何向日志事件添加结构并在查询日志时使用该结构。以后可以在日志中搜索的任何内容都应该是日志事件中的自定义字段。添加到日志事件的字段在很大程度上取决于我们正在构建的应用程序,因此在编写代码时,一定要考虑哪些信息可以帮助您分析日志。您可以在[GitHub](https://github.com/thombergs/...)上找到本文中讨论的代码示例。