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

[linghengqian]

Description

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

• When bump from 2.23.0 to 2.23.1, the status of the .properties configuration file no longer works. This is manifested as the log starting to print a lot of log4j2 internal TRACE and DEBUG level LOGs. The current issue is an extension of Fix handling of onMatch and onMismatch attributes in the properties configuration format #2791 to avoid addressing multiple, possibly unrelated issues in the same issue.
• I bump apache/log4j2 from 2.18.0 to 2.23.0 at HIVE-28417: Bump Log4j2 to 2.24.1 to facilitate compilation of GraalVM Native Image hive#5375 and everything worked fine.
• But in https://github.com/linghengqian/hive/pull/1 , after I bump from 2.23.0 to 2.23.1, hive-log4j2.properties seemed to be partially invalid, as reflected in the large number of TRACE and DEBUG logs. I can't seem to see any relevant information from the changelog of https://github.com/apache/logging-log4j2/releases/tag/rel%2F2.23.1.

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

• This is manifested as the log starting to print a lot of log4j2 internal TRACE and DEBUG level LOGs. Of course, apache/hive has a java function in org.apache.hive.hplsql.TestHplsqlLocal#getTestOutput(String) to filter some output.

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();
}

• I show the log in folded form. It's really long.

Error Log

-------------------------------------------------------------------------------
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.]

• I must admit that I am a log4j2 newbie. It's hard to say how I can immediately come up with a smaller reproducible unit test. I just did a small test at https://github.com/linghengqian/hive/pull/1 . The relevant operating methods are also located in the corresponding PR.

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

• The activated configuration file is located at /hive/data/conf/hive-log4j2.properties. It's really long.

`/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]

@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]

• I found a more embarrassing problem, I can only use the command line to execute the unit test of apache/hive, but I can't use IntelliJ IDEA to execute the unit test. I have opened https://issues.apache.org/jira/browse/HIVE-28432 , which may take some time to wait.

[vy]

@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]

@vy

• I executed mvn test -Dtest=TestHplsqlLocal -Dmaven.surefire.debug and started remote debugging on IntelliJ IDEA side. But things are getting weird. Neither the full-args constructor of org.apache.logging.log4j.status.StatusConsoleListener nor org.apache.logging.log4j.status.StatusConsoleListener#setLevel(org.apache.logging.log4j.Level) was called for either apache/logging-log4j2:2.23.0 where unit test execution succeeded, or apache/logging-log4j2:2.23.1 where unit test execution failed.
• 
• 
• But I did debug in org.apache.hive.hplsql.Exec#init() that the system property of log4j.configurationFile was successfully set to hive-log4j2.properties. This is what apache/logging-log4j2:2.23.1 can do.
• 
• 
• I feel like there is nothing wrong with the way I debug into unit testing. I’m still not sure which way to go.

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 -Dmaven.surefire.debug

[vy]

@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]

• Thank you very much for your help!

• I am actually waiting for the CI on the apache/hive side to complete. It always takes several hours to complete CI on the apache/hive side. Their CI resources are too tight. I directly updated HIVE-28417: Bump Log4j2 to 2.24.1 to facilitate compilation of GraalVM Native Image hive#5375, and now apache/hive can use apache/logging-log4j2:2.23.1 normally. At the same time, I also verified at https://github.com/linghengqian/log4j2-v2231-graalvm-native-image-test -- HiveServer2 JDBC Driver using apache/logging-log4j2:2.23.1 can be used normally under GraalVM Native Image.

• Should I close the current issue now?

[vy]

@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.