ftofficer|张聪的blog

来自Somasegar’s Weblog:

Visual C++ Futures

This team will be significantly increasing support for native development tools.  Central to this work is investigating ways to make C++ developers far more efficient in understanding, updating and validating the quality of large native code bases.  In fact, the team is already working on a front-end rewrite that will allow for a vastly improved IntelliSense experience.  This same work should pave the way for future enhancements such as refactoring and advanced source code analysis.

其中最激动人心的部分，就是微软决定将更多的精力放在Native Code编程的环境提升上面。现在的VS2005对于managed code的productivity已经做得很好了，从自动提示，自动完成，code snippet到重构支持，但是对于Native C++的支持除了增强了自动提示之外，其他的几乎都没有支持的很好。Visual Assist的自动完成和Code Snippet都有支持，但是重构支持离实用还有一定距离。CodeRush的重构工具Refactor! Pro宣称对于重构的支持非常好，但是对于大型程序几乎一定会挂掉，基本上也是不可用的状况。微软官方IDE支持的C++的重构，也许有点值得期待的东西。

在这个系列文章当中我把经验总结成了30个Tips，由于散布在文章各处，不便查找，因此在这里建立一个索引，以便可以方便的引用。

• 设计目标
  • Tip 1：调试日志的设计应该以“便于定位错误”为中心目标
• 输出调试日志的方式
  • Tip 2：选用合适的日志输出方式，以便于收集和处理为目标设计。用久经考验的方案，输出到stdout/stderr或具有统一文件名格式的日志文件。
• 调试日志的分级和分类
  • Tip 3：使用日志分级显示的机制，在正常运行当中控制日志的输出量，调试情况下输出尽可能细致。
  • Tip 4：在日志当中记录当前日志的级别，便于拿到日志之后的过滤和分析。
  • Tip 5：添加调试日志的工作越简单，开发人员越喜欢在代码当中添加调试日志。
  • Tip 6：即使需要对于每个模块分别控制日志级别，最好也能够提供一个全局的日志级别控制选项。
  • Tip 7：在子系统级别上，让不同的子系统把日志输出到不同的日志文件。
  • Tip 8：在子系统内部，对于不同的模块，使用不同的模块标识，便于开发人员进行分析和过滤。
  • Tip 9：使用一些tricks来简化调试日志的添加，减少开发人员在写调试日志时需要考虑的问题。

这是这个系列的第四部分，也是最后一部分，我们将讨论如何有效的分析调试日志，并给出一些典型的日志分析方法和经验。

如何分析调试日志

当支持人员或者开发人员拿到调试日志时，通常的分析方法是先找到用户遇到的问题所对应的日志，从这里出发，进行跟踪，并分析出现这种问题的原因。在这个过程当中，存在三个必要的步骤：发现问题所对应的日志，跟踪，分析原因，这也是分析调试日志的一般方法。

在整个过程当中，发现问题所对应的日志所在往往会消耗大量的时间。主要原因之一是分析人员拿到的日志往往是最低调试级别的，往往日志的条目非常巨大，而且可能不同
的模块、不同的线程的调试日志混杂在一起，导致难于分析。因此对于如此大量日志，通过必要的辅助工具支持能够大大的提高效率。

第一种辅助工具是日志过滤和切分工具。根据日志的所属的不同模块、级别，或者根据线程或日志的相关性键值，对日志进行过滤和切分，将其划分成多个小的相关的日志模块，将极大的方便进行分析。这种工具可以用脚本实现，或者用grep过滤，甚至直接使用编辑器的查找功能（如ultraedit的“列出所有行”功能），通常将在很多时候就足够了，因此不做细致的讨论。

Tip 23：使用切分和过滤工具将日志根据相关性划分成多个小的日志模块进行分析。

有的时候问题可能出现在不同子系统之间的交互之上，或者对于某一个对象的操作会跨越多个子系统，而不同的子系统的日志文件可能具有不同的文件前
缀。因此，必要时可以用日志组合工具将多个子系统的日志组合之后，再经过日志切分工具进行切分。这种操作通常就需要两个子系统之间保持一定的日志格式的规
约，以便工具可以容易的找到相关性的键值并根据这个键值进行组合。

Tip 24：当需要跨越子系统进行跟踪时，可以使用日志组合工具将日志组合之后再进行切分。

