OkhttpClient with Proxy does not handle Network changes

[Dohbedoh]

When using an OkHttpClient instance with a Proxy / ProxySelector, if a network change happens so that the proxy address resolves to a different IP address, the client is not able to reach out to the request URL anymore... In such a case, we typically see a SocketTimeoutException:

And note that:

• If you do not reuse your instance of OkhttpClient but create a new one, this issue does not happen.
• If you do NOT use the proxy, and change the scenario so that it is the request host DNS resolution that changes. The problem does not happen neither.

This tells me that this might be a bug very specific to the use of ProxySelector in OkHttp. Unless consumers are expected to handle this in which case I would be interested to know how exactly ? (Interceptors, ...)

---

How to Reproduce (Scenario)

To reproduce this, you need to have a proxy setup and you need to be able to change the address that the proxy hostname resolves to.

• Spin up a Proxy and a DNS to serve it with a specific hostname
• Create an OkHttpClient instance with a ProxySelector
• Execute a request with the OkHttpClient against a URL reachable through the proxy
• Make a change to the Proxy DNS resolution: typically the proxy host remain the same but the IP of the proxy - that the DNS will resolves to - changes
• Execute the same request with the same instance of the OkHttpClient
  --> it now fails to reach out to the proxy. Yo ucan try again and again and it always fails...

I am using kubernetes to do this. My proxy runs in a pod and has a service in front of it. So both the service and the POD have a specific IP. What I do to provoke that network change is to remove the service and the pods and recreate them. The hostname remains - the service DNS squid-proxy.squid.svc.cluster.local - but the IP it resolves to is now pointing to the new pod that is different.

---

Reproduction Project

I dod not find a way to create a simple test form this. But I created a small Java project https://github.com/Dohbedoh/test-clients that do the same request in a loop at 90s interval. The 90s interval is enough to provoke that network change. Also using an interceptor to get more logging. See https://github.com/Dohbedoh/test-clients/blob/f72cd1a3fdbd2b930b1297ee2d4a82f4237d7f26/src/main/java/com/dohbedoh/Main.java.

What I do is

• I run against https://api.github.com/rate_limit/:

java \
  -Dcom.dohbedoh.proxyHost="squid-proxy.squid.svc.cluster.local" \
  -Dcom.dohbedoh.proxyPort=3128 \
  -cp test-clients-1.0-SNAPSHOT-jar-with-dependencies.jar com.dohbedoh.Main "https://api.github.com/rate_limit"

• I wait for the first request to succeed:

Feb 17, 2023 2:25:19 AM com.dohbedoh.Main$LoggingInterceptor intercept
INFO: [APPLICATION] Sending request http://api.github.com/rate_limit on null

Feb 17, 2023 2:25:19 AM com.dohbedoh.Main$LoggingInterceptor intercept
INFO: [NETWORK] Sending request http://api.github.com/rate_limit on Connection{api.github.com:80, proxy=HTTP @ squid-proxy.squid.svc.cluster.local/10.30.130.211:3128 hostAddress=/10.30.130.211:3128 cipherSuite=none protocol=http/1.1}
Host: api.github.com
Connection: Keep-Alive
Accept-Encoding: gzip
User-Agent: okhttp/4.10.0

Feb 17, 2023 2:25:19 AM com.dohbedoh.Main$LoggingInterceptor intercept
INFO: [NETWORK] Received response for http://api.github.com/rate_limit in 74.0ms
Content-Length: 0
Location: https://api.github.com/rate_limit
Date: Fri, 17 Feb 2023 02:25:19 GMT
X-Cache: MISS from squid-proxy-bdb677474-scv2j
X-Cache-Lookup: MISS from squid-proxy-bdb677474-scv2j:3128
Via: 1.1 squid-proxy-bdb677474-scv2j (squid/5.6)
Connection: keep-alive

Feb 17, 2023 2:25:20 AM com.dohbedoh.Main$LoggingInterceptor intercept
INFO: [NETWORK] Sending request https://api.github.com/rate_limit on Connection{api.github.com:443, proxy=HTTP @ squid-proxy.squid.svc.cluster.local/10.30.130.211:3128 hostAddress=/10.30.130.211:3128 cipherSuite=TLS_AES_128_GCM_SHA256 protocol=h2}
Host: api.github.com
Connection: Keep-Alive
Accept-Encoding: gzip
User-Agent: okhttp/4.10.0

