C语言日志类库 zlog 使用指南（第七章 高级用法）

第七章 高级用法

7.1 MDC

MDC 是什么？在 log4j 中，它是 Mapped Diagnostic Context（映射诊断上下文）的缩写。听起来像是一个很复杂的术语。而实际上，MDC 只是一个键值对（key-value）映射。一旦你通过函数设置了它，zlog 库将在每次日志事件发生时将其记录到文件中，或者让它成为日志文件路径的一部分。让我们看看位于 $(top_builddir)/test/test_mdc.c 中的示例。

#include <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <unistd.h>
#include <string.h>
#include "zlog.h"

int main(int argc, char** argv)
{
  int rc;
  zlog_category_t *zc;

  rc = zlog_init("test_mdc.conf");

  if (rc) { 
    printf("init failed\n");
    return -1;
  }

  zc = zlog_get_category("my_cat");

  if (!zc) {
    printf("get cat fail\n");
    zlog_fini();
    return -2;
  }

  zlog_info(zc, "1.hello, zlog");

  zlog_put_mdc("myname", "Zhang");
  zlog_info(zc, "2.hello, zlog");

  zlog_put_mdc("myname", "Li");
  zlog_info(zc, "3.hello, zlog"); 

  zlog_fini(); 
  return 0;
}

配置文件为：

[formats]
mdc_format=     "%d.%ms %-6V (%c:%F:%L) [%M(myname)] - %m%n"

[rules]
*.*             >stdout; mdc_format

运行示例程序的输出如下：

$ ./test_mdc
2012-03-12 09:26:37.740 INFO   (my_cat:test_mdc.c:47) [] - 1.hello, zlog 
2012-03-12 09:26:37.740 INFO   (my_cat:test_mdc.c:51) [Zhang] - 2.hello, zlog 
2012-03-12 09:26:37.740 INFO   (my_cat:test_mdc.c:55) [Li] - 3.hello, zlog

可以看到，zlog_put_mdc() 函数将键值对 “myname: Zhang” 设置在 map 中，并且在配置文件中用 %M(myname) 指定了这个值在每条日志中的显示位置。第二次时，键 “myname” 的值被覆写为 “Li”，相应日志也随之改变。

MDC 什么时候使用？主要取决于用户何时需要通过不同的场景区分相同的日志操作。例如，在 C 代码中：

zlog_put_mdc("customer_name", get_customer_name_from_db() );

zlog_info("get in"); 
zlog_info("pick product"); 
zlog_info("pay");
zlog_info("get out");

在配置文件中：

&format  "%M(customer_name) %m%n"

当程序同时处理两个不同的客户时，输出可能如下：

Zhang get in
Li get in
Zhang pick product
Zhang pay
Li pick product
Li pay
Zhang get out
Li get out

现在你可以通过后续的 grep 命令区分不同的客户：

$ grep Zhang aa.log > Zhang.log
$ grep Li aa.log > Li.log

或者，另一种方法是当记录日志时将它们分别存到不同的日志文件中。在配置文件中：

*.* "mdc_%M(customer_name).log";

这将产生 3 个日志文件：

mdc_.log
mdc_Zhang.log
mdc_Li.log

如果你知道自己在做什么，这是一种快捷的方法。

在 MDC 中，map 属于一个线程，每个线程有自己的 map。在一个线程中调用 zlog_mdc_put() 不会影响其他线程的 map。如果你想区分不同的线程，使用 %t 转换字符已经足够。

7.2 为 zlog 本身配置日志

到目前为止，我们假设 zlog 库从不出错。zlog 库能够帮助应用程序记录日志条目和调试应用程序。但如果 zlog 本身有些问题，我们该如何发现呢？其他程序通过日志库进行调试，那么日志库该如何调试自己呢？答案是相同的，zlog 库也有自己的日志。这些配置日志通常是关闭的，可以通过设置环境变量来开启。