对于划分好的子模块的分析就是发挥人类洞察力的时候了，人类的智慧就应该用在这种地方:)。而一旦通过某种方式发现了问题所对应的日志，接下来的工作就相对简单了。而一旦发现了问题所在，我们建议将这种问题所对应的日志抽取出来适当的模式，并将过程或结果加以记录，用可运行的脚本或需要手动操作的条文都可以。这样未来就可以根据这些积累，快速的确定已知问题。

Tip 25：尝试将已知问题的日志模式加以记录，以便可以在问题到来时容易的确定是否是已知问题。

对于某些特定的问题，我们已经有了相应的日志模式。

第一类问题是程序崩溃，这种情况很容易通过分析PID变动之前的日志查出原因，因此，用某种工具快速的定位PID变动的地方，并查找附近的特征字符串，即可知道是否发生了崩溃。

Tip 26：使用工具定位PID变动的位置并查找特征字符串，可以检测到程序的崩溃。

第一类问题是性能问题或死锁。这也是Tip
18的来源。我们可以通过求出操作开始之前和结束之后的两条日志之间的时间差值来得到这个操作持续的时间，或者识别这些操作是否完成，是否陷
入了无限等待或超时等等。这种模式很容易通过自动化工具来找到。而对于性能问题，可以通过工具分析日志，统计其中最耗时的一些操作，并对其进行统计学分析，对于实际用户环境当中的性能瓶颈也可以有很好的预测，对于将来的设计和改进也是非常重要的资料。

Tip 27：通过分析日志之间的时间差，可以检测性能问题或死锁。

另一种问题是内存或资源的泄漏。虽然这种问题可能不是可以仅仅通过调试日志解决的。但是在有的时候，唯一能够用来调试内存泄漏的只有调试日志，因此先从
调试日志当中分析，有时也能够发现一些问题，至少可以排除掉一些可能。如果根据Tip
19的建议，在对象的构造、拷贝、析构的时候都加上了必要的日志，那么通过简单的脚本扫描所有的相关的日志项即可知道是否所有的对象都得到了正确的析构
了。如果需要对于内存泄漏问题进行更多的分析，也可以建立一种机制，在日志当中记录所有的内存分配和释放的操作，并加以分析。

Tip 28：通过分析日志当中资源分配和释放的配对情况，可以用来检测内存或资源泄漏。

在发现了问题之后，接下来的就是根据日志进行程序执行路径的跟踪。由于可能需要经过复杂的程序执行路径才能够出现问题，完全的手动跟踪是一件非常消耗人力物力的事情。由于在日志当中的记录了代码文件和行数，以及函数名，这种动作也可以一定程度上通过工具自动化寻找下面的执行路径，加快跟踪的速度。

Tip 29：使用自动化工具来辅助路径跟踪。

虽然我们一直在强调辅助工具的重要性，但更重要的还是日志的清晰程度和分析人员的耐心以及洞察力，而这种洞察力往往需要通过经验的积累才能获得。工具只能够用来辅助查找已知问题和给出建议，人的努力才是发现问题、解决问题的最终关键。

Tip 30：工具只是辅助，人的耐心、洞察力和经验才是分析日志的最重要资本。

总结

至此，这个四个部分的文章告一段落。我写这篇个系列文章的目的在于希望能够总结和分享有关调试日志经验，并为接下来的工作当中对于调试日志的书写、处理的标准化作一些思考。这些虽然都经验，但毕竟是一家之言，难免狭隘甚至错误，希望有更多的人可以参与讨论，给出更多的建议和分享更多的经验。

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

如何写调试日志

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

现在考虑我们应该在调试日志当中包含哪些内容，让我们能够从各个方面来定位错误。首先毋庸置疑，必要的元信息是应该被打印出来的，例如调试日志被打印出来的时间，而根据第二部分的建议，调试日志的级别和分类信息也是必要的。为了便于跟踪多线程程序，把进程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异常处将其打印到调试日志。

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

这是这个系列文章的第二部分，我们将关注如何过滤调试日志的问题，亦即索引当中“调试日志的分级和分类：提高日志的信噪比”一项。

调试日志的分级和分类

调试日志的分级和分类的目的在于能够更好的对大量的日志进行过滤，使得可以容易地从某个或某些方面分析日志。

日志的分级是已经广为接受的一种做法，例如Windows的事件日志就分为错误、警告、信息三种级别，而内核的DbgPrintEx函数也包含有日志分级的参数，并且给出了四种预设的级别。为调试日志实现分级的主要目的是过滤不必要的消息，以便能够让重要的调试信息不会淹没在大量的无用信息当中，同时在正常的使用过程当中，控制调试信息的输出也可以提高系统的效率。

在具有分级的调试日志实现当中，通常系统都会至少指定3种调试信息的级别，即错误、警告和信息。也有系统提供更加细致的级别，例如比错误更高级别的“致命错误”级别，或比信息级别更低的“调试”级别和“追踪”级别。通常情况下不同的级别使用一个正整数值来表示，一般的约定是使用较小的值表示优先级较高的调试信息，例如致命错误为0级，可恢复错误为1级等等。

通常具有调试日志分级的产品都会采用某种方式来指定需要打印的调试级别，这个可以通过命令行参数或者配置文件指定，通常接受一个正整数。在打印调试日志的地方，开发人员需要指定调试日志的级别，当这个级别高于或等于全局的调试级别时，这条调试日志便会输出。这种方式简单而且有效，因此得到了广泛的应用。

但是这里面隐含着一个实际当中需要面对的问题。虽然我们提供了不同的级别，四种或者五种，但是通常被用到的通常只有其中的两个极端的级别：在正常运行过程
当中，用户往往选择不打印任何的日志，或者只打印级别较高的日志；而当软件在客户处遇到了问题的时候，支持人员往往要求客户直接将调试日志级别调到最详细
的级别，然后搜集日志。因此，日志分级需要首要考虑的问题很多的时候并非为用户提供对于日志输出量的控制，而是为了开发人员拿到细致的日志的时候，能够快速的对其进行过滤，并在不同级别
上定位问题。因此调试级别不宜太多，分的过细没有太大的意义，而且容易使得在编写调试日志的时候难以确定正确的级别。我们比较倾向于五个级别：致命错误、可恢复错误、警告、信息、调试，有时候致命错误和可恢复错误不加区分，也就变成的四种级别。另外，应当在最终的日志文件当中记录每条日志的级别，以便于拿到日志之后可以根据级别过滤。

因此，我们有了Tip 3和Tip 4：

Tip 3：使用日志分级显示的机制，在正常运行当中控制日志的输出量，调试情况下输出尽可能细致。
Tip 4：在日志当中记录当前日志的级别，便于拿到日志之后的过滤和分析。

由于通常开发人员拿到的都是最详细的级别的调试日志，而在这个级别上面，各个模块通常都会打印出大量的日志，这种日志到了支持人员和开发人员手中之后，也往往由于数量巨大而难于处理和分析。因此如何可以更加细致的进行日志的分类，就是成了另一个需要解决的问题。

对于调试日志分类的设计有两个方面的考虑：一方面，对于日志分类倾向于尽可能的细致，以便拿到日志的开发人员能够在更加细致的级别上分析日志，另一方面，由于日志所从属的类别需要开发人员在写每一条日志的时候确定，因此，应该能够让开发人员能够快速的决定日志的类别，以便减少开发人员的工作，这就要求日志的分类不能过于细致。这两个方面相互矛盾，因此，设计良好分类方式，抛弃不必要的分类，使设计当中需要考虑的一个重要方面，否则开发人员花费在确定日志的类别上的时间比写代码的时间还多，就得不偿失了。

另外，由于调试日志的分类可以有几种不同的方式，例如基于模块进行分类，基于目的进行分类，等等，因此设计几个分类的维度也是一个需要仔细考虑的问题。因为开发人员在写日志的时候，需要考虑的问题目前至少有：什么级别，什么内容。我们每增加一个日志的分类维度，就使得开发人员增加了一个需要考虑的问题，这极大的增加了开发人员的工作，也可能是的开发人员因此开始不喜欢写调试日志，反而适得其反。因此，我们的经验是最多只添加一种分类的维度，这种通常就是基于模块的分类。

Tip 5：添加调试日志的工作越简单，开发人员越喜欢在代码当中添加调试日志。

基于模块的分类和过滤方案可以有多种方式实现。第一种是对于不同的模块使用不同的配置项控制其调试级别，之间互不影响。另一种使用全局的配置项控制调试级别，但是对于不同模块的日志文件使用不同的文件名前缀。例如按照第一部分的那种日志文件命名方案，使用不同的basename。第三种方案则使用类似于分级的方式实现，开发人员在代码当中加入调试日志的时候，指定一个模块的标识，而在程序运行的时候，通过某种方式如命令行和配置文件来指定需要显示的模块，来实现基于模块的过滤。

三种方案各有其优劣。

