When configuring TLS, getting vague error "Couldn't find the address for the requested channel"

[nddipiazza]

I've got a TLS enabled grpc server that won't let me connect to it and I get a bland error: io.grpc.StatusRuntimeException: UNAVAILABLE: Channel closed while performing protocol negotiation

https://github.com/nddipiazza/grpc-java/tree/Add-Tls-HelloWorld

Tested from OS

Linux mate 4.13.0-26-generic #29~16.04.2-Ubuntu SMP Tue Jan 9 22:00:44 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

gRPC version

Issue happens on master branch.

OpenSSL version

OpenSSL 1.0.2g 1 Mar 2016

Reproducer

I created a reproducer on https://github.com/nddipiazza/grpc-java/tree/Add-Tls-HelloWorld

I am using the server certs from grpc-java/testing/src/main/resources/certs

Steps to reproduce

1. git clone https://github.com/nddipiazza/grpc-java $GRPC_JAVA_DIR

2. cd $GRPC_JAVA_DIR; git checkout Add-Tls-HelloWorld

3. cd $GRPC_JAVA_DIR/examples; ../gradlew -PskipCodegen=true installDist

4. In a new terminal open $GRPC_JAVA_DIR/examples/build/install/examples/bin/hello-world-server-tls

5. In a new terminal open $GRPC_JAVA_DIR/examples/build/install/examples/bin/hello-world-client-tls

6. Check the SSL configuration using: openssl s_client -showcerts -connect localhost:50051

openssl s_client -showcerts -connect localhost:50051
CONNECTED(00000003)
depth=0 CN = localhost
verify error:num=18:self signed certificate
verify return:1
depth=0 CN = localhost
verify return:1
---
Certificate chain
 0 s:/CN=localhost
   i:/CN=localhost
