作為軟件開發(fā)者，要記錄軟件日志是再平常不過的事兒了————就跟吃家常便飯一樣，比如：日志是后臺服務(wù)進(jìn)程能唯一發(fā)出抱怨的地方(不信可以看看 ls /var/log)，可以用日志記錄用戶的行為及操作，還可以用日志記錄軟件自身的行為以便用于調(diào)試（見下一篇文章《基于日志的內(nèi)存泄露的檢測方法》就是利用這個哈）。既然這么多地方都用到了日志，那么作為一個崇尚自由的程序員，就不能重復(fù)造輪子———至少自己不能。所以必須要創(chuàng)建一個可移植的，簡便高效的日志模塊。
第一步要確定日志的格式，雖然各種風(fēng)格的日志格式各異，但我比較喜歡linux風(fēng)格的日志記錄，命令vim /var/log/kern.log，可以看到日志內(nèi)容被高亮顯示了：
其中每行的開頭是記錄此條記錄時的時間，這里是7月7日16時45分01秒，ulinux是主機(jī)名，CRON[25642]是記錄進(jìn)程的名字及PID(這里是內(nèi)核)，最后是日志內(nèi)容。Linux日志記錄根據(jù)重要性還分為從DEBUG到EMERG的若干等級，標(biāo)識該消息的重要性。在Linux下編程可以用syslog函數(shù)向系統(tǒng)日志(/var/log/syslog)中寫入信息，syslog函數(shù)的用法如下：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
|
/*
* ident字符串會被附加到每一條用syslog寫入的條目前面（可為NULL），
* option指定一些可選項(如是否記錄PID)，falicity用于指定該進(jìn)程的類型（如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的日志設(shè)計從輸出格式到函數(shù)用法都很有借鑒意義，但又考慮到此日志可能會作為軟件調(diào)試日志來用，因此還需要附上寫此條記錄的代碼所在的文件名、函數(shù)名、行號等信息，進(jìn)程名和PID顯然不需要了，在此用[]來存放等級信息，然后再用{}來存放代碼位置信息?，F(xiàn)在我們定義的日志格式就成了這個樣子了： 06/Jul/2012 22:28:18 [Debug] {test.c main 18} 記錄內(nèi)容… … ?？瓷先バU順眼的，就這么定了吧。
現(xiàn)在已經(jīng)設(shè)計完畢，該去實現(xiàn)它了。因為這些代碼將來還不知道在什么環(huán)境下運(yùn)行，所以在實現(xiàn)過程中要考慮到很多內(nèi)容：
1、可移植性。使用C語言編寫，因此各種平臺下的各種C/C++項目都可以用。
2、便捷性。向開發(fā)人員提供便捷的操作接口，只需一行代碼就可以寫入日志。
3、可靠性。需要考慮到多線程的情況，必須設(shè)計成線程安全的。
4、靈活性。提供稍微復(fù)雜一點(diǎn)的接口以完成更“個性化”的操作。
5、支持多個日志。默認(rèn)可以同時打開100個日志文件，此值可根據(jù)需要調(diào)整。
6、支持系統(tǒng)日志。開發(fā)人員除了那100個可以使用的日志外，還存在一個特殊的“系統(tǒng)日志”，用于跟蹤內(nèi)存分配/釋放操作，主要由內(nèi)存調(diào)試模塊用來分析內(nèi)存泄漏等（見下一篇文章《基于日志的內(nèi)存泄露的檢測方法》)，但是也允許開發(fā)人員使用。
根據(jù)這些準(zhǔn)則，首先把數(shù)據(jù)結(jié)構(gòu)和用戶接口實現(xiàn)了：
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 /* 用戶最多可打開日志數(shù) */
#define LOG_INVALID -1 /* 無效的日志描述符(初始化定義) */
#define LOG_SYSTEM 0 /* 系統(tǒng)日志(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); /* 打開系統(tǒng)日志文件 */
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); /* 將緩沖區(qū)數(shù)據(jù)寫入日志 */
void log_flush_sys();
void log_close(int log_id); /* 關(guān)閉日志文件 */
void log_close_sys();
void log_close_all(); |
用戶使用log_open來打開日志(參數(shù)跟fopen一樣)，然后就可以調(diào)用log_printf_raw和log_printf0來向日志中添加記錄了。這兩個函數(shù)的第一個參數(shù)都是log_open返回的描述符，兩者不同的是前者僅寫入用戶指定的內(nèi)容，而后者則會在每條記錄的開頭添加時間信息、重要等級信息。但是遺憾的是，兩者都沒有記錄代碼位置信息（文件名、函數(shù)名、行號等），這是因為以下兩個原因：1、再加上行號會導(dǎo)致函數(shù)的參數(shù)太多，易用性不強(qiáng)。2、用戶每調(diào)用這個函數(shù)都要鍵入文件名等信息，累不說，代碼也會不美觀。log_printf就是為了解決這個問題的，但是它的定義要頗費(fèi)一番周折，現(xiàn)在要一步步分析它產(chǎn)生的過程。
接下來就要談到宏的高級特性了。首先，有幾個特殊的宏是專門用來記錄該行代碼的文件名、函數(shù)名和行號信息的，它們是__FILE__, __FUNCTION__, __LINE__，這好像方便了一些，因為調(diào)用函數(shù)的時候不用先看一下文件名、函數(shù)名再數(shù)一下行號了，但是這還是不理想，還是累??！怎么辦呢？其實我們可以換個思路，當(dāng)用戶要調(diào)用寫入函數(shù)的時候，自動地給它加上這些信息多好！于是這需要用到宏的一般替換功能，比如這樣定義:
#define log_printf(x) log_printf0(x, __FILE__, __FUNCTION__, __LINE__)
于是當(dāng)用戶調(diào)用log_printf的時候，行號等信息就被自動加上了！但是，別高興地太早了，咱們這里的log_printf0有個可變參數(shù)”…”，要怎么替換它？沒轍。而且這樣的話還要修改log_printf0的定義，破壞了原來設(shè)計的接口。
是不是真沒辦法了？NO。您一定知道有可變參數(shù)函數(shù)，但您知道有可變參數(shù)紅這種東西嗎？如果不知道，那就真沒轍了。算起來這也算宏的高級特性了，最新的GCC和VS才開始支持?？勺儏?shù)宏就是為了解決這種情況而生的! 它用__VA_ARGS__來代表所有可變的參數(shù)部分。于是，我們的定義變成了這樣：
#define log_printf(id, level, fmt, …) log_printf0(id, level, __FILE__, __FUNCTION__, __LINE__, fmt, __VA_ARGS__)
現(xiàn)在目標(biāo)大體實現(xiàn)了，而且編譯通過。但是這還是改變了log_printf0的接口啊，以后調(diào)用太復(fù)雜了！別急，宏的威力還不止如此。您是否知道宏的連接特性？用##可以連接起兩個字符串來，就像”AB”##”CD”，在預(yù)處理之后就會變成”ABCD”了！而我們的fmt參數(shù)又是一個形如”%s %d”樣式的字符串，我們再給它加上幾個參數(shù)又如何！哈哈，感覺到希望了！
#define log_printf(id, level, fmt, …) log_printf0(id, level, “{%s %s %d} “##fmt, __FILE__, __FUNCTION__, __LINE__, __VA_ARGS)
現(xiàn)在，如果我們調(diào)用 log_printf(id, LOG_DEBUG, “%s”, “內(nèi)容”)，它就會被展開為 log_printf0(id, LOG_DEBUG, “{%s %s %d} %s”, __FILE__, __FUNCTION__, __LINE__ , “內(nèi)容”)
看似大功告成！但是其實還不夠完善，
首先，因為__FILE__是全路徑名，會導(dǎo)致日志臃腫；
其次，當(dāng)用戶沒有傳入可變參數(shù)的時候（比如fmt是一個純字符串），在展開后__LINE__后面還有一個多余的逗號。當(dāng)然可以告訴開發(fā)者一定要傳個參數(shù)進(jìn)來，但這太不友好了。其實編譯器開發(fā)者們也考慮到了這個問題，解決方法是在__VA_ARGS__前加上##（這里不是字符串連接作用哦）；
最后，在給用戶看的日志中，可能不希望透漏代碼位置信息；可以的解決方案是在DEBUG模式下生成代碼位置信息，而Release模式下不生成此信息，宏DBG_LOGTRACE控制此特性。
這是log_printf的最終版：
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 |
一個完整的日志使用示例如下：
1
2
3
4
5
6
7
8
9
10
11
12
|
int f1 = log_open(path, "w"); /* 軟件啟動時或使用前 */
...
log_printf(f1, LOG_DEBUG, "現(xiàn)在%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內(nèi)容如下：
06/Jul/2012 22:28:26 [Debug] {iri.c func1 144} 現(xiàn)在a的值是100
06/Jul/2012 22:28:26 [Debug] {iri.c func2 721} bb測試
日志格式完全滿足調(diào)試要求了。接下來看看具體的實現(xiàn)。使用靜態(tài)全部變量數(shù)據(jù)來存放文件指針，再聲明一個同樣大的數(shù)組來存放對應(yīng)的自旋鎖。
自旋鎖用來實現(xiàn)線程間的互斥，如果不明白可以參見前一篇文件《線程同步與互斥——可移植的用戶空間自旋鎖》。
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"調(diào)試" },
};
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;
}
/* 打開系統(tǒng)日志文件 */
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]);
} |
最后貼上一個現(xiàn)實項目中的調(diào)試日志內(nèi)容：
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. |
呵呵，這才算是大功告成了！
短短幾百行代碼，以后就能一勞永逸了 ~\(≧▽≦)/~