第一种方案的优势在于可以细致的控制各个模块的日志信息。这种在现场调试的时候比较有优势，但是在无法现场支持的时候就存在一定的操作难度。因为对于支持人员来说，往往倾向于拿到尽可能详细的日志，因此在搜集日志的时候，也往往要求用户将模块的调试级别都调到最详细。这样一来，一方面增加了用户的操作难度，另一方面对于最后分析日志的开发人员来说，这种方案并没有改变多少问题。因此，

Tip 6：即使需要对于每个模块分别控制日志级别，最好也能够提供一个全局的日志级别控制选项。

第二种方案则稍有改进，其优势在于便于搜集和浏览，因为每个文件都单纯的对应于一个模块，不存在模块之间互相穿插的问题，因此人阅读比较容易，也便于工具的处理。但是如果模块划分过细，会导致难于跟踪模块之间的互操作。比如模块A会在处理过程当中调用模块B，但是两者的日志分布在不同的日志文件当中，这样的结果往往是在察看日志的时候，需要在两个日志文件之间跳来跳去，反而使得分析变得麻烦。因此这种方案通常用在比较粗粒度的子系统级别。将不同子系统的日志输出到不同前缀的日志文件，可以在划分模块和便于分析之间找到一种折中。而且结合第一种方案，也可以对于不同的子系统提供不同的调试级别的控制。

Tip 7：在子系统级别上，让不同的子系统把日志输出到不同的日志文件

第三种方案则在第二种方案上面更进了一步，可以用来区分子系统当中不同的模块。这种方案当中对于模块标识的选择也有几种不同的设计。一种是使用短字符串作为模块的标识，例如main，server，client等字符串，而在配置文件当中，使用逗号或其他符号分割的字符串选择需要输出的模块。另一种方案是使用整数的位掩码（bit mask），每个模块对应于一个整数当中的一个位，而使用位AND操作来确定是否需要输出该模块的信息。表面看起来似乎前者更具有良好的可读性和可配置性，而后者则相对难于理解和配置。但实际当中，这种考虑应该放在相对较为次要的位置。因为用户对于模块的调试日志的控制往往也是两个极端：none或all，而如何让开发人员更加容易的添加调试日志，以及拿到所有模块都打开的日志的时候如何便于根据模块进行过滤和分析，才是设计调试日志方案的首要考虑。因此，我更倾向于使用第二种方案来实现，这样在最后的日志分析当中，更容易用脚本来进行辅助。与日志级别类似，在最终的日志文件当中，也应该记录该日志条目所从属的类别。

Tip 8：在子系统内部，对于不同的模块，使用不同的模块标识，便于开发人员进行分析和过滤。

实际当中，这三种方案放在一起实现是最为有效的。总结一下就是：提供一个全局的调试级别控制，在每个子系统上面提供一个该子系统的级别控制，该控制默认情况下使用全局控制，在特殊情况下可以覆盖全局控制；让不同子系统的日志输出到不同的日志文件当中；子系统内部的模块使用模块标识区分，并将其记录进最终的日志条目当中，便于开发人员使用人工或脚本过滤和区分。

如上Tip 5所述，我们希望添加的模块信息不会增加开发人员的工作，因此实现日志根据模块划分类别，可以采用了一些tricks来简化日志的添加工作。例如，每个源代码文件通常都只从属于一个模块，因此，我们可以在每个源代码文件的顶端添加它从属的模块的信息，而使用宏来自动的在每条日志当中添加模块信息。这样，开发人员其实并没有增加太多的工作要做。

而在实际当中，很多时候简单的根据日志从属的模块区分还不够，比如可能需要把所有的函数跟踪日志和路径跟踪日志作为两个单独的级别，这时也许我们就需要引入一些别的分类方式，但是即使有这种需求，我们也建议把他们并入到模块级别当中，因为任何一个增加的维度都是以增加开发人员的工作作为代价的。通常，我们建议使用宏来简化这些添加动作，而且，除非真的必要（很多时候这两种需求是可以由其他的日志代替的），我们不建议增加更多的日志分类方式。

Tip 9：使用一些tricks来简化调试日志的添加，减少开发人员在写调试日志时需要考虑的问题。

下面，我们开始探讨如何在正确的地方添加正确的日志，也就是“日志应该写些什么”的问题。

有感于当时在学校的时候做项目和进入公司之后参与产品开发的经历，深感产品支持的难度——客户的环境千差万别，因此可能出现的问题也千差万别，而且很多问题只有在客户的环境当中才可能重现，这个时候，如何快速的定位问题并给出解决方案，是一个非常重要的问题。