$ export ZLOG_PROFILE_DEBUG=/tmp/zlog.debug.log
$ export ZLOG_PROFILE_ERROR=/tmp/zlog.error.log

配置日志只有两个级别：debug 和 error。设置好以后，运行 [sec:Hello-World-Example] 中的 test_hello 程序，调试日志将会显示如下：

$ more zlog.debug.log

03-13 09:46:56 DEBUG (7503:zlog.c:115) ------zlog_init start, compile time[Mar 13 2012 11:28:56]------

03-13 09:46:56 DEBUG (7503:spec.c:825) spec:[0x7fdf96b7c010][%d(%F %T)][%F %T 29][]

03-13 09:46:56 DEBUG (7503:spec.c:825) spec:[0x7fdf96b52010][ ][ 0][]

......

03-13 09:52:40 DEBUG (8139:zlog.c:291) ------zlog_fini end------

查看 zlog.error.log 中没有创建任何内容，因为没有发生错误。

如你所见，调试日志展示了 zlog 是如何初始化和结束的，但是当 zlog_info() 执行时没有记录调试日志。这是为了效率考虑。

如果 zlog 库有任何问题，一切都会显示在 zlog.error.log 中。例如，在 zlog() 使用错误的 printf 语法：

zlog_info(zc, "%l", 1);

然后运行程序，zlog.error.log 应该会显示如下内容：

$ cat zlog.error.log

03-13 10:04:58 ERROR (10102:buf.c:189) vsnprintf fail, errno[0]

03-13 10:04:58 ERROR (10102:buf.c:191) nwrite[-1], size_left[1024], format[%l]

03-13 10:04:58 ERROR (10102:spec.c:329) zlog_buf_vprintf maybe fail or overflow

03-13 10:04:58 ERROR (10102:spec.c:467) a_spec->gen_buf fail

03-13 10:04:58 ERROR (10102:format.c:160) zlog_spec_gen_msg fail

03-13 10:04:58 ERROR (10102:rule.c:265) zlog_format_gen_msg fail

03-13 10:04:58 ERROR (10102:category.c:164) hzb_log_rule_output fail

03-13 10:04:58 ERROR (10102:zlog.c:632) zlog_output fail, srcfile[test_hello.c], srcline[41]

现在，你可以找到预期日志未生成的原因，并修正错误的 printf 语法。

运行时分析会导致效率损失。通常，我会在环境中保留 ZLOG_PROFILE_ERROR 开启而 ZLOG_PROFILE_DEBUG 关闭。

还有另一种方法来剖析 zlog 库。zlog_init() 会将配置文件读入内存。所有日志操作过程中，配置结构保持不变。有可能这个内存被应用程序中的其它函数破坏，或内存与配置文件描述不一致。因此有一个函数可以在运行时显示这个内存，并将其打印到 ZLOG_PROFILE_ERROR 中。

查看 $(top_builddir)/test/test_profile.c

$ cat test_profile.c

#include <stdio.h>
#include "zlog.h"

int main(int argc, char** argv)
{
    int rc;
    rc = dzlog_init("test_profile.conf", "my_cat");
    if (rc) {
        printf("init failed\n");
        return -1;
    }

    dzlog_info("hello, zlog");

    zlog_profile();
    
    zlog_fini();
    return 0;
}

zlog_profile() 是这个函数。配置文件很简单：

$ cat test_profile.conf

[formats]
simple = "%m%n"

[rules]
my_cat.*                >stdout; simple

然后 zlog.error.log 会显示如下内容：

$ cat /tmp/zlog.error.log

06-01 11:21:26 WARN  (7063:zlog.c:783) ------zlog_profile start------

06-01 11:21:26 WARN  (7063:zlog.c:784) init_flag:[1]

06-01 11:21:26 WARN  (7063:conf.c:75) -conf[0x2333010]-

06-01 11:21:26 WARN  (7063:conf.c:76) --global--

06-01 11:21:26 WARN  (7063:conf.c:77) ---file[test_profile.conf],mtime[2012-06-01 11:20:44]---

06-01 11:21:26 WARN  (7063:conf.c:78) ---strict init[1]---

06-01 11:21:26 WARN  (7063:conf.c:79) ---buffer min[1024]---

06-01 11:21:26 WARN  (7063:conf.c:80) ---buffer max[2097152]---

06-01 11:21:26 WARN  (7063:conf.c:82) ---default_format---

06-01 11:21:26 WARN  (7063:format.c:48) ---format[0x235ef60][default = %d(%F %T) %V [%p:%F:%L] %m%n(0x233b810)]---

06-01 11:21:26 WARN  (7063:conf.c:85) ---file perms[0600]---

06-01 11:21:26 WARN  (7063:conf.c:87) ---rotate lock file[/tmp/zlog.lock]---

06-01 11:21:26 WARN  (7063:rotater.c:48) --rotater[0x233b7d0][0x233b7d0,/tmp/zlog.lock,4]--

06-01 11:21:26 WARN  (7063:level_list.c:37) --level_list[0x2335490]--

06-01 11:21:26 WARN  (7063:level.c:37) ---level[0x23355c0][0,*,*,1,6]---

06-01 11:21:26 WARN  (7063:level.c:37) ---level[0x23375e0][20,DEBUG,debug,5,7]---

06-01 11:21:26 WARN  (7063:level.c:37) ---level[0x2339600][40,INFO,info,4,6]---

06-01 11:21:26 WARN  (7063:level.c:37) ---level[0x233b830][60,NOTICE,notice,6,5]---

06-01 11:21:26 WARN  (7063:level.c:37) ---level[0x233d850][80,WARN,warn,4,4]---

06-01 11:21:26 WARN  (7063:level.c:37) ---level[0x233fc80][100,ERROR,error,5,3]---

通过这些详细的日志，我们可以了解 zlog 配置在运行时的状态及其内部结构，从而判断并修复可能存在的问题。

7.3 用户自定义日志级别

以下是定义您自己的日志级别的所有步骤。

1. 在配置文件中定义日志级别

在配置文件中添加以下内容：

$ cat $(top_builddir)/test/test_level.conf

[global]
default format  =  "%V %v %m%n"

[levels]
TRACE = 30, LOG_DEBUG

[rules]
my_cat.TRACE >stdout;

zlog 内部默认的日志级别为（无需在配置文件中写出）：

• DEBUG = 20, LOG_DEBUG
• INFO = 40, LOG_INFO
• NOTICE = 60, LOG_NOTICE
• WARN = 80, LOG_WARNING
• ERROR = 100, LOG_ERR
• FATAL = 120, LOG_ALERT
• UNKNOWN = 254, LOG_ERR

在 zlog 中，日志级别由一个整数（例如 30）和一个级别字符串（例如 TRACE）表示。注意，这个整数必须在 [1,253] 范围内，其他数字都是非法的。数字越大，级别越重要。因此 TRACE 比 DEBUG 更重要（30>20），但不如 INFO 重要（30<40）。定义后，TRACE 可以在配置文件中的规则中使用。例如：

my_cat.TRACE >stdout;

这表示日志级别>=TRACE 的日志（即 TRACE、INFO、NOTICE、WARN、ERROR、FATAL）将被写入标准输出。

format 字符串中的转换字符 %V 生成日志级别字符串的大写形式，而 %v 生成小写形式。

在级别定义中，LOG_DEBUG 表示当在规则中使用 >syslog 时，所有 TRACE 日志将作为 syslog 的 LOG_DEBUG 级别输出。

2. 在源文件中使用新的日志级别

最直接的方式如下：

zlog(cat, __FILE__, sizeof(__FILE__)-1, \
__func__, sizeof(__func__)-1, __LINE__, \
30, "test %d", 1);

为了方便使用，可以创建一个 .h 文件：

$ cat $(top_builddir)/test/test_level.h

#ifndef __test_level_h
#define __test_level_h

#include "zlog.h"

