okhttp icon indicating copy to clipboard operation
okhttp copied to clipboard

Published 20 hours ago • verified publisher icon square

On network change (e.g. wifi -> cellular) okhttp on android fails to connect to a reachable endpoint

Open maheshkelkar opened this issue 5 years ago • 5 comments

okhttp:3.12.1 okio:1.16.0

  • I wrote a simple loop that will synchronously execute "GET www.lookout.com" every 250 ms.
  • When I flip-flop between wifi and cellular network a couple of times, then the okhttp fails to connect to endpoint "wireless.cingular.com"; I am not sure what this endpoint is, my assumption is - its a DNS server for cellular network
  • If switch networks again or launch another similar loop (in-parallel - which shares the OkHttpClient), then it breaks out of these failures and starts working again
03-24 11:57:40.232 30296 12290 I AP-TESTHARNESS: [rest-client] [191 ms] responseBodyEnd: byteCount=129359
03-24 11:57:40.232 30296 12290 I AP-TESTHARNESS: [rest-client] [192 ms] connectionReleased
03-24 11:57:40.232 30296 12290 I AP-TESTHARNESS: [rest-client] [192 ms] callEnd

everything seem to be working fine, I just disabled wifi here, so underlying active network will be cellular network:

03-24 11:57:40.517 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 11:57:40.519 30296 12290 I AP-TESTHARNESS: [rest-client] [1 ms] connectionAcquired: Connection{www.lookout.com:443, proxy=DIRECT hostAddress=www.lookout.com/23.219.165.43:443 cipherSuite=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 protocol=http/1.1}
03-24 11:57:40.519 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] requestHeadersStart
03-24 11:57:40.519 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] requestHeadersEnd
03-24 11:57:40.519 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] responseHeadersStart
03-24 11:57:40.589 30296 12290 I AP-TESTHARNESS: [rest-client] [72 ms] connectionReleased
03-24 11:57:40.591 30296 12290 I AP-TESTHARNESS: [rest-client] [73 ms] dnsStart: www.lookout.com
03-24 11:57:40.597 30296 12290 I AP-TESTHARNESS: [rest-client] [79 ms] callFailed: java.net.UnknownHostException: Unable to resolve host "www.lookout.com": No address associated with hostname

it failed here and keeps failing for a while

03-24 11:57:48.639 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 11:57:48.646 30296 12290 I AP-TESTHARNESS: [rest-client] [6 ms] dnsStart: wireless.cingular.com
03-24 11:57:48.652 30296 12290 I AP-TESTHARNESS: [rest-client] [12 ms] dnsEnd: [wireless.cingular.com/66.209.11.32]
03-24 11:57:48.654 30296 12290 I AP-TESTHARNESS: [rest-client] [14 ms] connectStart: wireless.cingular.com/66.209.11.32:80 HTTP @ wireless.cingular.com:80
03-24 11:57:49.674 30296 12290 I AP-TESTHARNESS: [rest-client] [1035 ms] connectFailed: null java.net.ConnectException: Failed to connect to wireless.cingular.com/66.209.11.32:80
03-24 11:57:49.678 30296 12290 I AP-TESTHARNESS: [rest-client] [1039 ms] callFailed: java.net.ConnectException: Failed to connect to wireless.cingular.com/66.209.11.32:80
03-24 11:57:49.950 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 11:57:49.954 30296 12290 I AP-TESTHARNESS: [rest-client] [3 ms] dnsStart: wireless.cingular.com
03-24 11:57:49.955 30296 12290 I AP-TESTHARNESS: [rest-client] [4 ms] dnsEnd: [wireless.cingular.com/66.209.11.32]
03-24 11:57:49.957 30296 12290 I AP-TESTHARNESS: [rest-client] [6 ms] connectStart: wireless.cingular.com/66.209.11.32:80 HTTP @ wireless.cingular.com:80
03-24 11:57:50.976 30296 12290 I AP-TESTHARNESS: [rest-client] [1025 ms] connectFailed: null java.net.ConnectException: Failed to connect to wireless.cingular.com/66.209.11.32:80
03-24 11:57:50.978 30296 12290 I AP-TESTHARNESS: [rest-client] [1027 ms] callFailed: java.net.ConnectException: Failed to connect to wireless.cingular.com/66.209.11.32:80
03-24 11:57:51.267 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 11:57:51.270 30296 12290 I AP-TESTHARNESS: [rest-client] [3 ms] dnsStart: wireless.cingular.com
03-24 11:57:51.274 30296 12290 I AP-TESTHARNESS: [rest-client] [7 ms] dnsEnd: [wireless.cingular.com/66.209.11.32]
03-24 11:57:51.275 30296 12290 I AP-TESTHARNESS: [rest-client] [8 ms] connectStart: wireless.cingular.com/66.209.11.32:80 HTTP @ wireless.cingular.com:80
03-24 11:57:52.284 30296 12290 I AP-TESTHARNESS: [rest-client] [1017 ms] connectFailed: null java.net.ConnectException: Failed to connect to wireless.cingular.com/66.209.11.32:80
03-24 11:57:52.287 30296 12290 I AP-TESTHARNESS: [rest-client] [1019 ms] callFailed: java.net.ConnectException: Failed to connect to wireless.cingular.com/66.209.11.32:80

