Openj9: Test-sanity.system-JDK8-linux_ppc-64_cmprssptrs_le MauveMultiThreadLoadTest_0 java.security.AccessControlException: access denied

Created on 11 Feb 2019 · 15Comments · Source: eclipse/openj9

https://ci.eclipse.org/openj9/job/Test-sanity.system-JDK8-linux_ppc-64_cmprssptrs_le/234

01:20:29.105 - First failure detected by thread: load-2. Not creating dumps as no dump generation is requested for this load test
01:20:29.107 - Test failed
  Failure num.  = 1
  Test number   = 3033
  Test details  = 'Mauve[gnu.testlet.java.net.HttpURLConnection.requestPropertiesTest]'
  Suite number  = 0
  Thread number = 2
>>> Captured test output >>>
PASS: gnu.testlet.java.net.HttpURLConnection.requestPropertiesTest: Default properties (number 0)
Test failed:
java.lang.ExceptionInInitializerError
    at java.lang.J9VMInternals.ensureError(J9VMInternals.java:146)
    at java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:135)
    at sun.net.www.protocol.http.Handler.openConnection(Handler.java:62)
    at sun.net.www.protocol.http.Handler.openConnection(Handler.java:57)
    at java.net.URL.openConnection(URL.java:979)
    at gnu.testlet.java.net.HttpURLConnection.requestPropertiesTest.test_Properties(requestPropertiesTest.java:63)
    at gnu.testlet.java.net.HttpURLConnection.requestPropertiesTest.test(requestPropertiesTest.java:44)
    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 net.adoptopenjdk.loadTest.adaptors.MauveAdaptor.executeTest(MauveAdaptor.java:74)
    at net.adoptopenjdk.loadTest.LoadTestRunner$2.run(LoadTestRunner.java:182)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:813)
Caused by: java.security.AccessControlException: access denied
    at gnu.testlet.java.util.logging.Handler.TestSecurityManager.checkPermission(TestSecurityManager.java:48)
    at java.util.logging.LogManager.checkPermission(LogManager.java:1586)
    at java.util.logging.Logger.setParent(Logger.java:2035)
    at java.util.logging.LogManager$7.run(LogManager.java:1205)
    at java.security.AccessController.doPrivileged(AccessController.java:647)
    at java.util.logging.LogManager.doSetParent(LogManager.java:1202)
    at java.util.logging.LogManager.access$1200(LogManager.java:145)
    at java.util.logging.LogManager$LoggerContext.addLocalLogger(LogManager.java:830)
    at java.util.logging.LogManager$LoggerContext.addLocalLogger(LogManager.java:758)
    at java.util.logging.LogManager$SystemLoggerContext.demandLogger(LogManager.java:927)
    at java.util.logging.LogManager.demandSystemLogger(LogManager.java:581)
    at java.util.logging.Logger.getPlatformLogger(Logger.java:576)
    at java.util.logging.LoggingProxyImpl.getLogger(LoggingProxyImpl.java:41)
    at sun.util.logging.LoggingSupport.getLogger(LoggingSupport.java:100)
    at sun.util.logging.PlatformLogger$JavaLoggerProxy.<init>(PlatformLogger.java:602)
    at sun.util.logging.PlatformLogger$JavaLoggerProxy.<init>(PlatformLogger.java:597)
    at sun.util.logging.PlatformLogger.<init>(PlatformLogger.java:239)
    at sun.util.logging.PlatformLogger.getLogger(PlatformLogger.java:198)
    at sun.net.www.protocol.http.HttpURLConnection.<clinit>(HttpURLConnection.java:431)
    ... 14 more
<<<

test test failure

Source

pshipton

Most helpful comment

I also opened https://github.com/AdoptOpenJDK/openjdk-systemtest/issues/263 for the above.

pshipton on 21 May 2019

👍2

All 15 comments

The test code snippet in question is as following

