log4j-layout-template-json:2.21.0 Introduced Backward Incompatible Change

[iManageDave]

Description

My organization has developed a Log4J plugin that implements an EventResolver. The plugin compiles with version 2.20.0 but not 2.21.0 due to it's newly added module-info.java. 2.21.0's module-info.java is a welcome addition; however, it exports EventResolver but not JsonWriter which is referenced by the TemplateResolver<V> super-interface. This results in a compilation error.

Configuration

Version: 2.21.0

Operating system: Ubuntu 22.04

JDK: OpenJDK Runtime Environment Temurin-17.0.8.1+1 (build 17.0.8.1+1)

Logs

[ERROR] /home/dave/src/log4j-datamessage-plugin/src/main/java/com/imanage/logging/log4j/layout/template/json/resolver/DataMessageResolver.java:[7,53] package org.apache.logging.log4j.layout.template.json.util is not visible
[ERROR]   (package org.apache.logging.log4j.layout.template.json.util is declared in module org.apache.logging.log4j.layout.template.json, which does not export it)

[vy]

@iManageDave, thanks for the heads up! The new OSGi/JPMS descriptors are... new. 😅 I will take care of your issue and probably do a patch release. (Note that this is a quick response, I still need to verify your finding and figure out what needs to be done.)

For the records, 2.21.1 is already about to get released for some other problem. Your fix will probably appear in 2.21.2, FYI.

[iManageDave]

@iManageDave, thanks for the heads up! The new OSGi/JPMS descriptors are... new. 😅 I will take care of your issue and probably do a patch release. (Note that this is a quick response, I still need to verify your finding and figure out what needs to be done.)

For the records, 2.21.1 is already about to get released for some other problem. Your fix will probably appear in 2.21.2, FYI.

Thanks for the blindingly fast response, @vy!

JPMS helps keep us (esp. me!) honest 😉

[ppkarwasz]

@iManageDave,

We use BND to generate JPMS and OSGi descriptors. Unfortunately BND considers API leakage a warning:

[WARNING] /home/piotr/workspace/log4j2/2.x/log4j-layout-template-json/.flattened-pom.xml [0:0]: Export org.apache.logging.log4j.layout.template.json,  has 1,  private references [org.apache.logging.log4j.layout.template.json.util]
[WARNING] /home/piotr/workspace/log4j2/2.x/log4j-layout-template-json/.flattened-pom.xml [0:0]: Export org.apache.logging.log4j.layout.template.json.resolver,  has 1,  private references [org.apache.logging.log4j.layout.template.json.util]

so we didn't see it.

Fortunately we can configure BND to mark these warning as errors.

[rickardoberg]

Came here to make the same bug report, but @iManageDave was faster. Here's the error that I get, different symptom same cause:
Caused by: java.lang.IllegalAccessException: class org.apache.logging.log4j.core.util.ReflectionUtil (in module org.apache.logging.log4j.core) cannot access class org.apache.logging.log4j.layout.template.json.util.RecyclerFactoryConverter (in module org.apache.logging.log4j.layout.template.json) because module org.apache.logging.log4j.layout.template.json does not export org.apache.logging.log4j.layout.template.json.util to module org.apache.logging.log4j.core at java.base/jdk.internal.reflect.Reflection.newIllegalAccessException(Reflection.java:392) at java.base/java.lang.reflect.AccessibleObject.checkAccess(AccessibleObject.java:674) at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:489) at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)

[vy]

@iManageDave, @rickardoberg, could you give the recently uploaded 2.22.0-SNAPSHOT a try, please? (See this section of the manual on details for accessing to the snapshot repository.)

[rickardoberg]

@iManageDave, @rickardoberg, could you give the recently uploaded 2.22.0-SNAPSHOT a try, please? (See this section of the manual on details for accessing to the snapshot repository.)

If I mvn install our project with 2.21.0 for all other log4j artifacts and the 2.22.0-SNAPSHOT for template only, then it works.

However, if I use 2.22.0-SNAPSHOT for all log4j artifacts then I get the following error:
"module not found: org.osgi.core"

So seems like you've fixed your issue, but some other module introduced an OSGi dependency.

