search

adoptium / aqa-tests

Home of test infrastructure for Adoptium builds
https://adoptium.net/aqavit
Apache License 2.0
129 stars 308 forks source link

extended.openjdk failure: com/sun/jndi/ldap/LdapTimeoutTest.java.LdapTimeoutTest #2355

Open andrew-m-leonard opened 3 years ago

andrew-m-leonard commented 3 years ago

com/sun/jndi/ldap/LdapTimeoutTest.java.LdapTimeoutTest https://ci.adoptopenjdk.net/job/Test_openjdk8_j9_extended.openjdk_x86-32_windows/14/consoleFull

12:45:18  openjdk version "1.8.0_292"
12:45:18  OpenJDK Runtime Environment (build 1.8.0_292-202103091148-b05)
12:45:18  Eclipse OpenJ9 VM (build openj9-0.26.0-m1, JRE 1.8.0 Windows Server 2012 R2 x86-32-Bit 20210309_870 (JIT enabled, AOT enabled)
12:45:18  OpenJ9   - b227feba2
12:45:18  OMR      - 4665e2f72
12:45:18  JCL      - 1780cbc92b based on jdk8u292-b05)
12:54:08  [TestNG] Running:
12:54:08    com/sun/jndi/ldap/LdapTimeoutTest.java
12:54:08  
12:54:08  Starting diagnostic output (probe)
12:54:08  config LdapTimeoutTest.beforeTest(): success
12:54:08  (probe) expected [ms.]: 0, actual [ms.]: 0
12:54:08  (probe) expected [ms.]: 500, actual [ms.]: 580
12:54:08  (probe) expected [ms.]: 1000, actual [ms.]: 1000
12:54:08  (probe) expected [ms.]: 1500, actual [ms.]: 1500
12:54:08  (probe) expected [ms.]: 2000, actual [ms.]: 1999
12:54:08  (probe) expected [ms.]: 2500, actual [ms.]: 2507
12:54:08  (probe) expected [ms.]: 3000, actual [ms.]: 2999
12:54:08  (probe) expected [ms.]: 3500, actual [ms.]: 3573
12:54:08  (probe) expected [ms.]: 4000, actual [ms.]: 4000
12:54:08  (probe) expected [ms.]: 4500, actual [ms.]: 4519
12:54:08  (probe) expected [ms.]: 5000, actual [ms.]: 5183
12:54:08  (probe) expected [ms.]: 5500, actual [ms.]: 5572
12:54:08  (probe) expected [ms.]: 6000, actual [ms.]: 6047
12:54:08  (probe) expected [ms.]: 6500, actual [ms.]: 6502
12:54:08  (probe) expected [ms.]: 7000, actual [ms.]: 7000
12:54:08  (probe) expected [ms.]: 7500, actual [ms.]: 7499
12:54:08  (probe) expected [ms.]: 8000, actual [ms.]: 8000
12:54:08  (probe) expected [ms.]: 8500, actual [ms.]: 8499
12:54:08  (probe) expected [ms.]: 9000, actual [ms.]: 8999
12:54:08  (probe) expected [ms.]: 9500, actual [ms.]: 9500
12:54:08  (probe) expected [ms.]: 10000, actual [ms.]: 10010
12:54:08  (probe) expected [ms.]: 500, actual [ms.]: 508
12:54:08  (probe) expected [ms.]: 1000, actual [ms.]: 1022
12:54:08  (probe) expected [ms.]: 1500, actual [ms.]: 1520
12:54:08  (probe) expected [ms.]: 2000, actual [ms.]: 2015
12:54:08  (probe) expected [ms.]: 2500, actual [ms.]: 2501
12:54:08  (probe) expected [ms.]: 3000, actual [ms.]: 3004
12:54:08  (probe) expected [ms.]: 3500, actual [ms.]: 3506
12:54:08  (probe) expected [ms.]: 4000, actual [ms.]: 4165
12:54:08  (probe) expected [ms.]: 4500, actual [ms.]: 4499
12:54:08  (probe) expected [ms.]: 5000, actual [ms.]: 5013
12:54:08  (probe) expected [ms.]: 5500, actual [ms.]: 5500
12:54:08  (probe) expected [ms.]: 6000, actual [ms.]: 6031
12:54:08  (probe) expected [ms.]: 6500, actual [ms.]: 6506
12:54:08  (probe) expected [ms.]: 7000, actual [ms.]: 7008
12:54:08  java.util.ServiceConfigurationError: com.sun.jndi.ldap.spi.LdapDnsProvider: Provider dnsprovider.MissingDnsProvider not found
12:54:08    at java.util.ServiceLoader.fail(ServiceLoader.java:239)
12:54:08    at java.util.ServiceLoader.access$300(ServiceLoader.java:185)
12:54:08    at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:372)
12:54:08    at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
12:54:08    at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
12:54:08    at com.sun.jndi.ldap.LdapDnsProviderService.lookupEndpoints(LdapDnsProviderService.java:101)
12:54:08    at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:166)
12:54:08    at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:243)
12:54:08    at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:154)
12:54:08    at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:84)
12:54:08    at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:684)
12:54:08    at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:313)
12:54:08    at javax.naming.InitialContext.init(InitialContext.java:244)
12:54:08    at javax.naming.InitialContext.<init>(InitialContext.java:216)
12:54:08    at javax.naming.directory.InitialDirContext.<init>(InitialDirContext.java:101)
12:54:08    at LdapTimeoutTest.test2(LdapTimeoutTest.java:161)
12:54:08    at LdapTimeoutTest.lambda$test$1(LdapTimeoutTest.java:113)
12:54:08    at LdapTimeoutTest$$Lambda$4/0x00000000.call(Unknown Source)
12:54:08    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
12:54:08    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
12:54:08    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
12:54:08    at java.lang.Thread.run(Thread.java:823)
12:54:08  test LdapTimeoutTest.test(): failure
12:54:08  java.lang.RuntimeException: 1 (sub)tests failed
12:54:08    at LdapTimeoutTest.test(LdapTimeoutTest.java:132)
12:54:08    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
12:54:08    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
12:54:08    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
12:54:08    at java.lang.reflect.Method.invoke(Method.java:498)
12:54:08    at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
12:54:08    at org.testng.internal.Invoker.invokeMethod(Invoker.java:639)
12:54:08    at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:821)
12:54:08    at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1131)
12:54:08    at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
12:54:08    at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:108)
12:54:08    at org.testng.TestRunner.privateRun(TestRunner.java:773)
12:54:08    at org.testng.TestRunner.run(TestRunner.java:623)
12:54:08    at org.testng.SuiteRunner.runTest(SuiteRunner.java:357)
12:54:08    at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:352)
12:54:08    at org.testng.SuiteRunner.privateRun(SuiteRunner.java:310)
12:54:08    at org.testng.SuiteRunner.run(SuiteRunner.java:259)
12:54:08    at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
12:54:08    at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
12:54:08    at org.testng.TestNG.runSuitesSequentially(TestNG.java:1185)
12:54:08    at org.testng.TestNG.runSuitesLocally(TestNG.java:1110)
12:54:08    at org.testng.TestNG.run(TestNG.java:1018)
12:54:08    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
12:54:08    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
12:54:08    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
12:54:08    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
12:54:08    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
12:54:08    at java.lang.reflect.Method.invoke(Method.java:498)
12:54:08    at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
12:54:08    at java.lang.Thread.run(Thread.java:823)
lumpfish commented 3 years ago