public class TestSecurityManager
  extends SecurityManager
{
  private boolean grantLogging = false;

  private final Permission controlPermission
    = new LoggingPermission("control", null);

  private SecurityManager oldManager;

  public void checkPermission(Permission perm)
  {
    if (controlPermission.implies(perm) && !grantLogging)
      throw new AccessControlException("access denied", perm);  --> failure was here
  }

This appears a problem to set the value of grantLogging. However it is not immediate clear from the stacktrace how this variable is controlled.
Also it is interesting to note that this was a sole failure in past ten runs.

Can we launch a grinder to determine the failure rate?

JasonFengJ9 on 12 Feb 2019

@JasonFengJ9 please try an internal grinder first and if it can't be recreated I will try externally.

pshipton on 12 Feb 2019

👍1

Not able to reproduce in a 30x grinder, so please try in an eclipse grinder instead.

JasonFengJ9 on 13 Feb 2019

https://ci.eclipse.org/openj9/view/Test/job/Test-Grinder/270/

pshipton on 13 Feb 2019

Reproduced once at gnu.testlet.java.util.logging.Logger.TestSecurityManager (initial failure was gnu.testlet.java.util.logging.Handler.TestSecurityManager).

 Caused by: java.security.AccessControlException: access denied: ("java.util.logging.LoggingPermission" "control")
LT      at gnu.testlet.java.util.logging.Logger.TestSecurityManager.checkPermission(TestSecurityManager.java:48)
LT      at java.util.logging.LogManager.checkPermission(LogManager.java:1586)

The code in question is similar.

package gnu.testlet.java.util.logging.Logger;
...
public class TestSecurityManager
  extends SecurityManager
{
  private boolean grantLogging = false;

  private final Permission controlPermission
    = new LoggingPermission("control", null);

  private SecurityManager oldManager;

  public void checkPermission(Permission perm)
  {
    if (controlPermission.implies(perm) && !grantLogging)
      throw new AccessControlException("access denied: " + perm, perm);  --> failed here
  }

JasonFengJ9 on 13 Feb 2019

Update

This a MauveMultiThreadLoadTest which involves multiple threads:

LT  01:20:28.199 - Parameters for suite 0
LT  01:20:28.199 -   Suite name     = mauve
LT  01:20:28.199 -   Number threads = 15

The test code snippet LoadTestRunner.java in question:

        ExecutorService es = Executors.newCachedThreadPool();   
        int nextThreadNum = 0;
        for (int i=0; i<suites.size(); i++) {
            final SuiteData suite = suites.get(i);
            for (int t=0; t<suite.getNumberThreads(); t++) {
                final int threadNum = nextThreadNum++;
                final AtomicLong numberPassingTests = passingTestCounters[suite.getSuiteId()];
                final AtomicLong numberFailingTests = failingTestCounters[suite.getSuiteId()];              
                logger.info("Starting thread. Suite=" + suite.getSuiteId() + " thread=" + threadNum);
                // Start thread to run tests
                es.execute(new Runnable() {
                   public void run() {

The test scenario caused AccessControlException: access denied:

One thread run a security related test, installed gnu.testlet.java.util.logging.Handler.TestSecurityManager and set the flag grantLogging accordingly (false to indicate the permission not granted);
Before the thread above finishes and uninstall the gnu.testlet.java.util.logging.Handler.TestSecurityManager, another thread starts running gnu.testlet.java.net.HttpURLConnection.requestPropertiesTest (or similar tests invoking security sensitive APIs like java.util.logging.Logger.setParent), unexpectedly invokes gnu.testlet.java.util.logging.Handler.TestSecurityManager.checkPermission() and eventually hits AccessControlException: access denied.

Solution proposed
The fix would be to break the test mauve_multiThread.xml into two groups, one contains security related tests with references to gnu.testlet.TestSecurityManager, gnu.testlet.java.util.logging.Handler.TestSecurityManager or gnu.testlet.java.util.logging.Logger.TestSecurityManager, the other contains rest of existing tests. The group containing security tests should run with single thread since installing SecurityManager has JVM wide impact.

@smlambert @Mesbah-Alam could you arrange such a modification?

JasonFengJ9 on 15 Feb 2019

We could give it a try. @Mesbah-Alam is away until March, not sure if @lumpfish has any spare cycles for this work?

smlambert on 15 Feb 2019

I'll move the security related tests out of the multi-threaded version of the mauve load tests and put them into the single-threaded version.

Mesbah-Alam on 28 Mar 2019

I downloaded the Mauve test source and performed a search based on the 3 classes mentioned in https://github.com/eclipse/openj9/issues/4681#issuecomment-464166070 above:

Tests with reference to : gnu.testlet.TestSecurityManager

./gnu/testlet/java/net/NetworkInterface/security.java:35:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/net/URL/security.java:34:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/net/InetAddress/security.java:31:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/net/DatagramSocket/security.java:36:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/net/URLClassLoader/security.java:35:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/net/ServerSocket/security.java:34:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/net/Socket/security.java:34:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/util/logging/LogManager/Security.java:36:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/security/ProtectionDomain/Security.java:35:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/io/ObjectInputStream/security.java:32:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/io/File/security.java:40:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/io/ObjectOutputStream/security.java:34:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/io/FileOutputStream/security.java:33:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/io/RandomAccessFile/security.java:35:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/io/FileInputStream/security.java:33:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/reflect/AccessibleObject/security.java:35:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/Runtime/security.java:31:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/ClassLoader/security.java:33:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/System/security.java:31:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/ThreadGroup/insecurity.java:29:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/ThreadGroup/security.java:29:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/SecurityManager/thread.java:28:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/Class/security.java:34:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/Thread/insecurity.java:29:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/lang/Thread/security.java:33:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/awt/Graphics2D/security.java:37:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/awt/Robot/security.java:34:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/awt/Window/security.java:33:import gnu.testlet.TestSecurityManager;
./gnu/testlet/java/awt/Toolkit/security.java:37:import gnu.testlet.TestSecurityManager;
./Makefile.am:21:   $(srcdir)/gnu/testlet/TestSecurityManager.java \
./RunnerProcess.java:30:import gnu.testlet.TestSecurityManager;
./Makefile.in:178:  $(srcdir)/gnu/testlet/TestSecurityManager.java \

Tests with reference to : gnu.testlet.java.util.logging.Handler.TestSecurityManager

./ChangeLog:13124:  * gnu/testlet/java/util/logging/Handler/TestSecurityManager.java
./ChangeLog:21473:  gnu/testlet/java/util/logging/Handler/TestSecurityManager.java

Tests with reference to “gnu.testlet.java.util.logging.Logger.TestSecurityManager"

./ChangeLog:13126:  * gnu/testlet/java/util/logging/Logger/TestSecurityManager.java
./ChangeLog:21051:  * gnu/testlet/java/util/logging/Logger/TestSecurityManager.java 
./ChangeLog:21523:  gnu/testlet/java/util/logging/Logger/TestSecurityManager.java

Note: None of these tests are part of mauve_multiThread.xml

Looking at the failure exception trace in this PR, and also in https://github.com/eclipse/openj9/issues/5288, it seems that, the tests (e.g. gnu.testlet.java.net.HttpURLConnection.requestPropertiesTest) are not directly referencing the 3 classes in concern, but are referencing other classes who in tern are referencing them (e.g. HttpURLConnection conn = (HttpURLConnection) url.openConnection(); - for the case of the exception in this issue).

So, we should be excluding the tests (from multithreaded mauve load test runs) where the above scenario is happening.

Mesbah-Alam on 28 Mar 2019

grep -rnw . -e "(HttpURLConnection) url.openConnection();":

./gnu/testlet/java/net/URLConnection/post.java:34:  HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/URLConnection/URLConnectionTest.java:446:      HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/illegalStateException.java:43:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/reuseConnection.java:334:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/reuseConnection.java:354:        conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/reuseConnection.java:377:        conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/reuseConnection.java:397:        conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/reuseConnection.java:453:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/reuseConnection.java:472:        conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/reuseConnection.java:505:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/reuseConnection.java:524:        conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/nullPointerException.java:42:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/requestPropertiesTest.java:63:        HttpURLConnection conn = (HttpURLConnection) url.openConnection(); **(excluded)**
./gnu/testlet/java/net/HttpURLConnection/requestPropertiesTest.java:123:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/fileNotFound.java:45:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/getRequestProperty.java:42:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/postHeaders.java:128:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/responseCodeTest.java:122:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/getOutputStream.java:45:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/timeout.java:164:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/timeout.java:184:        conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/timeout.java:198:        conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/timeout.java:234:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();
./gnu/testlet/java/net/HttpURLConnection/responseHeadersTest.java:120:        HttpURLConnection conn = (HttpURLConnection) url.openConnection(); **(excluded)**
./gnu/testlet/java/net/HttpURLConnection/responseHeadersTest.java:277:        HttpURLConnection conn = (HttpURLConnection) url.openConnection();

Note: there were two tests found to be excluded from mauve_multiThread.xml -- the rest are either not present or already excluded. The tests excluded from mauve_multiThread.xml are present in mauve_all_.xml . So, we they will keep running in the "single" threaded variation of the mauve load tests.

Mesbah-Alam on 28 Mar 2019

Another occurrence: https://ci.eclipse.org/openj9/job/Test_openjdk12_j9_sanity.system_ppc64le_linux_Nightly/37/tapResults/. This is MauveMultiThreadLoadTest_OpenJ9_0.
fyi: @Mesbah-Alam

JasonFengJ9 on 21 May 2019

👍1

I also opened https://github.com/AdoptOpenJDK/openjdk-systemtest/issues/263 for the above.

pshipton on 21 May 2019

👍2

The failing subtest will be permanently disabled: https://github.com/AdoptOpenJDK/openjdk-systemtest/pull/265

Mesbah-Alam on 21 May 2019

Assuming this is resolved, we can reopen if we find another test that fails.

pshipton on 24 May 2019

Another failure at https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_ppc64le_linux_Nightly/59/tapResults/