Here is the fix part:

still failing

03-24 12:21:16.331 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 12:21:16.332 30296 12290 I AP-TESTHARNESS: [rest-client] [1 ms] dnsStart: wireless.cingular.com
03-24 12:21:16.333 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] dnsEnd: [wireless.cingular.com/66.209.11.32]
03-24 12:21:16.333 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] connectStart: wireless.cingular.com/66.209.11.32:80 HTTP @ wireless.cingular.com:80
03-24 12:21:17.348 30296 12290 I AP-TESTHARNESS: [rest-client] [1016 ms] connectFailed: null java.net.ConnectException: Failed to connect to wireless.cingular.com/66.209.11.32:80
03-24 12:21:17.348 30296 12290 I AP-TESTHARNESS: [rest-client] [1017 ms] callFailed: java.net.ConnectException: Failed to connect to wireless.cingular.com/66.209.11.32:80

I launched another thread 30296 20313, due to which last-but-one call on the extant thread works:

03-24 12:21:17.616 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 12:21:17.618 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] dnsStart: wireless.cingular.com
03-24 12:21:17.618 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] dnsEnd: [wireless.cingular.com/66.209.11.32]
03-24 12:21:17.618 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] connectStart: wireless.cingular.com/66.209.11.32:80 HTTP @ wireless.cingular.com:80
03-24 12:21:18.917 30296 12290 I AP-TESTHARNESS: [rest-client] [1301 ms] secureConnectStart
03-24 12:21:19.023 30296 12290 I AP-TESTHARNESS: [rest-client] [1407 ms] secureConnectEnd
03-24 12:21:19.024 30296 12290 I AP-TESTHARNESS: [rest-client] [1408 ms] connectEnd: http/1.1
03-24 12:21:19.024 30296 12290 I AP-TESTHARNESS: [rest-client] [1408 ms] connectionAcquired: Connection{www.lookout.com:443, proxy=HTTP @ wireless.cingular.com:80 hostAddress=wireless.cingular.com/66.209.11.32:80 cipherSuite=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 protocol=http/1.1}
03-24 12:21:19.024 30296 12290 I AP-TESTHARNESS: [rest-client] [1408 ms] requestHeadersStart
03-24 12:21:19.024 30296 12290 I AP-TESTHARNESS: [rest-client] [1408 ms] requestHeadersEnd
03-24 12:21:19.024 30296 12290 I AP-TESTHARNESS: [rest-client] [1408 ms] responseHeadersStart
03-24 12:21:19.317 30296 12290 I AP-TESTHARNESS: [rest-client] [1701 ms] responseHeadersEnd: Response{protocol=http/1.1, code=200, message=OK, url=https://www.lookout.com/}
03-24 12:21:19.317 30296 12290 I AP-TESTHARNESS: [rest-client] [1701 ms] responseBodyStart
03-24 12:21:19.848 30296 12290 I AP-TESTHARNESS: [rest-client] [2232 ms] responseBodyEnd: byteCount=129359
03-24 12:21:19.849 30296 12290 I AP-TESTHARNESS: [rest-client] [2233 ms] connectionReleased
03-24 12:21:19.849 30296 12290 I AP-TESTHARNESS: [rest-client] [2233 ms] callEnd
03-24 12:21:20.111 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 12:21:20.112 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] connectionAcquired: Connection{www.lookout.com:443, proxy=HTTP @ wireless.cingular.com:80 hostAddress=wireless.cingular.com/66.209.11.32:80 cipherSuite=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 protocol=http/1.1}
03-24 12:21:20.112 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] requestHeadersStart
03-24 12:21:20.112 30296 12290 I AP-TESTHARNESS: [rest-client] [1 ms] requestHeadersEnd
03-24 12:21:20.112 30296 12290 I AP-TESTHARNESS: [rest-client] [1 ms] responseHeadersStart