Feb 17, 2023 2:25:20 AM com.dohbedoh.Main$LoggingInterceptor intercept
INFO: [NETWORK] Received response for https://api.github.com/rate_limit in 74.8ms
access-control-allow-origin: *
access-control-expose-headers: ETag, Link, Location, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval, X-GitHub-Media-Type, Deprecation, Sunset
cache-control: no-cache
content-security-policy: default-src 'none'
content-type: application/json; charset=utf-8
referrer-policy: origin-when-cross-origin, strict-origin-when-cross-origin
x-content-type-options: nosniff
x-frame-options: deny
x-github-media-type: github.v3; format=json
x-ratelimit-limit: 60
x-ratelimit-remaining: 59
x-ratelimit-reset: 1676602459
x-ratelimit-resource: core
x-ratelimit-used: 1
x-xss-protection: 1; mode=block
date: Fri, 17 Feb 2023 02:25:20 GMT
content-length: 465
accept-ranges: bytes
x-github-request-id: 1801:3F23:A07AFF:1481DEF:63EEE58F

Feb 17, 2023 2:25:20 AM com.dohbedoh.Main$LoggingInterceptor intercept
INFO: [APPLICATION] Received response for https://api.github.com/rate_limit in 665.3ms
access-control-allow-origin: *
access-control-expose-headers: ETag, Link, Location, Retry-After, X-GitHub-OTP, X-RateLimit-Limit, X-RateLimit-Remaining, X-RateLimit-Reset, X-OAuth-Scopes, X-Accepted-OAuth-Scopes, X-Poll-Interval, X-GitHub-Media-Type, Deprecation, Sunset
cache-control: no-cache
content-security-policy: default-src 'none'
content-type: application/json; charset=utf-8
referrer-policy: origin-when-cross-origin, strict-origin-when-cross-origin
x-content-type-options: nosniff
x-frame-options: deny
x-github-media-type: github.v3; format=json
x-ratelimit-limit: 60
x-ratelimit-remaining: 59
x-ratelimit-reset: 1676602459
x-ratelimit-resource: core
x-ratelimit-used: 1
x-xss-protection: 1; mode=block
date: Fri, 17 Feb 2023 02:25:20 GMT
content-length: 465
accept-ranges: bytes
x-github-request-id: 1801:3F23:A07AFF:1481DEF:63EEE58F

Feb 17, 2023 2:25:20 AM com.dohbedoh.Main testUrl
INFO: {"resources":{"core":{"limit":60,"remaining":59,"reset":1676602459,"used":1,"resource":"core"},"graphql":{"limit":0,"remaining":0,"reset":1676604320,"used":0,"resource":"graphql"},"integration_manifest":{"limit":5000,"remaining":5000,"reset":1676604320,"used":0,"resource":"integration_manifest"},"search":{"limit":10,"remaining":10,"reset":1676600780,"used":0,"resource":"search"}},"rate":{"limit":60,"remaining":59,"reset":1676602459,"used":1,"resource":"core"}}

Feb 17, 2023 2:25:20 AM com.dohbedoh.Main testDns
INFO: Lookup DNS for api.github.com
Feb 17, 2023 2:25:20 AM com.dohbedoh.Main lambda$testDns$0
INFO:   api.github.com/140.82.112.5
Feb 17, 2023 2:25:20 AM com.dohbedoh.Main testDns
INFO: Lookup DNS for squid-proxy.squid.svc.cluster.local
Feb 17, 2023 2:25:20 AM com.dohbedoh.Main lambda$testDns$1
INFO:   squid-proxy.squid.svc.cluster.local/10.30.130.211

• I provoke the network change:

k delete svc squid-proxy; k delete pods --all;k apply -f svc.yaml;

• the next requests fail with SocketTimeoutException. And see how OkHttpClient.dns().lookup(PROXY_HOST) actually correctly resolves to the new IP:

Feb 17, 2023 2:26:50 AM com.dohbedoh.Main$LoggingInterceptor intercept
INFO: [APPLICATION] Sending request http://api.github.com/rate_limit on null

