【注】本文譯自： Saving Time with Structured Logging - Reflectoring

日誌記錄是調查事件和了解應用程式中發生的事情的終極資源。每個應用程式都有某種型別的日誌。

然而，這些日誌通常很混亂，分析它們需要付出很多努力。在本文中，我們將研究如何利用結構化日誌來大大增加日誌的價值。

我們將通過一些非常實用的技巧來提高應用程式日誌資料的價值，並使用 Logz.io 作為日誌平臺來查詢日誌。

程式碼示例

本文附有 GitHub 上的工作程式碼示例。

什麼是結構化日誌？

“正常”日誌是非結構化的。它們通常包含一個訊息字串：

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 上找到本文中討論的程式碼示例。