在记录活动中使用 readConfiguration 方法

Question

为了在小型 Java 桌面应用程序中使用日志记录，我试图深入了解一些方法的操作。我使用一个非常愚蠢的小型 Java 程序来测试它们。

特别是在测试 LogManager.readConfiguration() 方法的行为时，我发现了一些奇怪的东西。在所有测试中，LogManager 从位于 JRE 目录的 lib/logging.properties 中的属性文件中读取其配置。此时这个文件的内容如下：

handlers=java.util.logging.ConsoleHandler
myapp2.handlers=java.util.logging.ConsoleHandler
myapp2.MyApp2.handlers=java.util.logging.ConsoleHandler
.level=OFF
java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=%4$s: %5$s [%1$tc]%n
myapp2.level=WARNING
myapp2.MyApp2.level=INFO

java程序的代码是：

package myapp2;

import java.io.IOException;
import java.util.logging.LogManager;
import java.util.logging.Logger;

public class MyApp2 {

    private static final Logger LOGGER = Logger.getLogger(MyApp2.class.getPackage().getName());
    private static final Logger LOGGER1 = Logger.getLogger(MyApp2.class.getName());

    /**
     * @param args the command line arguments
     */
    public static void main(String[] args) {
        LOGGER.severe("severe at MyApp2");
        LOGGER.warning("warning at MyApp2");
        LOGGER.info("info at MyApp2");
        LOGGER1.severe("severe1 at MyApp2");
        LOGGER1.warning("warning1 at MyApp2");
        LOGGER1.info("info1 at MyApp2");
        LOGGER1.setLevel(null);
        LOGGER1.setUseParentHandlers(false);
        LOGGER1.severe("severe2 at MyApp2");
        LOGGER1.warning("warning2 at MyApp2");
        LOGGER1.info("info2 at MyApp2");
        try {
            LogManager.getLogManager().readConfiguration();
        } catch (IOException ex) {
            System.out.println("I/O Exception found");
        } catch (SecurityException ex) {
            System.out.println("Error SecurityException found");
        }
        LOGGER.severe("severe3 at MyApp2"); 
        LOGGER1.severe("severe4 at MyApp2");
    }
}

如果我们在没有围绕 readConfiguration() 的 try-catch 的情况下执行它，则按预期工作，输出如下：

SEVERE: severe at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe at MyApp2 [dc. maig 08 14:45:38 CEST 2013] 
WARNING: warning at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning at MyApp2 [dc. maig 08 14:45:38 CEST 2013] 
SEVERE: severe1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe2 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning2 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe3 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe3 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe4 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]

但是，如果我们用 try-catch 执行，输出是：

SEVERE: severe at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe2 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning2 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe3 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]

读取 readConfiguration() 方法的 API 应该重新初始化日志记录属性并从之前命名的文件中重新读取日志记录配置。如果是这样，为什么severe3只显示一次（我希望显示两次，因为程序中存在两个LOGGER和转发行为）而severe4丢失了（我希望显示一次）？谁能帮我理解这个？

Answer 1

在 JDK 9 中，JDK-8033661: readConfiguration does not cleanly reinitialize the logging system 已被标记为已解决。 LogManager.readConfiguration 已被重新指定为仅在 LogManager 初始化期间设置记录器。

要在初始化后更新记录器，应该使用LogManager.updateConfiguration(java.util.function.Function) 方法。可以在HandlersOnComplexResetUpdate.java 测试中找到一个示例重映射函数：

static void updateConfigurationWith(Properties propertyFile, boolean append) {
    try {
        ByteArrayOutputStream bytes = new ByteArrayOutputStream();
        propertyFile.store(bytes, propertyFile.getProperty("test.name"));
        ByteArrayInputStream bais = new ByteArrayInputStream(bytes.toByteArray());
        Function<String, BiFunction<String,String,String>> remapper =
            append ? (x) -> ((o, n) -> n == null ? o : n)
                   : (x) -> ((o, n) -> n);
        LogManager.getLogManager().updateConfiguration(bais, remapper);
     } catch (IOException ex) {
         throw new RuntimeException(ex);
     }
}

