记录一次排查log4cxx库按照日期回滚,不创建新目录的BUG

时间:2023-02-07 21:10:18

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