Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
maheshkelkar opened this issue Mar 24, 2019 · 9 comments
Closed

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

maheshkelkar opened this issue Mar 24, 2019 · 9 comments
Labels
bug Bug in existing code
Milestone
Backlog

Comments

@maheshkelkar
Copy link

maheshkelkar commented Mar 24, 2019 •
edited
Loading

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 maheshkelkar added the bug Bug in existing code label Mar 24, 2019
@maheshkelkar
Copy link
Author

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);
}

@heyangJob
Copy link

Our app has the same problem
Is there a solution?

@TangHuaiZhe
Copy link
Contributor

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

@heyangJob
Copy link

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

@swankjesse swankjesse added this to the Backlog milestone Apr 13, 2019
@WoodyMKD
Copy link

WoodyMKD commented Apr 3, 2022

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

@yschimke
Copy link
Collaborator

I suspect related to #3278

@sharun
Copy link

sharun commented Aug 25, 2023

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

@shriharsha-bhagwat
Copy link

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

@yschimke
Copy link
Collaborator

yschimke commented Feb 3, 2024

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 yschimke closed this as completed Feb 3, 2024
@yschimke yschimke mentioned this issue Feb 14, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Bug in existing code
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
8 participants
@swankjesse @yschimke @heyangJob @sharun @TangHuaiZhe @maheshkelkar @shriharsha-bhagwat @WoodyMKD