[vy]

@rickardoberg, I am checking stuff out on my side, though OSGi/JPMS is not my primary expertise. I would really appreciate it if you can bisect the problematic Log4j artifact. That is, switch log4j-layout-template-json to 2.22.0-SNAPSHOT and everything else to 2.21.0, and switch the rest of the Log4j artifacts one at a time to 2.22.0-SNAPSHOT.

[iManageDave]

I am able to compile with log4j-layout-template-json:2.22.0-SNAPSHOT, log4j-api:2.21.1, and log4j-core:2.21.1; however, the Surefire plugin crashes running unit tests (see below). I will take some time to debug today.

[INFO] --- surefire:3.1.2:test (default-test) @ log4j-datamessage-plugin ---
[INFO] Using auto detected provider org.apache.maven.surefire.junitplatform.JUnitPlatformProvider
[INFO]
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[ERROR] Error occurred during initialization of boot layer
[ERROR] java.lang.module.FindException: Module org.jctools.core not found, required by org.apache.logging.log4j.layout.template.json
[INFO]
[INFO] Results:
[INFO]
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[WARNING] Corrupted channel by directly writing to native stream in forked JVM 1. See FAQ web page and the dump file /home/dave/src/log4j-datamessage-plugin/target/surefire-reports/2023-10-24T09-02-09_518-jvmRun1.dumpstream
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  3.617 s
[INFO] Finished at: 2023-10-24T09:02:09-05:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:3.1.2:test (default-test) on project log4j-datamessage-plugin:
[ERROR]
[ERROR] Please refer to /home/dave/src/log4j-datamessage-plugin/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd '/home/dave/src/log4j-datamessage-plugin' && '/usr/lib/jvm/java-17-openjdk-amd64/bin/java' '-javaagent:/home/dave/.m2/repository/org/jacoco/org.jacoco.agent/0.8.11/org.jacoco.agent-0.8.11-runtime.jar=de
stfile=/home/dave/src/log4j-datamessage-plugin/target/jacoco.exec' '@/home/dave/src/log4j-datamessage-plugin/target/surefire/surefireargs-20231024090209688_3' '/home/dave/src/log4j-datamessage-plugin/target/surefire' '2023-10-24T09-02-0
9_518-jvmRun1' 'surefire-20231024090209688_1tmp' 'surefire_0-20231024090209688_2tmp'
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 1
[ERROR] org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd '/home/dave/src/log4j-datamessage-plugin' && '/usr/lib/jvm/java-17-openjdk-amd64/bin/java' '-javaagent:/home/dave/.m2/repository/org/jacoco/org.jacoco.agent/0.8.11/org.jacoco.agent-0.8.11-runtime.jar=de
stfile=/home/dave/src/log4j-datamessage-plugin/target/jacoco.exec' '@/home/dave/src/log4j-datamessage-plugin/target/surefire/surefireargs-20231024090209688_3' '/home/dave/src/log4j-datamessage-plugin/target/surefire' '2023-10-24T09-02-0
9_518-jvmRun1' 'surefire-20231024090209688_1tmp' 'surefire_0-20231024090209688_2tmp'
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 1
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:643)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:285)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:250)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1203)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1055)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:871)
[ERROR]         at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:126)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute2(MojoExecutor.java:328)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.doExecute(MojoExecutor.java:316)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:212)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:174)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.access$000(MojoExecutor.java:75)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor$1.run(MojoExecutor.java:162)
[ERROR]         at org.apache.maven.plugin.DefaultMojosExecutionStrategy.execute(DefaultMojosExecutionStrategy.java:39)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:159)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:105)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:73)
[ERROR]         at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:53)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:118)
[ERROR]         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:261)
[ERROR]         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:173)
[ERROR]         at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:101)
[ERROR]         at org.apache.maven.cli.MavenCli.execute(MavenCli.java:906)
[ERROR]         at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:283)
[ERROR]         at org.apache.maven.cli.MavenCli.main(MavenCli.java:206)
[ERROR]         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[ERROR]         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[ERROR]         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[ERROR]         at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:283)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:226)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:407)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:348)
[ERROR]
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException