Update protobuf/grpc/tcnative dependencies

[garrettjonesgoogle]

Grpc: Now = 1.0.3; update to 1.2.0
Protobuf: Now = 3.0.0 & 3.0.2 (depending on where); update to 3.2.0
netty-tcnative: Now = 1.1.33.Fork19; update to 1.1.33.Fork26

Note: this also involves updating the generated grpc packages and gax.

[garrettjonesgoogle]

Also do googleapis/gax-java#186 while we're at it (move from grpc-all to more minimal grpc dependency set)

[kinow]

I'd suggest updating netty-tcnative to 2.x as per netty/netty#5766

Right now it is blocking using 0.9.4-alpha (or 0.8.0 or 0.7.0) in Linux+Tomcat / SpringBoot+TomcatEmbeddedServletContainer / or Elastic Beanstalk + Tomcat8

[garrettjonesgoogle]

@kinow , Is it blocking because of conflicting netty versions? What version of netty does your version of Tomcat depend on?

[kinow]

I have successfully deployed the application using Jetty, and packaging it as an executable war. I'm in the process of creating a smaller example that can be uploaded to GitHub, and also a blog post about it.

My guess is that google-cloud-java is using a version of netty lower than 2.x. Because of that this application is loading a version of netty-tcnative-boringssl-static that loads a class in a package from Apache Tomcat.

What happens in this application, is that it successfully starts up with Spring Boot, then during my first request it will create the authentication tokens and submit the first request. This request is simply never processed, and after a few moments I will see a DEADLINE_EXCEEDED exception (IIRC, at home right now).

I believe that updating to netty-tcnative 2.x, this issue will be gone, and google-cloud-java should be fully compatible with Spring Boot + Tomcat.

[kinow]

Here's an example project.

https://github.com/kinow/gs-spring-boot/tree/reproduce-google-nlp-issue/complete

Here's the diff: spring-guides/gs-spring-boot@master...kinow:reproduce-google-nlp-issue

I forked the Spring Boot Getting Started sample application, which is using the latest version of Spring Boot. Created a branch, and added google-cloud-language 0.9.4-alpha (used the sample code from https://cloud.google.com/natural-language/docs/samples).

If you start the original project with mvn clean spring-boot:run, you will see a page with just the "Greetings from Spring Boot!" text. Starting the branch (you may have to export JSON credentials location via envVar), instead of seeing that message, you will get a Whitelabel Error Page (default error handler page for SpringBoot apps). Looking at the logs, you will find the following exception:

io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED
	at io.grpc.Status.asRuntimeException(Status.java:545) ~[grpc-core-1.0.3.jar:1.0.3]
	at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:442) ~[grpc-stub-1.0.3.jar:1.0.3]
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:481) ~[grpc-core-1.0.3.jar:1.0.3]
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:398) ~[grpc-core-1.0.3.jar:1.0.3]
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:513) ~[grpc-core-1.0.3.jar:1.0.3]
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:52) ~[grpc-core-1.0.3.jar:1.0.3]
	at io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:154) ~[grpc-core-1.0.3.jar:1.0.3]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_121]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_121]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_121]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_121]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]

In the branch pom.xml, I added the entries to use Jetty instead of Tomcat embedded container. Uncommenting those lines and running again with mvn clean spring-boot:run, you will have Jetty embedded container, which works fine with Google Cloud NLP API.

Adding an exclusion to io.netty:netty-tcnative-boringssl-static to google-cloud-language does not work. The issue persists, and you still get a DEADLINE EXCEEDED exception.

I've cloned the google-cloud-java locally. Updated all dependencies as suggested in this issue, except for Grpc which was breaking the tests, installed a snapshot locally, and updated the example to use google-cloud-java:0.9.5-alpha-SNAPSHOT. All tests in google-cloud-java passed, and the application also started up successfully, but the issue persisted.

Simply updating netty-tcnative to 2.x won't fix the issue. My guess now is that with a version of grpc-netty (and hence a newer version of netty, compatible with netty-tcnative 2.x) the issue may be fixed. Will file a new issue for that, once I have some more time to debug the problem. Sorry for hijacking this issue.

Bruno

[garrettjonesgoogle]

