logo
搜索
我的图书馆

发文章

发文工具

其他工具

留言交流
搜索
分享

高效可靠的日志记录模块的构建 | 艾瑞枫∑°

 青松卓然 2012-08-09

高效可靠的日志记录模块的构建

　　作为软件开发者，要记录软件日志是再平常不过的事儿了————就跟吃家常便饭一样，比如：日志是后台服务进程能唯一发出抱怨的地方(不信可以看看 ls /var/log)，可以用日志记录用户的行为及操作，还可以用日志记录软件自身的行为以便用于调试（见下一篇文章《基于日志的内存泄露的检测方法》就是利用这个哈）。既然这么多地方都用到了日志，那么作为一个崇尚自由的程序员，就不能重复造轮子———至少自己不能。所以必须要创建一个可移植的，简便高效的日志模块。

　　第一步要确定日志的格式，虽然各种风格的日志格式各异，但我比较喜欢linux风格的日志记录，命令vim /var/log/kern.log，可以看到日志内容被高亮显示了：



　　其中每行的开头是记录此条记录时的时间，这里是7月7日16时45分01秒，ulinux是主机名，CRON[25642]是记录进程的名字及PID(这里是内核)，最后是日志内容。Linux日志记录根据重要性还分为从DEBUG到EMERG的若干等级，标识该消息的重要性。在Linux下编程可以用syslog函数向系统日志(/var/log/syslog)中写入信息，syslog函数的用法如下：

View Code C
1
2
3
4
5
6
7
8
9
10
11
12
13
14

 
/* 
 * ident字符串会被附加到每一条用syslog写入的条目前面（可为NULL），
 * option指定一些可选项(如是否记录PID)，falicity用于指定该进程的类型（如FTP是LOG_FTP）
 */
void openlog(const char *ident, int option, int facility); 
 
/*
 * priority指定消息的等级，有LOG_EMERG/ALERT/CRIT/ERR/WARNING/NOTICE/INFO/DEBUG
 * 等8个等级，越往后的等级越不重要
 */
void syslog(int priority, const char*format, ...);
 
void closelog(void);

　　Linux的日志设计从输出格式到函数用法都很有借鉴意义，但又考虑到此日志可能会作为软件调试日志来用，因此还需要附上写此条记录的代码所在的文件名、函数名、行号等信息，进程名和PID显然不需要了，在此用[]来存放等级信息，然后再用{}来存放代码位置信息。现在我们定义的日志格式就成了这个样子了： 06/Jul/2012 22:28:18 [Debug] {test.c main 18} 记录内容… … 。看上去蛮顺眼的，就这么定了吧。

　　现在已经设计完毕，该去实现它了。因为这些代码将来还不知道在什么环境下运行，所以在实现过程中要考虑到很多内容：

　　1、可移植性。使用C语言编写，因此各种平台下的各种C/C++项目都可以用。
　　2、便捷性。向开发人员提供便捷的操作接口，只需一行代码就可以写入日志。
　　3、可靠性。需要考虑到多线程的情况，必须设计成线程安全的。
　　4、灵活性。提供稍微复杂一点的接口以完成更“个性化”的操作。
　　5、支持多个日志。默认可以同时打开100个日志文件，此值可根据需要调整。
　　6、支持系统日志。开发人员除了那100个可以使用的日志外，还存在一个特殊的“系统日志”，用于跟踪内存分配/释放操作，主要由内存调试模块用来分析内存泄漏等（见下一篇文章《基于日志的内存泄露的检测方法》)，但是也允许开发人员使用。

　　根据这些准则，首先把数据结构和用户接口实现了：

View Code C
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29

#define MAX_LOGS		100					/* 用户最多可打开日志数 */
 
#define LOG_INVALID		-1					/* 无效的日志描述符(初始化定义) */
#define LOG_SYSTEM		 0					/* 系统日志(xmalloc, xabort.etc) */
#define LOG_USER		 1					/* 分配给用户的最小日志描述符 */
 