this is the actual new thread (but as you can see from logs just above, things seem to have fixed

03-24 12:21:20.136 30296 20313 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 12:21:20.137 30296 20313 I AP-TESTHARNESS: [rest-client] [0 ms] dnsStart: wireless.cingular.com
03-24 12:21:20.140 30296 20313 I AP-TESTHARNESS: [rest-client] [3 ms] dnsEnd: [wireless.cingular.com/66.209.11.32]
03-24 12:21:20.140 30296 20313 I AP-TESTHARNESS: [rest-client] [3 ms] connectStart: wireless.cingular.com/66.209.11.32:80 HTTP @ wireless.cingular.com:80
03-24 12:21:20.413 30296 12290 I AP-TESTHARNESS: [rest-client] [301 ms] responseHeadersEnd: Response{protocol=http/1.1, code=200, message=OK, url=https://www.lookout.com/}
03-24 12:21:20.413 30296 12290 I AP-TESTHARNESS: [rest-client] [301 ms] responseBodyStart
03-24 12:21:20.616 30296 20313 I AP-TESTHARNESS: [rest-client] [479 ms] secureConnectStart
03-24 12:21:20.783 30296 12290 I AP-TESTHARNESS: [rest-client] [671 ms] responseBodyEnd: byteCount=129359
03-24 12:21:20.783 30296 12290 I AP-TESTHARNESS: [rest-client] [672 ms] connectionReleased
03-24 12:21:20.783 30296 12290 I AP-TESTHARNESS: [rest-client] [672 ms] callEnd
03-24 12:21:20.932 30296 20313 I AP-TESTHARNESS: [rest-client] [795 ms] secureConnectEnd
03-24 12:21:20.932 30296 20313 I AP-TESTHARNESS: [rest-client] [795 ms] connectEnd: http/1.1
03-24 12:21:20.932 30296 20313 I AP-TESTHARNESS: [rest-client] [795 ms] connectionAcquired: Connection{www.lookout.com:443, proxy=HTTP @ wireless.cingular.com:80 hostAddress=wireless.cingular.com/66.209.11.32:80 cipherSuite=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 protocol=http/1.1}
03-24 12:21:20.932 30296 20313 I AP-TESTHARNESS: [rest-client] [795 ms] requestHeadersStart
03-24 12:21:20.932 30296 20313 I AP-TESTHARNESS: [rest-client] [795 ms] requestHeadersEnd
03-24 12:21:20.932 30296 20313 I AP-TESTHARNESS: [rest-client] [795 ms] responseHeadersStart
03-24 12:21:21.054 30296 12290 I AP-TESTHARNESS: [rest-client] [0 ms] callStart: Request{method=GET, url=https://www.lookout.com/, tags={}}
03-24 12:21:21.056 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] connectionAcquired: Connection{www.lookout.com:443, proxy=HTTP @ wireless.cingular.com:80 hostAddress=wireless.cingular.com/66.209.11.32:80 cipherSuite=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 protocol=http/1.1}
03-24 12:21:21.057 30296 12290 I AP-TESTHARNESS: [rest-client] [2 ms] requestHeadersStart
03-24 12:21:21.057 30296 12290 I AP-TESTHARNESS: [rest-client] [3 ms] requestHeadersEnd
03-24 12:21:21.057 30296 12290 I AP-TESTHARNESS: [rest-client] [3 ms] responseHeadersStart
03-24 12:21:21.168 30296 20313 I AP-TESTHARNESS: [rest-client] [1031 ms] responseHeadersEnd: Response{protocol=http/1.1, code=200, message=OK, url=https://www.lookout.com/}
03-24 12:21:21.168 30296 20313 I AP-TESTHARNESS: [rest-client] [1031 ms] responseBodyStart
03-24 12:21:21.379 30296 12290 I AP-TESTHARNESS: [rest-client] [324 ms] responseHeadersEnd: Response{protocol=http/1.1, code=200, message=OK, url=https://www.lookout.com/}
03-24 12:21:21.379 30296 12290 I AP-TESTHARNESS: [rest-client] [325 ms] responseBodyStart
03-24 12:21:21.651 30296 12290 I AP-TESTHARNESS: [rest-client] [597 ms] responseBodyEnd: byteCount=129359
03-24 12:21:21.652 30296 12290 I AP-TESTHARNESS: [rest-client] [597 ms] connectionReleased
03-24 12:21:21.652 30296 12290 I AP-TESTHARNESS: [rest-client] [597 ms] callEnd

Question/Notes:

  1. How do I dump internal state of okhttp, to get more visibility into why does it fail to connect
  2. I wonder for second thread, if we are instantiating some okhttp API call, which unravels everything
  3. I also see newCall remains stuck ranging from 1 minute to 1 hour

maheshkelkar avatar Mar 24 '19 19:03 maheshkelkar

Test Code:

A button in test app triggers this code

OkHttpClient okHttpClient = getSharedOkHttpClientInstance();
Request = <GET www.lookout.com>
for (int i = 1; i <= 10000; i++) {
    String tag = Thread.currentThread().getName() + "-" + i;
    Response response = null;
    long startMs = System.currentTimeMillis();
    try {
        response = okHttpClient.newCall(request).execute();
        long tookMs = System.currentTimeMillis() - startMs;
        if (response != null && isSuccess(response.getHttpStatusCode())) {
            sLogger.info("***{}: success: took={}, resp={}",
                tag, tookMs, response.toString().substring(0, 40));
        } else {
            sLogger.info("***{}: failed: took={}, respCode={}",
                tag, tookMs, response == null ? 0 : response.getHttpStatusCode());
        }
    } catch (Exception e) {
        long tookMs = System.currentTimeMillis() - startMs;
        sLogger.warn("***" + tag + ": failed: took=" + tookMs + ", exception=" +
            e.getMessage(), e);
    }
    Thread.sleep(250);
}

maheshkelkar avatar Mar 25 '19 01:03 maheshkelkar

Our app has the same problem Is there a solution?

heyangJob avatar Apr 11 '19 10:04 heyangJob

wireless.cingular.com looks like MMS Proxy of APN Setiing in Mobile Phone. Refer to Cingular APN Settings

TangHuaiZhe avatar Apr 12 '19 01:04 TangHuaiZhe

parser gslb dns exception:java.net.UnknownHostException: Unable to resolve host

heyangJob avatar Apr 12 '19 03:04 heyangJob

This issue is still present... Is there any workaround at least?

WoodyMKD avatar Apr 03 '22 22:04 WoodyMKD

I suspect related to https://github.com/square/okhttp/issues/3278

yschimke avatar May 21 '23 08:05 yschimke

We see this issue in our app too. Any solution or workaround for this ?

sharun avatar Aug 25 '23 12:08 sharun

@sharun Do you have any updates here ? I see mainly in Android 13 Samsung/Huawei devices.

shriharsha-bhagwat avatar Sep 18 '23 06:09 shriharsha-bhagwat

Based on the caching in Android, I'm going to close this.

https://cs.android.com/android/platform/superproject/main/+/main:libcore/ojluni/src/main/java/java/net/Inet6AddressImpl.java which calls https://cs.android.com/android/platform/superproject/main/+/main:libcore/luni/src/main/java/java/net/AddressCache.java;l=30?q=AddressCache&sq=

Results are cached for 2 seconds, and the DNS.System is network unaware. You can implement a custom DNS pinning to a network, but we haven't currently done that.

wireless.cingular.com is being configured as a proxy which is why you are seeing it in your results.

yschimke avatar Feb 03 '24 16:02 yschimke