通常我们采用的都是调试日志，也就是Debug Logging的方法。在正常的情况下，调试日志并不会被打印出来，只有当出现问题时，通过适当的方式（配置文件或者命令行）将其打开，在客户环境当中重现，并将调试日志收集到开发者处分析。因此，如何有效地在产品代码当中添加调试日志，是影响了软件维护效率的一个重要因素。

这几篇文章主要关注的就是如何有效的写调试日志以便于分析。因为我所从事的项目主要使用C/C++进行开发，因此文章当中的介绍也主要集中在如何在C/C++的大型程序当中撰写调试日志。

文章主要关注在以下几点问题：

• 调试日志的目的：确定调试日志设计的目标
• 输出调试日志的方式：调试日志应该输出到哪里
• 调试日志的分级和分类：提高日志的信噪比
• 如何写调试日志：应该在什么地方写什么
• 如何分析调试日志：精力应该放在刀刃上

这是第一部分，我们主要关注在前两个主题：调试日志的目的和输出调试日志的方式。

调试日志的目的和设计目标

调试日志的根本目的是为了定位错误。在这个目的下，我们才会进行更加细致的调试日志的设计。

说起定位错误，首先是这种行为的主体：谁来定位错误？首先当然是用户。我们希望，在大多数情况下，用户可以在出现错误时通过对于调试日志的简单分析即可定位错误。但是这种方法很容易让人将调试日志的作用高估：程序员希望用户会去看调试日志。事实上，调试日志对于用户的排错工作并不应作为一线工具，至少不应该用来报告系统的错误；对于系统的错误，例如用户没有给与正确的输入，或配置文件解析错误，这种需要用户去做一些行为才能让系统工作起来的消息，应该用更加直接的方式通知用户。例如在Windows上面，使用Windows事件日志(Event Log)就是一种很好的选择。但是，这条消息仍然应该记录进调试日志，以便可以记录下错误发生的细节以便于程序员进行分析。

另外一个需要分析调试日志来定位错误的就是软件维护人员。因为软件的规模问题，或者由于流程的不同，也许软件维护人员并不是本来的系统开发人员，而无论如何，对于系统的工作方式，软件维护人员都比用户了解的更多。因此如果调试日志足够好，他们可以通过调试日志，结合对于软件工作方式的理解发现更多的问题，并给出用户解决方案。因此，将调试日志写得更加易懂，说明软件“做了什么，发生了什么结果”，而不是“调用了什么函数，返回了什么值”，就能够让更加前端的软件维护人员的处理掉更多的问题，相应的，需要开发人员亲自解决的问题的数量就会减少。

最后的会去分析日志的就是软件开发人员。因此，添加必要的开发人员理解的信息也是必要的，比如函数调用参数和返回值的跟踪，条件分支的跟踪，出现错误的代码行和源文件等等，以便掌握有源代码的开发人员可以对错误的流程进行跟踪并重现。同时，由于到了开发人员手中的往往都是非常棘手的问题，往往伴随的大量的调试日志条目，因此，让调试日志的分析更容易自动化对于开发人员定位错误的帮助也是非常大的。在建立了良好的自动的调试日志分析工具之后，对于已知的问题，就可以通过工具进行快速的定位了。

综上，我们所做得对于调试日志的工作都是为了能够更容易、更早的定位错误。为了达到这个目的，我们需要能够让调试日志便于查找和搜集，便于人读取和理解，以及便于工具进行解析。

Tip 1：调试日志的设计应该以“便于定位错误”为中心目标

第一个问题就是需要调试日志便于搜集，也就是调试日志的输出问题。

输出调试日志的方式

对于调试日志应该输出到哪里，人们有很多不同的看法，在不同的环境当中也各有优劣。比较流行的几种观点是：

