Bug ID: JDK-8292498 java/lang/invoke/lambda/LogGeneratedClassesTest.java failed with "AssertionError: only show error once expected [1] but found [0]"

JDK-8292498 : java/lang/invoke/lambda/LogGeneratedClassesTest.java failed with "AssertionError: only show error once expected [1] but found [0]"

Type: Bug
Component: core-libs
Sub-Component: java.lang.invoke
Affected Version: 20

Priority: P2
Status: Closed
Resolution: Fixed
OS: windows
CPU: x86_64

Submitted: 2022-08-16
Updated: 2024-10-27
Resolved: 2022-08-18

Versions (Unresolved/Resolved/Fixed)

The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.

JDK 20
20 b12Fixed

Related Reports

Relates :

JDK-8289106 - Add model of class file versions to core reflection

Sub Tasks

JDK-8292509 :

ProblemList java/lang/invoke/lambda/LogGeneratedClassesTest.java on windows - Resolved

Description

The following test failed in the JDK20 CI:

java/lang/invoke/lambda/LogGeneratedClassesTest.java

Here's a snippet from the log file:

#section:testng
----------messages:(5/169)----------
command: testng LogGeneratedClassesTest
reason: User specified action: run testng LogGeneratedClassesTest 
Mode: agentvm
Agent id: 12
elapsed time (seconds): 2.126
----------configuration:(16/1596)*----------
Boot Layer
  class path: C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\javatest.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\jtreg.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\junit.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\hamcrest.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\testng.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\jcommander.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\guice.jar 
  patch:      java.base C:\\sb\\prod\\1660677053\\testoutput\\test-support\\jtreg_open_test_jdk_tier1_part1\\patches\\java.base

Test Layer
  class path: C:\\sb\\prod\\1660677053\\testoutput\\test-support\\jtreg_open_test_jdk_tier1_part1\\classes\\1\\java\\lang\\invoke\\lambda\\LogGeneratedClassesTest.d
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-20+11-642\\src.full\\open\\test\\jdk\\java\\lang\\invoke\\lambda
              C:\\sb\\prod\\1660677053\\testoutput\\test-support\\jtreg_open_test_jdk_tier1_part1\\classes\\1\\java\\nio\\file
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-20+11-642\\src.full\\open\\test\\jdk\\java\\nio\\file

----------rerun:(34/5377)*----------

<snip>

----------System.out:(120/7518)*----------
config LogGeneratedClassesTest.setup(): success
test LogGeneratedClassesTest.testDumpDirIsFile(): failure
java.lang.AssertionError: only show error once expected [1] but found [0]
	at org.testng.Assert.fail(Assert.java:99)
	at org.testng.Assert.failNotEquals(Assert.java:1037)
	at org.testng.Assert.assertEqualsImpl(Assert.java:140)
	at org.testng.Assert.assertEquals(Assert.java:122)
	at org.testng.Assert.assertEquals(Assert.java:797)
	at LogGeneratedClassesTest.testDumpDirIsFile(LogGeneratedClassesTest.java:165)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
	at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
	at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
	at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
	at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
	at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.testng.TestRunner.privateRun(TestRunner.java:764)
	at org.testng.TestRunner.run(TestRunner.java:585)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
	at org.testng.SuiteRunner.run(SuiteRunner.java:286)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
	at org.testng.TestNG.runSuites(TestNG.java:1069)
	at org.testng.TestNG.run(TestNG.java:1037)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
	at java.base/java.lang.Thread.run(Thread.java:1589)
test LogGeneratedClassesTest.testDumpDirNotExist(): failure
java.lang.AssertionError: only show error once expected [1] but found [0]
	at org.testng.Assert.fail(Assert.java:99)
	at org.testng.Assert.failNotEquals(Assert.java:1037)
	at org.testng.Assert.assertEqualsImpl(Assert.java:140)
	at org.testng.Assert.assertEquals(Assert.java:122)
	at org.testng.Assert.assertEquals(Assert.java:797)
	at LogGeneratedClassesTest.testDumpDirNotExist(LogGeneratedClassesTest.java:149)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
	at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
	at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
	at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
	at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
	at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.testng.TestRunner.privateRun(TestRunner.java:764)
	at org.testng.TestRunner.run(TestRunner.java:585)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
	at org.testng.SuiteRunner.run(SuiteRunner.java:286)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
	at org.testng.TestNG.runSuites(TestNG.java:1069)
	at org.testng.TestNG.run(TestNG.java:1037)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
	at java.base/java.lang.Thread.run(Thread.java:1589)
