將程式碼中的偵錯資訊輸出到紀錄檔檔案中

一、將偵錯資訊輸出到螢幕中

1.1 一般寫法

我們平常在寫程式碼時，肯定會有一些偵錯資訊的輸出：

#include <stdio.h>
#include <stdlib.h>

int main()
{
    char szFileName[] = "test.txt";
    FILE *fp = fopen(szFileName, "r");
    if (fp == NULL)
    {
        // 檔案開啟失敗，提示錯誤並退出
        printf("open file(%s) error.\n", szFileName);
        exit(0);
    }
    else
    {
        // 檔案開啟成功，進行相應的檔案讀/寫操作
    }

    return 0;
}

假設當前目錄下沒有 test.txt 檔案。當程式執行到第 7 行時，必然返回 NULL，這時候通過第 11 行的偵錯資訊，我們可以幫助我們精確排查到程式退出的原因：原來是檔案開啟失敗了。

那如果當前目錄下存在 test.txt 檔案，只是不可讀呢？

同樣輸出了 open file(test.txt) error

在這種情況下如何快速定位檔案開啟失敗的原因呢？我們可以考慮使用 errno。

1.2 使用 errno

errno 是記錄系統的最後一次錯誤程式碼。錯誤程式碼是一個 int 型的值，在 errno.h 中定義。

#include <errno.h>	// errno 標頭檔案
#include <string.h>	// strerror 標頭檔案

// 檔案開啟失敗，提示錯誤並退出
printf("open file(%s) error, errno[%d](%s).\n", szFileName, errno, strerror(errno));

修改後再次執行 main.exe：

如果程式碼中包含很多的偵錯資訊呢？我們並不能一下子知道這條資訊到底是在哪裡列印出來的，於是，我們又想，能不能把當前偵錯資訊所在的檔名和原始碼行位置也列印出來呢，這樣不就一目瞭然了嗎。基於此，便有了 1.3 的內容。

1.3 編譯器內建宏

ANSI C 標準中有幾個標準預定義宏：

__LINE__：在原始碼中插入當前原始碼行號
__FILE__：在原始檔中插入當前原始檔名
__FUNCTION_：在原始檔中插入當前函數名
__DATE__：在原始檔中插入當前的編譯日期
__TIME__：在原始檔中插入當前編譯時間
__STDC__：當要求程式嚴格遵循ANSI C標準時該標識被賦值為 1
__cplusplus：當編寫C++程式時該識別符號被定義

於是我們這麼修改輸出語句：

// 檔案開啟失敗，提示錯誤並退出
printf("[%s][%s:%d] open file(%s) error, errno[%d](%s).\n", 
                                                    __FILE__,
                                                    __FUNCTION__,
                                                    __LINE__,
                                                    szFileName, 
                                                    errno, strerror(errno));

從紀錄檔資訊中，我們可以精確的獲取到：main.c 檔案中的 main 函數的第 16 行報錯了，錯誤原因是 Permission denied

相比於之前，確實是能幫助我們精準的定位問題，但是，總不能每次都要寫這麼長的 printf 吧，有沒有偷懶的辦法呢？

1.4 使用可變宏輸出偵錯資訊

1.4.1 可變宏介紹

用可變引數宏（variadic macros）傳遞可變參數列，你可能很熟悉在函數中使用可變參數列，如：

void printf(const char* format, ...);

在 1999 年版本的 ISO C 標準中，宏可以像函數一樣，定義時可以帶有可變引數。宏的語法和函數的語法類似，如下所示：

#define DEBUG(...) printf(__VA_ARGS__)

int main()
{
    int x = 10;
    DEBUG("x = %d\n", x); // 等價於 printf("x = %d\n", x);
    
    return 0;
}

預設號（...）指可變引數
__VA_ARGS__宏用來接收不定數量的引數