1. 输出到标准输出(stdout)或标准错误(stderr)。这种一般出现在交互式命令行工具当中，使用stdio或iostream当中的库函数来书写。这种书写方式符合程序员的习惯，例如Unix的传统的工具通常使用-v(如mplayer)，-debug(如openssl)或其他的选项来把细致的日志输出到stdout和stderr。这种输出的优势在于便于重定向到文件或管道。重定向的文件比较适合搜集调试日志，而使用管道比较适合实时分析。其劣势也是非常明显的：这种方式仅适用于交互式命令行工具，对于GUI程序、后台守护进程或者服务程序就不太适合了。当然对于Windows GUI程序，有一种方式可以使用CRT Output Routing，但是并不通用，而且会失去使用这种方式的根本优势，即灵活的重定向。
2. 输出到System Debug Buffer。即通过OutputDebugStringW/A函数，或者内核态的DbgPrint(Ex)函数。这种方式并不见得有多少优势，尤其是必须通过调试器或其他工具才可以看到或dump到文件，给在用户处搜集信息造成了很大的麻烦。在我看来，使用这种方式很多时候还是不得已而为之，例如在内核态除了DbgPrint(Ex)，似乎没有别的选择。但是使用调试器来搜集一些信息还是一种可以选择的方案，例如对于Windows API调用的记录，skywing在他的blog上面提供了一种在WinDbg当中可用的方法，但是仍然如我所说，在实际的用户那里，并没有太大的意义。
3. 输出到日志文件。这种是使用的最多的方案。这种方式可以适用于除了交互式命令行工具之外的所有组件，而且非常适合用来从用户出现问题的环境当中直接收集，并由程序员进行分析。但是这种方案可能存在一些细节问题需要考虑，例如将日志文件写在哪里（临时文件目录，专用的调试日志目录，或者其他地方），文件如何命名和切分，如果调试日志量过大如何处理，写调试日志时出现错误怎么办等等。这几个问题没有固定的答案，关键在于一旦确定下来，就需要在整个软件当中保持一致。在我现在从事的项目中，我们使用的是写入到专用的调试日志目录当中，同时这个目录可以由用户通过配置文件修改；文件名使用basename.yyyymmdd.####的格式，yyyymmdd是用户本地时间的年月日，####是从1开始的编号。每个文件大小不超过某个值，一旦超过就另开一个文件。这种结构便于辅助工具寻找和收集调试日志并打包，以及在调试日志过多的时候由一个守护程序进行清理。对于写入日志的错误，建议根据当前的日志级别来处理，如果需要打出的本身就是一个严重错误的日志，最好使用某种不太容易失败的方式将日志写入其他地方，例如系统事件日志；而如果写入的只是一些信息性的或者调试
   性的消息，则可以选择忽略。

Tip 2：选用合适的日志输出方式，以便于收集和处理为目标设计。用久经考验的方案，输出到stdout/stderr或具有统一文件名格式的日志文件。

如果没有特殊的需求，对于交互式命令行工具使用直接输出到stdout/stderr，对于其他直接输出到日志文件，是调试日志输出的首选。我们当前使用的文件组织方式也可以借鉴。接下来我们就开始谈论如何能够有效的书写调试日志的内容。

今天花了一下午整出来的东西，似乎是work的，从http://www.millersmiles.co.uk/上面找了两个phishing URL，比如这个。

E:\zhangc\Documents\Works\security\SafeBrowsing\GSBDemo\Debug>GSBDemo.exe
Google Malware Hash List: version 1.117, 51242 items.
Google Black Hash List: version 1.971, 9170 items.

URL:>http://singngngdaxngggg.pochta.ru/logi22.html
This URL is unsafe because "singngngdaxngggg.pochta.ru/logi22.html" is in goog-black-hash

不过有的还不work，比如Li Fanxi给出来的那两个：

URL:>http://220.225.4.14/icons/www.paypal.com/cgi-bin/SecureInfo=_update/
This URL seems safe.

URL:>http://kallu.ch/www.PaYPaL.Com/cgi-binn/verify-account/paypal12321625615235
2132314132123/paypal-email-verification/p1_webscr-cmd-login-run.htm
This URL seems safe.

不知道是我的实现的原因还是真的就在列表当中没有。

今天读到byte写的一篇blog，记录了一下vc当中的时间表达方式，随手回复了一篇，当敲入mktime的时候，突然心中一震，有一种误人子弟的感觉，因为想到了之前一个项目当中对于时间处理的问题的切肤之痛。

当时那个问题是这样的：程序会调用time函数得到time_t（这个是GMT时间距离1970年1月1日的秒数），然后用localtime把它转换成可读的struct tm格式，即年月日时分秒的格式，然后根据它来创建文件夹，比如我现在时区是GMT+8，即北京时间，凌晨3点32分，程序就会创建一个名为20070617\0332的文件夹，然后把一些东西放在里面。过一会之后，程序会去枚举所有的文件夹然后对其中的东西进行处理，枚举的时候，程序会根据这个目录的字符串来切开做成一个struct tm格式，然后调用mktime去转换成time_t进行进一步的处理。程序会传递这个time_t，并在必要的时候重新根据它来找到文件所在的目录。简单的逻辑可以这样认为：

