ftofficer|张聪的blog

在前面的两个部分当中，我们讨论了将调试日志写到什么地方，以及如何对调试日志进行分级和分类。但是至今我们仍然没有涉及到最核心的问题：应该在什么地方写调试日志？应该怎么写调试日志？这就是这一部分的主题。

如何写调试日志

如何写调试日志的核心问题就是，应该在什么地方写什么内容。在考虑写日志的时候，我们的最基本的考量仍然是在第一部分当中提到的核心标准：如何便于添加、便于分析处理，进而容易定位错误。

现在考虑我们应该在调试日志当中包含哪些内容，让我们能够从各个方面来定位错误。首先毋庸置疑，必要的元信息是应该被打印出来的，例如调试日志被打印出来的时间，而根据第二部分的建议，调试日志的级别和分类信息也是必要的。为了便于跟踪多线程程序，把进程ID和线程ID包含在其中也是天经地义的事情。如果为了便于开发人员定位日志在代码当中的位置，把打印日志的语句所在的代码文件、代码行以及函数名称包含在其中也是必要的。幸运的是这些问题在一个好的日志记录模块之下，大多数都可以通过一些辅助函数或系统内置的宏（例如__FILE__，__LINE__，__FUNCTION__）自动获取和添加，不需要开发人员去过多关心。因此需要开发人员添加日志时真正需要关心的问题其实只剩下了这条日志的级别和日志的消息字符串了。

Tip 10：在日志条目当中包含必要的元信息，例如时间、PID/TID、日志级别和分类、代码文件、代码行、函数等。

在这里单独把时间的输出提出来讨论一下。在时间的打印上，有多种方式可供选择。一般的说，我们比较倾向于使用标准的格式来打印时间，如RFC822当中规定的标准Internet时间格式，或者asctime输出的格式，同时在其中包含必要的时区信息。使用标准的格式打印时间，可以使得日志便于被脚本程序处理，因为主流的脚本程序都有相应的库来进行时间的解析；添加必要的时区信息是为了得到更多的关于客户环境的信息，例如夏令时切换和非标准的整小时时区。

Tip 11：在调试日志的时间当中，包含必要的时区信息。

日志的消息字符串是日志当中灵活性最大的部分。正因为灵活性大，开发人员也往往可能遗漏某些信息，导致在拿到用户处搜集的调试日志之后，无法进行有效的分析。根据我的一些经验，在这里就如何包含有效的信息给出一些讨论。

第一个需要考虑的问题是日志的相关性。例如一个采用异步IO模型的服务器程序，通过有限的几个线程来服务大量的会话，因为每个线程都可能服务多个会话，而每个会话可能先后由不同的线程来服务，因此需要在日志当中添加某种可以将这些日志关联起来的键值，通过这个键值，分析日志的开发人员就可以将对于同一个对象的操作聚合在一起进行分析。这个键值应该可以唯一地标示所操作的对象（例如会话对象），比如可以使用对象的地址、会话当中socket的值，业务相关的对象ID如邮件的Message ID等等。

Tip 12：在调试信息当中包含可以区分不同操作对象的键值，以便保证对同一对象操作的日志的相关性。

另一个问题是保证根据拿到的日志可以对程序的执行路径进行跟踪。一个简单的方法就是在各个条件分支处添加合适的日志，保证每个分支都被日志覆盖。通常条件分支分为两类，一类是错误处理的分支，另一类是业务逻辑相关的分支。对于前者，比较常见的就是在函数调用结束之后，对于返回值得检查，例如

FILE* pf = fopen(fileName, "r");
if ( NULL == pf ) {
   DebugLog(LOG_ERROR, "open file %s to read failed. CRT errno=%d", fileName, errno);
   // Other error handling code
}

DebugLog(LOG_INFO, "Open file %s to read succeeded", fileName);

