如何使用日志进行程序调试

by Maya Gilad

通过Maya Gilad

如何使用日志节省调试时间 (How to save hours of debugging with logs)

A good logging mechanism helps us in our time of need.

一个 良好的日志记录机制可以在需要时帮助我们。

When we’re handling a production failure or trying to understand an unexpected response, logs can be our best friend or our worst enemy.

当我们处理生产故障或试图了解意外的响应时，日志可能是我们最好的朋友，也可能是我们最大的敌人。

Their importance for our ability to handle failures is enormous. When it comes to our day to day work, when we design our new production service/feature, we sometimes overlook their importance. We neglect to give them proper attention.

它们对于我们处理故障的能力至关重要。 当涉及到日常工作时，当我们设计新的生产服务/功能时，有时会忽略它们的重要性。 我们忽略给他们适当的关注。

When I started developing, I made a few logging mistakes that cost me many sleepless nights. Now, I know better, and I can share with you a few practices I’ve learned over the years.

当我开始开发时，我犯了一些记录错误，这些错误使我失去了许多不眠之夜。 现在，我知道的更多了，我可以与您分享我多年来学到的一些实践。

没有足够的磁盘空间 (Not enough disk space)

When developing on our local machine, we usually don’t mind using a file handler for logging. Our local disk is quite large and the amount of log entries being written is very small.

在本地计算机上进行开发时，我们通常不介意使用文件处理程序进行日志记录。 我们的本地磁盘很大，正在写入的日志条目数量很少。

That is not the case in our production machines. Their local disk usually has limited free disk space. In time the disk space won’t be able to store log entries of a production service. Therefore, using a file handler will eventually result in losing all new log entries.

在我们的生产机器中并非如此。 他们的本地磁盘通常具有有限的可用磁盘空间。 随着时间的推移，磁盘空间将无法存储生产服务的日志条目。 因此，使用文件处理程序最终将导致丢失所有新的日志条目。

If you want your logs to be available on the service’s local disk, don’t forget to use a rotating file handler. This can limit the max space that your logs will consume. The rotating file handler will handle overriding old log entries to make space for new ones.

如果您希望日志在服务的本地磁盘上可用， 请不要忘记使用旋转文件处理程序。 这个 可以限制您的日志将占用的最大空间。 旋转文件处理程序将处理覆盖的旧日志条目，以为新日志条目腾出空间。

Eeny，meeny，miny，moe (Eeny, meeny, miny, moe)

Our production service is usually spread across multiple machines. Searching a specific log entry will require investigating all them. When we’re in a hurry to fix our service, there’s no time to waste on trying to figure out where exactly did the error occur.

我们的生产服务通常分布在多台机器上。 搜索特定的日志条目将需要调查所有这些条目。 当我们急于修复我们的服务时，没有时间浪费在试图弄清楚错误的确切位置。

Instead of saving logs on local disk, stream them into a centralized logging system. This allows you to search all them at the same time.

与其将日志保存在本地磁盘上， 不如将它们流式传输到集中式日志系统中。 这使您可以同时搜索所有它们。

If you’re using AWS or GCP — you can use their logging agent. The agent will take care of streaming the logs into their logging search engine.

如果您使用的是AWS或GCP，则可以使用其日志记录代理。 代理将负责将日志流式传输到其日志搜索引擎中。

要登录还是不登录？ 这是问题... (To log or not log? this is the question…)

There is a thin line between too few and too many logs. In my opinion, log entries should be meaningful and only serve the purpose of investigating issues on our production environment. When you’re about to add a new log entry, you should think about how you will use it in the future. Try to answer this question: What information does the log message provide the developer who will read it?

日志太少与太多之间有一条细线。 我认为，日志条目应该有意义，并且仅用于调查生产环境中的问题。 当您要添加新的日志条目时，应考虑将来如何使用它。 尝试回答以下问题： 日志消息为开发人员提供了哪些信息？

Too many times I see logs being used for user analysis. Yes, it is much easier to write “user watermelon2018 has clicked the button” to a log entry than to develop a new events infrastructure. This is not the what logs are meant for (and parsing log entries is not fun either, so extracting insights will take time).

我看到很多次日志都用于用户分析。 是的，在日志条目中写“ user lemon2018 has clicked the button”要比开发新的事件基础架构容易得多。 这不是日志的目的(解析日志条目也不是一件好事，因此提取见解将需要时间)。

大海捞针 (A needle in a haystack)

In the following screenshot we see three requests which were processed by our service.

在以下屏幕截图中，我们看到三个请求已由我们的服务处理。

How long did it take to process the second request? Is it 1ms, 4ms or 6ms?

处理第二个请求花了多长时间？ 是1ms，4ms还是6ms？

2018-10-21 22:39:07,051 - simple_example - INFO - entered request 2018-10-21 
22:39:07,053 - simple_example - INFO - entered request 2018-10-21 
22:39:07,054 - simple_example - INFO - ended request 2018-10-21 
22:39:07,056 - simple_example - INFO - entered request 2018-10-21 
22:39:07,057 - simple_example - INFO - ended request 2018-10-21 
22:39:07,059 - simple_example - INFO - ended request

Since we don’t have any additional information on each log entry, we cannot be sure which is the correct answer. Having the request id in each log entry could have reduced the number of possible answers to one. Moreover, having metadata inside each log entry can help us filter the logs and focus on the relevant entries.

由于我们在每个日志条目上没有任何其他信息，因此我们无法确定哪个是正确的答案。 在每个日志条目中都有请求ID可以将可能的答案数量减少到一个。 此外， 在每个日志条目中包含元数据可以帮助我们过滤日志并专注于相关条目。

Let’s add some metadata to our log entry:

让我们在日志条目中添加一些元数据：

