記錄一次排查log4cxx庫按照日期回滾,不建立新目錄的BUG

2023-02-08 06:01:27

1、背景

C++ 專案,使用了 log4cxx 紀錄檔庫,版本為:0.10.0

專案中需要按照日期備份紀錄檔,即一天一個紀錄檔目錄,目錄下是紀錄檔檔案,即目錄層級為:.../log/2022-10-02/log.log,當日期變更後,目錄變化:.../log/2022-10-03/log.log

使用的 log4cxx 的組態檔如下:

log4j.rootLogger=INFO,R
# Pattern to output the caller's file name and line number.
log4j.appender.R=org.apache.log4j.DailyRollingFileAppender
log4j.appender.R.ImmediateFlush=true
log4j.appender.R.Append=true
log4j.appender.R.DatePattern='${LOG_HOMR_DIR}/'yyyy-MM-dd'/log.log'
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d{yyyy-MM-dd hh:mm:ss.SSS} %-5p [%c] %m %n

網路上和官方的教學中,DatePattern 都是作為紀錄檔備份的策略,當日期變化時,使用 DatePattern 的規則追加到舊紀錄檔的檔案字尾上,完成紀錄檔按照日期回滾,但是這和我們的需求不符合

經查詢,DatePattern 中的 ' 包含的不會被程式碼解析,利用此特性,寫成上面的格式,可以實現按照日期建立目錄

問題來了,剛開始程式啟動一切正常,但是當日期變化時,新的日期目錄並沒有如期建立,紀錄檔內容還是記錄在程式啟動時建立的紀錄檔檔案中

2、排查步驟

2.1、錯誤程式碼定位

剛開始以為是組態檔寫錯了,在網路上查詢並嘗試了一天,毫無收穫,開始懷疑是不是log4cxx的原始碼有問題,遂下載原始碼檢視

下載編譯使用過程略過

偵錯發現,當日期變化時,終端列印了一行錯誤資訊:

log4cxx: Exception during rollover

從原始碼中搜尋,所幸該錯誤資訊列印只有兩處,且出現在一個函數中,檔案:rollingfileappender.cpp,函數:rolloverrollover 方法用在紀錄檔的回滾處,比如這裡是 DailyRollingFileAppender,所以當日期變動時,會觸發紀錄檔回滾,該方法被呼叫

但是這裡面有兩處一模一樣的列印,因為無法單步偵錯,這裡通過修改紀錄檔,發現錯誤列印是在函數最後,但是這裡只列印了異常,沒有任何錯誤資訊,所以我們稍微修改一下程式碼,列印一下錯誤資訊:

try{
    ...
}catch (std::exception& ex) {
	LogLog::warn(LOG4CXX_STR("Exception during rollover"));
    //新增下面一行程式碼
    LogLog::warn(LOG4CXX_STR("Exception during rollover, " + std::string(ex.what())));
}

列印出來的錯誤資訊如下:

Exception during rollover, status code=2

沒有太多的資訊,只有一個錯誤碼,嘗試在網路上搜尋了一下,沒有太大的收貨

只用使用死方法,加大量的紀錄檔,最終找到了錯誤的那一行程式碼:

OutputStreamPtr os(new FileOutputStream(rollover1->getActiveFileName(), rollover1->getAppend()));

這裡是建立了一個檔案輸出流,用於紀錄檔檔案的輸出

rollover1->getActiveFileName() 返回紀錄檔檔案的絕對路徑

rollover1->getAppend() 返回一個bool變數,表示紀錄檔內容是否追加,值由組態檔中的 log4j.appender.R.Append=true 決定

2.2、問題猜測

注意,到這裡涉及到了檔案流,那麼結合之前偵錯現象,程式剛啟動的時候會建立目錄(甚至時多級目錄)和檔案,但是日期變化時沒有新目錄建立

猜測,會不會是日期變動的時候,log4cxx 在使用檔案流的時候,沒有找到對應目錄導致的錯誤

針對該猜想,我們手動建立日期目錄,再次偵錯,發現,按照日期備份紀錄檔的功能OK了,說明我們的猜測是正確的,那麼就是 log4cxx 的程式碼問題了,後面定位錯誤就方便了

2.3、錯誤程式碼分析

我們繼續檢視 FileOutputStream 的程式碼,如下:

FileOutputStream::FileOutputStream(const LogString& filename,bool append) : pool(), fileptr(open(filename, append, pool)) {}

我們發現,這裡就是個建構函式,唯一有邏輯的就是 open 方法的呼叫,那就檢視一下:

apr_file_t* FileOutputStream::open(const LogString& filename,
    bool append, Pool& pool) {
    apr_fileperms_t perm = APR_OS_DEFAULT;
    apr_int32_t flags = APR_WRITE | APR_CREATE;
    if (append) {
        flags |= APR_APPEND;
    } else {
        flags |= APR_TRUNCATE;
    }
    File fn;
    fn.setPath(filename);
    apr_file_t* fileptr = 0;
    apr_status_t stat = fn.open(&fileptr, flags, perm, pool);
    if (stat != APR_SUCCESS) {
      throw IOException(stat);
    }
    return fileptr;
}

