search

apache / logging-log4j2

Apache Log4j 2 is a versatile, feature-rich, efficient logging API and backend for Java.
https://logging.apache.org/log4j/2.x/
Apache License 2.0
3.35k stars 1.59k forks source link

When bump from 2.23.0 to 2.23.1, the `status` of the `.properties` configuration file no longer works #2794

Closed linghengqian closed 1 month ago

linghengqian commented 1 month ago

Description

[A clear and concise description of what the bug is.]

Configuration

Version: [Log4j version] 2.23.1

Operating system: [OS and version] Ubuntu WSL 22.04.4

JDK: [JDK distribution and version] 8.0.422-tem on SDKMAN!

Logs

String getTestOutput(String s) throws Exception {
    StringBuilder sb = new StringBuilder();
    BufferedReader reader = new BufferedReader(new StringReader(s));
    String line = null;
    while ((line = reader.readLine()) != null) {
      if (!line.startsWith("log4j:")
              && !line.contains("INFO Log4j")
              && !line.startsWith("SLF4J")
              && !line.contains(" StatusLogger ")
              && !line.contains("Configuration file: ")
              && !line.contains("Parser tree: ")) {
        sb.append(line);
        sb.append("\n");
      }
    }
    return sb.toString();
}
Error Log ```shell ------------------------------------------------------------------------------- Test set: org.apache.hive.hplsql.TestHplsqlLocal ------------------------------------------------------------------------------- Tests run: 86, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 3.069 s <<< FAILURE! - in org.apache.hive.hplsql.TestHplsqlLocal org.apache.hive.hplsql.TestHplsqlLocal.testException Time elapsed: 0.667 s <<< FAILURE! org.junit.ComparisonFailure: expected:<[]Ln:2 PRINT Correct L...> but was:<[2024-08-03T02:11:24.570Z main DEBUG Using ShutdownCallbackRegistry class org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry 2024-08-03T02:11:24.572Z main TRACE Log4jLoggerFactory.getContext() found anchor class org.apache.hive.hplsql.Exec 2024-08-03T02:11:24.638Z main DEBUG Took 0.058799 seconds to load 265 plugins from sun.misc.Launcher$AppClassLoader@3d4eac69 2024-08-03T02:11:24.638Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.661Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.664Z main DEBUG PluginManager 'Converter' found 48 plugins 2024-08-03T02:11:24.679Z main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false-1 2024-08-03T02:11:24.679Z main DEBUG Starting LoggerContext[name=3d4eac69, org.apache.logging.log4j.core.LoggerContext@5a7fe64f]... 2024-08-03T02:11:24.680Z main DEBUG Reconfiguration started for context[name=3d4eac69] at URI null (org.apache.logging.log4j.core.LoggerContext@5a7fe64f) with optional ClassLoader: null 2024-08-03T02:11:24.681Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.681Z main DEBUG PluginManager 'ConfigurationFactory' found 6 plugins 2024-08-03T02:11:24.682Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.682Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.725Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.725Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.726Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.726Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.727Z main DEBUG Using configurationFactory org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@4b5189ac 2024-08-03T02:11:24.735Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.737Z main DEBUG Apache Log4j Core 2.23 initializing configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@31920ade 2024-08-03T02:11:24.737Z main DEBUG PluginManager 'Core' found 140 plugins 2024-08-03T02:11:24.737Z main DEBUG PluginManager 'Level' found 0 plugins 2024-08-03T02:11:24.739Z main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2024-08-03T02:11:24.745Z main TRACE TypeConverterRegistry initializing. 2024-08-03T02:11:24.745Z main DEBUG PluginManager 'TypeConverter' found 26 plugins 2024-08-03T02:11:24.748Z main DEBUG createProperty(name="hive.log.file", value="hive.log", Configuration(HiveLog4j2Test)) 2024-08-03T02:11:24.748Z main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2024-08-03T02:11:24.749Z main DEBUG createProperty(name="hive.log.dir", value="${sys:test.tmp.dir}/log", Configuration(HiveLog4j2Test)) 2024-08-03T02:11:24.750Z main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2024-08-03T02:11:24.750Z main DEBUG createProperty(name="hive.root.logger", value="DRFA", Configuration(HiveLog4j2Test)) 2024-08-03T02:11:24.750Z main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2024-08-03T02:11:24.750Z main DEBUG createProperty(name="hive.log.level", value="DEBUG", Configuration(HiveLog4j2Test)) 2024-08-03T02:11:24.750Z main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2024-08-03T02:11:24.751Z main DEBUG createProperty(name="hive.test.console.log.level", value="INFO", Configuration(HiveLog4j2Test)) 2024-08-03T02:11:24.751Z main DEBUG Building Plugin[name=properties, class=org.apache.logging.log4j.core.config.PropertiesPlugin]. 2024-08-03T02:11:24.752Z main DEBUG configureSubstitutor(={hive.log.file=hive.log, hive.log.dir=/home/linghengqian/TwinklingLiftWorks/git/public/hive/hplsql/target/tmp/log, hive.root.logger=DRFA, hive.log.level=DEBUG, hive.test.console.log.level=INFO}, Configuration(HiveLog4j2Test)) 2024-08-03T02:11:24.753Z main DEBUG PluginManager 'Lookup' found 17 plugins 2024-08-03T02:11:24.753Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.757Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.hadoop.hive.ql.exec.Operator", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.758Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.758Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="com.amazonaws", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.758Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.758Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="BlockStateChange", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.758Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.759Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.zookeeper.server.NIOServerCnxn", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.759Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.759Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.tez", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.759Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.760Z main DEBUG LoggerConfig$Builder(additivity="null", level="DEBUG", levelAndRefs="null", name="org.apache.hadoop.hive.ql.optimizer.SharedWorkOptimizer", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.760Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.760Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.hadoop.hdfs", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.760Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.760Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.http", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.760Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.760Z main DEBUG LoggerConfig$Builder(additivity="null", level="ERROR", levelAndRefs="null", name="JPOX", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.760Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.760Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.hadoop.yarn", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.761Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.761Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.zookeeper.server.ServerCnxn", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.761Z main DEBUG Building Plugin[name=filter, class=org.apache.logging.log4j.core.filter.MarkerFilter]. 2024-08-03T02:11:24.762Z main DEBUG createFilter(marker="FULL_PLAN", onMatch="DENY", onMismatch="NEUTRAL") 2024-08-03T02:11:24.762Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.763Z main DEBUG LoggerConfig$Builder(additivity="null", level="OFF", levelAndRefs="null", name="org.apache.hadoop.hive.ql.optimizer.calcite.RuleEventLogger", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), MarkerFilter(FULL_PLAN)) 2024-08-03T02:11:24.763Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.763Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.hadoop.yarn.server", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.763Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.763Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.calcite.plan.RelOptPlanner", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.763Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.764Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.zookeeper.ClientCnxnSocket", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.764Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.764Z main DEBUG LoggerConfig$Builder(additivity="null", level="ERROR", levelAndRefs="null", name="org.apache.hadoop.conf.Configuration", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.764Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.764Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.thrift", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.764Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.764Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.hadoop.hive.metastore.ObjectStore", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.765Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.765Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.hadoop.hdfs.server", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.765Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.765Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.hadoop.metrics2", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.765Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.765Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.hadoop.hive.serde2.lazy", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.766Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.766Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.zookeeper.ClientCnxn", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.766Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.766Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.hadoop.security", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.766Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.766Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.hadoop.ipc", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.766Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.767Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.apache.zookeeper.ClientCnxnSocketNIO", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.767Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.767Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.mortbay", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.767Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.767Z main DEBUG LoggerConfig$Builder(additivity="null", level="ERROR", levelAndRefs="null", name="DataNucleus", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.767Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.767Z main DEBUG LoggerConfig$Builder(additivity="null", level="ERROR", levelAndRefs="null", name="Datastore", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.767Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.767Z main DEBUG LoggerConfig$Builder(additivity="null", level="INFO", levelAndRefs="null", name="org.apache.zookeeper", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.767Z main DEBUG Building Plugin[name=logger, class=org.apache.logging.log4j.core.config.LoggerConfig]. 2024-08-03T02:11:24.768Z main DEBUG LoggerConfig$Builder(additivity="null", level="WARN", levelAndRefs="null", name="org.eclipse.jetty", includeLocation="null", ={}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.768Z main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef]. 2024-08-03T02:11:24.768Z main DEBUG createAppenderRef(ref="console", level="INFO", Filter=null) 2024-08-03T02:11:24.769Z main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef]. 2024-08-03T02:11:24.769Z main DEBUG createAppenderRef(ref="DRFA", level="null", Filter=null) 2024-08-03T02:11:24.769Z main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger]. 2024-08-03T02:11:24.770Z main DEBUG LoggerConfig$RootLogger$Builder(additivity="null", level="DEBUG", levelAndRefs="null", includeLocation="null", ={console, DRFA}, ={}, Configuration(HiveLog4j2Test), Filter=null) 2024-08-03T02:11:24.770Z main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin]. 2024-08-03T02:11:24.770Z main DEBUG createLoggers(={org.apache.hadoop.hive.ql.exec.Operator, com.amazonaws, BlockStateChange, org.apache.zookeeper.server.NIOServerCnxn, org.apache.tez, org.apache.hadoop.hive.ql.optimizer.SharedWorkOptimizer, org.apache.hadoop.hdfs, org.apache.http, JPOX, org.apache.hadoop.yarn, org.apache.zookeeper.server.ServerCnxn, org.apache.hadoop.hive.ql.optimizer.calcite.RuleEventLogger, org.apache.hadoop.yarn.server, org.apache.calcite.plan.RelOptPlanner, org.apache.zookeeper.ClientCnxnSocket, org.apache.hadoop.conf.Configuration, org.apache.thrift, org.apache.hadoop.hive.metastore.ObjectStore, org.apache.hadoop.hdfs.server, org.apache.hadoop.metrics2, org.apache.hadoop.hive.serde2.lazy, org.apache.zookeeper.ClientCnxn, org.apache.hadoop.security, org.apache.hadoop.ipc, org.apache.zookeeper.ClientCnxnSocketNIO, org.mortbay, DataNucleus, Datastore, org.apache.zookeeper, org.eclipse.jetty, root}) 2024-08-03T02:11:24.770Z main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2024-08-03T02:11:24.771Z main DEBUG PatternLayout$Builder(pattern="%d{ISO8601} %5p [%t] %c{2}: %m%n", PatternSelector=null, Configuration(HiveLog4j2Test), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null") 2024-08-03T02:11:24.771Z main DEBUG PluginManager 'Converter' found 48 plugins 2024-08-03T02:11:24.779Z main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender]. 2024-08-03T02:11:24.780Z main DEBUG ConsoleAppender$Builder(target="SYSTEM_ERR", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{ISO8601} %5p [%t] %c{2}: %m%n), name="console", Configuration(HiveLog4j2Test), Filter=null, ={}) 2024-08-03T02:11:24.782Z main DEBUG Starting OutputStreamManager SYSTEM_ERR.false.false 2024-08-03T02:11:24.782Z main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2024-08-03T02:11:24.784Z main DEBUG PatternLayout$Builder(pattern="%d{ISO8601} %5p [%t] %c{2}: %m%n", PatternSelector=null, Configuration(HiveLog4j2Test), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null") 2024-08-03T02:11:24.785Z main DEBUG Building Plugin[name=TimeBasedTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy]. 2024-08-03T02:11:24.786Z main DEBUG TimeBasedTriggeringPolicy$Builder(interval="1", modulate="true", maxRandomDelay="null") 2024-08-03T02:11:24.786Z main DEBUG Building Plugin[name=Policies, class=org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy]. 2024-08-03T02:11:24.787Z main DEBUG createPolicy(={TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1, modulate=true)}) 2024-08-03T02:11:24.787Z main DEBUG Building Plugin[name=DefaultRolloverStrategy, class=org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy]. 2024-08-03T02:11:24.788Z main DEBUG DefaultRolloverStrategy$Builder(max="30", min="null", fileIndex="null", compressionLevel="null", ={}, stopCustomActionsOnError="null", tempCompressedFilePattern="null", Configuration(HiveLog4j2Test)) 2024-08-03T02:11:24.788Z main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender]. 2024-08-03T02:11:24.790Z main DEBUG RollingRandomAccessFileAppender$Builder(fileName="/home/linghengqian/TwinklingLiftWorks/git/public/hive/hplsql/target/tmp/log/hive.log", filePattern="/home/linghengqian/TwinklingLiftWorks/git/public/hive/hplsql/target/tmp/log/hive.log.%d{yyyy-MM-dd}", append="null", Policies(CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1, modulate=true)])), DefaultRolloverStrategy(DefaultRolloverStrategy(min=1, max=30, useMax=true)), advertise="null", advertiseURI="null", filePermissions="null", fileOwner="null", fileGroup="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{ISO8601} %5p [%t] %c{2}: %m%n), name="DRFA", Configuration(HiveLog4j2Test), Filter=null, ={}) 2024-08-03T02:11:24.793Z main TRACE RandomAccessFile /home/linghengqian/TwinklingLiftWorks/git/public/hive/hplsql/target/tmp/log/hive.log seek to 0 2024-08-03T02:11:24.793Z main DEBUG Starting RollingRandomAccessFileManager /home/linghengqian/TwinklingLiftWorks/git/public/hive/hplsql/target/tmp/log/hive.log 2024-08-03T02:11:24.794Z main DEBUG PluginManager 'FileConverter' found 3 plugins 2024-08-03T02:11:24.797Z main DEBUG Setting prev file time to 2024-08-02T19:11:24.791-0700 2024-08-03T02:11:24.797Z main DEBUG Initializing triggering policy CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1, modulate=true)]) 2024-08-03T02:11:24.797Z main DEBUG Initializing triggering policy TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1, modulate=true) 2024-08-03T02:11:24.798Z main TRACE PatternProcessor.getNextTime returning 2024/08/03-00:00:00.000, nextFileTime=2024/08/02-00:00:00.000, prevFileTime=1969/12/31-16:00:00.000, current=2024/08/02-19:11:24.798, freq=DAILY 2024-08-03T02:11:24.798Z main TRACE PatternProcessor.getNextTime returning 2024/08/03-00:00:00.000, nextFileTime=2024/08/02-00:00:00.000, prevFileTime=2024/08/02-00:00:00.000, current=2024/08/02-19:11:24.798, freq=DAILY 2024-08-03T02:11:24.798Z main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin]. 2024-08-03T02:11:24.798Z main DEBUG createAppenders(={console, DRFA}) 2024-08-03T02:11:24.799Z main DEBUG Configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@31920ade initialized 2024-08-03T02:11:24.799Z main DEBUG Starting configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@31920ade 2024-08-03T02:11:24.799Z main DEBUG Started configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@31920ade OK. 2024-08-03T02:11:24.799Z main TRACE Stopping org.apache.logging.log4j.core.config.DefaultConfiguration@4201c465... 2024-08-03T02:11:24.799Z main TRACE DefaultConfiguration notified 1 ReliabilityStrategies that config will be stopped. 2024-08-03T02:11:24.799Z main TRACE DefaultConfiguration stopping root LoggerConfig. 2024-08-03T02:11:24.799Z main TRACE DefaultConfiguration notifying ReliabilityStrategies that appenders will be stopped. 2024-08-03T02:11:24.800Z main TRACE DefaultConfiguration stopping remaining Appenders. 2024-08-03T02:11:24.800Z main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1 2024-08-03T02:11:24.800Z main DEBUG OutputStream closed 2024-08-03T02:11:24.800Z main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true 2024-08-03T02:11:24.800Z main DEBUG Appender DefaultConsole-1 stopped with status true 2024-08-03T02:11:24.800Z main TRACE DefaultConfiguration stopped 1 remaining Appenders. 2024-08-03T02:11:24.800Z main TRACE DefaultConfiguration cleaning Appenders from 1 LoggerConfigs. 2024-08-03T02:11:24.800Z main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@4201c465 OK 2024-08-03T02:11:24.846Z main TRACE Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@d62fe5b 2024-08-03T02:11:24.846Z main TRACE Reregistering context (1/1): '3d4eac69' org.apache.logging.log4j.core.LoggerContext@5a7fe64f 2024-08-03T02:11:24.846Z main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=3d4eac69' 2024-08-03T02:11:24.846Z main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=3d4eac69,component=StatusLogger' 2024-08-03T02:11:24.846Z main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=3d4eac69,component=ContextSelector' 2024-08-03T02:11:24.847Z main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=*' 2024-08-03T02:11:24.847Z main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=3d4eac69,component=Appenders,name=*' 2024-08-03T02:11:24.847Z main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=3d4eac69,component=AsyncAppenders,name=*' 2024-08-03T02:11:24.847Z main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=3d4eac69,component=AsyncLoggerRingBuffer' 2024-08-03T02:11:24.847Z main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=*,subtype=RingBuffer' 2024-08-03T02:11:24.849Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69 2024-08-03T02:11:24.850Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=StatusLogger 2024-08-03T02:11:24.850Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=ContextSelector 2024-08-03T02:11:24.851Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name= 2024-08-03T02:11:24.851Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.tez 2024-08-03T02:11:24.851Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=com.amazonaws 2024-08-03T02:11:24.851Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.thrift 2024-08-03T02:11:24.851Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=BlockStateChange 2024-08-03T02:11:24.851Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.eclipse.jetty 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.metrics2 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.zookeeper.ClientCnxn 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.zookeeper 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=JPOX 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.security 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.hive.ql.optimizer.SharedWorkOptimizer 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.yarn.server 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.conf.Configuration 2024-08-03T02:11:24.852Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.yarn 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.zookeeper.ClientCnxnSocketNIO 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.zookeeper.server.ServerCnxn 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.hdfs 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.hdfs.server 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.hive.serde2.lazy 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.zookeeper.ClientCnxnSocket 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.mortbay 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.hive.ql.optimizer.calcite.RuleEventLogger 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.http 2024-08-03T02:11:24.853Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.hive.ql.exec.Operator 2024-08-03T02:11:24.854Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=DataNucleus 2024-08-03T02:11:24.854Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.hive.metastore.ObjectStore 2024-08-03T02:11:24.854Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=Datastore 2024-08-03T02:11:24.854Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.hadoop.ipc 2024-08-03T02:11:24.854Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.zookeeper.server.NIOServerCnxn 2024-08-03T02:11:24.854Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Loggers,name=org.apache.calcite.plan.RelOptPlanner 2024-08-03T02:11:24.855Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Appenders,name=console 2024-08-03T02:11:24.855Z main DEBUG Registering MBean org.apache.logging.log4j2:type=3d4eac69,component=Appenders,name=DRFA 2024-08-03T02:11:24.856Z main TRACE Using default SystemClock for timestamps. 2024-08-03T02:11:24.857Z main DEBUG org.apache.logging.log4j.core.util.SystemClock does not support precise timestamps. 2024-08-03T02:11:24.857Z main TRACE Using DummyNanoClock for nanosecond timestamps. 2024-08-03T02:11:24.857Z main DEBUG Reconfiguration complete for context[name=3d4eac69] at URI /home/linghengqian/TwinklingLiftWorks/git/public/hive/hplsql/target/testconf/hive-log4j2.properties (org.apache.logging.log4j.core.LoggerContext@5a7fe64f) with optional ClassLoader: null 2024-08-03T02:11:24.857Z main DEBUG Shutdown hook enabled. Registering a new one. 2024-08-03T02:11:24.857Z main DEBUG LoggerContext[name=3d4eac69, org.apache.logging.log4j.core.LoggerContext@5a7fe64f] started OK. 2024-08-03T02:11:24.886Z main TRACE Log4jLoggerFactory.getContext() found anchor class org.apache.hadoop.conf.Configuration 2024-08-03T02:11:24.886Z main TRACE Log4jLoggerFactory.getContext() found anchor class org.apache.hadoop.conf.Configuration 2024-08-03T02:11:24.892Z main TRACE Log4jLoggerFactory.getContext() found anchor class org.apache.hadoop.util.Preconditions ]Ln:2 PRINT Correct L...> at org.junit.Assert.assertEquals(Assert.java:117) at org.junit.Assert.assertEquals(Assert.java:146) at org.apache.hive.hplsql.TestHplsqlLocal.run(TestHplsqlLocal.java:482) at org.apache.hive.hplsql.TestHplsqlLocal.testException(TestHplsqlLocal.java:229) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63) at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) at org.junit.runners.ParentRunner.run(ParentRunner.java:413) at org.junit.runner.JUnitCore.run(JUnitCore.java:137) at org.junit.runner.JUnitCore.run(JUnitCore.java:115) at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:43) at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183) at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) at java.util.Iterator.forEachRemaining(Iterator.java:116) at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801) at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482) at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472) at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150) at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173) at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485) at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:82) at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:73) at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:248) at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$5(DefaultLauncher.java:211) at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:226) at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:199) at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:132) at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:154) at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:123) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:377) at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:138) at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:465) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:451) ```