2018-10-21 23:17:09,139 - INFO - entered request 1 - simple_example
2018-10-21 23:17:09,141 - INFO - entered request 2 - simple_example
2018-10-21 23:17:09,142 - INFO - ended request id 2 - simple_example
2018-10-21 23:17:09,143 - INFO - req 1 invalid request structure - simple_example
2018-10-21 23:17:09,144 - INFO - entered request 3 - simple_example
2018-10-21 23:17:09,145 - INFO - ended request id 1 - simple_example
2018-10-21 23:17:09,147 - INFO - ended request id 3 - simple_example

The metadata is placed as part of the free text section of the entry. Therefore, each developer can enforce his/her own standards and style. This will result in a complicated search.

元数据被放置为条目的自由文本部分的一部分。 因此，每个开发人员都可以执行自己的标准和样式。 这将导致复杂的搜索。

Our metadata should be defined as part of the entry’s fixed structure.

我们的元数据应定义为条目的固定结构的一部分。

2018-10-21 22:45:38,325 - simple_example - INFO - user/create - req 1 - entered request
2018-10-21 22:45:38,328 - simple_example - INFO - user/login - req 2 - entered request
2018-10-21 22:45:38,329 - simple_example - INFO - user/login - req 2 - ended request
2018-10-21 22:45:38,331 - simple_example - INFO - user/create - req 3 - entered request
2018-10-21 22:45:38,333 - simple_example - INFO - user/create - req 1 - ended request
2018-10-21 22:45:38,335 - simple_example - INFO - user/create - req 3 - ended request

Each message in the log was pushed aside by our metadata. Since we read from left to right, we should place the message as close as possible to the beginning of the line. In addition, placing the message in the beginning “breaks” the line’s structure. This helps us with identifying the message faster.

日志中的每条消息都被我们的元数据推开了。 由于我们是从左到右阅读的，因此应该将消息放置在尽可能靠近行首的位置。 此外，将消息放在开头会“破坏”行的结构。 这有助于我们更快地识别消息。

2018-10-21 23:10:02,097 - INFO - entered request [user/create] [req: 1] - simple_example
2018-10-21 23:10:02,099 - INFO - entered request [user/login] [req: 2] - simple_example
2018-10-21 23:10:02,101 - INFO - ended request [user/login] [req: 2] - simple_example
2018-10-21 23:10:02,102 - INFO - entered request [user/create] [req: 3] - simple_example
2018-10-21 23:10:02,104 - INFO - ended request [user/create [req: 1] - simple_example
2018-10-21 23:10:02,107 - INFO - ended request [user/create] [req: 3] - simple_example

Placing the timestamp and log level prior to the message can assist us in understanding the flow of events. The rest of the metadata is mainly used for filtering. At this stage it is no longer necessary and can be placed at the end of the line.

在消息之前放置时间戳和日志级别可以帮助我们了解事件的流程。 元数据的其余部分主要用于过滤。 在此阶段，它不再是必需的，可以放在行尾。

An error which is logged under INFO will be lost between all normal log entries. Using the entire range of logging levels (ERROR, DEBUG, etc.) can reduce search time significantly. If you want to read more about log levels, you can continue reading here.

在INFO下记录的错误将在所有普通日志条目之间丢失。 使用整个范围的日志记录级别(ERROR，DEBUG等)可以大大减少搜索时间 。 如果您想了解更多有关日志级别的信息，可以继续阅读此处 。

2018-10-21 23:12:39,497 - INFO - entered request [user/create] [req: 1] - simple_example
2018-10-21 23:12:39,500 - INFO - entered request [user/login] [req: 2] - simple_example
2018-10-21 23:12:39,502 - INFO - ended request [user/login] [req: 2] - simple_example
2018-10-21 23:12:39,504 - ERROR - invalid request structure [user/login] [req: 1] - simple_example
2018-10-21 23:12:39,506 - INFO - entered request [user/create] [req: 3] - simple_example
2018-10-21 23:12:39,507 - INFO - ended request [user/create [req: 1] - simple_example
2018-10-21 23:12:39,509 - INFO - ended request [user/create] [req: 3] - simple_example

日志分析 (Logs analysis)

Searching files for log entries is a long and frustrating process. It usually requires us to process very large files and sometimes even to use regular expressions.

在文件中搜索日志条目是一个漫长而令人沮丧的过程。 它通常需要我们处理非常大的文件，有时甚至需要使用正则表达式。

Nowadays, we can take advantage of fast search engines such as Elastic Search and index our log entries in it. Using ELK stack will also provide you the ability to analyze your logs and answer questions such as:

如今，我们可以利用诸如Elastic Search之类的快速搜索引擎 ，并在其中索引日志条目。 使用ELK堆栈还将使您能够分析日志并回答以下问题：

1. Is the error localized to one machine? or does it occur in all the environment?
   错误是否局限于一台机器？ 还是发生在所有环境中？
2. When did the error started? What is the error’s occurrence rate?
   错误何时开始？ 错误的发生率是多少？

Being able to perform aggregations on log entries can provide hints for possible failure’s causes that will not be noticed just by reading a few log entries.

能够对日志条目执行聚合可以为可能的失败原因提供提示，仅通过读取一些日志条目就不会注意到这些提示。

In conclusion, do not take logging for granted. On each new feature you develop, think about your future self and which log entry will help you and which will just distract you.

总之，不要将日志记录视为理所当然。 在开发的每个新功能上，请考虑一下自己的未来，哪些日志条目将对您有所帮助，哪些只会分散您的注意力。

Remember: your logs will help you solve production issues only if you let them.

请记住：只有让日志允许，您的日志才会帮助您解决生产问题。

翻译自: https://www.freecodecamp.org/news/how-to-save-hours-of-debugging-with-logs-6989cc533370/

如何使用日志进行程序调试