log4j Appender 因捕获异常而关闭

发布于 2024-09-28 12:29:23 字数 2074 浏览 0 评论 0原文

历史背景:这个问题最终完全不是我想象的那样。原因和解决方法如下,但原帖留作参考。

我正在开发一个简单的框架,用于定期轮询目录中的 .properties 文件,然后执行 SQL 查询并根据其配置发送电子邮件。由于每个 .properties 文件具有相同的操作范围,因此它们都由相同的 Task 类解释。但由于它们各自代表不同的逻辑操作,因此它们各自获得单独的日志文件。

这是通过共享 log4j RollingFileAppender 的一个实例并根据 .properties 文件中的值动态更改其输出文件来实现的。由于这是一个单线程应用程序,因此工作正常。

但是,我注意到在某些情况下,此 RollingFileAppender 将关闭,并且应用程序将毫无察觉地继续运行,只是现在不进行任何日志记录。由于控制台输出,我只成功捕获了一次此操作,因为通常此服务在 Linux 服务器上作为后台进程运行。发生的情况如下:

1) 主类 StartScheduler 每分钟创建一个新的 TaskPoller 实例。

2) TaskPoller 扫描目录,从每个 .properties 文件加载一些信息,并确定是否应该运行它。它还具有自己单独的 RollingFileAppender,可通过 Logger.getLogger(TaskPoller.class) 检索。如果应该运行一个任务,那么它会实例化一个任务对象,并传入要运行的特定 .properties 文件。

3) Task 获取其 RollingFileAppender,然后调用 fileAppender.setFile("newtaskname.log") 和 fileAppender.activateOptions() 来更改输出文件位置。然后,在执行过程中,会发生类似这样的事情:

[TaskPoller]
...
task = new Task(fileName); //Points RollingFileAppender to the right place
if (!task.Execute())
    logger.warn(fileName + " returned with an error code."); //Succeeds
[Task.Execute]
...
try {
    dbDAO.Connect();
} catch (Exception e) {
    logger.fatal{"Database connection error.", e}; //Different RFA; Fails
    return false;
}
[DBDAO.Connect throws SQLException, ClassNotFoundException]
...
try {
    Class.forName(dbDriver); //Dynamically loaded jdbc driver class name
    connection = DriverManager.getConnection(urlString, userName, password);
} catch (SQLException e) {
    if (connection != null)
        try { connection.close(); } catch (Exception e2) { ; }
    throw e;
}

发生的情况是,在 DBDAO.Connect() 期间,有时我会得到 com.mysql.jdbc.exceptions.jdbc4.CommunicationsException (或来自哪个 jdbc 类的其他意外异常)已加载)。这不会被 Connect() 捕获,但会被 Execute() 捕获。

不知何故,这个过程会导致 Task 的 RollingFileAppender 关闭。我能想到的唯一一件事是这种情况的特殊性,而不是其一致且稳定的正常操作,是抛出的异常没有被声明为由 Connect() 抛出。但我认为这不会导致 log4j Appender 关闭。

所以我的问题是,什么可能导致此附加程序在与其配置无关的方法中意外关闭?

- 编辑 - 看来我完全被误导了;问题出在 Quartz 和 log4j 之间的交互中,我用它让 TaskPoller 每分钟触发一次。我还不完全理解它的原因,但是[这个解决方案][1]似乎解决了这个问题。直到现在它才表现为一个观察到的问题,所以我认为这与最近发生的事情有关。

Historical Context: This problem ended up being not at all what I thought it was. The cause and solution are below, but the original posting is left for reference.

I'm developing a simple framework for periodically polling a directory for .properties files, then performing SQL queries and sending e-mails based on their configurations. Because each .properties file has the same spectrum of operations, they are all interpreted by the same Task class. But since they each represent different logical operations, they each get separate log files.

This is accomplished by sharing one instance of a log4j RollingFileAppender, and dynamically changing its output file based on a value in the .properties file. Since this is a single-threaded application, this works fine.

However, I've noticed that in certain situations, this RollingFileAppender will become closed, and the application will continue on obliviously except that now no logging takes place. I've only managed to catch this in action once, thanks to the console output, since usually this service is running as a background process on a Linux server. Here's what happened:

1) StartScheduler, the main class, creates a new instance of TaskPoller every minute.

2) TaskPoller scans the directory, loads a little information from each .properties file, and determines if it should be run. It also has its own separate RollingFileAppender, which it retrieves via Logger.getLogger(TaskPoller.class). If a Task should be run, then it instantiates a Task object, passing in the specific .properties file to be run.

3) Task gets its RollingFileAppender, then calls fileAppender.setFile("newtaskname.log") and fileAppender.activateOptions() to change the output file location. Then, during its execution, something like this happens:

[TaskPoller]
...
task = new Task(fileName); //Points RollingFileAppender to the right place
if (!task.Execute())
    logger.warn(fileName + " returned with an error code."); //Succeeds
[Task.Execute]
...
try {
    dbDAO.Connect();
} catch (Exception e) {
    logger.fatal{"Database connection error.", e}; //Different RFA; Fails
    return false;
}
[DBDAO.Connect throws SQLException, ClassNotFoundException]
...
try {
    Class.forName(dbDriver); //Dynamically loaded jdbc driver class name
    connection = DriverManager.getConnection(urlString, userName, password);
} catch (SQLException e) {
    if (connection != null)
        try { connection.close(); } catch (Exception e2) { ; }
    throw e;
}

What's happening is that during DBDAO.Connect(), sometimes I'll get a com.mysql.jdbc.exceptions.jdbc4.CommunicationsException (or some other unexpected exception from whichever jdbc class is loaded). This will not be caught by Connect(), but it will be caught by Execute().

Somehow, this process causes Task's RollingFileAppender to become closed. The only thing I can think of that's special to this situation, as opposed to its consistent and stable normal operation, is that the exception being thrown isn't declared as thrown by Connect(). But I don't think that should cause a log4j Appender to close.

So my question is, what could be causing this appender to unexpectedly close in methods that have nothing to do with its configuration?

--Edit--
It looks like I've been misdirected entirely; the problem is somewhere in the interactions between Quartz, which I was using to have TaskPoller fire every minute, and log4j. I don't entirely understand its cause yet, but [this solution][1] seems to solve this problem. It just didn't manifest itself as an observed problem until now, so I thought it had something to do with what was happening recently.

如果你对这篇内容有疑问,欢迎到本站社区发帖提问 参与讨论,获取更多帮助,或者扫码二维码加入 Web 技术交流群。

扫码二维码加入Web技术交流群

发布评论

需要 登录 才能够评论, 你可以免费 注册 一个本站的账号。

评论(1

水水月牙 2024-10-05 12:29:23

这个问题的真正原因是 Quartz 调度程序和我使用 log4j 的方式之间的交互。事实证明,如果您在 Quartz 工作线程上修改 log4j 的属性(我是通过调用 fileAppender.setFile(fileName) 和 fileAppender.activateOptions() 来完成的)(即使 Quartz 配置为一次只运行一个线程) ),事情就崩溃了。这是通过在使用工作线程之前在每个新实例上重新加载 log4j 属性来解决的,我是这样完成的:

[Task() Constructor]
Properties props = new Properties();
URL url = ClassLoader.getSystemResource("log4j.properties");
try {
    props.load(url.openStream());
    PropertyConfigurator.configure(props);
} catch (Exception e) {
    //The logger that never got renamed never stopped working.
    Logger.getLogger(TaskPoller.class).error("Diagnostics!");
}
logger = Logger.getLogger(Task.class);

The real cause of this problem is an interaction between the Quartz scheduler and the way I was using log4j. It turns out, if you modify log4j's properties (which I was doing by calling fileAppender.setFile(fileName) and fileAppender.activateOptions()) on a Quartz worker thread (even if Quartz is configured to only have a single thread running at a time), things break down. This is fixed by reloading the log4j properties on each new instance of the worker thread before using it, which I accomplished like so:

[Task() Constructor]
Properties props = new Properties();
URL url = ClassLoader.getSystemResource("log4j.properties");
try {
    props.load(url.openStream());
    PropertyConfigurator.configure(props);
} catch (Exception e) {
    //The logger that never got renamed never stopped working.
    Logger.getLogger(TaskPoller.class).error("Diagnostics!");
}
logger = Logger.getLogger(Task.class);
~没有更多了~
我们使用 Cookies 和其他技术来定制您的体验包括您的登录状态等。通过阅读我们的 隐私政策 了解更多相关信息。 单击 接受 或继续使用网站,即表示您同意使用 Cookies 和您的相关数据。
原文