WARNING: POSIX is not supported. Skipping testDumpDirNotWritable test.
test LogGeneratedClassesTest.testDumpDirNotWritable(): success
test LogGeneratedClassesTest.testLogging(): success
accepted: dumpLong
accepted: dumpLong\\com
accepted: dumpLong\\com\\example
accepted: dumpLong\\com\\example\\nonsense
accepted: dumpLong\\com\\example\\nonsense\\nonsense
filetered out: dumpLong\\java
filetered out: dumpLong\\java\\lang
filetered out: dumpLong\\java\\lang\\Class$$Lambda$41.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$21.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$22.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$23.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$24.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$25.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$26.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$27.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$28.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$29.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$30.class
filetered out: dumpLong\\java\\lang\\SecurityManager$$Lambda$31.class
filetered out: dumpLong\\java\\lang\\System$$Lambda$32.class
filetered out: dumpLong\\java\\util
filetered out: dumpLong\\java\\util\\ServiceLoader$$Lambda$40.class
filetered out: dumpLong\\jdk
filetered out: dumpLong\\jdk\\internal
filetered out: dumpLong\\jdk\\internal\\loader
filetered out: dumpLong\\jdk\\internal\\loader\\BuiltinClassLoader$$Lambda$39.class
filetered out: dumpLong\\jdk\\internal\\loader\\BuiltinClassLoader$$Lambda$49.class
filetered out: dumpLong\\jdk\\internal\\logger
filetered out: dumpLong\\jdk\\internal\\logger\\SimpleConsoleLogger$CallerFinder$$Lambda$42.class
filetered out: dumpLong\\sun
filetered out: dumpLong\\sun\\net
filetered out: dumpLong\\sun\\net\\www
filetered out: dumpLong\\sun\\net\\www\\protocol
filetered out: dumpLong\\sun\\net\\www\\protocol\\jrt
filetered out: dumpLong\\sun\\net\\www\\protocol\\jrt\\JavaRuntimeURLConnection$$Lambda$38.class
test LogGeneratedClassesTest.testLoggingException(): success
test LogGeneratedClassesTest.testNotLogging(): success
config LogGeneratedClassesTest.cleanup(): success

===============================================
java/lang/invoke/lambda/LogGeneratedClassesTest.java
Total tests run: 6, Passes: 4, Failures: 2, Skips: 0
===============================================

----------System.err:(24/1402)----------
TestLambda.java:7: warning: [removal] SecurityManager in java.lang has been deprecated and marked for removal
        System.setSecurityManager(new SecurityManager());
                                      ^
TestLambda.java:7: warning: [removal] setSecurityManager(SecurityManager) in System has been deprecated and marked for removal
        System.setSecurityManager(new SecurityManager());
              ^
2 warnings
LongPackageName.java:7: warning: [removal] SecurityManager in java.lang has been deprecated and marked for removal
        System.setSecurityManager(new SecurityManager());
                                      ^
LongPackageName.java:7: warning: [removal] setSecurityManager(SecurityManager) in System has been deprecated and marked for removal
        System.setSecurityManager(new SecurityManager());
              ^
2 warnings
java.lang.Exception: failures: 2
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:96)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
	at java.base/java.lang.Thread.run(Thread.java:1589)

JavaTest Message: Test threw exception: java.lang.Exception
JavaTest Message: shutting down test