Reproduction

[An isolated test reproducing the test. JUnit tests similar to the ones in the code base are extremely appreciated.]

git clone git@github.com:linghengqian/hive.git -b test-v2230-log4j
cd ./hive/
sdk install java 8.0.422-tem
sdk use java 8.0.422-tem
sdk install maven
mvn clean install -DskipTests
mvn test -Dtest=TestHplsqlLocal
`/hive/data/conf/hive-log4j2.properties` 
status = INFO
name = HiveLog4j2Test

# list of properties
property.hive.log.level = DEBUG
property.hive.root.logger = DRFA
property.hive.log.dir = ${sys:test.tmp.dir}/log
property.hive.log.file = hive.log
property.hive.test.console.log.level = INFO

# console appender
appender.console.type = Console
appender.console.name = console
appender.console.target = SYSTEM_ERR
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %d{ISO8601} %5p [%t] %c{2}: %m%n

# daily rolling file appender
appender.DRFA.type = RollingRandomAccessFile
appender.DRFA.name = DRFA
appender.DRFA.fileName = ${sys:hive.log.dir}/${sys:hive.log.file}
appender.DRFA.filePattern = ${sys:hive.log.dir}/${sys:hive.log.file}.%d{yyyy-MM-dd}
appender.DRFA.layout.type = PatternLayout
appender.DRFA.layout.pattern = %d{ISO8601} %5p [%t] %c{2}: %m%n
appender.DRFA.policies.type = Policies
appender.DRFA.policies.time.type = TimeBasedTriggeringPolicy
appender.DRFA.policies.time.interval = 1
appender.DRFA.policies.time.modulate = true
appender.DRFA.strategy.type = DefaultRolloverStrategy
appender.DRFA.strategy.max = 30