time_t now = time(NULL);
struct tm* tnow = localtime(now);
sprintf(szPath, "%4d%02d%02d\\%02d%02d",
tm->tm_year+1900, tm->tm_mon+1, tm->mday,
tm->tm_hour, tm->tm_min);
CreateDirectory(szPath);

// later
// find each directory to szPath, and get year, month, day, hour, min from the szPath.
// Then set struct tm dirTm;

time_t dirTime = mktime(&dirTm);
ProcessThem(dirTime);

void ProcessThem(time_t dirTime) {
struct tm* dirTm = localtime(dirTime);
szPath = getPathFromTime(dirTm);
// open the file
}

这个逻辑在中国的区域设置下面毫无问题，一切都如预想的一样运行。但是这个产品还需要被卖到美国，区域设置为太平洋标准时间的地方。那个地方有一种东西叫做夏令时，Daylight Saving Time, DST。每年的4月的第一个周日（现在已经是3月的第二个周日了，这是今年的新规定，所谓的DSTE，为此还有更多的I18N的麻烦，有机会再说），当种走到凌晨1:59:59过后，并不是正常的跳到2:00:00，而是变成3:00:00。也就是说，钟快了一个小时。到了10月的最后一个星期天（现在是11月的第一个星期天）的钟表指到1:59:59之后，钟会跳到1:00:00，也就把钟调了回来。

于是产品在进入夏令时之后出了问题，日志当中报告了大量的“找不到文件”错误。经过分析发现，在上面的逻辑当中，在夏令时切换之后，比如钟表时间3:01:00（实际上物理时间是2:01:00），第一个localtime的调用创建了一个名为20060402\0301的文件夹，之后根据这个路径初始化struct tm dirTm，但是struct tm当中的tm_idst域并没有赋值（也就是0），所以调用mktime的时候，这个函数会把struct tm结构当中的值当作非夏令时，这样转换回的time_t就指到了物理时间的3:01:00，之后再次调用localtime，获取的struct tm当中，tm_hour变成了4。这样一来，程序试图去20060402\0401下面去寻找文件，这就导致了大量的找不到文件的错误。

解决的方法有两个，一个是初始化struct tm dirTm的时候，将tm_idst设成负数，例如-1，这样mktime会根据当前时区来决定是否根据夏令时进行校对。另一种方法是完全使用GMT函数替换本地时间函数。例如localtime->gmtime，mktime->_mkgmtime。

这个问题本质上就是一个软件的I18N问题。I18N=Internationalization，即国际化，因为I和N中间有18个字符而得名，类似的还有L10N（Localization，本地化），以及G11N（Globalization，全球化）。软件的I18N问题之所以成为一个问题，是因为这个世界上有接近200个国家和地区，2000多个民族，4200多种语言，以及，地球是圆的。

应该庆幸我们生活在中国，因为中国的很多东西都很简单，尤其是牵涉到软件I18N的时候。没错，可以认为中国有世界上最大的字符集，最复杂的文字表达方式，但是我们的时区是GMT+8，没有零头，没有夏令时；中文的编码GB2312å’ŒGB18030都是上下文无关的编码，而且广泛使用的GB2312还是定长的编码（两个字节一个汉字），而且任何字节不会和7位ASCII码重叠；我们使用格列高里历法，使用公元纪年；我们的默认键盘布局是标准101é”®qwerty键盘；我们的文字像世界上绝大多数文字一样从左向右横向书写……所有这一切对于写软件的人来说是这是多么美好的一件事情啊。我们可以获取当前的时间，存储其年月日时分秒，将来无论什么时候拿到这个年月日时分秒，都不会有什么问题；我们可以在一个中文编码的字符串当中肆意地用strchr查找’\\’来切割文件路径，而不用担心0x5C在当前的上下文当中是表示反斜线还是日元符号（在日文编码shiftJIS当中，日元符号的编码和ASCII当中反斜线编码重叠，都是0x5C，这种问题在GB系列编码中不会存在）；还有，我们的小数点就是圆点，负数就是在数字前面加上负号，而不是用逗号表示小数点（德文地区是这样的），而且不会用括号表示负数（欧洲某地如此，不记得哪国了）。