這類宏在被呼叫時，它（這裡指預設號...）被表示成零個或多個符號（包括裡面的逗號），一直到右括弧結束為止。當被呼叫時，在宏體（ macro body ）中，這些符號序列集合將代替裡面的 _VA_ARGS_ 識別符號。當宏的呼叫展開時，實際的引數就傳遞給 printf 了。

相比於 ISO C 標準，GCC 始終支援複雜的宏，它使用一種不同的語法從而可以使你可以給可變引數一個名字，如同其它引數一樣。例如下面的例子：

#define DEBUG(format, args...) printf(format, args)

int main()
{
    int x = 10;
    DEBUG("x = %d\n", x); // 等價於 printf("x = %d\n", x);
    
    return 0;
}

這和上面舉的「ISO C」定義的宏例子是完全一樣的，但是這麼寫可讀性更強並且更容易進行描述

在標準 C 裡，你不能省略可變引數，但是你卻可以給它傳遞一個空的引數。例如，下面的宏呼叫在「ISO C」裡是非法的，因為字串後面沒有逗號：

#define DEBUG(...) printf(__VA_ARGS__)

int main()
{
    DEBUG("hello world.\n"); // 非法呼叫
}

GCC 在這種情況下可以讓你完全的忽略可變引數。在上面的例子中，編譯是仍然會有問題，因為宏展開後，裡面的字串後面會有個多餘的逗號。為了解決這個問題， GCC 使用了一個特殊的##操作。書寫格式為：

#define DEBUG(format, args...) printf(format, ##args)

這裡，如果可變引數被忽略或為空，##操作將使前處理器去除掉它前面的那個逗號
如果你在宏呼叫時，確實提供了一些可變引數，該宏定義也會工作正常，它會把這些可變引數放到逗號的後面

1.4.2 使用可變宏輸出偵錯資訊

有了 1.4.1 的基礎知識，我們可以這麼修改程式碼：