enum{
	LOG_LEVEL_EMERG = 0,						/* System is unusable */
	LOG_LEVEL_ALERT,						/* Action must be taken immediately */
	LOG_LEVEL_CRIT,							/* Critical conditions */
	LOG_LEVEL_ERROR,						/* Error conditions */
	LOG_LEVEL_WARNING,						/* Warning conditions */
	LOG_LEVEL_NOTICE,						/* Normal, but significant */
	LOG_LEVEL_INFO,							/* Information */
	LOG_LEVEL_DEBUG,						/* DEBUG message */
};
 
int	log_open(const char *path, const char* mode);			/* 打开用户日志文件 */
int	log_open_sys(const char *path, const char* mode);		/* 打开系统日志文件 */
 
void	log_printf_raw(int log_id, const char *fmt, ...);		/* 无日期、等级、位置信息 */
void	log_printf0(int log_id, int level, const char *fmt, ...);	/* 无位置信息 */
 
void	log_flush(int log_id);						/* 将缓冲区数据写入日志 */
void	log_flush_sys();
 
void	log_close(int log_id);						/* 关闭日志文件 */
void	log_close_sys();
void	log_close_all();



　　用户使用log_open来打开日志(参数跟fopen一样)，然后就可以调用log_printf_raw和log_printf0来向日志中添加记录了。这两个函数的第一个参数都是log_open返回的描述符，两者不同的是前者仅写入用户指定的内容，而后者则会在每条记录的开头添加时间信息、重要等级信息。但是遗憾的是，两者都没有记录代码位置信息（文件名、函数名、行号等），这是因为以下两个原因：1、再加上行号会导致函数的参数太多，易用性不强。2、用户每调用这个函数都要键入文件名等信息，累不说，代码也会不美观。log_printf就是为了解决这个问题的，但是它的定义要颇费一番周折，现在要一步步分析它产生的过程。

　　接下来就要谈到宏的高级特性了。首先，有几个特殊的宏是专门用来记录该行代码的文件名、函数名和行号信息的，它们是__FILE__, __FUNCTION__, __LINE__，这好像方便了一些，因为调用函数的时候不用先看一下文件名、函数名再数一下行号了，但是这还是不理想，还是累啊！怎么办呢？其实我们可以换个思路，当用户要调用写入函数的时候，自动地给它加上这些信息多好！于是这需要用到宏的一般替换功能，比如这样定义:

#define log_printf(x) log_printf0(x, __FILE__, __FUNCTION__, __LINE__)

　　于是当用户调用log_printf的时候，行号等信息就被自动加上了！但是，别高兴地太早了，咱们这里的log_printf0有个可变参数”…”，要怎么替换它？没辙。而且这样的话还要修改log_printf0的定义，破坏了原来设计的接口。
　　是不是真没办法了？NO。您一定知道有可变参数函数，但您知道有可变参数红这种东西吗？如果不知道，那就真没辙了。算起来这也算宏的高级特性了，最新的GCC和VS才开始支持。可变参数宏就是为了解决这种情况而生的! 它用__VA_ARGS__来代表所有可变的参数部分。于是，我们的定义变成了这样：

#define log_printf(id, level, fmt, …) log_printf0(id, level, __FILE__, __FUNCTION__, __LINE__, fmt, __VA_ARGS__)

　　现在目标大体实现了，而且编译通过。但是这还是改变了log_printf0的接口啊，以后调用太复杂了！别急，宏的威力还不止如此。您是否知道宏的连接特性？用##可以连接起两个字符串来，就像”AB”##”CD”，在预处理之后就会变成”ABCD”了！而我们的fmt参数又是一个形如”%s %d”样式的字符串，我们再给它加上几个参数又如何！哈哈，感觉到希望了！

#define log_printf(id, level, fmt, …) log_printf0(id, level, “{%s %s %d} “##fmt, __FILE__, __FUNCTION__, __LINE__, __VA_ARGS)

