Fix handling of `onMatch` and `onMismatch` attributes in the properties configuration format #2791

linghengqian · 2024-08-02T04:06:09Z

Description

Since apache/logging-log4j2:2.23.0, onMismatch of MarkerFilter is no longer available. This was actually found from HIVE-28417: Bump Log4j2 to 2.24.1 to facilitate compilation of GraalVM Native Image hive#5375 . It can be reproduced in both 2.23.0 and 2.23.1. This will be reflected in a log similar to ERROR MarkerFilter contains an invalid element or attribute "onMismatch".

Configuration

Version: [Log4j version] 2.23.0

Operating system: [OS and version] Ubuntu WSL 22.04.4

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

Logs

-------------------------------------------------------------------------------
Test set: org.apache.hive.hplsql.TestHplsqlLocal
-------------------------------------------------------------------------------
Tests run: 86, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 3.359 s <<< FAILURE! - in org.apache.hive.hplsql.TestHplsqlLocal
org.apache.hive.hplsql.TestHplsqlLocal.testException  Time elapsed: 0.676 s  <<< FAILURE!
org.junit.ComparisonFailure: 
expected:<[]Ln:2 PRINT
Correct
L...> but was:<[2024-08-02T03:55:09.225Z main ERROR MarkerFilter contains an invalid element or attribute "onMismatch"
]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

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 Bump Log4j2 to 2.23.1 linghengqian/hive#1 . The relevant operating methods are also located in the corresponding PR.

git clone [email protected]: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.

status = INFO
name = HiveLog4j2Test
packages = org.apache.hadoop.hive.ql.log

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

appenders = console, DRFA

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

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

loggers = HadoopIPC, HadoopSecurity, Hdfs, HdfsServer, HadoopMetrics2, Mortbay, Yarn, YarnServer, Tez, HadoopConf, Zookeeper, ServerCnxn, NIOServerCnxn, ClientCnxn, ClientCnxnSocket, ClientCnxnSocketNIO, DataNucleus, Datastore, JPOX, Operator, Serde2Lazy, ObjectStore, CalcitePlanner, AmazonAws, ApacheHttp, Thrift, Jetty, BlockStateChange, swo, CBORuleLogger

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

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

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

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

The text was updated successfully, but these errors were encountered:

ppkarwasz · 2024-08-02T06:33:15Z

Hi @linghengqian,

Could you point us to how you generate the GraalVM image?

As almost all filters (except DenyAllFilter and Filters), MarkerFilter has a onMismatch property. I suspect that the GraalVM reflection metadata you use might lack the property, hence the problem in the native image.

linghengqian · 2024-08-02T06:38:36Z

Hi @linghengqian,

Could you point us to how you generate the GraalVM image?

As almost all filters (except DenyAllFilter and Filters), MarkerFilter has a onMismatch property. I suspect that the GraalVM reflection metadata you use might lack the property, hence the problem in the native image.

Hi, the steps I mentioned in the issue description never involve using log4j2 under GraalVM Native Image. I assume you are referring to Add GraalVM Reachability Metadata and corresponding nativeTest for Iceberg table in HiveServer2 shardingsphere#31526 . On the shardingspehre side, all nativeTest under GraalVM Native Image have excluded log4j2 in maven pom, and I am actually waiting for the release of log4j2 2.24.0.
On the hive side, the Error Log of ERROR MarkerFilter contains an invalid element or attribute "onMismatch" is obtained by executing unit tests under Hotspot JDK 8. Hive can still only be compiled with openjdk 8, and it is too early to discuss graalvm native image in the hive community.

ppkarwasz · 2024-08-02T10:00:18Z

@linghengqian,

The problem is due to a typo in your configuration file:

logger.CBORuleLogger.filter.marker.type = MarkerFilter
logger.CBORuleLogger.filter.marker.marker = FULL_PLAN
logger.CBORuleLogger.filter.marker.onMatch = DENY
logger.CBORuleLogger.filter.marker.onMisMatch = NEUTRAL

You have onMisMatch instead of onMismatch. The misleading error message is due to the following code in PropertiesConfigurationBuilder:

logging-log4j2/log4j-core/src/main/java/org/apache/logging/log4j/core/config/properties/PropertiesConfigurationBuilder.java

Lines 234 to 236 in eaae9e3

    
           final String onMatch = (String) properties.remove(AbstractFilterBuilder.ATTR_ON_MATCH); 
        
           final String onMismatch = (String) properties.remove(AbstractFilterBuilder.ATTR_ON_MISMATCH); 
        
           final FilterComponentBuilder filterBuilder = builder.newFilter(type, onMatch, onMismatch);