logger.HadoopIPC.name = org.apache.hadoop.ipc
logger.HadoopIPC.level = WARN

logger.HadoopSecurity.name = org.apache.hadoop.security
logger.HadoopSecurity.level = INFO

logger.Hdfs.name = org.apache.hadoop.hdfs
logger.Hdfs.level = INFO

logger.HdfsServer.name = org.apache.hadoop.hdfs.server
logger.HdfsServer.level = WARN

logger.HadoopMetrics2.name = org.apache.hadoop.metrics2
logger.HadoopMetrics2.level = INFO

logger.Mortbay.name = org.mortbay
logger.Mortbay.level = INFO

logger.Yarn.name = org.apache.hadoop.yarn
logger.Yarn.level = INFO

logger.YarnServer.name = org.apache.hadoop.yarn.server
logger.YarnServer.level = WARN

logger.Tez.name = org.apache.tez
logger.Tez.level = INFO

logger.HadoopConf.name = org.apache.hadoop.conf.Configuration
logger.HadoopConf.level = ERROR

logger.Zookeeper.name = org.apache.zookeeper
logger.Zookeeper.level = INFO

logger.ServerCnxn.name = org.apache.zookeeper.server.ServerCnxn
logger.ServerCnxn.level = WARN

logger.NIOServerCnxn.name = org.apache.zookeeper.server.NIOServerCnxn
logger.NIOServerCnxn.level = WARN