在这个例子当中，无论进入哪个分支，均有调试日志打印出来。而且，在正常的运行状态下，客户可以将日志级别调到错误或更高，这样除非出错，用户不需要操心大量的日志输出所占用的磁盘空间和造成的效率损失。通过在错误处理分支上添加错误级别的日志，在正常流程上添加信息或调试级别的日志，能够有效的跟踪错误发生之前的程序执行路径。

而对于业务逻辑造成的条件分支，也可以通过类似的方式，在每个分支的入口处添加日志。在理想的情况下，任何条件分支语句都应该可以被调试日志覆盖到。

Tip 13：在每一个存在错误处理的地方，在错误处理分支上添加错误级别的日志，在正常流程上添加信息或调试级别的日志。

Tip 14：对于业务逻辑造成的条件分支，在每个分支的入口处添加日志，保证任何分支路径都在调试日志覆盖之下。

上面的例子还展示了打印调试日志时需要注意的另外几个问题。为了使得日志容易理解，最好让日志根据通用的句法来组织，例如例子当中，就根据句法“对什么做了什么操作，结果如何，为什么”来组织的。相反，如果在打开文件出错的时候仅仅打印出"Cannot open file"，其实对于排错并没有什么用处：拿到这个日志的开发人员既无法知道打开哪个文件出错，也不知道为什么出错。

这里列出一些通用的句法模式：

• [操作] [某对象] [成功/失败]，(如果失败，失败原因是[某原因])
  例子：Open file [d:\test.txt] for read failed. Win32 Last Error=2. The system cannot file the file specified.
• 现在[条件]成立，需要做[某种操作]
  例子：Command [TEST] is not recoginized, will ignore it.
• 现在系统处在[某种状态]，（如果不是正常状态，什么原因）
  例子：Virus scanning is disabled, invalid Activation Code is provided.
  例子2：SMTP server status is SMTP_EHLO_ISSUED.
• [某对象]进行了[某种操作]
  例子：Server thread #1 started.
• [某对象]即将进行[某种操作]
  例子：Will send response [220 ready] to socket 0x1234.

Tip 15：尽量保证每条日志信息的完整性，根据通用的句法模式来组织每一条调试信息。

在上述句法当中，常常需要输出出错的原因，我们可以采用几种方式输出：可以通过打印错误代码实现，或者将其转换为易于理解的字符串打印。前者比较容易加入程序当中，但是后者更便于察看。但是建议即使使用后者的方式，同时也打印出原始的错误代码，因为对于开发人员来讲，错误代码更具有确定性，也更容易从代码的角度定位错误的原因。与此同时，在打印错误代码时建议将“这是什么类型的错误代码”打印出来，因为不同的库和代码使用的错误码体系也不同，在一个稍稍复杂的Windows程序当中，就至少存在CRT errno，Win32 Last Error，COM HRESULT，NTSTATUS，Winsock Last Error，可能还包括应用程序自定义的错误代码。如果ä¸
æ‰“印出“什么类型的错误码”，则很容易将这些错误码混淆，使得难于跟踪。例如在例子当中，输出"CRT errno=%d"，这样分析日志的时候开发人员可以去CRTçš„errno可能的取值当中去查找对应的原因，如果单单输出"error no=%d"，则可能造成混淆，例如13在CRT errno当中表示Access Denied，而在Win32 error code当中表示invalid data。

Tip 16：在日志当中输出错误代码时，同时输出错误代码的类别。

在多线程程序当中，因为不同的线程可能打印的日志类型也不同，例如代理服务器软件的服务端线程和客户端线程所打印的日志显然不同。在需要使用脚本等工具自动分析的情况下，需要能够简单的区分线程的类型。同时，由于线程的生命周期可能比整个进程要短，因此在线程入口函数的开始处和结束处输出必要的信息，并且在开始处提供能够区分不同线程的日志信息，例如"Server listen thread #1 started"，或者"Client listen thread #1 exit with code 0x00"等等。

Tip 17：在线程函数的开始和结束处添加日志，并提供能够简单的区分线程类型的字符串。