logging-log4j2/log4j-core/src/main/java/org/apache/logging/log4j/core/config/builder/impl/DefaultConfigurationBuilder.java

Lines 462 to 465 in eaae9e3

    
           @Override 
        
           public FilterComponentBuilder newFilter(final String type, final String onMatch, final String onMismatch) { 
        
               return new DefaultFilterComponentBuilder(this, type, onMatch, onMismatch); 
        
           }

logging-log4j2/log4j-core/src/main/java/org/apache/logging/log4j/core/config/builder/impl/DefaultFilterComponentBuilder.java

Lines 29 to 37 in eaae9e3

    
           public DefaultFilterComponentBuilder( 
        
                   final DefaultConfigurationBuilder<? extends Configuration> builder, 
        
                   final String type, 
        
                   final String onMatch, 
        
                   final String onMismatch) { 
        
               super(builder, type); 
        
               addAttribute(AbstractFilterBuilder.ATTR_ON_MATCH, onMatch); 
        
               addAttribute(AbstractFilterBuilder.ATTR_ON_MISMATCH, onMismatch); 
        
           }

Since you don't have an onMismatch attribute, the code creates a synthetic onMismatch attribute with an invalid null value.

Remark: Fixing this also fixes LOG4J2-2931, so I am redirecting that issue here.

PS: I noticed that Apache Hive uses a pre-2.6 properties configuration format (the loggers is not required since version 2.6).
Would you consider switching to a more easily readable configuration format? Version 3.x will introduce breaking changes to the properties format, but not the hierarchical ones.

linghengqian · 2024-08-03T03:07:02Z

@ppkarwasz

Late reply, because I need to wait for verification on apache/hive's CI side. apache/hive's CI resources are too tight, and apache/hive's jenkins node limits each contributor to 5 hours between 2 consecutive CIs. To be honest, HIVE-28417: Bump Log4j2 to 2.24.1 to facilitate compilation of GraalVM Native Image hive#5375 is the first PR I opened on apache/hive's side, and I know almost nothing about apache/hive's logging design.
I updated HIVE-28417: Bump Log4j2 to 2.24.1 to facilitate compilation of GraalVM Native Image hive#5375 not long ago, I removed the packages, appenders, loggers nodes of /hive/data/conf/hive-log4j2.properties, and changed logger.CBORuleLogger.filter.marker.onMisMatch to logger.CBORuleLogger.filter.marker.onMismatch. apache/hive's CI is now back on apache/logging-log4j2:2.23.0. I'm assuming this is a reasonable way forward to not break compatibility with future versions of log4j2. I'm assuming the changes are in line with what's documented in [improve][misc] Upgrade log4j2 to 2.23.1 pulsar#22327 , https://logging.apache.org/log4j/2.x/manual/configuration.html , and https://logging.apache.org/log4j/2.x/manual/plugins.html . I note from https://issues.apache.org/jira/browse/LOG4J2-3644 that the packages property seems to be straightforward to remove, though Migrate log4j2 to logback jmeter#5937 on the apache/jmeter side is still unclear as to the way forward.

2024-08-02T10:55:16.634Z main WARN The use of package scanning to locate plugins is deprecated and will be removed in a future release
2024-08-02T10:55:16.650Z main WARN The use of package scanning to locate plugins is deprecated and will be removed in a future release
2024-08-02T10:55:16.670Z main WARN The use of package scanning to locate plugins is deprecated and will be removed in a future release
2024-08-02T10:55:16.686Z main WARN The use of package scanning to locate plugins is deprecated and will be removed in a future release

On the apache/hive side, I noticed a new issue when bump from apache/logging-log4j2:2.23.0 to apache/logging-log4j2:2.23.1, the status = INFO defined in hive-log4j2.properties is no longer valid, and Log4j2 internal logs at TRACE and DEBUG levels will be printed starting from apache/logging-log4j2:2.23.1. Since the current issue is bound to https://issues.apache.org/jira/browse/LOG4J2-2931 , I opened When bump from 2.23.0 to 2.23.1, the status of the .properties configuration file no longer works #2794 to avoid ambiguity.
I will say that I personally don't know how to fix Fix handling of onMatch and onMismatch attributes in the properties configuration format #2791 with the good first issue tag.

