[CI] SSLConfigurationReloaderTests fail on Java 11

[davidkyle]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java11,ES_RUNTIME_JAVA=java11,nodes=virtual&&linux/180
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java10,ES_RUNTIME_JAVA=java11,nodes=virtual&&linux/181

The failures are due to the test timing out

java.lang.Exception: Suite timeout exceeded (>= 1200000 msec).
	at __randomizedtesting.SeedInfo.seed([5DB61DD425F081B]:0)

And the logs show some interesting errors

1> java.lang.NullPointerException: null
1> 	at org.elasticsearch.xpack.core.ssl.SSLService$SSLContextHolder.invalidateSessions(SSLService.java:552) ~[main/:?]
1> 	at org.elasticsearch.xpack.core.ssl.SSLService$SSLContextHolder.reload(SSLService.java:558) ~[main/:?]
1> 	at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloader.reloadSSLContext(SSLConfigurationReloader.java:80) ~[main/:?]
1> 	at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests$5.reloadSSLContext(SSLConfigurationReloaderTests.java:447) ~[test/:?]
1> 	at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloader$ChangeListener.onFileChanged(SSLConfigurationReloader.java:120) ~

The test fails with a different error when I run it with Java 11

ERROR   0.06s | SSLConfigurationReloaderTests.testReloadingTrustStore <<< FAILURES!
   > Throwable #1: java.lang.RuntimeException: Error connecting to the mock server
   >    at __randomizedtesting.SeedInfo.seed([5DB61DD425F081B:A93AE0D293F69319]:0)
   >    at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests.lambda$testReloadingTrustStore$13(SSLConfigurationReloaderTests.java:216)
   >    at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests.validateSSLConfigurationIsReloaded(SSLConfigurationReloaderTests.java:455)
   >    at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests.testReloadingTrustStore(SSLConfigurationReloaderTests.java:238)
   >    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   >    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   >    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   >    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
   >    at java.base/java.lang.Thread.run(Thread.java:834)
   > Caused by: java.lang.NullPointerException
   >    at java.base/sun.security.ssl.SSLSessionImpl.getLocalPrincipal(SSLSessionImpl.java:661)
   >    at org.apache.http.impl.client.DefaultUserTokenHandler.getUserToken(DefaultUserTokenHandler.java:83)
   >    at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:327)
   >    at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184)
   >    at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88)
   >    at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
   >    at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)
   >    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
   >    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107)
   >    at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests.lambda$testReloadingTrustStore$12(SSLConfigurationReloaderTests.java:214)
   >    at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests.lambda$privilegedConnect$24(SSLConfigurationReloaderTests.java:533)
   >    at java.base/java.security.AccessController.doPrivileged(Native Method)
   >    at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests.privilegedConnect(SSLConfigurationReloaderTests.java:532)
   >    at org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests.lambda$testReloadingTrustStore$13(SSLConfigurationReloaderTests.java:214)
   >    ... 38 more

Reproduce:

./gradlew :x-pack:plugin:core:test \
  -Dtests.seed=5DB61DD425F081B \
  -Dtests.class=org.elasticsearch.xpack.core.ssl.SSLConfigurationReloaderTests \
  -Dtests.security.manager=true \
  -Dtests.locale=en-US \
  -Dtests.timezone=Etc/UTC

[elasticmachine]

Pinging @elastic/es-security

[cbuescher]

Some more of these today:

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java10,ES_RUNTIME_JAVA=java11,nodes=virtual&&linux/185/console
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java11,ES_RUNTIME_JAVA=java11,nodes=virtual&&linux/186/console

[tvernum]

This issue which @davidkyle hit locally:

   > Caused by: java.lang.NullPointerException
   >    at java.base/sun.security.ssl.SSLSessionImpl.getLocalPrincipal(SSLSessionImpl.java:661)

should be fixed. There was a bug in earlier JDK11 builds that's fixed in ea22.

However the issue that CI is reporting is a failure to do with getting sessions by id.

This code:

       private void invalidateSessions(SSLSessionContext sslSessionContext) {
            Enumeration<byte[]> sessionIds = sslSessionContext.getIds();
            while (sessionIds.hasMoreElements()) {
                byte[] sessionId = sessionIds.nextElement();
                sslSessionContext.getSession(sessionId).invalidate();
            }
        }

is causing a NPE on the getSession which is strange since the ID came from getIds on the same object.

@jkakavas is investigating.

[jkakavas]

It looks as if we get a rogue session in the sessionCache with JDK11.

The behavior of JDK10 is that getIds() returns one sessionId ( as expected as there has only been one connection to the MockServer that uses this context ) while in JDK11 we get 2 sessionIds and the following two cases

• Both sessionIds can be used to getSession() an SSLSession. The two SSLSessions seem to be almost identical but one is missing information regarding localPrincipal and localCertificates. In this case the test passes.
• One of the sessionIds can be used to getSession() an SSLSession while the other causes getSession() to return null which leads to an NPE.

This behavior only manifests when attempting to get the sessions for the serverContext and thus affects testPEMKeyConfigReloading and testReloadingKeyStore

I couldn't easily validate if this is a regression in ea22 since ea21 and earlier were affected by the getLocalPrincipal bug and this test fails eitherway.

I will attempt to make the error reproducible and submit an issue upstream if applicable

[tvernum]

One of the sessionIds can be used to getSession() an SSLSession while the other causes getSession() to return null which leads to an NPE.

Is it that the first invalidation causes the second session to be removed as well? Or was it always associated with a null SSLSession?

[tvernum]