　　现在，如果我们调用 log_printf(id, LOG_DEBUG, “%s”, “内容”)，它就会被展开为 log_printf0(id, LOG_DEBUG, “{%s %s %d} %s”, __FILE__, __FUNCTION__, __LINE__ , “内容”)

　　看似大功告成！但是其实还不够完善，
　　首先，因为__FILE__是全路径名，会导致日志臃肿；
　　其次，当用户没有传入可变参数的时候（比如fmt是一个纯字符串），在展开后__LINE__后面还有一个多余的逗号。当然可以告诉开发者一定要传个参数进来，但这太不友好了。其实编译器开发者们也考虑到了这个问题，解决方法是在__VA_ARGS__前加上##（这里不是字符串连接作用哦）；
　　最后，在给用户看的日志中，可能不希望透漏代码位置信息；可以的解决方案是在DEBUG模式下生成代码位置信息，而Release模式下不生成此信息，宏DBG_LOGTRACE控制此特性。

这是log_printf的最终版：

View Code C
1
2
3
4
5
6
7
8
9

#ifdef DBG_LOGTRACE
  #define log_printf(id, level, fmt, ...)			 		log_printf0(id, level, "{%s %s %d} "##fmt,   		path_find_file_name(__FILE__), __FUNCTION__, 		__LINE__, ##__VA_ARGS__)
#else
  #define log_printf(id, level, fmt, ...)			 		log_printf0(id, level, fmt, ##__VA_ARGS__)
#endif

一个完整的日志使用示例如下：

View Code C
1
2
3
4
5
6
7
8
9
10
11
12

 
int f1 = log_open(path, "w");   /* 软件启动时或使用前 */
...
 
log_printf(f1, LOG_DEBUG, "现在%s的值是%d", "a", 100);
log_printf(f1, LOG_DEBUG, "%s测试", "bb");
 
int f2 = log_open(path2, "a");  /* 又要写另一个日志了 */
log_printf (f2, LOG_INFO, "另一个日志");
log_close(f2);
...
log_close(f1);   /* 软件推出前或不再使用日志后 */

生成的第一个LOG内容如下：

06/Jul/2012 22:28:26 [Debug] {iri.c func1 144} 现在a的值是100
06/Jul/2012 22:28:26 [Debug] {iri.c func2 721} bb测试

日志格式完全满足调试要求了。接下来看看具体的实现。使用静态全部变量数据来存放文件指针，再声明一个同样大的数组来存放对应的自旋锁。
自旋锁用来实现线程间的互斥，如果不明白可以参见前一篇文件《线程同步与互斥——可移植的用户空间自旋锁》。

View Code C
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102

/* 日志记录 */
struct log_level_desc{
	enum LOG_LEVEL	level;
	char*			endesc;
	wchar_t*		cndesc;
};
 
static struct log_level_desc log_level_descs[] = {
	{ LOG_LEVEL_EMERG,	"Emergency",		L"致命" },
	{ LOG_LEVEL_ALERT,	"Alert",		L"危急" },
	{ LOG_LEVEL_CRIT,	"Critical",		L"紧急" },
	{ LOG_LEVEL_ERROR,	"Error",		L"错误" },
	{ LOG_LEVEL_WARNING,	"Warning",		L"警告" },
	{ LOG_LEVEL_NOTICE,	"Notice",		L"注意" },
	{ LOG_LEVEL_INFO,	"Info",			L"消息" },
	{ LOG_LEVEL_DEBUG,	"Debug",		L"调试" },
};
 
static FILE* log_files[MAX_LOGS+1];
static spin_lock_t log_locks[MAX_LOGS+1];
 
/* 打开用户日志文件 */
int	log_open(const char *path, const char* mode)
{
	int i;
 
	for (i = LOG_USER; i < MAX_LOGS; i++)
	{
		if (log_files[i] == NULL)
		{
			log_files[i] = fopen(path, mode);
 
			if (!log_files[i])
				return LOG_INVALID;
 
			spin_init(&log_locks[i], NULL);
			return i;
		}
	}
 
	return LOG_INVALID;
}
 