Two tests in `hplsql` module make assertions on the output to `System.out` and `System.err`. This makes the tests fragile to any other output that might appear there (see apache/logging-log4j2#2791 for example). This PR introduces a custom `Console` implementation to capture the output of these tests and make them independent from whatever is printed to the standard output and error descriptors.

ppkarwasz · 2024-08-03T21:42:58Z

@ppkarwasz

I note from https://issues.apache.org/jira/browse/LOG4J2-3644 that the packages property seems to be straightforward to remove, though Migrate log4j2 to logback jmeter#5937 on the apache/jmeter side is still unclear as to the way forward.

There is no problem in Apache Hive: I checked that the appropriate annotation processor is configured in the hive-exec project and there is a Log4j2Plugins.dat file in the JAR. You can safely remove the packages configuration attribute.

* I will say that I personally don't know how to fix [Fix handling of `onMatch` and `onMismatch` attributes in the properties configuration format #2791](https://github.com/apache/logging-log4j2/issues/2791) with the `good first issue` tag.

I believe that the problem breaks down to a missing null-check: ComponentBuilder#addAttribute should add an attribute if the value is not null and remove it if the value is null.

null is never a valid value for an attribute.

BTW: All the problems you are having are due to the fact that TestHplsqlLocal and TestHplsqlOffline are fragile tests. They write something to System.out and they make assertions about that. The problem is: other components (like the status logger) might also write to System.out. I proposed a solution to this in apache/hive#5381

linghengqian · 2024-08-04T04:43:29Z

Hi @linghengqian,

Could you point us to how you generate the GraalVM image?

As almost all filters (except DenyAllFilter and Filters), MarkerFilter has a onMismatch property. I suspect that the GraalVM reflection metadata you use might lack the property, hence the problem in the native image.

As an external update, I have provided a partial GRM for log4j2 at Add GraalVM native compilation support #1539 (comment) .

linghengqian mentioned this issue Aug 2, 2024

HIVE-28417: Bump Log4j2 to 2.24.1 to facilitate compilation of GraalVM Native Image apache/hive#5375

Merged

ppkarwasz changed the title ~~Since apache/logging-log4j2:2.23.0, onMismatch of MarkerFilter is no longer available~~ Fix handling of onMatch and onMismatch attributes in the properties configuration format Aug 2, 2024

ppkarwasz added bug Incorrect, unexpected, or unintended behavior of existing code good first issue Issues that are good for contributors looking to get started configuration Affects the configuration system in a general way labels Aug 2, 2024

linghengqian mentioned this issue Aug 3, 2024

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

Closed

ppkarwasz mentioned this issue Aug 3, 2024

Improve HPL/SQL tests apache/hive#5381

Open

linghengqian mentioned this issue Aug 4, 2024

Add GraalVM native compilation support #1539

Open

linghengqian mentioned this issue Aug 4, 2024

Add GraalVM Reachability Metadata and corresponding nativeTest for Iceberg table in HiveServer2 apache/shardingsphere#31526

Merged

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix handling of `onMatch` and `onMismatch` attributes in the properties configuration format #2791

Fix handling of `onMatch` and `onMismatch` attributes in the properties configuration format #2791

linghengqian commented Aug 2, 2024 •

edited

Loading

ppkarwasz commented Aug 2, 2024

linghengqian commented Aug 2, 2024 •

edited

Loading

ppkarwasz commented Aug 2, 2024 •

edited

Loading

linghengqian commented Aug 3, 2024 •

edited

Loading

ppkarwasz commented Aug 3, 2024

linghengqian commented Aug 4, 2024

Fix handling of onMatch and onMismatch attributes in the properties configuration format #2791

Fix handling of onMatch and onMismatch attributes in the properties configuration format #2791

Comments

linghengqian commented Aug 2, 2024 • edited Loading

Description

Configuration

Logs

Reproduction

ppkarwasz commented Aug 2, 2024

linghengqian commented Aug 2, 2024 • edited Loading

ppkarwasz commented Aug 2, 2024 • edited Loading

linghengqian commented Aug 3, 2024 • edited Loading

ppkarwasz commented Aug 3, 2024

linghengqian commented Aug 4, 2024

Fix handling of `onMatch` and `onMismatch` attributes in the properties configuration format #2791

Fix handling of `onMatch` and `onMismatch` attributes in the properties configuration format #2791

linghengqian commented Aug 2, 2024 •

edited

Loading

linghengqian commented Aug 2, 2024 •

edited

Loading

ppkarwasz commented Aug 2, 2024 •

edited

Loading

linghengqian commented Aug 3, 2024 •

edited

Loading