-----BEGIN CERTIFICATE-----
MIIEnDCCAoQCAQEwDQYJKoZIhvcNAQELBQAwFDESMBAGA1UEAwwJbG9jYWxob3N0
MB4XDTE4MDEyMzE2MjkzN1oXDTE5MDEyMzE2MjkzN1owFDESMBAGA1UEAwwJbG9j
YWxob3N0MIICIjANBgkqhkiG9w0BAQEFAAOCAg8AMIICCgKCAgEA9dT0cLk2rwMy
lV54viVC7r3Thtc3S8ZRX4jUE6vQDbA9TzitXz3fh7/pSEDOji82MPxHk6tlk5KS
GRLGxIT3lHlebnk1yTC4ToQAaJ32xEtHRL50vvDyYSsYnz8vudbJFCJNCo4RCoSs
cWRDqBEQwzc8PirBYS0T2KNN9ijBM5GFMlo+bHmdkq54SDj4LQ6AiXp0mb6NJbT0
tSbTd/KT3zJ4no4c2SX+PO2UaJ8TADETcMpCpKrWoghlyld0XrGZ5uFZ+aAmW7cu
GrCUI+7LGUM7xgN00q3RuREcTe40xQl4EVDH82x9IsJUUmIMujrv/pDvhx8DzGho
V6EjdWiE9rYqHKvHq0FmssR6mTi37TLSKjV3v8r5lkoTIDNnmF0+Ht/ZU4YTHjWE
Usy6JgO3BEA2RoG+AttKmA/gV+ckpSPW+LdNT6fOe4OKD6QdOcNJs3uFADoGNOVj
2WYObuPx2RIvkVmRu8YTf52iPnWxhd0NZvwy7S0Cy1KuNNzASoQZfv5GaETlqV9x
6ks/g8jVx5iYd71i4uoFE+flsDljXKCqZJzoyhXdZCTSdJf3t7zzGVQQN3lyX0DP
QydfdoWyV6NWp2jtD87YnImI7OcC8Ef5Ada+hHQ3jltqAPEdDOplC5CAqGza4hHv
bjzNNp2+DnBt4cEAJ7g/DdmWTGBGOmsCAwEAATANBgkqhkiG9w0BAQsFAAOCAgEA
ags5gJnUZmUChTSdClnrOWoJYP/GrlPmXMXGU5uROaOnZMl0SXpuYKRaMzn7JL6n
JGXIpMvmc+9gA5wsyzXe8yEDVKSXM26banZWwTKwCDiIxXoyp9DsvI7EZKDFSg3R
sfwCIweKuPdqznibV5adBO+wfMsIpg7lZx5xGt63p99SD4lq7goKYDJ/AW/FePTN
PSL8C8RqaDo8vbMrb/8btkVnFM9ZqVL9r6VGuul/+FyVFVtyqLDNqL4XWxQRDHwX
kCiuMb1CpiX3JqnbA63dM7W6wtkuw5XZMBEB+KtGqWA9XbLMXWfQ1WuwjUcWeuQM
PrYcd6TYBhZnhsc43SBtVthf/R4TPn0MTt5y0cLy7BMiSL3BSmRXDTtDepn7B9qr
IIDFfGO3RabWPNtgiJxQofdgrAYUPAi5RlQap/7GlSHMLJYhBf+mmlzE/v7YH4zk
S4YUPC3YFioTgBuiElYkFEJ7Np4jmWqBfqxsjrcveapYJmnKcGmh+ueLSB0gufu7
HQPHANersfMv49s7a5T9ns/Y9bZssAUhVsJoKjcBPGUDZn9ME1+eVcU0hwwW8jyY
U3AkSF+/jgokgrDy70cd90tDMe/L6L8M4uoU1VfH1c9LbRKstKKLIaVeosxq7kD1
EwuLwW1eny57q5WeSJq/s8R/Ai7OT3zgY5KK9uwwXes=
-----END CERTIFICATE-----
---
Server certificate
subject=/CN=localhost
issuer=/CN=localhost
---
No client certificate CA names sent
Peer signing digest: SHA256
Server Temp Key: ECDH, P-256, 256 bits
---
SSL handshake has read 1945 bytes and written 431 bytes
---
New, TLSv1/SSLv3, Cipher is ECDHE-RSA-AES256-GCM-SHA384
Server public key is 4096 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : ECDHE-RSA-AES256-GCM-SHA384
    Session-ID: 95D0BA5A02188E1E1AF518D6FF02941AAE1D3535C5256F3BBBAEED9C2DDDDEC6
    Session-ID-ctx: 
    Master-Key: C3E1D2404AE3039E95689F31C0AC45D1711027BE7B19EB3802130BB374BD4941004E35D4602D857C3CF03A901C7EB6A9
    Key-Arg   : None
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1516734011
    Timeout   : 300 (sec)
    Verify return code: 18 (self signed certificate)
---
read:errno=0

Results

Client gets the error: io.grpc.StatusRuntimeException: UNAVAILABLE: Channel closed while performing protocol negotiation with no other error indication of what's wrong.

Server output:

./build/install/examples/bin/hello-world-server-tls
Jan 23, 2018 12:55:16 PM io.grpc.examples.helloworldtls.HelloWorldServerTls start
INFO: Server started, listening on 50051

Client output:

./build/install/examples/bin/hello-world-client-tls
Jan 23, 2018 12:55:56 PM io.grpc.examples.helloworldtls.HelloWorldClientTls greet
INFO: Will try to greet world ...
Jan 23, 2018 12:55:57 PM io.grpc.examples.helloworldtls.HelloWorldClientTls greet
WARNING: RPC failed: Status{code=UNAVAILABLE, description=Channel closed while performing protocol negotiation, cause=null}

Expected results

Client should connect successfully. Just like hello-world-server / hello-world-client

[carl-mastrangelo]

Sadly, the original exception is lost in the stub code, so the only way to debug this is to modify the gRPC library to log the exception. Alternatively you can attach a debugger to see what happened.

[nddipiazza]

@carl-mastrangelo Would this be in the grpc java code? Or is it somehow in some sort of c/c++ library?
If you tell me where to debug, I can put in a breakpoint.

[carl-mastrangelo]

This can happen if the server closes the connection prematurely, after the client has sent its hello. There should be a server log message complaining about something. Do you see such an exception?

I have stepped through the code a couple times now, and in the event of a real SSL failure, the exception is saved and put somewhere, indicating where it happened. (See ProtocolNegotiators). This normally runs fist, but in rare cases the connection can be closed early, resulting in the vague error you see.

[nddipiazza]

No exception in the logs as far as i can see. Did you see my issue with reproducer steps? You can see the error in action pretty quick.

[carl-mastrangelo]

I did, and while there is a superficial problem with it (you need to install a keystore on your ManagedChannel), the issue you raised shows that the error message is unhelpful.

I tried to reproduce it on my machine, but I don't have your keys or certs which you set in the example. I was able to get the StatusRuntimeException you have, but in each case it was because the server terminated the connection early.

[nddipiazza]

Hi @carl-mastrangelo . thanks for spending some time on this.

The keys and certs are in the grpc-java project. https://github.com/grpc/grpc-java/tree/master/testing/src/main/resources/certs

I just pushed setting the trust store, and also added a keymanager on client... still same error.

but in each case it was because the server terminated the connection early.

Any idea why it's doing that? Is this a legit issue?

[carl-mastrangelo]

Minor update, I was able to reproduce this. The exception is in the SslHandler.wrap function, which gets back an error from the JDK: java.io.IOException: No data available in passed DER encoded value.

I'm not so keen on how the JDK parses SSL stuff, but that seems to be the current cause.

I think our error message is getting triggered too early, by the channel getting closed, which is why it isn't visible. You can probably debug faster starting by breaking on SslHandler.handleUnwrapThrowable

[nddipiazza]

confirmed https://github.com/grpc/grpc-java/pull/3997/files from https://github.com/carl-mastrangelo/grpc-java/tree/earyladd allows me to see the error

WARNING: RPC failed: Status{code=UNAVAILABLE, description=io exception, cause=javax.net.ssl.SSLHandshakeException: General OpenSslEngine problem
	at io.netty.handler.ssl.ReferenceCountedOpenSslContext$AbstractCertificateVerifier.verify(ReferenceCountedOpenSslContext.java:648)
	at io.netty.internal.tcnative.SSL.readFromSSL(Native Method)
	at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.readPlaintextData(ReferenceCountedOpenSslEngine.java:489)
	at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1039)
	at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1146)
	at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1189)
	at io.netty.handler.ssl.SslHandler$SslEngineType$1.unwrap(SslHandler.java:216)
	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1247)
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1158)
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1193)
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:489)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:138)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.security.cert.CertificateParsingException: java.io.IOException: No data available in passed DER encoded value.
	at sun.security.x509.X509CertImpl.getSubjectAlternativeNames(X509CertImpl.java:1684)
	at java.security.cert.X509Certificate.getSubjectAlternativeNames(X509Certificate.java:605)
	at sun.security.util.HostnameChecker.matchDNS(HostnameChecker.java:189)
	at sun.security.util.HostnameChecker.match(HostnameChecker.java:95)
	at sun.security.ssl.X509TrustManagerImpl.checkIdentity(X509TrustManagerImpl.java:455)
	at sun.security.ssl.X509TrustManagerImpl.checkIdentity(X509TrustManagerImpl.java:436)
	at sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:252)
	at sun.security.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:136)
	at io.netty.handler.ssl.ReferenceCountedOpenSslClientContext$ExtendedTrustManagerVerifyCallback.verify(ReferenceCountedOpenSslClientContext.java:221)
	at io.netty.handler.ssl.ReferenceCountedOpenSslContext$AbstractCertificateVerifier.verify(ReferenceCountedOpenSslContext.java:644)
	... 27 more
Caused by: java.io.IOException: No data available in passed DER encoded value.
	at sun.security.x509.GeneralNames.<init>(GeneralNames.java:61)
	at sun.security.x509.SubjectAlternativeNameExtension.<init>(SubjectAlternativeNameExtension.java:141)
	at sun.security.x509.X509CertImpl.getSubjectAlternativeNames(X509CertImpl.java:1670)
	... 36 more

[carl-mastrangelo]

@nddipiazza You mentioned you are using the certs from our repo, I'm still surprised to see them not be valid. Are you still having issues, or where you able to fix the IOException ?

[nddipiazza]

They didn't work with the No data available in passed DER encoded value. error above.
When I used the following script to generate certs: https://github.com/nddipiazza/grpc-java/blob/29f6ae04008930dbd8458210df90fdbc9db19a84/examples/README.md
It worked fine.