#define DEBUG(format, args...) \
            printf("[%s][%s:%d] "format"\n", \
                        		__FILE__, \
                        		__FUNCTION__, \
                        		__LINE__, \
                        		##args)

// 檔案開啟失敗，提示錯誤並退出
DEBUG("open file(%s) error, errno[%d](%s).", szFileName, errno, strerror(errno));

通過可變宏，完美解決了偵錯資訊書寫過長的問題

書寫過長的問題解決後，又來新問題了，如果我想知道某一偵錯資訊是何時被列印的呢？

下面讓我們學習一下 Linux 中與時間相關的內容。

二、Linux 中與時間相關的函數

2.1 表示時間的結構體

通過檢視標頭檔案「/usr/include/time.h」和「/usr/include/bits/time.h」，我們可以找到下列四種表示「時間」的結構體：

/* Returned by `time'. */
typedef __time_t time_t;

/* A time value that is accurate to the nearest
   microsecond but also has a range of years. */
struct timeval
{
    __time_t tv_sec;       /* Seconds. */
    __suseconds_t tv_usec; /* Microseconds. */
};

struct timespec
{
    __time_t tv_sec;  /* Seconds. */
    long int tv_nsec; /* Nanoseconds. */
};

struct tm
{
    int tm_sec;   /* Seconds.		[0-59] (1 leap second) */
    int tm_min;   /* Minutes.		[0-59] */
    int tm_hour;  /* Hours.    		[0-23] */
    int tm_mday;  /* Day.			[1-31] */
    int tm_mon;   /* Month.			[0-11] */
    int tm_year;  /* Year.			自 1900 起的年數 */
    int tm_wday;  /* Day of week.	[0-6] */
    int tm_yday;  /* Days in year.	[0-365] */
    int tm_isdst; /* DST.			夏令時 */

#ifdef __USE_BSD
    long int tm_gmtoff;    /* Seconds east of UTC. */
    __const char *tm_zone; /* Timezone abbreviation. */
#else
    long int __tm_gmtoff;    /* Seconds east of UTC. */
    __const char *__tm_zone; /* Timezone abbreviation. */
#endif
};

time_t 是一個長整型，用來表示「秒數」
struct timeval 結構體用「秒和微秒」來表示時間
struct timespec 結構體用「秒和納秒」來表示時間
struct tm 直接用「秒、分、小時、天、月、年」等來表示時間

2.2 獲取當前時間

// 可以獲取精確到秒的當前距離1970-01-01 00:00:00 +0000 (UTC)的秒數
time_t time(time_t *t);

// 可以獲取精確到微秒的當前距離1970-01-01 00:00:00 +0000 (UTC)的微秒數
int gettimeofday(struct timeval *tv, struct timezone *tz);

// 可以獲取精確到納秒的當前距離1970-01-01 00:00:00 +0000 (UTC)的納秒數
int clock_gettime(clockid_t clk_id, struct timespec *tp)

使用方式如下所示：

#include <stdio.h>
#include <time.h>
#include <sys/time.h>

int main()
{
    time_t lTime;
    time(&lTime);
    printf("lTime       : %ld\n", lTime);

    struct timeval stTimeVal;
    gettimeofday(&stTimeVal, NULL);
    printf("stTimeVal   : %ld\n", stTimeVal.tv_sec);

    struct timespec stTimeSpec;
    clock_gettime(CLOCK_REALTIME, &stTimeSpec);
    printf("stTimeSpec  : %ld\n", stTimeSpec.tv_sec);

    return 0;
}

我們可以通過上面三個函數獲得三種不同精度的當前時間

Notes：

POSIX.1-2008 marks gettimeofday() as obsolete, recommending the use of clock_gettime(2) instead.

並且，有人曾經做過測試，連續兩次使用 gettimeofday 時，會以一種小概率出現「時光倒流」的現象，第二次函數呼叫得到的時間要小於或說早於第一次呼叫得到的時間。

gettimeofday 函數並不是那麼穩定，沒有 times 或 clock 計時準確，但它們用法相似。

clock有計時限制，據說是 596.5+小時，一般情況足以應付。

ntpd 之類的程序可能會修改系統時間，導致計時出現誤差。

據網上的討論來看，TSC 和 HPET 中斷之類的東西，可能導致系統的 wall time 回退。這個應該和具體的系統實現有關了，總之 gettimeofday 函數並沒有保證提供怎樣的精度，也不保證得到系統的準確時間，它返回的結果是「the system's best guess at wall time」。

有可能的話，儘量使用 clock_gettime(CLOCK_MONOTONIC)，不過不是所有系統都實現了 posix realtime，例如 mac os x。

所以現在應該用：int clock_gettime(CLOCK_MONOTONIC, struct timespec *tp);
CLOCK_MONOTONIC：Clock that cannot be set and represents monotonic time since some unspecified starting point.

2.3 秒、毫秒、微秒、納秒之間的轉換

1 秒 = 1000 毫秒
1 毫秒 = 1000 微秒
1 微秒 = 1000 納秒

so:

1 秒 = 1000,000 微秒（一百萬微秒）
1 秒 = 1000,000,000 納秒（十億納秒）

從秒到毫秒，毫秒到微秒，微秒到納秒都是 1000 的倍關係，也就是多 3 個 0 的關係。

另：個人電腦的微處理器執行一道指令（如將兩數相加）約需 2~4 納秒，所以程式只要精確到納秒就夠了。

2.4 對時間進行格式化輸出

首先將 struct timeval 或 struct timespec 轉換成 time_t 表示的秒數：

struct timeval stTimeVal;
gettimeofday(&stTimeVal, NULL);

time_t lTime = stTimeVal.tv_sec;

利用系統函數將 time_t 轉換為 struct tm：

struct tm stTime;
localtime_r(&lTime, &stTime); // 注意，localtime_r 的第二個引數是入參

格式化輸出：

char buf[128];
// 自定義輸出格式：YYYY-MM-DD hh:mm:ss
snprintf(buf, 128, "%.4d-%.2d-%.2d %.2d:%.2d:%.2d", 
                        stTime.tm_year + 1900,
                        stTime.tm_mon + 1,
                        stTime.tm_mday,
                        stTime.tm_hour,
                        stTime.tm_min,
                        stTime.tm_sec);
puts(buf);

將 time_t 轉換成 struct tm 的函數一共有 4 個，分別為：

struct tm *gmtime(const time_t *timep);

struct tm *gmtime_r(const time_t *timep, struct tm *result);

struct tm *localtime(const time_t *timep);

struct tm *localtime_r(const time_t *timep, struct tm *result);

形如 localtime 和形如 localtime_r 函數的區別是：localtime 獲得的返回值存在於一個 static 的 struct tm 型的變數中，可能被後面的 localtime 呼叫覆蓋掉。如果要防止覆蓋，我們可以自己提供一個 struct tm 型的變數，利用 localtime_r 函數，將我們自己定義的變數的地址傳進去，將結果儲存在其中，這樣就可以避免覆蓋。

因此可知，函數 gmtime 和 localtime 是執行緒不安全的，多執行緒程式設計中要慎用！

2.5 獲取毫秒時間

#include <stdio.h>
#include <time.h>
#include <sys/time.h>
#include <stdlib.h>
#include <string.h>

char *GetMsecTime()
{
    static char buf[128];
    time_t lTime = 0;
    struct timeval stTimeVal = {0};
    struct tm stTime = {0};

    gettimeofday(&stTimeVal, NULL);
    lTime = stTimeVal.tv_sec;
    localtime_r(&lTime, &stTime);

    snprintf(buf, 128, "%.4d-%.2d-%.2d %.2d:%.2d:%.2d.%.3d",
             stTime.tm_year + 1900,
             stTime.tm_mon + 1,
             stTime.tm_mday,
             stTime.tm_hour,
             stTime.tm_min,
             stTime.tm_sec,
             stTimeVal.tv_usec / 1000); // 微秒 -> 毫秒
    return buf;
}
int main()
{
    puts(GetMsecTime());

    return 0;
}

注意，該函數所返回的 buf 是通過 static 修飾的，是執行緒不安全的

2.6 偵錯資訊中新增時間資訊

#define DEBUG(format, args...) \
            printf("%s [%s][%s:%d] "format"\n", \
                        		GetMsecTime(), \
                        		__FILE__, \
                        		__FUNCTION__, \
                        		__LINE__, \
                        		##args)

至此，我們已經將偵錯資訊的輸出格式完善了，接下來就要考慮怎麼將偵錯資訊輸出到紀錄檔檔案中了。

三、將偵錯資訊輸出到紀錄檔檔案中

3.1 紀錄檔等級

Log4J 定義了 8 個級別的 Log（除去 OFF 和 ALL，可以說分為 6 個級別），優先順序從高到低依次為：OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、 ALL。

OFF：最高等級的，用於關閉所有紀錄檔記錄
FATAL：指出每個嚴重的錯誤事件將會導致應用程式的退出。這個級別比較高了，重大錯誤，這種級別你可以直接停止程式了
ERROR：指出雖然發生錯誤事件，但仍然不影響系統的繼續執行。列印錯誤和異常資訊，如果不想輸出太多的紀錄檔，可以使用這個級別
WARN：表明會出現潛在錯誤的情形，有些資訊不是錯誤資訊，但是也要給程式設計師的一些提示
INFO：列印一些你感興趣的或者重要的資訊，這個可以用於生產環境中輸出程式執行的一些重要資訊，但是不能濫用，避免列印過多的紀錄檔
DEBUG：主要用於開發過程中列印一些執行資訊
TRACE： 很低的紀錄檔級別，一般不會使用
ALL： 最低等級的，用於開啟所有紀錄檔記錄

Log4J 建議只使用四個級別，優先順序從高到低分別是 ERROR、WARN、INFO、DEBUG。我們下面的程式也將圍繞這四個紀錄檔等級來進行編碼。

先貼上原始碼，後續有時間在詳細解釋~

3.2 原始碼

3.2.1 log.h

#ifndef __LOG_H__
#define __LOG_H__

#ifdef __cplusplus
extern "C"
{
#endif

// 紀錄檔路徑
#define LOG_PATH       "./Log/"
#define LOG_ERROR             "log.error"
#define LOG_WARN              "log.warn"
#define LOG_INFO              "log.info"
#define LOG_DEBUG             "log.debug"
#define LOG_OVERFLOW_SUFFIX             "00"    // 紀錄檔溢位後的檔案字尾，如 log.error00

#define LOG_FILE_SIZE  (5*1024*1024)            // 單個紀錄檔檔案的大小，5M

// 紀錄檔級別
typedef enum tagLogLevel
{
    LOG_LEVEL_ERROR    = 1,                             /* error級別 */
    LOG_LEVEL_WARN     = 2,                             /* warn級別  */
    LOG_LEVEL_INFO     = 3,                             /* info級別  */
    LOG_LEVEL_DEBUG    = 4,                             /* debug級別 */
} LOG_LEVEL_E;

typedef struct tagLogFile
{
    char szCurLog[64];
    char szPreLog[64];
} LOG_FILE_S;

#define PARSE_LOG_ERROR(format, args...)  \
    WriteLog(LOG_LEVEL_ERROR, __FILE__, __FUNCTION__, __LINE__, format, ##args)

#define PARSE_LOG_WARN(format, args...)  \
    WriteLog(LOG_LEVEL_WARN, __FILE__, __FUNCTION__, __LINE__, format, ##args)

#define PARSE_LOG_INFO(format, args...)  \
    WriteLog(LOG_LEVEL_INFO, __FILE__, __FUNCTION__, __LINE__, format, ##args)

#define PARSE_LOG_DEBUG(format, args...)  \
    WriteLog(LOG_LEVEL_DEBUG, __FILE__, __FUNCTION__, __LINE__, format, ##args)

extern void WriteLog
(
    LOG_LEVEL_E enLogLevel,
    const char *pcFileName,
    const char *pcFuncName,
    int iFileLine,
    const char *format, 
    ...
);

#ifdef __cplusplus
}
#endif

#endif

3.2.2 log.c

#include <stdio.h>
#include <string.h>
#include <stdlib.h>
#include <stdarg.h>     // va_stat 標頭檔案
#include <errno.h>      // errno 標頭檔案
#include <time.h>       // 時間結構體標頭檔案
#include <sys/time.h>   // 時間函數標頭檔案
#include <sys/stat.h>   // stat 標頭檔案
#include "log.h"

static LOG_FILE_S gstLogFile[5] = 
{
    {"", ""},
    {
        /* error級別 */
        LOG_PATH LOG_ERROR,                     // ./Log/log.error
        LOG_PATH LOG_ERROR LOG_OVERFLOW_SUFFIX  // ./Log/log.error00
    },
    {
        /* warn級別 */
        LOG_PATH LOG_WARN,                      // ./Log/log.warn
        LOG_PATH LOG_WARN LOG_OVERFLOW_SUFFIX   // ./Log/log.warn00
    }, 
    {
        /* info級別 */
        LOG_PATH LOG_INFO,                      // ./Log/log.info
        LOG_PATH LOG_INFO LOG_OVERFLOW_SUFFIX   // ./Log/log/info00
    }, 
    {
        /* debug級別 */
        LOG_PATH LOG_DEBUG,                     // ./Log/log.debug
        LOG_PATH LOG_DEBUG LOG_OVERFLOW_SUFFIX  // ./Log/log.debug00
    }, 
};

static void __Run_Log
(
    LOG_LEVEL_E enLogLevel,
    const char *pcFileName,
    const char *pcFuncName,
    int iFileLine,
    const char *format,
    va_list vargs
)
{
    FILE *logfile = NULL;
    logfile = fopen(gstLogFile[enLogLevel].szCurLog, "a");
    if (logfile == NULL)
    {
        printf("open %s error[%d](%s).\n", gstLogFile[enLogLevel].szCurLog, errno, strerror(errno));
        return;
    }

    /* 獲取時間資訊 */
    struct timeval stTimeVal = {0};
    struct tm stTime = {0};
    gettimeofday(&stTimeVal, NULL);
    localtime_r(&stTimeVal.tv_sec, &stTime);

    char buf[768];
    snprintf(buf, 768, "%.2d-%.2d %.2d:%.2d:%.2d.%.3lu [%s][%s:%d] ",
                                            stTime.tm_mon + 1,
                                            stTime.tm_mday,
                                            stTime.tm_hour,
                                            stTime.tm_min,
                                            stTime.tm_sec,
                                            (unsigned long)(stTimeVal.tv_usec / 1000),
                                            pcFileName,
                                            pcFuncName,
                                            iFileLine);

    fprintf(logfile, "%s", buf);
    vfprintf(logfile, format, vargs);
    fprintf(logfile, "%s", "\r\n");
    fflush(logfile);

    fclose(logfile);

    return;
}
static void __LogCoverStrategy(char *pcPreLog) // 紀錄檔滿後的覆蓋策略
{
    int iLen = strlen(pcPreLog);
    int iNum = (pcPreLog[iLen - 2] - '0') * 10 + (pcPreLog[iLen - 1] - '0');
    iNum = (iNum + 1) % 10;

    pcPreLog[iLen - 2] = iNum / 10 + '0';
    pcPreLog[iLen - 1] = iNum % 10 + '0';
}

void WriteLog
(
    LOG_LEVEL_E enLogLevel,
    const char *pcFileName,
    const char *pcFuncName,
    int iFileLine,
    const char *format, 
    ...
)
{
    char szCommand[64]; // system函數中的指令
    struct stat statbuff;
    if (stat(gstLogFile[enLogLevel].szCurLog, &statbuff) >= 0) // 如果存在
    {
        if (statbuff.st_size > LOG_FILE_SIZE) // 如果紀錄檔檔案超出限制
        {
            printf("LOGFILE(%s) > 5M, del it.\n", gstLogFile[enLogLevel].szCurLog);
            snprintf(szCommand, 64, "cp -f %s %s", gstLogFile[enLogLevel].szCurLog, gstLogFile[enLogLevel].szPreLog); 
            puts(szCommand);
            system(szCommand);      // 將當前超出限制的紀錄檔儲存到 log.error00 中

            snprintf(szCommand, 64, "rm -f %s", gstLogFile[enLogLevel].szCurLog);
            system(szCommand);      // 刪掉 log.error
            printf("%s\n\n", szCommand);
            
            // 如果 log.error 超出 5M 後，將依次儲存在 log.error00、log.error01、... 中
            __LogCoverStrategy(gstLogFile[enLogLevel].szPreLog); 
        }
    }
    else // 如果不存在，則建立
    {
        printf("LOGFILE(%s) is not found, create it.\n\n", gstLogFile[enLogLevel].szCurLog);
        snprintf(szCommand, 64, "touch %s", gstLogFile[enLogLevel].szCurLog);
        system(szCommand);
    }

    va_list argument_list;
    va_start(argument_list, format);

    if (format)
    {
        __Run_Log(enLogLevel, pcFileName, pcFuncName, iFileLine, format, argument_list);
    }

    va_end(argument_list);

    return;
}

3.3.3 main.c

#include <stdio.h>
#include <unistd.h> // sleep 標頭檔案
#include "log.h"

int main()
{
    for (int i = 0; i < 5; i++)
    {
        PARSE_LOG_ERROR("我是第 %d 條紀錄檔", i+1);
    }

    return 0;
}

3.3.4 Tutorial

將 log.h、log.c、main.c 置於同一個目錄中
並新建一個 Log 目錄
編譯、執行