這裡發現一個 throw IOException(stat);,應該就是前面列印錯誤資訊的那個,所以這裡的 stat 應該是2,這裡先記錄下,後面會用到

那麼錯誤程式碼應該就是這一行了:

apr_status_t stat = fn.open(&fileptr, flags, perm, pool);

再進入看程式碼:

log4cxx_status_t File::open(apr_file_t** file, int flags,
      int perm, Pool& p) const {
    return apr_file_open(file, getPath(p), flags, perm, p.getAPRPool());
}

詳細閱讀程式碼,可以發現,這裡使用了 apr 庫進行檔案讀寫

上網查詢了一圈 apr 的資料,加上自己測試程式碼:

#include <cstdio>
#include <iostream>
#include <string>
#include <apr-1.0/apr_file_io.h>
#include <apr-1.0/apr_file_info.h>
using namespace std;
void printError(apr_status_t rv)
{
    char errbuf[256];
    apr_strerror(rv, errbuf, sizeof(errbuf));
    cout << errbuf << endl;
}

string FILENAME = "../log/test.log";//紀錄檔路徑

int main()
{
    apr_pool_t *p;
    apr_initialize();
    apr_pool_create(&p, NULL);
    apr_file_t *filetest = NULL;
    filetest = NULL;
    try
    {
        printError(stat);
        stat = apr_file_open(&filetest, FILENAME.c_str(),
                                          APR_WRITE | APR_CREATE | APR_APPEND,
                                          APR_UREAD | APR_UWRITE | APR_GREAD, p);
        cout << stat << endl;
        printError(stat);//目錄不存在時,這裡列印2
        apr_size_t byte = 3;
        apr_file_write(filetest, "aaa", &byte);
        apr_file_close(filetest);
    }
    catch (std::exception &e)
    {
        cout << e.what() << endl;
    }

    apr_pool_destroy(p);
    return 0;
}

簡單的測試發現,如果檔案路徑存在,則正常,如果不存在則異常,且異常時,state的值為2

這裡就和上面的偵錯(staus code=2)呼應上了,那麼這裡的2就是apr庫的一個錯誤碼,表示目錄不存在

到此,問題原因基本定位到了

2.4、錯誤原因

綜上,定位到了錯誤程式碼,找到了錯誤原因

log4cxx 使用 apr 庫進行檔案的讀寫操作,但是在紀錄檔回滾的時候,沒有考慮到目錄不存在的情況,導致呼叫 apr_file_open 方法失敗,返回值2,並通過 std::exception 丟擲來

3、解決方法

既然找到了錯誤原因,那麼就好解決了,既然是目錄不存在,我們在開啟檔案之前建立目錄不就行了

可以建立目錄的地方有幾處:

  1. rollingfileappender.cpp 的建立檔案流的地方;
  2. fileoutputstream.cpp 的建構函式中;
  3. file.cpp 的 open 方法中;
  4. fileoutputstream.cpp 的 open 方法中;

我們知道 rollingfileappender.cpp 檔案是檔案回滾的 appender,不應該有太多的實際操作,加在這裡不合適;

細看 file.cpp,我們發現,這就是一個對 apr 檔案操作的封裝,給外層提供操作檔案的簡單介面,這裡應該正常丟擲錯誤,如果有些地方就需要目錄不存在報錯呢?所以加在這裡也不合適

那麼應該加在 fileoutputstream.cpp 中,且類名也是檔案輸出流,它也需要保證檔案輸出正確,那在這裡加目錄的建立是對的,且加在 open 方法中最合理,且應該呼叫 file.cpp 中的方法才不會破壞程式碼的結構,我們發現 log4cxx::Filemkdir 方法的定義,那正好,省的我們自己封轉,還需要去熟悉 apr

修改 fileoutputstream.cpp 檔案的 open()

需要新增的程式碼如下:

File pathFn(filename.substr(0, filename.find_last_of("/")));//linux的路徑,windows需要使用\\
pathFn.mkdirs(pool);

open() 的整體程式碼如下:

apr_file_t* FileOutputStream::open(const LogString& filename,
    bool append, Pool& pool) {
    //下面兩行程式碼是新增的
    File pathFn(filename.substr(0, filename.find_last_of("/")));
    pathFn.mkdirs(pool);
    
    apr_fileperms_t perm = APR_OS_DEFAULT;
    apr_int32_t flags = APR_WRITE | APR_CREATE;
    if (append) {
        flags |= APR_APPEND;
    } else {
        flags |= APR_TRUNCATE;
    }
    File fn;
    fn.setPath(filename);
    apr_file_t* fileptr = 0;
    apr_status_t stat = fn.open(&fileptr, flags, perm, pool);
    if (stat != APR_SUCCESS) {
      throw IOException(stat);
    }
    return fileptr;
}

編譯,測試,一切OK