search

spotify / helios

Docker container orchestration platform
Apache License 2.0
2.11k stars 234 forks source link

helios-cli incompatibilities with Java 9 / 10 #1158

Open mattnworb opened 7 years ago

mattnworb commented 7 years ago

I am creating this issue to start to catalog some incompatibilities with Java 9's new module system.

[mattbrown@mattbrown-air ~]$ java -version
java version "9"
Java(TM) SE Runtime Environment (build 9+181)
Java HotSpot(TM) 64-Bit Server VM (build 9+181, mixed mode)
  1. If the ~/.helios directory contains cached certificates, an exception is encountered when loading them and the operation never succeeds.
$ helios -z https://some-master.example.net:443 masters
16:09:31.758 WARN  RetryingRequestDispatcher: Failed to connect to http://helios/masters/?user=mattbrown, retrying in 5 seconds. Exception chain was: java.lang.RuntimeException: java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.io.IOException: getSecretKey failed: Password is not ASCII, java.security.spec.InvalidKeySpecException: Password is not ASCII
16:09:36.769 WARN  RetryingRequestDispatcher: Failed to connect to http://helios/masters/?user=mattbrown, retrying in 5 seconds. Exception chain was: java.lang.RuntimeException: java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.io.IOException: getSecretKey failed: Password is not ASCII, java.security.spec.InvalidKeySpecException: Password is not ASCII

with more logs:

$ helios -vvvv -z https://some-master.example.net:443 mastersmasters
16:09:51.779 DEBUG Utils: using HeliosClient httpTimeout=30, retryTimeout=120
16:09:51.879 DEBUG GoogleCredentialsAccessTokenProvider: Using Google Application Default Credentials
16:09:52.434 DEBUG AgentProxies$DefaultAgentProxy: connected to [family=PF_UNIX path=/private/tmp/com.apple.launchd.bLCjuWG8cR/Listeners]
16:09:52.451 DEBUG AgentOutput: Sent SSH2_AGENTC_REQUEST_IDENTITIES message to ssh-agent.
16:09:52.451 DEBUG AgentInput: Received SSH2_AGENT_IDENTITIES_ANSWER message from ssh-agent.
16:09:52.545 DEBUG AuthenticatingHttpConnector: connecting to https://192.121.53.77:443/masters/?user=mattbrown
16:09:52.545 DEBUG AuthenticatingHttpConnector: Add Authorization header with bearer token
16:09:52.576 TRACE DefaultHttpConnector: req: GET https://192.121.53.77:443/masters/?user=mattbrown 2 Helios-Version=[0.9.156],Authorization=[Bearer ya29.Gl3ZBH1iJxqWqVObtRuaHGSxPR7lbPR_PaZSA46Lgv2o5yrzOoOhakz2EZiUOkd_iBRTHx6ag5VxI-kg3RRe3a1DaXPAnnCKNXnj0Z8qnY6zDpQPg5GQgMkac_R2pUw] 0 ""
16:09:52.577 DEBUG HostnameVerifierProvider: configuring DefaultHostnameVerifier to expect hostname=sto3-heliosmaster-a3.sto3.spotify.net
16:09:52.611 DEBUG X509CachingCertKeyCreator: using existing cert for mattbrown fromPaths /Users/mattbrown/.helios/54bfe47d.crt
16:09:52.620 WARN  RetryingRequestDispatcher: Failed to connect to http://helios/masters/?user=mattbrown, retrying in 5 seconds. Exception chain was: java.lang.RuntimeException: java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII, java.io.IOException: getSecretKey failed: Password is not ASCII, java.security.spec.InvalidKeySpecException: Password is not ASCII
16:09:52.623 DEBUG RetryingRequestDispatcher: Specific reason for connection failure follows
java.lang.RuntimeException: java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII
        at com.spotify.sshagenttls.CertHttpsHandler.handle(CertHttpsHandler.java:127)
        at com.spotify.sshagenttls.SshAgentHttpsHandler.handle(SshAgentHttpsHandler.java:34)
        at com.spotify.helios.client.DefaultHttpConnector.handleHttps(DefaultHttpConnector.java:143)
        at com.spotify.helios.client.DefaultHttpConnector.connect0(DefaultHttpConnector.java:105)
        at com.spotify.helios.client.DefaultHttpConnector.connect(DefaultHttpConnector.java:71)
        at com.spotify.helios.client.AuthenticatingHttpConnector.doConnect(AuthenticatingHttpConnector.java:202)
        at com.spotify.helios.client.AuthenticatingHttpConnector.connectWithIdentities(AuthenticatingHttpConnector.java:179)
        at com.spotify.helios.client.AuthenticatingHttpConnector.connect(AuthenticatingHttpConnector.java:126)
        at com.spotify.helios.client.DefaultRequestDispatcher$1.call(DefaultRequestDispatcher.java:71)
        at com.spotify.helios.client.DefaultRequestDispatcher$1.call(DefaultRequestDispatcher.java:67)
        at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111)
        at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:58)
        at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:299)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.base/java.lang.Thread.run(Thread.java:844)
