我的最佳日志实践

前言

本文译自：https://tuhrig.de/my-logging-best-practices/

如果你是一名后端开发者，那么日志就相当于你的应用的窗口。不像前端，除了日志消息外没有太多别的东西。接下来将介绍一些我个人写日志时的指导思想。

Log After, not before

回想以下以前，每艘船都会有一本航海日志，就像日记一样，记录着每天发生的重要事情。就像一本传统的航海日志，我们应该记录已经发生的事情，而不是我们将要做的事情。

举一个简单的例子：

// don't do that
log.info("Making request to REST API")
restClient.makeRequest()
 
// do that
restClient.makeRequest()
log.info("Made request to REST API")

第一个 log 声明并没有给出太多信息。当读到它的时候，你并不知道REST调用是否成功。而为了知道是否调用成功，你必须寻找是否存在异常。当你读到这条log，但是却没有找到相应的 exception 异常，你将会困惑一整天。

这里感觉没太翻译明白，可以对照原文看：The first log statement doesn’t tell much. When reading it, you will not know if the REST call was successful or not. To do so you must look for the absence of an exception. And if you read this log but miss the subsequent exception you will be confused for the rest of the day (trust me).

第二个 log 方式则好了许多。它清楚地表明了刚刚的操作成功了。如果REST调用失败了，你将看不到这条 log，而是会有一个 exception。

我将对所有 INFO 日志遵守这条规则，然后对于 DEBUG 来说会生成 exceptions。

Separate parameters and messages

一个典型的 log 小心包含两种类型的数据，一种是手写的消息，来声明接下来的消息内容。另一种类型数据则是一系列包含在之前操作中的参数。你应该区分这两部分。

// don't do that
restClient.makeRequest()
log.info("Made request to {} on REST API.", url)
 
// do that
restClient.makeRequest()
log.info("Made request to REST API. [url={}]", url)

第一种 log 消息有一些缺点。它是难以解析的，比如他对于 Grok pattern

来说。所以在我们的日志工具中，自动抽取 IDs 或者其他参数就会变得更困难。并且它也是难以阅读的。想象一下，一个非常长的 URL 在末端带有一系列参数。该条 log 消息的一半就超过了你的屏幕。同时，这个 log 也是难以扩展的。如果你想添加另一个参数（比如使用的 HTTP 方法）你就必须重写整个句子。

第二个版本就没有以上的缺点。它是非常容易解析的，因为它有清晰的结构。你在句子的前部分就能看到整个句子的内容。并且也十分容易扩展，只需要在列表里添加另一个参数。

Distinguish between WARNING and ERROR

显然，有多种级别的 log 是有它存在的原因的，你应该适当地使用它们。在 WARNING 和 ERROR 之间存在明显的区别。

如果你做一些操作并且切实生效了，但是依然存在一些问题，这就是 WARNING。当如果你做了一些操作，它并没有生效，那就是一个 ERROR。

再来看一个例子：

try {
    restClient.makeRequest()
    log.info("Made request to REST API. [url={}]", url)
} catch(e: UnauthorizedException) {
    log.warn("Request to REST API was rejected because user is unauthorized. [url={}, result={}]", url, result)
} catch(e: Exception) {
    log.error("Request to REST API failed. [url={}, exception={}]", url, exception)
}

这个 REST 调用可能有三种输出情况：

• 它可以正常工作。那就会有一个 INFO 输出。
• 当它失败了，遇到了一个预期外的异常，那就是一个 ERROR。
• 当它导致了一些预期内的异常，那就是 WARNING。

所以在 WARNING 的例子中，你做了一些事情，但你没有完美地做好。而在 ERROR 中，你并没有做事情。

另外注意，一个 WARNING（当然 ERROR 也是）是一个调用动作。如果没有人需要对此做出反应或者要做些什么，那么你也就不必去 log 输出 WARNING。

INFO is for business, DEBUG for technology

INFO 日志应该看起来像一本书，它告诉你发生了什么，而不是如何发生的。这意味着 INFO 更适合于业务逻辑消息，相比于技术细节来说。技术相关的消息应该使用 DEBUG。

INFO  | User registered for newsletter. [user="Thomas", email="thomas@tuhrig.de"]
INFO  | Newsletter send to user. [user="Thomas"]
INFO  | User unsubscribed from newsletter. [user="Thomas", email="thomas@tuhrig.de"]

上面 INFO 类型的日志，从我们业务逻辑的视角告诉你发生了什么。

DEBUG | Saved user to newsletter list. [user="Thomas", email="thomas@tuhrig.de"]
DEBUG | Send welcome mail. [user="Thomas", email="thomas@tuhrig.de"]
INFO  | User registered for newsletter. [user="Thomas", email="thomas@tuhrig.de"]
DEBUG | Started cron job to send newsletter of the day. [subscribers=24332]
INFO  | Newsletter send to user. [user="Thomas"]
INFO  | User unsubscribed from newsletter. [user="Thomas", email="thomas@tuhrig.de"]

每个业务用例都会导致一条 INFO 日志输出。此外，会有 DEBUG 日志来给出更多细节信息，来描述处理过程。

Much more

当然，对于好的日志来说还有许多值得做的。你还需要考虑 tracing, log aggregation and metrics 。但当提及如何书写时，我非常推荐上面的规则。