This is blocked on artman updates to fix grpc package generation (googleapis/gapic-generator#803). cc @shinfan

[buchgr]

@kinow
the DEADLINE_EXCEEDED and any netty-tcnative issues seem unrelated.

• gRPC uses netty-tcnative to use openssl/boringssl instead of the JDK's (slower) TLS implementation.
• The gRPC protocol supports deadlines/timeouts, so that when making an RPC call you can set an upper limit on how long this call may take, if this time is exceeded you get the DEADLINE_EXCEEDED. Google Cloud NLP is likely just setting a timeout somewhere.

So while an updated tcnative might fix your tomcat issues, it won't fix any DEADLINE_EXCEEDED errors.

[kinow]

@buchgr

You could be right. If I find time next week I will debug what happens in the Google Cloud NLP API. So far what I noticed is that when using Tomcat with Google Cloud NLP, I can see that it

• instantiates the channel and executors thread
• successfully finds the credentials and crafts a request payload
• an asynchronous request is sent (or prepared to be sent? will use Wireshark or debug in Eclipse next time)
• the timeout expires (agree with what you said about a timeout being set somewhere), and then I receive the DEADLINE_EXCEEDED exception.

When I replace Tomcat by Jetty, the three first steps are successfully executed. And then the fourth step (where DEADLINE_EXCEEDED exception happens) works with no exception.

The first time I debugged in Eclipse I noticed either in the console or logs, a message with a Google Cloud URL and the 443 (can't really remember off the top of my head, but it was something like "opening connection to cloud.google.com 443").

Next time I debug it, I will work with the hypothesis that when I use Tomcat; some thing (interface/class/service loader/native library/etc) provided by both netty-tcnative and Tomcat fails when it tries to open a SSL connection to the google cloud server. Then either the connection is never successfully established, or maybe something else happens, and the Future class times out.

First thing I will do is probably fire Wireshark and just see what client / server are sending with Jetty and with Tomcat.

Cheers
Bruno

[kinow]

Had some time before going to sleep. Running the sample application with Tomcat embedded container, I still get the DEADLINE_EXCEEDED exception. Filtering packages in wireshark (query: (ip.src eq 192.168.20.3 and tcp.dstport eq 443 and ip.dst eq 172.217.25.45) or ip.src eq 172.217.25.45), I can see some TCP packages being transmitted. Among the initial ones I can see one that contains accounts.google.com.

So client is sending the packages to the server. For some reason it is getting stuck and timing out.

[garrettjonesgoogle]

cc @ejona86 here is another example of the DEADLINE_EXCEEDED issue.

@buchgr and @kinow , this is very likely caused by an issue with loading netty-tcnative, similar to #1430 and #1772 . Basically when netty-tcnative doesn't load right, there is some misbehavior somewhere and grpc accepts the request but it never successfully gets issued, so the only thing that stops it is whatever timeout is set. I filed issue grpc/grpc-java#2599 against grpc-java asking for them to make the error messaging more accurate.

To be sure, you need to set your logging level to FINE to see if you see logs that say Unable to load the library: netty-tcnative-linux-x86_64.

[kinow]

Thanks @garrettjonesgoogle

Note to self, check the logs :-) Here's the output after adding a logback file like this:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                %d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n
            </Pattern>
        </layout>
    </appender>

    <root level="ALL">
        <appender-ref ref="STDOUT" />
    </root>

</configuration>

Omitting only the access settings

2017-03-24 11:00:48 [http-nio-8080-exec-1] DEBUG s.n.w.p.http.HttpURLConnection - sun.net.www.MessageHeader@7b62dbc614 pairs: {null: HTTP/1.1 200 OK}{Content-Type: application/json; charset=utf-8}{X-Content-Type-Options: nosniff}{Cache-Control: no-cache, no-store, max-age=0, must-revalidate}{Pragma: no-cache}{Expires: Mon, 01 Jan 1990 00:00:00 GMT}{Date: Thu, 23 Mar 2017 22:00:48 GMT}{Content-Disposition: attachment; filename="json.txt"; filename*=UTF-8''json.txt}{Content-Encoding: gzip}{Server: ESF}{X-XSS-Protection: 1; mode=block}{X-Frame-Options: SAMEORIGIN}{Alt-Svc: quic=":443"; ma=2592000; v="37,36,35"}{Transfer-Encoding: chunked}
2017-03-24 11:00:48 [http-nio-8080-exec-1] INFO  c.g.api.client.http.HttpTransport - -------------- RESPONSE --------------
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: quic=":443"; ma=2592000; v="37,36,35"
Server: ESF
X-Content-Type-Options: nosniff
Pragma: no-cache
Date: Thu, 23 Mar 2017 22:00:48 GMT
X-Frame-Options: SAMEORIGIN
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Content-Disposition: attachment; filename="json.txt"; filename*=UTF-8''json.txt
Content-Encoding: gzip
Expires: Mon, 01 Jan 1990 00:00:00 GMT
X-XSS-Protection: 1; mode=block
Content-Type: application/json; charset=utf-8

2017-03-24 11:00:48 [http-nio-8080-exec-1] INFO  c.g.api.client.http.HttpTransport - Total: 1,118 bytes
2017-03-24 11:00:48 [http-nio-8080-exec-1] INFO  c.g.api.client.http.HttpTransport - {
  "access_token" : "*****",
  "expires_in" : 3600,
  "id_token" : "*****",
  "token_type" : "Bearer"
}
2017-03-24 11:00:48 [http-nio-8080-ClientPoller-1] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=1; now=1490306448614; nextExpiration=1490306447991; keyCount=0; hasEvents=false; eval=false
2017-03-24 11:00:48 [pool-2-thread-1] DEBUG io.grpc.internal.ManagedChannelImpl - [ManagedChannelImpl@2d6d265] TransportSet@323e2231 created for [language.googleapis.com/216.58.203.106:443, language.googleapis.com/216.58.199.74:443, language.googleapis.com/172.217.25.138:443, language.googleapis.com/216.58.196.138:443, language.googleapis.com/216.58.199.42:443, language.googleapis.com/172.217.25.170:443, language.googleapis.com/216.58.200.106:443, language.googleapis.com/2404:6800:4006:803:0:0:0:200a:443]
2017-03-24 11:00:48 [pool-2-thread-1] DEBUG i.n.u.internal.NativeLibraryLoader - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
2017-03-24 11:00:48 [pool-2-thread-1] DEBUG i.n.u.internal.NativeLibraryLoader - -Dio.netty.native.workdir: /tmp (io.netty.tmpdir)
2017-03-24 11:00:48 [pool-2-thread-1] DEBUG i.n.u.internal.NativeLibraryLoader - Successfully loaded the library: netty-tcnative-linux-x86_64
2017-03-24 11:00:48 [pool-2-thread-1] DEBUG io.netty.handler.ssl.OpenSsl - Failed to initialize netty-tcnative; OpenSslEngine will be unavailable. See http://netty.io/wiki/forked-tomcat-native.html for more information.
java.lang.UnsatisfiedLinkError: no provided in java.library.path
	at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1867)
	at java.lang.Runtime.loadLibrary0(Runtime.java:870)
	at java.lang.System.loadLibrary(System.java:1122)
	at org.apache.tomcat.jni.Library.<init>(Library.java:80)
	at org.apache.tomcat.jni.Library.initialize(Library.java:180)
	at io.netty.handler.ssl.OpenSsl.initializeTcNative(OpenSsl.java:385)
	at io.netty.handler.ssl.OpenSsl.<clinit>(OpenSsl.java:110)
	at io.grpc.netty.GrpcSslContexts.defaultSslProvider(GrpcSslContexts.java:137)
	at io.grpc.netty.GrpcSslContexts.configure(GrpcSslContexts.java:119)
	at io.grpc.netty.GrpcSslContexts.forClient(GrpcSslContexts.java:90)
	at io.grpc.netty.NettyChannelBuilder.createProtocolNegotiator(NettyChannelBuilder.java:265)
	at io.grpc.netty.NettyChannelBuilder$NettyTransportFactory.newClientTransport(NettyChannelBuilder.java:324)
	at io.grpc.internal.CallCredentialsApplyingTransportFactory.newClientTransport(CallCredentialsApplyingTransportFactory.java:62)
	at io.grpc.internal.TransportSet.startNewTransport(TransportSet.java:215)
	at io.grpc.internal.TransportSet.obtainActiveTransport(TransportSet.java:192)
	at io.grpc.internal.ManagedChannelImpl$3.getTransport(ManagedChannelImpl.java:651)
	at io.grpc.internal.ManagedChannelImpl$3.getTransport(ManagedChannelImpl.java:592)
	at io.grpc.DummyLoadBalancerFactory$DummyLoadBalancer$1.get(DummyLoadBalancerFactory.java:135)
	at io.grpc.internal.DelayedClientTransport$2.run(DelayedClientTransport.java:262)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
2017-03-24 11:00:48 [http-nio-8080-ClientPoller-0] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=0; now=1490306448993; nextExpiration=1490306448992; keyCount=0; hasEvents=false; eval=false
2017-03-24 11:00:49 [http-nio-8080-ClientPoller-1] DEBUG o.apache.tomcat.util.net.NioEndpoint - timeout completed: keys processed=1; now=1490306449615; nextExpiration=1490306449614; keyCount=0; hasEvents=false; eval=false

[garrettjonesgoogle]

@shinfan when you do this in the generated packages, at the same time it would be nice to convert from depending on grpc-all to depending on more granular grpc packages.

[pongad]

@garrettjonesgoogle Updated. Do we want to close this now? Or are there pending items?

[kinow]

When there is a new release of google-cloud-java, I can try building the language-api and test it (or even better if there was an updated release of language-api). Feel free to close this issue in the meantime, will comment here with the result of the testing for posteriority

[garrettjonesgoogle]

It looks like the tcnative dependency didn't get updated - it seems that this time, the newer grpc still works with the previous tcnative. In any case, I think it would be prudent to update it before releasing.

[garrettjonesgoogle]

I have updated the tcnative dependency. Closing out this issue now.

[buchgr]

thanks @garrettjonesgoogle and @pongad