logger.ClientCnxn.name = org.apache.zookeeper.ClientCnxn
logger.ClientCnxn.level = WARN

logger.ClientCnxnSocket.name = org.apache.zookeeper.ClientCnxnSocket
logger.ClientCnxnSocket.level = WARN

logger.ClientCnxnSocketNIO.name = org.apache.zookeeper.ClientCnxnSocketNIO
logger.ClientCnxnSocketNIO.level = WARN

logger.DataNucleus.name = DataNucleus
logger.DataNucleus.level = ERROR

logger.Datastore.name = Datastore
logger.Datastore.level = ERROR

logger.JPOX.name = JPOX
logger.JPOX.level = ERROR

logger.Operator.name = org.apache.hadoop.hive.ql.exec.Operator
logger.Operator.level = INFO

logger.Serde2Lazy.name = org.apache.hadoop.hive.serde2.lazy
logger.Serde2Lazy.level = INFO

logger.ObjectStore.name = org.apache.hadoop.hive.metastore.ObjectStore
logger.ObjectStore.level = INFO

logger.CalcitePlanner.name = org.apache.calcite.plan.RelOptPlanner
logger.CalcitePlanner.level = INFO

# Change logger level to DEBUG, to see all application of CBO rules and the operators they produce
logger.CBORuleLogger.name = org.apache.hadoop.hive.ql.optimizer.calcite.RuleEventLogger
logger.CBORuleLogger.level = OFF
logger.CBORuleLogger.filter.marker.type = MarkerFilter
logger.CBORuleLogger.filter.marker.marker = FULL_PLAN
# Change filter to ACCEPT, to see the produced plan after every rule invocation using the EXPLAIN CBO format
logger.CBORuleLogger.filter.marker.onMatch = DENY
logger.CBORuleLogger.filter.marker.onMismatch = NEUTRAL