result: Failed. Execution failed: `main' threw exception: java.lang.Exception: failures: 2

Comments

A pull request was submitted for review. Branch: master URL: https://git.openjdk.org/jdk/pull/9911 Date: 2022-08-17 22:33:03 +0000

27-10-2024

Changeset: f567fa0f Author: Joe Darcy <darcy@openjdk.org> Date: 2022-08-18 16:09:26 +0000 URL: https://git.openjdk.org/jdk/commit/f567fa0fd53c519cdda1da8a7aaa0df895abc6e9

18-08-2022

I had a deeper look at this. The failure reported in mach5 are only on Windows systems. However, after figuring out what is going, I can now reproduce this on non-Windows setups too (and even locally). This specific test case LogGeneratedClassesTest internally launches Java process (one each in a test method) and passes it values to the system property "jdk.internal.lambda.dumpProxyClasses". This system property takes a path as a value. The java.lang.invoke.ProxyClassesDumper then reads this value and expects it to be a directory (which exists). Those checks are done in this ProxyClassesDumper class and if those requirements aren't satisfied then it logs a WARNING message to the process' output. The test then verifies/asserts that these specific WARNING messages are present. In the failing cases above, this logging message is absent. The code in ProxyClassesDumper which does that logging is as follows: ... } catch (IllegalArgumentException iae) { PlatformLogger.getLogger(ProxyClassesDumper.class.getName()) .warning(iae.getMessage() + " - dumping disabled"); So it uses the PlatformLogger.getLogger(...) to do the logging. I added a bit of manual debug messages to the relevant parts of the code and what's happening is that the call to PlatformLogger.getLogger(...) is triggering a NullPointerException. Very specifically, this is what that exception stacktrace looks like (I had to modify the JDK code to generate this, because by default the stacktrace isn't logged): Error occurred during initialization of boot layer java.lang.ExceptionInInitializerError at java.base/java.lang.invoke.LambdaMetafactory.metafactory(LambdaMetafactory.java:331) at java.base/java.lang.invoke.BootstrapMethodInvoker.invoke(BootstrapMethodInvoker.java:134) at java.base/java.lang.invoke.CallSite.makeSite(CallSite.java:315) at java.base/java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:279) at java.base/java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:269) at java.base/java.lang.reflect.AccessFlag.<clinit>(AccessFlag.java:100) at java.base/java.lang.module.ModuleDescriptor$Modifier.<clinit>(ModuleDescriptor.java:109) at java.base/java.lang.module.ModuleDescriptor.<init>(ModuleDescriptor.java:1326) at java.base/java.lang.module.ModuleDescriptor$1.newModuleDescriptor(ModuleDescriptor.java:2738) at java.base/jdk.internal.module.Builder.build(Builder.java:270) at java.base/jdk.internal.module.SystemModules$default.moduleDescriptors(Unknown Source) at java.base/jdk.internal.module.SystemModuleFinders.of(SystemModuleFinders.java:146) at java.base/jdk.internal.module.ModuleBootstrap.boot2(ModuleBootstrap.java:240) at java.base/jdk.internal.module.ModuleBootstrap.boot(ModuleBootstrap.java:174) at java.base/java.lang.System.initPhase2(System.java:2214) Caused by: java.lang.NullPointerException at java.base/java.util.Objects.requireNonNull(Objects.java:233) at java.base/jdk.internal.logger.LazyLoggers$LazyLoggerAccessor.<init>(LazyLoggers.java:126) at java.base/jdk.internal.logger.LazyLoggers$LazyLoggerAccessor.makeAccessor(LazyLoggers.java:293) at java.base/jdk.internal.logger.LazyLoggers$JdkLazyLogger.<init>(LazyLoggers.java:372) at java.base/jdk.internal.logger.LazyLoggers.getLazyLogger(LazyLoggers.java:443) at java.base/sun.util.logging.PlatformLogger.getLogger(PlatformLogger.java:297) at java.base/java.lang.invoke.ProxyClassesDumper.getInstance(ProxyClassesDumper.java:79) at java.base/java.lang.invoke.InnerClassLambdaMetafactory.<clinit>(InnerClassLambdaMetafactory.java:102) ... 15 more The member that is null (which triggers this NPE) is the following member in java.lang.Class: // set by VM private transient Module module; Looking at the stacktrace it appears that during the boot sequence, the java.lang.reflect.AccessFlag in its static init code is using lambdas which seems to be triggering the above code in ProxyClassesDumper. The usage of lambdas in AccessFlag is only very recent change through https://bugs.openjdk.org/browse/JDK-8289106. Perhaps it should instead use anonymous classes? The reason why this fails only on Windows on mach5, I think, is because booting from a CDS archive is perhaps disabled on Windows (I don't know, I'm just guessing here) and hence it enters the ModuleBootstrap.boot2() method on Windows (from ModuleBootstrap.boot())? On other setups, my experiments show that it uses CDS archive to bootstrap the bootlayer and hence doesn't end up in that code (during the boot sequence). To reproduce this consistently on all setups, the following change to the test should help (I pass -Xshare:off to the Java launch command in the test to disable CDS archive usage): diff --git a/test/jdk/java/lang/invoke/lambda/LogGeneratedClassesTest.java b/test/jdk/java/lang/invoke/lambda/LogGeneratedClassesTest.java index d75e9b4d2a5..f9779be6f3c 100644 --- a/test/jdk/java/lang/invoke/lambda/LogGeneratedClassesTest.java +++ b/test/jdk/java/lang/invoke/lambda/LogGeneratedClassesTest.java @@ -145,8 +145,12 @@ public class LogGeneratedClassesTest extends LUtils { "-cp", ".", "-Djava.security.manager=allow", "-Djdk.internal.lambda.dumpProxyClasses=notExist", + "-Xshare:off", "com.example.TestLambda"); - assertEquals(tr.testOutput.stream() + final List<String> processOutput = tr.testOutput; + System.err.println("Process output from testDumpDirNotExist: "); + processOutput.forEach(System.err::println); + assertEquals(processOutput.stream() .filter(s -> s.startsWith("WARNING")) .filter(s -> s.contains("does not exist")) .count(), @@ -161,8 +165,12 @@ public class LogGeneratedClassesTest extends LUtils { "-cp", ".", "-Djava.security.manager=allow", "-Djdk.internal.lambda.dumpProxyClasses=file", + "-Xshare:off", "com.example.TestLambda"); - assertEquals(tr.testOutput.stream() + final List<String> processOutput = tr.testOutput; + System.err.println("Process output from testDumpDirIsFile: "); + processOutput.forEach(System.err::println); + assertEquals(processOutput.stream() .filter(s -> s.startsWith("WARNING")) .filter(s -> s.contains("not a directory")) .count(),

17-08-2022