Caused by: java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII
        at java.base/sun.security.pkcs12.PKCS12KeyStore.setKeyEntry(PKCS12KeyStore.java:664)
        at java.base/sun.security.pkcs12.PKCS12KeyStore.engineSetKeyEntry(PKCS12KeyStore.java:560)
        at java.base/sun.security.util.KeyStoreDelegator.engineSetKeyEntry(KeyStoreDelegator.java:111)
        at java.base/java.security.KeyStore.setKeyEntry(KeyStore.java:1174)
        at com.spotify.sshagenttls.CertHttpsHandler.handle(CertHttpsHandler.java:108)
        ... 18 common frames omitted
Caused by: java.security.UnrecoverableKeyException: Encrypt Private Key failed: getSecretKey failed: Password is not ASCII
        at java.base/sun.security.pkcs12.PKCS12KeyStore.encryptPrivateKey(PKCS12KeyStore.java:911)
        at java.base/sun.security.pkcs12.PKCS12KeyStore.setKeyEntry(PKCS12KeyStore.java:600)
        ... 22 common frames omitted
Caused by: java.io.IOException: getSecretKey failed: Password is not ASCII
        at java.base/sun.security.pkcs12.PKCS12KeyStore.getPBEKey(PKCS12KeyStore.java:828)
        at java.base/sun.security.pkcs12.PKCS12KeyStore.encryptPrivateKey(PKCS12KeyStore.java:892)
        ... 23 common frames omitted
Caused by: java.security.spec.InvalidKeySpecException: Password is not ASCII
        at java.base/com.sun.crypto.provider.PBEKey.<init>(PBEKey.java:64)
        at java.base/com.sun.crypto.provider.PBEKeyFactory.engineGenerateSecret(PBEKeyFactory.java:219)
        at java.base/javax.crypto.SecretKeyFactory.generateSecret(SecretKeyFactory.java:344)
        at java.base/sun.security.pkcs12.PKCS12KeyStore.getPBEKey(PKCS12KeyStore.java:824)
        ... 24 common frames omitted
  1. With no cached certificates, then the operation fails due to java.lang.NoClassDefFoundError: org/omg/CORBA/portable/IDLEntity when generating the certificate.