Answer 2

据我所见，readConfiguration 方法只有一个缺陷，这是我通过 JDK 代码调试发现的，因为我也错过了日志消息。它们不加载每个记录器的处理程序。如果您不使用每个记录器处理程序，readConfiguration 方法应该可以正常工作。 readConfiguration 首先重置所有记录器，删除处理程序等，然后忘记检查每个记录器处理程序。 因此，您会错过日志消息。您最初有三个处理程序，根处理程序、包上的处理程序和类上的处理程序。然后你关闭了你班级上的 useParentHandlers 并调用了readConfiguration。现在 - 因为 useParentHandlers 没有重置，可能它应该 - 并且您的每个记录器处理程序不再设置，severe3 只通过根处理程序记录一次，而严重 4 根本没有记录，因为 useParentHandlers 是假的，所以没有回退到根处理程序已完成。

Dieter 描述的“更多错误”是顺便说一句。完全相同的问题。

如果您更喜欢使用日志记录配置文件，也可以轻松解决该错误。只需在调用 readConfiguration 并为每个记录器调用 LogManager.loadLoggerHandlers 后遍历已经存在的记录器。在 Groovy 中，这将是

def logManager = LogManager.logManager
logManager.loggerNames.each {
    logManager.loadLoggerHandlers logManager.getLogger(it), it, "${it}.handlers"
}

我对此进行了测试，它可以工作。 对于 Java，您必须使用反射，因为它是一种私有方法。应该是这样的

LogManager logManager = LogManager.getLogManager();
Method loadLoggerHandlers = LogManager.class.getDeclaredMethod("loadLoggerHandlers", Logger.class, String.class, String.class);
loadLoggerHandlers.setAccessible(true);
for (String loggerName : logManager.getLoggerNames()) {
    loadLoggerHandlers.invoke(logManager, logManager.getLogger(loggerName), loggerName, loggerName + ".handlers");
}

Answer 3

我在使用 readConfiguration 方法时遇到了更多错误。它不符合您的期望。我创建了一个小型单元测试来说明这一点：

package com.demo;

import java.io.IOException;
import java.io.InputStream;
import java.util.logging.LogManager;
import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * @author dhubau
 */
public class LogTest {

    private static final Logger logger = LoggerFactory.getLogger(LogTest.class.getCanonicalName());

    @Test
    public void testLogs() throws IOException {
        logger.trace("BEFORE");
        logger.debug("BEFORE");
        logger.info("BEFORE");
        logger.warn("BEFORE");
        logger.error("BEFORE");

        InputStream is = LogTest.class.getResourceAsStream("/logging.properties");

        LogManager.getLogManager().readConfiguration(is);

        logger.trace("AFTER");
        logger.debug("AFTER");
        logger.info("AFTER");
        logger.warn("AFTER");
        logger.error("AFTER");
    }
}

开始单元测试时，会读取默认的 logging.properties（默认所有内容为 INFO 日志记录）。我记录每个级别一次，然后读入我自己的 logging.properties 文件：

# Specify the handlers to create in the root logger
handlers = java.util.logging.ConsoleHandler

# Set the default logging level for the root logger
.level = INFO

# Do not use the root handlers
com.demo.useParentHandlers = false

# DEMO log handlers
com.demo.handlers = java.util.logging.ConsoleHandler

# DEMO log level
com.demo.level = ALL

# Set the default logging level for new ConsoleHandler instances
java.util.logging.ConsoleHandler.level = ALL

之后我得到以下输出：

May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
INFO: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
WARNING: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
SEVERE: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
INFO: AFTER
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
WARNING: AFTER
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
SEVERE: AFTER

所以你看，com.demo 包没有记录 TRACE 或 DEBUG 级别。当我将以下参数传递给单元测试时：

java.util.logging.config.file = C:\TEMP\logging.properties

它给了我以下输出：

May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
FINEST: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
FINE: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
INFO: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
WARNING: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
SEVERE: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
INFO: AFTER
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
WARNING: AFTER
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
SEVERE: AFTER