Can't connect to Cloudant through proxy

jwalcorn commented 3 years ago

Please read these guidelines before opening an issue.

Bug Description

1. Steps to reproduce and the simplest code sample possible to demonstrate the issue

I'm calling proxyURL on my ClientBuilder, but it doesn't seem to be getting used. Just getting a TimeoutException. The same program, used in an environment where a proxy isn't needed, works great. And that proxy (http://10.177.140.102:3128) works fine for other Java libraries I'm using. Note this proxy does NOT require credentials be passed, so I'm not calling proxyUser or proxyPassword on the ClientBuilder. Note the real app is an Open Liberty-based JAX-RS microservice running in the Tanzu Kubernetes Grid. But I've reproduced the problem with the following simpler code:

import com.cloudant.client.api.ClientBuilder;
import com.cloudant.client.api.CloudantClient;
import com.cloudant.client.api.Database;
import java.io.InputStream;
import java.net.URL;
import java.nio.charset.StandardCharsets;

public class CloudantTest {
    public static void main(String[] arg) {
        if (arg.length == 1) {
            System.out.println(getEntryFromCloudant(arg[0]));
        } else {
            System.out.println("Usage: CloudantTest <id>");
        }
    }

    public static String getEntryFromCloudant(String id) {
        String response = null;
        try {
            String url = System.getenv("CLOUDANT_URL");
            if ((url == null) || url.isEmpty()) return "CLOUDANT_URL not set";

            String username = System.getenv("CLOUDANT_ID");
            if ((username == null) || username.isEmpty()) return "CLOUDANT_ID not set";

            String password = System.getenv("CLOUDANT_PASSWORD");
            if ((password == null) || password.isEmpty()) return "CLOUDANT_PASSWORD not set";

            String db = System.getenv("CLOUDANT_DB");
            if ((db == null) || db.isEmpty()) return "CLOUDANT_DB not set";

            ClientBuilder builder = ClientBuilder.url(new URL(url)).username(username).password(password);

            String proxy = System.getenv("CLOUDANT_PROXY");
            if ((proxy != null) && !proxy.isEmpty()) {
                System.out.println("Adding proxy");
                builder = builder.proxyURL(new URL(proxy));
            }

            CloudantClient client = builder.build();

            Database database = client.database(db, false);

            InputStream stream = database.find(id);
            response = new String(stream.readAllBytes(), StandardCharsets.UTF_8);
        } catch (Throwable t) {
            t.printStackTrace();
            response = t.getMessage();
        }
        return response;
    }
}

And I'm using this manifest in the "executable" jar to get the class path setup right:

Manifest-Version: 1.0
Class-Path: cloudant-client-2.19.2.jar cloudant-http-2.19.2.jar gson-2.8.2.jar commons-io-2.4.jar
Main-Class: CloudantTest

2. What you expected to happen

The connection to Cloudant should have gone through the proxy out to the internet and worked. Here's the output from my test program above when I run it in an environment that doesn't need a proxy (like my laptop):

jalcorn@Johns-MBP-8 account % java -jar cloudantTest.jar 014aa25148df4eea85b15b3e81ce52d7              
{"_id":"014aa25148df4eea85b15b3e81ce52d7","_rev":"2-99b94bc1438706a4d92ad5611e8ffda9","owner":"Looper8","loyalty":"Basic","balance":40.01,"commissions":9.99,"free":0,"sentiment":"Unknown","nextCommission":9.99}

jalcorn@Johns-MBP-8 account %

3. What actually happened

I get the following exception when running the above when kubectl exec' d into the Kubernetes pod (which needs the proxy to get out to the internet):

com.cloudant.client.org.lightcouch.CouchDbException: Error retrieving server response at https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud:443/account/0004422e801c4590bab285e31b769ea4.
        at com.cloudant.client.org.lightcouch.CouchDbClient.execute(CouchDbClient.java:632)
        at com.cloudant.client.org.lightcouch.CouchDbClient.executeToInputStream(CouchDbClient.java:648)
        at com.cloudant.client.org.lightcouch.CouchDbClient.get(CouchDbClient.java:389)
        at com.cloudant.client.org.lightcouch.CouchDatabaseBase.find(CouchDatabaseBase.java:148)
        at com.cloudant.client.api.Database.find(Database.java:839)
        at CloudantTest.getEntryFromCloudant(CloudantTest.java:44)
        at CloudantTest.main(CloudantTest.java:11)