$ helios -vvvv -z https://some-master.example.net:443 masters
16:10:31.127 DEBUG Utils: using HeliosClient httpTimeout=30, retryTimeout=120
16:10:31.223 DEBUG GoogleCredentialsAccessTokenProvider: Using Google Application Default Credentials
16:10:31.751 DEBUG AgentProxies$DefaultAgentProxy: connected to [family=PF_UNIX path=/private/tmp/com.apple.launchd.bLCjuWG8cR/Listeners]
16:10:31.770 DEBUG AgentOutput: Sent SSH2_AGENTC_REQUEST_IDENTITIES message to ssh-agent.
16:10:31.770 DEBUG AgentInput: Received SSH2_AGENT_IDENTITIES_ANSWER message from ssh-agent.
16:10:31.898 DEBUG AuthenticatingHttpConnector: connecting to https://192.121.53.77:443/masters/?user=mattbrown
16:10:31.898 DEBUG AuthenticatingHttpConnector: Add Authorization header with bearer token
16:10:31.938 TRACE DefaultHttpConnector: req: GET https://192.121.53.77:443/masters/?user=mattbrown 2 Helios-Version=[0.9.156],Authorization=[Bearer ya29.Gl3ZBH05SdNuqN_AF1dLKLjcBvUTJuhzVEatKL1hzGsm8nz_t3C_pdMO7BAXyJcsM-CHbV0qHEw1C_fMeE9GrzwPQ8PES_TeCoebc_p7QUJl5ZLjumI-JW_HG7vHS3k] 0 ""
16:10:31.939 DEBUG HostnameVerifierProvider: configuring DefaultHostnameVerifier to expect hostname=sto3-heliosmaster-a3.sto3.spotify.net
16:10:31.945 WARN  RetryingRequestDispatcher: Failed to connect to http://helios/masters/?user=mattbrown, retrying in 5 seconds. Exception chain was: java.lang.NoClassDefFoundError: org/omg/CORBA/portable/IDLEntity, java.lang.ClassNotFoundException: org.omg.CORBA.portable.IDLEntity
16:10:31.948 DEBUG RetryingRequestDispatcher: Specific reason for connection failure follows
java.lang.NoClassDefFoundError: org/omg/CORBA/portable/IDLEntity
        at java.base/java.lang.ClassLoader.defineClass1(Native Method)
        at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1007)
        at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:174)
        at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:801)
        at java.base/jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(BuiltinClassLoader.java:699)
        at java.base/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:622)
        at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:580)
        at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:185)
        at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:496)
        at com.spotify.sshagenttls.X509CertKeyCreator.createCertKey(X509CertKeyCreator.java:100)
        at com.spotify.sshagenttls.X509CachingCertKeyCreator.createCertKey(X509CachingCertKeyCreator.java:118)
        at com.spotify.sshagenttls.SshAgentHttpsHandler.createCertKey(SshAgentHttpsHandler.java:107)
        at com.spotify.sshagenttls.CertHttpsHandler.handle(CertHttpsHandler.java:70)
        at com.spotify.sshagenttls.SshAgentHttpsHandler.handle(SshAgentHttpsHandler.java:34)
        at com.spotify.helios.client.DefaultHttpConnector.handleHttps(DefaultHttpConnector.java:143)
        at com.spotify.helios.client.DefaultHttpConnector.connect0(DefaultHttpConnector.java:105)
        at com.spotify.helios.client.DefaultHttpConnector.connect(DefaultHttpConnector.java:71)
        at com.spotify.helios.client.AuthenticatingHttpConnector.doConnect(AuthenticatingHttpConnector.java:202)
        at com.spotify.helios.client.AuthenticatingHttpConnector.connectWithIdentities(AuthenticatingHttpConnector.java:179)
        at com.spotify.helios.client.AuthenticatingHttpConnector.connect(AuthenticatingHttpConnector.java:126)
        at com.spotify.helios.client.DefaultRequestDispatcher$1.call(DefaultRequestDispatcher.java:71)
        at com.spotify.helios.client.DefaultRequestDispatcher$1.call(DefaultRequestDispatcher.java:67)
        at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111)
        at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:58)
        at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:299)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.base/java.lang.Thread.run(Thread.java:844)
Caused by: java.lang.ClassNotFoundException: org.omg.CORBA.portable.IDLEntity
        at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:582)
        at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:185)
        at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:496)
        ... 31 common frames omitted
  1. When using the --domains (or -d) flag to have the helios masters looked up dynamically, a warning is output about "illegal reflective access" (and then the request fails as 2 above). Note that this warning does not prevent the action but currently (in Java 9) just warns about it - in the future it will be denied.
$ helios -d guc3 masters
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.spotify.helios.client.shaded.org.xbill.DNS.ResolverConfig (file:/usr/local/Cellar/helios/0.9.156/libexec/helios-tools-0.9.156-shaded.jar) to method sun.net.dns.ResolverConfiguration.open()
WARNING: Please consider reporting this to the maintainers of com.spotify.helios.client.shaded.org.xbill.DNS.ResolverConfig
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
16:13:35.025 WARN  RetryingRequestDispatcher: Failed to connect to http://helios/masters/?user=mattbrown, retrying in 5 seconds. Exception chain was: java.lang.NoClassDefFoundError: org/omg/CORBA/portable/IDLEntity, java.lang.ClassNotFoundException: org.omg.CORBA.portable.IDLEntity
mattnworb commented 7 years ago

3 has been reported in dns-java at https://sourceforge.net/p/dnsjava/bugs/58/ , but I have no idea if anyone watches that sourceforge project or maintains it.

mattnworb commented 7 years ago

1 and 2 both originate in https://github.com/spotify/ssh-agent-tls

mattnworb commented 6 years ago

Noting for posterity that the same warnings/problems apply to Java 10 as well.

mattnworb commented 6 years ago

Reopening as there are still several warnings printed when using Java 9 or 10 about "Illegal reflective access" which I think we should track. #1213 only fixed one issue.