Also seen on test-macstadium-macos1014-x64-3: https://ci.adoptopenjdk.net/job/Test_openjdk8_j9_extended.openjdk_x86-64_mac/33/consoleFull Build

openjdk version "1.8.0_292"
OpenJDK Runtime Environment (build 1.8.0_292-b10)
Eclipse OpenJ9 VM (build openj9-0.26.0, JRE 1.8.0 Mac OS X amd64-64-Bit Compressed References 20210421_909 (JIT enabled, AOT enabled)
OpenJ9   - b4cc246d9
OMR      - 162e6f729
JCL      - 2a5e268814 based on jdk8u292-b10)

Output of failing test:

14:10:05  ACTION: testng -- Failed. Execution failed: `main' threw exception: java.lang.Exception: failures: 1
14:10:05  REASON: User specified action: run testng/othervm LdapTimeoutTest 
14:10:05  TIME:   160.984 seconds
14:10:05  messages:
14:10:05  command: testng LdapTimeoutTest
14:10:05  reason: User specified action: run testng/othervm LdapTimeoutTest 
14:10:05  Mode: othervm [/othervm specified]
14:10:05  elapsed time (seconds): 160.984
14:10:05  configuration:
14:10:05  STDOUT:
14:10:05  [TestNG] Running:
14:10:05    com/sun/jndi/ldap/LdapTimeoutTest.java
14:10:05  
14:10:05  Starting diagnostic output (probe)
14:10:05  (probe) expected [ms.]: 0, actual [ms.]: 0
14:10:05  config LdapTimeoutTest.beforeTest(): success
14:10:05  (probe) expected [ms.]: 500, actual [ms.]: 500
14:10:05  (probe) expected [ms.]: 1000, actual [ms.]: 1000
14:10:05  (probe) expected [ms.]: 1500, actual [ms.]: 1501
14:10:05  (probe) expected [ms.]: 2000, actual [ms.]: 2002
14:10:05  (probe) expected [ms.]: 2500, actual [ms.]: 2502
14:10:05  (probe) expected [ms.]: 3000, actual [ms.]: 3002
14:10:05  (probe) expected [ms.]: 3500, actual [ms.]: 3500
14:10:05  (probe) expected [ms.]: 4000, actual [ms.]: 4000
14:10:05  (probe) expected [ms.]: 4500, actual [ms.]: 4502
14:10:05  (probe) expected [ms.]: 5000, actual [ms.]: 5000
14:10:05  (probe) expected [ms.]: 5500, actual [ms.]: 5502
14:10:05  (probe) expected [ms.]: 6000, actual [ms.]: 6002
14:10:05  (probe) expected [ms.]: 6500, actual [ms.]: 6500
14:10:05  (probe) expected [ms.]: 7000, actual [ms.]: 7000
14:10:05  (probe) expected [ms.]: 7500, actual [ms.]: 7501
14:10:05  (probe) expected [ms.]: 8000, actual [ms.]: 8002
14:10:05  (probe) expected [ms.]: 8500, actual [ms.]: 8502
14:10:05  (probe) expected [ms.]: 9000, actual [ms.]: 9002
14:10:05  (probe) expected [ms.]: 9500, actual [ms.]: 9501
14:10:05  (probe) expected [ms.]: 10000, actual [ms.]: 10000
14:10:05  (probe) expected [ms.]: 500, actual [ms.]: 502
14:10:05  (probe) expected [ms.]: 1000, actual [ms.]: 1000
14:10:05  (probe) expected [ms.]: 1500, actual [ms.]: 1500
14:10:05  (probe) expected [ms.]: 2000, actual [ms.]: 2002
14:10:05  (probe) expected [ms.]: 2500, actual [ms.]: 2500
14:10:05  (probe) expected [ms.]: 3000, actual [ms.]: 3002
14:10:05  (probe) expected [ms.]: 3500, actual [ms.]: 3500
14:10:05  (probe) expected [ms.]: 4000, actual [ms.]: 4002
14:10:05  (probe) expected [ms.]: 4500, actual [ms.]: 4501
14:10:05  (probe) expected [ms.]: 5000, actual [ms.]: 5002
14:10:05  (probe) expected [ms.]: 5500, actual [ms.]: 5501
14:10:05  (probe) expected [ms.]: 6000, actual [ms.]: 6000
14:10:05  (probe) expected [ms.]: 6500, actual [ms.]: 6501
14:10:05  (probe) expected [ms.]: 7000, actual [ms.]: 7000
14:10:05  java.util.ServiceConfigurationError: com.sun.jndi.ldap.spi.LdapDnsProvider: Provider dnsprovider.MissingDnsProvider not found
14:10:05    at java.util.ServiceLoader.fail(ServiceLoader.java:239)
14:10:05    at java.util.ServiceLoader.access$300(ServiceLoader.java:185)
14:10:05    at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:372)
14:10:05    at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
14:10:05    at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
14:10:05    at com.sun.jndi.ldap.LdapDnsProviderService.lookupEndpoints(LdapDnsProviderService.java:101)
14:10:05    at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:166)
14:10:05    at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:243)
14:10:05    at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:154)
14:10:05    at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:84)
14:10:05    at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:695)
14:10:05    at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:313)
14:10:05    at javax.naming.InitialContext.init(InitialContext.java:244)
14:10:05    at javax.naming.InitialContext.<init>(InitialContext.java:216)
14:10:05    at javax.naming.directory.InitialDirContext.<init>(InitialDirContext.java:101)
14:10:05    at LdapTimeoutTest.test3(LdapTimeoutTest.java:176)
14:10:05    at LdapTimeoutTest.lambda$test$2(LdapTimeoutTest.java:114)
14:10:05    at LdapTimeoutTest$$Lambda$5/0x0000000000000000.call(Unknown Source)
14:10:05    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
14:10:05    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
14:10:05    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
14:10:05    at java.lang.Thread.run(Thread.java:823)
14:10:05  test LdapTimeoutTest.test(): failure
14:10:05  java.lang.RuntimeException: 1 (sub)tests failed
14:10:05    at LdapTimeoutTest.test(LdapTimeoutTest.java:132)
14:10:05    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
14:10:05    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
14:10:05    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
14:10:05    at java.lang.reflect.Method.invoke(Method.java:498)
14:10:05    at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
14:10:05    at org.testng.internal.Invoker.invokeMethod(Invoker.java:639)
14:10:05    at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:821)
14:10:05    at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1131)
14:10:05    at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
14:10:05    at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:108)
14:10:05    at org.testng.TestRunner.privateRun(TestRunner.java:773)
14:10:05    at org.testng.TestRunner.run(TestRunner.java:623)
14:10:05    at org.testng.SuiteRunner.runTest(SuiteRunner.java:357)
14:10:05    at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:352)
14:10:05    at org.testng.SuiteRunner.privateRun(SuiteRunner.java:310)
14:10:05    at org.testng.SuiteRunner.run(SuiteRunner.java:259)
14:10:05    at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
14:10:05    at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
14:10:05    at org.testng.TestNG.runSuitesSequentially(TestNG.java:1185)
14:10:05    at org.testng.TestNG.runSuitesLocally(TestNG.java:1110)
14:10:05    at org.testng.TestNG.run(TestNG.java:1018)
14:10:05    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
14:10:05    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
14:10:05    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
14:10:05    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
14:10:05    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
14:10:05    at java.lang.reflect.Method.invoke(Method.java:498)
14:10:05    at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
14:10:05    at java.lang.Thread.run(Thread.java:823)
14:10:05  
14:10:05  ===============================================
14:10:05  com/sun/jndi/ldap/LdapTimeoutTest.java
14:10:05  Total tests run: 1, Failures: 1, Skips: 0
14:10:05  ===============================================
14:10:05  
14:10:05  STDERR:
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer start
14:10:05  INFO: Starting server at port 52,304
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer start
14:10:05  INFO: Starting server at port 52,303
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server is accepting connections at port 52,303
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer start
14:10:05  INFO: Starting server at port 52,301
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server is accepting connections at port 52,301
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer start
14:10:05  INFO: Starting server at port 52,305
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server is accepting connections at port 52,305
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer start
14:10:05  INFO: Starting server at port 52,300
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server is accepting connections at port 52,300
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer close
14:10:05  INFO: Stopping server at port 52,303
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server is accepting connections at port 52,304
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Accepted new connection at Socket[addr=/127.0.0.1,port=52307,localport=52300]
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer start
14:10:05  INFO: Starting server at port 52,306
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server is accepting connections at port 52,306
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Accepted new connection at Socket[addr=/127.0.0.1,port=52311,localport=52306]
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server stopped accepting connections at port 52,303
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Accepted new connection at Socket[addr=/127.0.0.1,port=52310,localport=52304]
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Accepted new connection at Socket[addr=/127.0.0.1,port=52308,localport=52305]
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Accepted new connection at Socket[addr=/127.0.0.1,port=52309,localport=52301]
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer start
14:10:05  INFO: Starting server at port 52,302
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server is accepting connections at port 52,302
14:10:05  Apr 21, 2021 2:07:17 PM BaseLdapServer acceptConnections
14:10:05  INFO: Accepted new connection at Socket[addr=/127.0.0.1,port=52312,localport=52302]
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer close
14:10:05  INFO: Stopping server at port 52,301
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server stopped accepting connections at port 52,301
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer handleConnection
14:10:05  INFO: Connection Handler exit Socket is closed
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer close
14:10:05  INFO: Stopping server at port 52,304
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server stopped accepting connections at port 52,304
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer handleConnection
14:10:05  INFO: Connection Handler exit Socket is closed
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer close
14:10:05  INFO: Stopping server at port 52,306
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server stopped accepting connections at port 52,306
14:10:05  Apr 21, 2021 2:07:41 PM BaseLdapServer handleConnection
14:10:05  INFO: Connection Handler exit Socket is closed
14:10:05  Apr 21, 2021 2:08:37 PM BaseLdapServer close
14:10:05  INFO: Stopping server at port 52,305
14:10:05  Apr 21, 2021 2:08:37 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server stopped accepting connections at port 52,305
14:10:05  Apr 21, 2021 2:08:37 PM BaseLdapServer handleConnection
14:10:05  INFO: Connection Handler exit Socket closed
14:10:05  Apr 21, 2021 2:09:57 PM BaseLdapServer close
14:10:05  INFO: Stopping server at port 52,300
14:10:05  Apr 21, 2021 2:09:57 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server stopped accepting connections at port 52,300
14:10:05  Apr 21, 2021 2:09:57 PM BaseLdapServer handleConnection
14:10:05  INFO: Connection Handler exit Socket closed
14:10:05  Apr 21, 2021 2:09:57 PM BaseLdapServer close
14:10:05  INFO: Stopping server at port 52,302
14:10:05  Apr 21, 2021 2:09:57 PM BaseLdapServer acceptConnections
14:10:05  INFO: Server stopped accepting connections at port 52,302
14:10:05  Apr 21, 2021 2:09:57 PM BaseLdapServer handleConnection
14:10:05  INFO: Connection Handler exit Socket is closed
14:10:05  java.lang.Exception: failures: 1
14:10:05    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:96)
14:10:05    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
14:10:05    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
14:10:05    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
14:10:05    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
14:10:05    at java.lang.reflect.Method.invoke(Method.java:498)
14:10:05    at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
14:10:05    at java.lang.Thread.run(Thread.java:823)
14:10:05  
14:10:05  JavaTest Message: Test threw exception: java.lang.Exception: failures: 1
14:10:05  JavaTest Message: shutting down test
14:10:05  
14:10:05  STATUS:Failed.`main' threw exception: java.lang.Exception: failures: 1
lumpfish commented 3 years ago