Caused by: java.io.IOException: Failed to read server response from  https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud:443/_session
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.wrapIOException(CookieInterceptorBase.java:263)
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.makeSessionRequest(CookieInterceptorBase.java:164)
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.requestCookie(CookieInterceptorBase.java:100)
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.interceptRequest(CookieInterceptorBase.java:176)
        at com.cloudant.http.HttpConnection.execute(HttpConnection.java:291)
        at com.cloudant.client.org.lightcouch.CouchDbClient.execute(CouchDbClient.java:552)
        ... 6 more
Caused by: java.net.ConnectException: Connection timed out (Connection timed out)
        at java.base/java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399)
        at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242)
        at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224)
        at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.base/java.net.Socket.connect(Socket.java:609)
        at java.base/sun.security.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:289)
        at java.base/sun.net.NetworkClient.doConnect(NetworkClient.java:177)
        at java.base/sun.net.www.http.HttpClient.openServer(HttpClient.java:474)
        at java.base/sun.net.www.http.HttpClient.openServer(HttpClient.java:569)
        at java.base/sun.net.www.protocol.https.HttpsClient.<init>(HttpsClient.java:265)
        at java.base/sun.net.www.protocol.https.HttpsClient.New(HttpsClient.java:372)
        at java.base/sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.getNewHttpClient(AbstractDelegateHttpsURLConnection.java:203)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1187)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1081)
        at java.base/sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:189)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1367)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1342)
        at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getOutputStream(HttpsURLConnectionImpl.java:246)
        at com.cloudant.http.HttpConnection.execute(HttpConnection.java:317)
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.makeSessionRequest(CookieInterceptorBase.java:140)
        ... 10 more

Environment details

Version(s) that are affected by this issue.

2.19.2
Java version including vendor and platform

Eclipse OpenJ9 VM, version 11.0.12+7 (en_US)
Using the optional okhttp dependency.

Yes

jwalcorn commented 3 years ago

There are some similarities to issue #282. However its proxy needed credentials, whereas mine doesn't. Note I am NOT using the JVM parameters that issue suggested.

ricellis commented 3 years ago

From the stack trace (and Class-Path) it looks like you are not using OkHttp, but that contradicts your provided "Environment details". Please confirm if you have seen the same error with both HTTP clients or whether the environment details are just incorrect so we can make sure we look in the right place, thanks.

jwalcorn commented 3 years ago

