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

sherlock_lin發表於2023-02-07

目錄

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，函式：rollover，rollover 方法用在日誌的回滾處，比如這裡是 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::File 有 mkdir 方法的定義，那正好，省的我們自己封轉，還需要去熟悉 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

相關文章