enum {
    ZLOG_LEVEL_TRACE = 30,
    /* 必须与配置文件中的设置相等 */
};

#define zlog_trace(cat, format, ...) \
    zlog(cat, __FILE__, sizeof(__FILE__)-1, \
        __func__, sizeof(__func__)-1, __LINE__, \
        ZLOG_LEVEL_TRACE, format, ##__VA_ARGS__)

#endif

3. 在 .c 文件中使用 zlog_trace

接下来在 .c 文件中使用 zlog_trace：

$ cat $(top_builddir)/test/test_level.c

#include <stdio.h>
#include "test_level.h"

int main(int argc, char** argv) 
{
    int rc;
    zlog_category_t *zc;

    rc = zlog_init("test_level.conf");
    if (rc) {
        printf("init failed\n");
        return -1;
    }

    zc = zlog_get_category("my_cat");
    if (!zc) {
        printf("get cat fail\n");
        zlog_fini();
        return -2;
    }

    zlog_trace(zc, "hello, zlog - trace");
    zlog_debug(zc, "hello, zlog - debug");
    zlog_info(zc, "hello, zlog - info");

    zlog_fini();
    return 0;
}

4. 查看输出

最后，编译并运行程序：

$ ./test_level

TRACE trace hello, zlog - trace 
INFO info hello, zlog - info

这正是我们所期望的。配置文件仅允许 >=TRACE 级别的日志输出到屏幕。同时，%V 和 %v 也工作正常。

7.4 用户定义输出

用户定义输出的目标是让 zlog 放弃一些控制权。zlog 只负责根据用户的配置动态地生成路径和消息，但将日志输出、轮转和清理动作的权限交给用户自定义。通过设置一个函数来适应特定规则，你可以完全按照自己的需求来处理日志。以下是定义自有输出函数的步骤。

步骤 1：在配置文件中定义输出规则

$ cat test_record.conf

内容如下：

[formats]
simple = "%m%n"

[rules]
my_cat.*      $myoutput, " mypath %c %d";simple

步骤 2：为 myoutput 设置输出函数并使用它

首先我们需要包含必要的头文件并定义输出函数：

#include <stdio.h>
#include "zlog.h"

int output(zlog_msg_t *msg) 
{ 
    printf("[mystd]:[%s][%s][%ld]\n", msg->path, msg->buf, (long)msg->len); 	
    return 0; 
}

然后是 main 函数：

int main(int argc, char** argv)
{
    int rc;
    zlog_category_t *zc;

    rc = zlog_init("test_record.conf");
    if (rc) {
        printf("init failed\n");
        return -1;
    }

    zlog_set_record("myoutput", output);

    zc = zlog_get_category("my_cat");
    if (!zc) {
        printf("get cat fail\n");
        zlog_fini();
        return -2;
    }

    zlog_info(zc, "hello, zlog");

    zlog_fini();
    return 0;
}

步骤 3：查看用户自定义输出函数的工作方式

编译并运行程序：

$ ./test_record

输出结果：

[mystd]:[ mypath my_cat 2012-07-19 11:01:12][hello, zlog][12]

如你所见，msg->len 是 12，且 zlog 格式化的消息包含了一个新行字符。

步骤 4：用户可以通过自定义输出函数做很多事情

例如，一个用户（flw@newsmth.net）提供了以下示例：

(a) 日志文件名是 foo.log。

(b) 如果 foo.log 大于 100M，则生成一个包含 foo.log 所有内容的新日志文件。然后 zlog 将 foo.log 截断为 0，并在下次日志记录时重新附加。

© 即使 foo.log 没有超过 100M，当最后一次记录时间超过 5 分钟时，zlog 也会跳转到一个新文件。

(d) 新文件名应根据自己的需求定义。例如，可以添加设备编号作为前缀，时间字符串作为后缀。

(e) 你可以压缩新的日志文件以节省磁盘空间和网络带宽。

希望他在多进程或多线程情况下编写这样的函数时好运！