Feb 17, 2023 2:27:00 AM com.dohbedoh.Main testUrl
SEVERE: Failure executing request
java.net.SocketTimeoutException: connect timed out
        at java.base/java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:412)
        at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:255)
        at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:237)
        at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.base/java.net.Socket.connect(Socket.java:609)
        at okhttp3.internal.platform.Platform.connectSocket(Platform.kt:128)
        at okhttp3.internal.connection.RealConnection.connectSocket(RealConnection.kt:295)
        at okhttp3.internal.connection.RealConnection.connect(RealConnection.kt:207)
        at okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:226)
        at okhttp3.internal.connection.ExchangeFinder.findHealthyConnection(ExchangeFinder.kt:106)
        at okhttp3.internal.connection.ExchangeFinder.find(ExchangeFinder.kt:74)
        at okhttp3.internal.connection.RealCall.initExchange$okhttp(RealCall.kt:255)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:32)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.dohbedoh.Main$LoggingInterceptor.intercept(Main.java:187)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
        at okhttp3.internal.connection.RealCall.execute(RealCall.kt:154)
        at com.dohbedoh.Main.testUrl(Main.java:99)
        at com.dohbedoh.Main.main(Main.java:55)

Feb 17, 2023 2:27:00 AM com.dohbedoh.Main testDns
INFO: Lookup DNS for api.github.com
Feb 17, 2023 2:27:00 AM com.dohbedoh.Main lambda$testDns$0
INFO:   api.github.com/140.82.112.5
Feb 17, 2023 2:27:00 AM com.dohbedoh.Main testDns
INFO: Lookup DNS for squid-proxy.squid.svc.cluster.local
Feb 17, 2023 2:27:00 AM com.dohbedoh.Main lambda$testDns$1
INFO:   squid-proxy.squid.svc.cluster.local/10.30.130.88

If I run the same tests but I create a new client every time instead, this issue never happens...

Using this tool, the simplest way to reproduce this in K8s:

• deploy a simple squid proxy kubectl apply -f https://raw.githubusercontent.com/Dohbedoh/test-clients/1474885fef7cba34fac37855f308593308acbd75/examples/proxy.yaml
• wait for it to be running
• deploy the test tool with kubectl apply -f https://raw.githubusercontent.com/Dohbedoh/test-clients/1474885fef7cba34fac37855f308593308acbd75/examples/test-clients.yaml that will start sending a request to https://api.github.com/rate_limit/ every 90s through the proxy
• remove the proxy with kubectl delete -f https://raw.githubusercontent.com/Dohbedoh/test-clients/1474885fef7cba34fac37855f308593308acbd75/examples/proxy.yaml
• recreate it with kubectl apply -f https://raw.githubusercontent.com/Dohbedoh/test-clients/1474885fef7cba34fac37855f308593308acbd75/examples/proxy.yaml
• check the log of the test-clients-xxx pod

---

I hope this is enough.

[Dohbedoh]

I will add that I tested this with both OKHttp 3.14.9 and 4.10.0 and both versions are actually failing in the same way.

[yschimke]

Would you be able to try with 5.0.0-alpha.11? I suspect it will fail also, but our connection code has changed so much in 5, to support Happy Eyeballs and so on. If we can find the bug, it's likely we will have to fix on 5 then backport to 4.

[yschimke]

I've created a synthetic test working via mangling DNS and Socket factories. #7720

It seems to show if the first proxy is shutdown cleanly, then the switch should happen seemlessly.

If it's not shutdown cleanly, then the second request will fail, but a following request will work.

[Dohbedoh]

Thanks for the update. So I tried with okhttp5-alpha11 and it still fails the same way. Based on your test, I attached a delegated socket factory and an event listener. Here is the outpout (still okhttp 5-alpha.11):