/* 打开系统日志文件 */
int log_open_sys(const char *path, const char* mode)
{
	if (log_files[LOG_SYSTEM])
		return LOG_SYSTEM;
 
	log_files[LOG_SYSTEM] = fopen(path, mode);
	if (!log_files[LOG_SYSTEM])
		return LOG_INVALID;
 
	spin_init(&log_locks[LOG_SYSTEM], NULL);
	return LOG_SYSTEM;
}
 
/* 写入日志文件 */
void log_printf0(int log_id, int log_level, const char *fmt, ...)
{
	FILE *fp;
	time_t t;
	char tmbuf[30];
	const char *p;
	va_list args;
	int level;
 
	if (log_id < 0 || log_id >= MAX_LOGS)
		return;
	else if (!(fp = log_files[log_id]))
		return;
 
	spin_lock(&log_locks[log_id]);
 
	if (log_level > LOG_LEVEL_DEBUG)
		level = LOG_LEVEL_DEBUG;
	else if (log_level < LOG_LEVEL_EMERG)
		level = LOG_LEVEL_EMERG;
	else
		level = log_level;
 
	//时间信息
	t = time(NULL);
	memset(tmbuf, 0, sizeof(tmbuf));
	strftime(tmbuf, sizeof(tmbuf), "%d/%b/%Y %H:%M:%S", localtime(&t));
	fprintf (fp, "%s ", tmbuf);
 
	//等级信息
	fprintf(fp, "[%s] ", log_level_descs[level].endesc);
 
	//正文信息
	va_start(args, fmt);
	vfprintf(fp, fmt, args);
	va_end(args);
 
	//换行符
	p = fmt + strlen(fmt) - 1;
	if (*p != '\n')
		fputc('\n', fp);
 
	spin_unlock(&log_locks[log_id]);
}

最后贴上一个现实项目中的调试日志内容：

View Code PLAIN
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

06/Jul/2012 21:46:42 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 190} =======================================
06/Jul/2012 21:46:42 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 191} Start download url http://www./wp-content/plugins/nextgen-gallery/js/jquery.cycle.all.min.js?ver=2.9995.
06/Jul/2012 21:46:42 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 192} Saving to E:\Projects\SafeSite\Debug\www.+80.5\wp-content\plugins\nextgen-gallery\js\jquery@ver=2.9995.cycle.all.min.js.
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 264} Mark this downloaded url as done.
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 348} Thread finished normally.
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 190} =======================================
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 191} Start download url http://www./wp-content/plugins/multi-level-navigation-plugin/scripts/superfish.js?ver=1.4.8.
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 192} Saving to E:\Projects\SafeSite\Debug\www.+80.5\wp-content\plugins\multi-level-navigation-plugin\scripts\superfish@ver=1.4.8.js.
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 264} Mark this downloaded url as done.
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 348} Thread finished normally.
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 190} =======================================
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 191} Start download url http://www./xmlrpc.php?rsd.
06/Jul/2012 21:46:43 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 192} Saving to E:\Projects\SafeSite\Debug\www.+80.5\xmlrpc@rsd.php.
06/Jul/2012 21:46:44 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 264} Mark this downloaded url as done.
06/Jul/2012 21:46:44 [Info] {retrthread.cpp CRetrThread::_GetURLDataBycurl 348} Thread finished normally.



呵呵，这才算是大功告成了！
短短几百行代码，以后就能一劳永逸了 ~\(≧▽≦)/~

    本站是提供个人知识管理的网络存储空间，所有内容均由用户发布，不代表本站观点。请注意甄别内容中的联系方式、诱导购买等信息，谨防诈骗。如发现有害或侵权内容，请点击一键举报。
    转藏 分享 献花（0）

    来自： 青松卓然 > 《CPP》

    举报/认领

    0条评论

    发表

    请遵守用户 评论公约

    类似文章 更多