$ java -version
java version "10.0.1" 2018-04-17
Java(TM) SE Runtime Environment 18.3 (build 10.0.1+10)
Java HotSpot(TM) 64-Bit Server VM 18.3 (build 10.0.1+10, mixed mode)

Illegal reflective access in com.spotify.helios.client.DefaultHttpConnector 

$ helios -z http://localhost:5801 masters
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.spotify.helios.client.DefaultHttpConnector (file:/usr/local/Cellar/helios/0.9.207/libexec/helios-tools-0.9.207-shaded.jar) to field java.net.HttpURLConnection.method
WARNING: Please consider reporting this to the maintainers of com.spotify.helios.client.DefaultHttpConnector
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
9e3182d622e9.

The issue from org.xbill.DNS.ResolverConfig is still there:

$ helios -d site masters
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.spotify.helios.client.shaded.org.xbill.DNS.ResolverConfig (file:/usr/local/Cellar/helios/0.9.207/libexec/helios-tools-0.9.207-shaded.jar) to method sun.net.dns.ResolverConfiguration.open()
WARNING: Please consider reporting this to the maintainers of com.spotify.helios.client.shaded.org.xbill.DNS.ResolverConfig
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
master1
master2
master3
master4
master5

Neither of these prevent the CLI from working but a) it is a big scary warning message that might confuse people b) in a future Java release these operations will be denied.

mattnworb commented 6 years ago

The DefaultHttpConnector warning is coming from

https://github.com/spotify/helios/blob/a11f2bed3c22352430498cd4272c48ba330d8eff/helios-client/src/main/java/com/spotify/helios/client/DefaultHttpConnector.java#L147-L171

I'm unclear why this code is using reflection to set this field when HttpUrlConnection.setRequestMethod(String) has existed for quite a while (at least as far back as Java 1.5) and seems to allow GET, POST, PUT, DELETE, HEAD etc since that far back as well according to the javadocs

vbhavsar commented 6 years ago

Just wanted to add that adding --illegal-access=warn to the java command that runs helios emits warnings for more methods in org.xbill.DNS.ResolverConfig:

➜  helios git:(master) ✗ cat /usr/local/bin/helios
#!/bin/bash
exec java --illegal-access=warn -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Xverify:none -jar /usr/local/Cellar/helios/0.9.170/libexec/helios-tools-0.9.170-shaded.jar "$@"
➜  helios git:(master) ✗ helios -z http://localhost:5801 masters
WARNING: Illegal reflective access by com.spotify.helios.client.DefaultHttpConnector (file:/usr/local/Cellar/helios/0.9.170/libexec/helios-tools-0.9.170-shaded.jar) to field java.net.HttpURLConnection.method
WARNING: Illegal reflective access by org.xbill.DNS.ResolverConfig (file:/usr/local/Cellar/helios/0.9.170/libexec/helios-tools-0.9.170-shaded.jar) to method sun.net.dns.ResolverConfiguration.open()
WARNING: Illegal reflective access by org.xbill.DNS.ResolverConfig (file:/usr/local/Cellar/helios/0.9.170/libexec/helios-tools-0.9.170-shaded.jar) to method sun.net.dns.ResolverConfiguration.nameservers()
WARNING: Illegal reflective access by org.xbill.DNS.ResolverConfig (file:/usr/local/Cellar/helios/0.9.170/libexec/helios-tools-0.9.170-shaded.jar) to method sun.net.dns.ResolverConfiguration.searchlist()
b07806a15aa3.
davidxia commented 6 years ago

After applying #1245, I still see the following transitive error.

helios -z https://heliosmaster:443 -k masters

WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.xbill.DNS.ResolverConfig (file:/Users/dxia/.m2/repository/dnsjava/dnsjava/2.1.7/dnsjava-2.1.7.jar) to method sun.net.dns.ResolverConfiguration.open()
WARNING: Please consider reporting this to the maintainers of org.xbill.DNS.ResolverConfig
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release

...

Process finished with exit code 0

Upgrading dnsjava:dnsjava to 2.1.8 doesn't help. Outstanding bug report here.

davidxia commented 6 years ago

I'm unclear why this code is using reflection to set this field when HttpUrlConnection.setRequestMethod(String) has existed for quite a while (at least as far back as Java 1.5) and seems to allow GET, POST, PUT, DELETE, HEAD etc since that far back as well according to the javadocs

@mattnworb Looks like using that method causes everything to blow up. See failed tests here https://github.com/spotify/helios/pull/1245.