This is intermittent - not been able to reproduce it on any of the three platforms it was recently seen on with the latest build (which for Mac was):

openjdk version "1.8.0_292-internal"
OpenJDK Runtime Environment (build 1.8.0_292-internal-202105031812-b10)
Eclipse OpenJ9 VM (build master-51fd0e1e4, JRE 1.8.0 Mac OS X amd64-64-Bit Compressed References 20210503_917 (JIT enabled, AOT enabled)
 OpenJ9   - 51fd0e1e4
OMR      - 79c52c726
JCL      - 2c626fee based on jdk8u292-b10)
lumpfish commented 3 years ago

It turns out that the test fails because it has a coexistence issue with another test, com/sun/jndi/ldap/LdapDnsProviderTest.java.

The other test, com/sun/jndi/ldap/LdapDnsProviderTest.java, creates a service provider file under META-INF/services, which points at a service which does not exist (dnsprovider.MissingDnsProvider) - the fact that the service does not exist is the purpose of the test. The file is not removed by the test before it completes.

The test failing in this issue, com/sun/jndi/ldap/LdapTimeoutTest.java, runs after that test, but the jdk 'sees' the service provider file because it is on the test's classpath. The test then tries to load the class for the service, which does not exist, and the jdk throws the exception

java.util.ServiceConfigurationError: com.sun.jndi.ldap.spi.LdapDnsProvider: Provider dnsprovider.MissingDnsProvider not found