logger.AmazonAws.name=com.amazonaws
logger.AmazonAws.level = INFO

logger.ApacheHttp.name=org.apache.http
logger.ApacheHttp.level = INFO

logger.Thrift.name = org.apache.thrift
logger.Thrift.level = WARN

logger.Jetty.name = org.eclipse.jetty
logger.Jetty.level = WARN

logger.BlockStateChange.name = BlockStateChange
logger.BlockStateChange.level = WARN

# root logger
rootLogger.level = ${sys:hive.log.level}
rootLogger.appenderRefs = root, console
rootLogger.appenderRef.root.ref = ${sys:hive.root.logger}
rootLogger.appenderRef.console.ref = console
rootLogger.appenderRef.console.level = ${sys:hive.test.console.log.level}

logger.swo.name = org.apache.hadoop.hive.ql.optimizer.SharedWorkOptimizer
logger.swo.level = DEBUG

vy commented 1 month ago

@linghengqian, I am not able to reproduce the issue. When I run the following code:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.status.StatusLogger;

public class Log4jIssue2794 {

    public static void main(String[] args) {
        LogManager.getLogger().info("foo");
        StatusLogger.getLogger().debug("bar");
        StatusLogger.getLogger().info("baz");
    }

}

using following system properties:

-Dlog4j.configurationFile=/path/to/hive-log4j2.properties -Dtest.tmp.dir=/tmp