Sorry about that. I do have the okhttp dependency listed in the pom.xml for my microservice (at https://github.com/IBMStockTrader/account), so it is ending up in my war's WEB-INF/lib. And that's where I originally detected the problem. But then when I wrote my small test program I pasted here, I didn't end up adding that jar, and it's happening that way too (when I kubectl cp the jars up to the Kube pod and then kubectl exec into the pod to run it there). So it seems unrelated to that dependency.

Are there any trace strings or other debug settings I could enable that would provide additional useful info? Thanks.

emlaver commented 3 years ago

@jwalcorn can you enable FINE level logging and share the output? For more details, there's a logging section in our javadoc.io documentation.

jwalcorn commented 3 years ago

here you go:

sh-4.4$ java -Djava.util.logging.config.file=./logging.properties -jar cloudantTest.jar 014aa25148df4eea85b15b3e81ce52d7
Aug 14, 2021 3:27:31 AM com.cloudant.client.api.ClientBuilder <init>
CONFIG: URL: https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix:58819704e70bb791d81eb09847e8da2d69cb492ed4fe35a4e682e38c0785e5e9@878ff
489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud
Adding proxy
Aug 14, 2021 3:27:31 AM com.cloudant.client.api.ClientBuilder build
CONFIG: Building client using URL: https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud:443
Aug 14, 2021 3:27:32 AM com.cloudant.client.api.ClientBuilder build
CONFIG: Added cookie interceptor
Aug 14, 2021 3:27:32 AM com.cloudant.client.api.ClientBuilder build
CONFIG: Connect timeout: 5 MINUTES
Aug 14, 2021 3:27:32 AM com.cloudant.client.api.ClientBuilder build
CONFIG: Read timeout: 5 MINUTES
Aug 14, 2021 3:27:32 AM com.cloudant.client.api.ClientBuilder build
CONFIG: Using default GSON builder
Aug 14, 2021 3:27:32 AM com.cloudant.http.internal.ok.OkHelper <clinit>
FINE: Failed to load okhttp: okhttp3.OkUrlFactory
Aug 14, 2021 3:27:32 AM com.cloudant.client.org.lightcouch.CouchDbClient <init>
CONFIG: Using built-in HttpUrlConnection
Aug 14, 2021 3:27:32 AM com.cloudant.http.internal.DefaultHttpUrlConnectionFactory setProxy
CONFIG: Configured HTTP proxy url http://10.177.140.102:3128
Aug 14, 2021 3:27:32 AM com.cloudant.http.HttpConnection execute
FINE: c081e450-9 POST https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud:443/_session request
com.cloudant.client.org.lightcouch.CouchDbException: Error retrieving server response at https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud:443/account/014aa25148df4eea85b15b3e81ce52d7.
        at com.cloudant.client.org.lightcouch.CouchDbClient.execute(CouchDbClient.java:632)
        at com.cloudant.client.org.lightcouch.CouchDbClient.executeToInputStream(CouchDbClient.java:648)
        at com.cloudant.client.org.lightcouch.CouchDbClient.get(CouchDbClient.java:389)
        at com.cloudant.client.org.lightcouch.CouchDatabaseBase.find(CouchDatabaseBase.java:148)
        at com.cloudant.client.api.Database.find(Database.java:839)
        at CloudantTest.getEntryFromCloudant(CloudantTest.java:44)
        at CloudantTest.main(CloudantTest.java:11)
Caused by: java.io.IOException: Failed to read server response from  https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud:443/_session
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.wrapIOException(CookieInterceptorBase.java:263)
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.makeSessionRequest(CookieInterceptorBase.java:164)
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.requestCookie(CookieInterceptorBase.java:100)
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.interceptRequest(CookieInterceptorBase.java:176)
        at com.cloudant.http.HttpConnection.execute(HttpConnection.java:291)
        at com.cloudant.client.org.lightcouch.CouchDbClient.execute(CouchDbClient.java:552)
        ... 6 more
Caused by: java.net.ConnectException: Connection timed out (Connection timed out)
        at java.base/java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399)
        at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242)
        at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224)
        at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.base/java.net.Socket.connect(Socket.java:609)
        at java.base/sun.security.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:289)
        at java.base/sun.net.NetworkClient.doConnect(NetworkClient.java:177)
        at java.base/sun.net.www.http.HttpClient.openServer(HttpClient.java:474)
        at java.base/sun.net.www.http.HttpClient.openServer(HttpClient.java:569)
        at java.base/sun.net.www.protocol.https.HttpsClient.<init>(HttpsClient.java:265)
        at java.base/sun.net.www.protocol.https.HttpsClient.New(HttpsClient.java:372)
        at java.base/sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.getNewHttpClient(AbstractDelegateHttpsURLConnection.java:203)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1187)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1081)
        at java.base/sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:189)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1367)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1342)
        at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getOutputStream(HttpsURLConnectionImpl.java:246)
        at com.cloudant.http.HttpConnection.execute(HttpConnection.java:317)
        at com.cloudant.http.internal.interceptors.CookieInterceptorBase.makeSessionRequest(CookieInterceptorBase.java:140)
        ... 10 more
Error retrieving server response at https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud:443/account/014aa25148df4eea85b15b3e81ce52d7.
sh-4.4$

jwalcorn commented 3 years ago

It's interesting the call stack shows I got past the client.database call, and didn't have a problem until the database.find call. Wouldn't client.database need to make a connection (through the proxy) - like it has the option to create the database if it doesn't exist. Or does passing false for that creation mean no communication happens, and that it wouldn't notice the database perhaps not existing until you tried to invoke a method on it?

ricellis commented 3 years ago

Or does passing false for that creation mean no communication happens, and that it wouldn't notice the database perhaps not existing until you tried to invoke a method on it?

Correct, if you don't ask to create the database it won't make a round trip to the server until you try to use the database.

The _session request that fails is the cookie request required for auth before it can do the document fetch.

This line of the log: FINE: c081e450-9 POST https://878ff489-3ab9-4d2d-86db-016f19864439-bluemix.cloudantnosqldb.appdomain.cloud:443/_session request should say via proxy at the end if a proxy is being used on the connection, but it doesn't so it looks like we're not correctly assigning the proxy config for the auth exchange.

jwalcorn commented 3 years ago

Cool. If you build a fix and would like me to try it prior to the next release push to Maven Central, happy to do so

cloudant / java-cloudant