但是这样也会让我们中国的软件工程师低估了软件I18N的难度：不是所有国家的人们的时间都是连续的，很多国家在使用夏令时；很多国家或地区不使用公元纪年，比如日本和台湾；还有些地方不使用格列高里历法，例如中东的很多国家。说起时间，时区也不一定总是东八区，西五区这么简单。印度大部分地区都是GMT+5.5，尼泊尔是GMT+5.75；太平洋上某岛国(TONGA)是GMT+13，这是全球最早的时间；中东某小国由于宗教原因时区是GMT-89，也许是全球最晚的时间了。可以看看这张全球时区划分图来看看有多少诡异的时区吧（这张图有些老，98年的，所以很多诡异的都还没有，不过已经够多了）。

而谈及语言编码，那又有了更多的问题，现在太晚了，有空再写。

今天在bbs上看到一篇帖子，里面讲了这么一句话：有两种方式构建软件设计：一种是把软件做得很简单以至于明显找不到缺陷；另一种是把它做得很复杂以至于找不到明显的缺陷。很有意思的一段话。传说这段话来自于《A Byte of Python》，没看过，但是可以想象，既然来自于python的社区，作者应该是倾向于前面半句话的。

OK，现在是提问时间：为什么人们都在追求简单？正如这段话当中所说：软件做的简单的目的是为了能够减少缺陷。究其原因就是人类思考能力的限制：人们计算(1+100)*100/2和计算1+2+3+…+100的出错概率是不可以同日而语的。如果我们快速的过一下软件开发的历史，从最早的打孔纸带和汇编语言，到C语言和众多的具有不同设计哲学的高级语言，再到今日蓬勃发展的脚本语言，似乎都在做同一件事：让程序变得简单。这种简单源于语言对于特定概念的抽象和众多可以复用的库和框架，在这种软件简单性，源于封装起来的复杂性，在其背后，也许是更加复杂部分的逻辑。这种复杂性，也就是软件的隐藏复杂性。

显然，软件的隐藏复杂性是一把双刃剑，一方面，对于不必要复杂性的封装，让程序本身变得简单，能够更加直接 地表明业务的逻辑；另一方面，作为软件一部分的它们，本身也是一个软件，也有存在缺陷的可能，而一旦来自这种隐藏的复杂性当中的缺陷出来，却也会带来排错的巨大难度。从实际当中来说，这种隐藏的复杂性源于很多地方：操作系统，运行库，第三方库，以及框架。如何处理隐藏的复杂性，以及决定是否要引入一种隐藏的复杂性，这是一个项目的领导者必须做的一个决定。每个隐藏的复杂性都可以引入更简单的设计和更多的潜在的缺陷。

举几个例子吧，我们在做最近的一个产品的时候，出现了内存泄漏，经过一个星期的分析和排错，最终发现内存泄漏发生在微软的CRT库的istream当中；在同一个产品当中，beta客户处出现了程序hang住的情况，最终发现问题出在第三方的icu库当中。使用C++ iostream库和icu库毫无疑问使得程序变得简单，但是一旦出现了缺陷，却也是非常难以排除的。

还有其他的隐藏复杂性却有更隐晦的潜在问题，有些问题甚至无法解决。另一个小组正在做的项目当中出现了另一个问题，tomcat在特定的情况下可能崩溃。经过近半个月的排查发现，问题出现在JRE的socket对于solaris操作系统的socket封装问题：JRE的socket可能在系统已经将socket关闭之后再对其进行操作，这导致了tomcat的崩溃。这也是操作系统和运行库所带来的隐藏复杂性的代价。

但是这并不应该成为拒绝引入隐藏复杂性的理由，否则就是把孩子和洗澡水一起泼掉了。这里提到的几个例子都是源于著名的运行库，虽然出现了问题，但是它们所带来的便利也是毋庸置疑的。我们需要做的，就是在这种简单性和隐藏的复杂性之间做出权衡。

看起来不错。

http://kupu.oscom.org

What is Kupu?

Kupu is a ‘document-centric’ open source
client-side editor for Mozilla, Netscape and Internet Explorer.
Inspired by Maik Jablonski’s Epoz editor, it was written by Paul
Everitt, Guido Wesdorp and Philipp von Weitershausen (and several other
contributors, for a complete list refer to the CREDITS.txt file) to improve the JavaScript code
and architecture, pluggability, standards support, support for
other webservers than Zope (which was the original target platform
for Epoz), configurability and a lot of other issues.

一个教程：
Rich Web Text Editing with Kupu
教程的作者还是个生物学家。