helios-cli incompatibilities with Java 9 / 10

[mattnworb]

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

2. 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

3. 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]

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]

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

[mattnworb]

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

[mattnworb]

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.