Feb 20, 2023 5:39:06 AM com.dohbedoh.Main$ConnectionListener connectStart
INFO: Connect Start to /10.30.130.226:3128 through HTTP @ squid-proxy/10.30.130.226:3128
Feb 20, 2023 5:39:06 AM com.dohbedoh.Main$LoggingSocketFactory createSocket
INFO: Socket connection to: api.github.com:443
Feb 20, 2023 5:39:06 AM com.dohbedoh.Main$ConnectionListener connectEnd
INFO: Connect End to /10.30.130.226:3128 through HTTP @ squid-proxy/10.30.130.226:3128
Feb 20, 2023 5:40:36 AM com.dohbedoh.Main$ConnectionListener connectStart
INFO: Connect Start to /10.30.130.226:3128 through HTTP @ squid-proxy/10.30.130.226:3128
Feb 20, 2023 5:40:46 AM com.dohbedoh.Main$ConnectionListener connectFailed
INFO: Connect Failed to /10.30.130.226:3128 through HTTP @ squid-proxy/10.30.130.226:3128 with java.net.SocketTimeoutException: connect timed out
Feb 20, 2023 5:40:46 AM com.dohbedoh.Main testUrl
SEVERE: Failure executing request
java.net.SocketTimeoutException: connect timed out
	at java.base/java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:412)
	at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:255)
	at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:237)
	at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
	at java.base/java.net.Socket.connect(Socket.java:609)
	at okhttp3.internal.platform.Platform.connectSocket(Platform.kt:128)
	at okhttp3.internal.connection.ConnectPlan.connectSocket(ConnectPlan.kt:254)
	at okhttp3.internal.connection.ConnectPlan.connectTcp(ConnectPlan.kt:128)
	at okhttp3.internal.connection.FastFallbackExchangeFinder$launchTcpConnect$1.runOnce(FastFallbackExchangeFinder.kt:138)
	at okhttp3.internal.concurrent.TaskRunner.runTask(TaskRunner.kt:117)
	at okhttp3.internal.concurrent.TaskRunner.access$runTask(TaskRunner.kt:42)
	at okhttp3.internal.concurrent.TaskRunner$runnable$1.run(TaskRunner.kt:66)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Feb 20, 2023 5:42:16 AM com.dohbedoh.Main$ConnectionListener connectStart
INFO: Connect Start to /10.30.130.226:3128 through HTTP @ squid-proxy/10.30.130.226:3128
Feb 20, 2023 5:42:26 AM com.dohbedoh.Main$ConnectionListener connectFailed
INFO: Connect Failed to /10.30.130.226:3128 through HTTP @ squid-proxy/10.30.130.226:3128 with java.net.SocketTimeoutException: connect timed out
Feb 20, 2023 5:42:26 AM com.dohbedoh.Main testUrl

We can see in the Connect Start that it still tries to use the old IP over and over.. The Proxy has already been cleanly shutdown and recreated at that time.

Hope that helps.

[yschimke]

My test isn't realistic in the sense that it's a pattern to copy. But its the best I can do without spinning up remote proxies. So I'll try to reproduce what you are seeing with it.

Thanks for testing with 5.

[Dohbedoh]

@yschimke Have you been able to make progress on this ? Let me know if I can help.

[yschimke]

Not yet, I'll post an update of where I got to this weekend. But not sure I'll have a lot of time in next few weeks, so help would be appreciated.

[elrob]

This seems to match an issue we get every few months but has been very difficult to determine the root cause of.
The HTTP client we use continues to work for the hosts which bypass the proxy but stops working for the hosts included in our ProxySelector. Restarting nodes resolves the issue.

We have DNS TTL set low but it seems the Proxy route is not obeying it.

        String dnsTtlProperty = "networkaddress.cache.ttl";
        String dnsTtlValue = "30";
        log.info("Setting Security property {} to {}", dnsTtlProperty, dnsTtlValue);
        java.security.Security.setProperty(dnsTtlProperty, dnsTtlValue);

[elrob]

micronaut-projects/micronaut-core#4656 (comment)

I think this is the issue and this solution can also resolve it.
new InetSocketAddress(String, int) does host -> IP resolution once in the Proxy constructor so any DNS changes are never propagated to Proxy, nor OkHttpClient

[yschimke]

@elrob That's a great tip.

So https://github.com/Dohbedoh/test-clients/blob/f72cd1a3fdbd2b930b1297ee2d4a82f4237d7f26/src/main/java/com/dohbedoh/Main.java should be

    public static class ProxySelectorImpl extends ProxySelector {

        private final Proxy proxy;

        public ProxySelectorImpl(final String host, final int port) {
            this.proxy = new Proxy(Proxy.Type.HTTP, InetSocketAddress.createUnresolved(host, port));
        }

        @Override
        public List<Proxy> select(URI uri) {
            return List.of(proxy);
        }

        @Override
        public void connectFailed(URI uri, SocketAddress sa, IOException ioe) {
            LOGGER.log(Level.WARNING, "Proxy connection failed", ioe);
        }
    }

Is there any change that OkHttp should be doing? I don't think we provide any ProxySelector for apps to use.

Do you know if JVM and Android implementations do the right thing?

[elrob]

I think this is more of a "gotcha" for the Proxy class rather than OkHttp

[yschimke]

I'll add a test to cover this in https://github.com/square/okhttp/blob/master/okhttp/src/jvmTest/java/okhttp3/RouteFailureTest.kt

Then close this

[yschimke]

Covered in #7720