it produces below output:

2024-08-03T19:36:04,784  INFO [main] volkan.Log4jIssue2794: foo
2024-08-03T17:36:04.786802627Z main INFO baz

That is, INFO-level status message is written and DEBUG-level status message is discarded, as configured via status = INFO.

Would you mind putting a breakpoint to StatusConsoleListener#setLevel(Level), please? It should be invoked by StatusConfiguration, the component responsible for reading status = INFO and propagating that to StatusConsoleListener.

linghengqian commented 1 month ago
vy commented 1 month ago

@linghengqian, Log4j is no different. You can run a particular test from the command line and debug it in IDEA:

  1. Run ./mvnw test -pl :SOME-HIVE-MODULE -Dtest=FooBarTest -Dmaven.surefire.debug (You need to replace SOME-HIVE-MODULE and FooBarTest)
  2. Use "Run > Attach to process" in IntelliJ IDEA (Eclipse has something similar too)
linghengqian commented 1 month ago

@vy

vy commented 1 month ago

@linghengqian, your Status Logger setup is broken by a combination of Status Logger enhancements introduced in Log4j 2.23.1 and <log4j.debug>true line in /pom.xml of the Hive repository, which gets injected into the systemPropertyVariables configuration of maven-surefire-plugin.

You can view the effective POM using:

mvn help:effective-pom -pl hplsql -Doutput=pom-effective.xml

Remove <log4j.debug>true</log4j.debug> line in /pom.xml and following passes:

mvn install -N   # Install `pom.xml` changes
mvn test -pl hplsql -Dtest=TestHplsqlLocal#testConversion

Details of how Status Logger works and the effect of log4j.debug on it can be found in the Status Logger manual. Status Logger is intended for troubleshooting Log4j itself and its components. I strongly advise you to avoid configuring it unless you are troubleshooting a Log4j issue.

linghengqian commented 1 month ago
vy commented 1 month ago

@linghengqian, I presume you don't have issues anymore or resolved them using my suggestions. I am closing this ticket. Feel free to re-open it if your problem persists.