The test does not catch the exception so the test fails.

This explains why when the failing test is rerun using jdk_custom it never fails as the other test is not run.

It gets more complicated.

The tests are run with a concurrency=nn argument. The value is assigned when the test makefiles are generated by TKG at runtime based on the number of CPUs found on the test machine. When concurrency=1, the classes for all tests in the run are compiled (by jtreg) to the same directory. All tests have the same classpath, so the error reported here is seen. When concurrency>1, the classes are built into a /0, /1, /2, etc. subdirectory, where the number is the concurrency thread instance the test is running under. When the two tests are run on different threads, their classes are therefore compiled to different directories, so the META-INF/services file created by the first test is not 'seen' by the second test and the test passes. When the two tests are run on the same thread, their classes are compiled to the same directory - basically the same situation as concurrency=1 and the test fails. This is the reason the test appears to fail intermittently when run across different builds, platforms and machines.

On jdk11+ jtreg isolates the classes for all tests into their own <testcase>.d directory, so there is no cross-test contamination and both tests pass regardless of the concurrency.

So what to do? The ideal fix would appear to be

  1. Change test com/sun/jndi/ldap/LdapDnsProviderTest.java to delete the META-INF/services provider file at the end of the test
  2. Change test com/sun/jndi/ldap/LdapTimeoutTest.java to catch the java.util.ServiceConfigurationError exception

These would need to be upstream contributions.

Test com/sun/jndi/ldap/LdapDnsProviderTest.java has another issue on jdk8 (which was fixed upstream on jdk11+): https://github.com/adoptium/aqa-tests/issues/2350. I suggest that that test (com/sun/jndi/ldap/LdapDnsProviderTest.java) be excluded until the test cases are modified upstream, which will enable com/sun/jndi/ldap/LdapTimeoutTest.java to pass consistently.

smlambert commented 3 years ago

That dependency is yucky, definitely agree on approaches to improvement upstream!

smlambert commented 3 years ago

how is this issue different than #2350 - they look like duplicates, can one of the 2 be closed as dup?

lumpfish commented 3 years ago

Not duplicates - but it is debatable whether this test should be changed..

This test succeeds if the https://github.com/adoptium/aqa-tests/issues/2350 test is excluded (as it now is), and that test could be changed to not leave behind the data which causes this test to fail. (It has another issue also which is the port it uses).

But this test could also be changed to catch the exception described in the comment above (https://github.com/adoptium/aqa-tests/issues/2355#issuecomment-839785098), which means it would no longer have a problem 'coexisting' with the https://github.com/adoptium/aqa-tests/issues/2350 test. (Any other test which started a service in the same test run would cause a similar failure).