Words are hard, and I realise my previous question isn't 100% clear so for clarification...
If we had the following code:

  public void testSessions(SSLSessionContext sslSessionContext) {
        List<byte[]> sessionIds = Collections.list(sslSessionContext.getIds());
        for (byte[] sessionId : sessionIds) {
            SSLSession session = sslSessionContext.getSession(sessionId)
            Objects.requireNotNull(session); // <<- A
        }
        for (byte[] sessionId : sessionIds) {
            SSLSession session = sslSessionContext.getSession(sessionId)
            Objects.requireNotNull(session); // <<- B
            session.invalidate();
        }
    } 

would we see a failure at A or at B (on the 2nd iteration of the loop)?

[jkakavas]

Spot on, the invalidate() call on the first session removes both, so the second getSession() call returns null. The two sessions share most of the information but have a different sessionId.
The behavior in 8,9,10 is different in that we only have the one session after the CloseableHttpClient connects. I can't seem to find anything related in the jdk11 docs that would indicate this is a purposeful change in behavior

[jkakavas]

This seems to be related to SSL Session initialization in TLS1.3.

For TLSv1.2 :

net.ssl|DEBUG|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[AAAF4D15951F68D8]|2018-07-23 03:55:55.846 EDT|SSLCipher.java:436|jdk.net.keyLimits:  entry = AES/GCM/NoPadding KeyUpdate 2^37. AES/GCM/NOPADDING:KEYUPDATE = 137438953472
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 03:55:57.126 EDT|SSLSessionImpl.java:202|Session initialized:  Session(1532332557126|SSL_NULL_WITH_NULL_NULL)
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 03:55:57.135 EDT|X509Authentication.java:241|No X.509 cert selected for EC
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 03:55:57.135 EDT|X509Authentication.java:241|No X.509 cert selected for EC
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 03:55:57.150 EDT|SSLSessionImpl.java:428|Negotiating session:  Session(1532332557126|TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384)
javax.net.ssl|ALL|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[AAAF4D15951F68D8]|2018-07-23 03:55:57.242 EDT|SSLSessionImpl.java:202|Session initialized:  Session(1532332557242|TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384)

while for TLSv1.3:

javax.net.ssl|DEBUG|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[19D93C9F49C87B1F]|2018-07-23 09:57:37.348 CEST|SSLCipher.java:436|jdk.net.keyLimits:  entry = AES/GCM/NoPadding KeyUpdate 2^37. AES/GCM/NOPADDING:KEYUPDATE = 137438953472
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 09:57:38.351 CEST|SSLSessionImpl.java:202|Session initialized:  Session(1532332658350|SSL_NULL_WITH_NULL_NULL)
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 09:57:38.354 CEST|SSLSessionImpl.java:428|Negotiating session:  Session(1532332658350|TLS_AES_128_GCM_SHA256)
javax.net.ssl|DEBUG|13|HTTP-Dispatcher|2018-07-23 09:57:38.368 CEST|SSLCipher.java:1823|KeyLimit read side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|DEBUG|13|HTTP-Dispatcher|2018-07-23 09:57:38.370 CEST|SSLCipher.java:1977|KeyLimit write side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 09:57:38.372 CEST|X509Authentication.java:241|No X.509 cert selected for EC
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 09:57:38.372 CEST|X509Authentication.java:241|No X.509 cert selected for EC
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 09:57:38.372 CEST|X509Authentication.java:241|No X.509 cert selected for EC
javax.net.ssl|DEBUG|13|HTTP-Dispatcher|2018-07-23 09:57:38.423 CEST|SSLCipher.java:1977|KeyLimit write side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|ALL|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[19D93C9F49C87B1F]|2018-07-23 09:57:38.425 CEST|SSLSessionImpl.java:202|Session initialized:  Session(1532332658425|TLS_AES_128_GCM_SHA256)
javax.net.ssl|DEBUG|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[19D93C9F49C87B1F]|2018-07-23 09:57:38.429 CEST|SSLCipher.java:1823|KeyLimit read side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|DEBUG|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[19D93C9F49C87B1F]|2018-07-23 09:57:38.430 CEST|SSLCipher.java:1977|KeyLimit write side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|DEBUG|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[19D93C9F49C87B1F]|2018-07-23 09:57:38.476 CEST|SSLCipher.java:1823|KeyLimit read side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|DEBUG|13|HTTP-Dispatcher|2018-07-23 09:57:38.479 CEST|SSLCipher.java:1823|KeyLimit read side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|ALL|13|HTTP-Dispatcher|2018-07-23 09:57:38.480 CEST|SSLSessionImpl.java:202|Session initialized:  Session(1532332658350|TLS_AES_128_GCM_SHA256)
javax.net.ssl|DEBUG|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[19D93C9F49C87B1F]|2018-07-23 09:57:38.483 CEST|SSLCipher.java:1977|KeyLimit write side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|ALL|0F|TEST-SSLConfigurationReloaderTests.testPEMKeyConfigReloading-seed#[19D93C9F49C87B1F]|2018-07-23 09:57:38.504 CEST|SSLSessionImpl.java:202|Session initialized:  Session(1532332658425|TLS_AES_128_GCM_SHA256)

This test uses a MockHttpServer and an SSLContext that is not bound by the supportedProtocols as an ES node would, and an Http client ( Apache HTTPClient ) that in jdk11 uses TLSv1.3 by default. This has the effect that TLSv1.3 is used and that leads to the observed behavior.
I will pin the HTTP client to use TLSv1.2 (even in JDK11) for now so that the failures are mitigated here and we will address TLSv1.3 support holistically starting in #32276

[tvernum]

I will pin the HTTP client to use TLSv1.2

Can we try pinning the server instead? We can't control clients, and we want to know that we can handle a TLSv1.3 client, even if that means forcing it to downgrade to 1.2