有的时候，线程可能需要等待某个同步对象，因为等待的结果多种多样，并且可能因为其他线程调用TerminateThread或类似的函数导致其退出，因此建议在等待操作之前打印一条日志，并在等待之后根据等待的结果打印出另一条日志，这样的好处在于，开发人员可以从日志当中发现线程非正常中止或非正常的等待结果。同样的建议适用于需要进行一些耗时的操作的时候，例如调用socket的IO相关函数的时候。这种日志有时也可以在没有性能分析器（Performance Profiler）的时候进行简单的性能分析。

Tip 18：在进行可能比较耗时的操作之前和之后，添加日志进行跟踪，以便发现异常情况或进行简单的性能分析。

与线程的生命周期跟踪类似，对于对象的构造和析构最好也能够进行适当的跟踪。这种日志信息建议添加在构造函数、拷贝构造函数、析构函数和赋值运算符当中。使用这种跟踪信息，可以方便对于内存泄漏的检查，也是和工具的分析。

Tip 19：在对象的构造、析构和拷贝处添加调试日志，其中包含对象的地址或其他可标示该对象的键值，用于跟踪对象的生命周期。

对于某些具有复杂状态的对象，有可能需要在跟踪时了解各个操作之后的对象状态，尤其当对象牵涉到复杂的线程同步的时候。因此可能需要为某些对象提供类似dump的操作，并在需要的时候将dump的结果写入调试日志。或者对于协议相关的问题，可以在每次收到数据之后或发送数据之前dump数据并写入日志，以便于更加细致的分析。这种日志可能非常消耗执行时间，因为他们可能被频繁的打印出来，而且可能每次的数据量都非常大，因此这种日志通常情况下建议使用非常低的级别，至少不应高于Debug或Tracing级别，如果必要，甚至可以单独成为一个级别。

Tip 20：如果必要，可以在较低的调试级别上提供对象或协议数据的转储(dump)，以便分析。

有时候软件产品的配置可能非常复杂，而不同的配置往往意味着不同的行为和对于环境的不同的依赖。因此，处于排错的需要，可以在日志当中输出一些与用户环境相关的信息，例如当前操作系统的版本，以及必要的配置项的值。但是如果使用这种方法，注意不要泄漏用户隐私，例如密码散列，或者其他隐私数据。

Tip 21：如果必要，在日志当中输出软件运行的环境信息，例如软件的配置和操作系统信息。

最后讨论一下异常的使用。通常情况下，虽然异常对于写出简单的程序非常有效，但是往往在出错时难于跟踪。因为异常往往会沿着调用栈依次向上传递，而在最外层被catch。这样，即使在最外层的catch处，其实也很难对于错误的细节原因给出答案。而C++标准库所给出的预定义异常数量又太少，因此使用try-catch往往是分析调试日志的大敌。为了尽可能的减少使用异常对分析调试日志带来的难度，建议在throw exception的地方将尽可能详细的信息保存在exception对象当中，究竟保存哪些信息可以借鉴一条完整的错误日志应该具有的信息，例如抛出异常的语句所在的代码行和代码文件，抛出异常的原因，必要的相关信息，例如无法打开的文件名。而无论在什么地方这个异常被catch，都应该将这些信息从中dump出来，并打印成调试日志。

显然，这样会极大的增加异常对象的复杂程度，但是我们认为，为了让调试日志更加容易理解和跟踪，这种复杂程度是必要的，而且与调试日志的打印类似，我们可以通过一些宏或者辅助函数来达到简化编程的目的。

Tip 22：如果使用异常，则尽可能在异常当中包含完整的可以构建一个错误日志的元信息，并在catch异常处将其打印到调试日志。

所有的这些写日志的建议，最终的目的还是能够容易的被人看懂，已经能够容易的被自动化程序分析。现在我们有了组织良好的日志文件，如何对其进行分析，这就是下一部分要讨论的问题。