Comments (17)
Is this happening on every request? or just the first one with each OkHttpClient instance?
If it's only on the first, then TLS initialisation is probably a factor.
from okhttp.
My Env: okhttp version is 4.9.1 java version is Java(TM) SE Runtime Environment (build 1.8.0_333-b02)
Problems encountered: I'm using okhttp to make requests to the website, GET&POST methods.
I am using okhttp to access a domain name website (https://test-rights-platform.e-buy.com). My program will record the request time. I found that in some cases, the delay in requesting this website is It will be extremely large (nearly 1 second), but I can ensure that my network outgoing network is normal.
In response to the above situation, I deliberately captured the data packets when this happened. I found that after obtaining the IP address returned by DNS, the program waited nearly 800ms before initiating the TCP three-way handshake. I understand that when dns returns the IP address, it should immediately initiate the TCP three-way handshake instead of waiting for a while before handshaking.
I'm not sure about the entire process of okhttp requesting a domain name. Is this normal? I have repeatedly checked my network environment, there is no packet loss, and the network outgoing delay is normal. But this problem still occurs occasionally, or there is something wrong with my okhttp usage or configuration.
Hope to get your reply~
Datagram After completing the DNS query, it waited nearly 800ms before sending out the tcp syn packet. I don't know if this is controlled by okhttp. .
Have no idea why there was a delay. But noticed that the [SYN] packet from source to destination, which initiates handshake, was missing in your wireshark log. By the way, how did you record the request time? This information might help with pinpointing the issue. Thanks.
from okhttp.
I suspect the delay is waiting for an IPv4 dns response. You can confirm that by decorating DNS and printing out when it returns.
from okhttp.
@Endeavour233 Thank you for your reply.
Before requesting, my program will output the log to logger.info, so I can clearly see the time when this logic is entered. To find the corresponding request from the message.
Regarding the [SYN] request, I'm sorry, it should be that my NPM mirroring traffic is not mirrored. But this should not affect it.
Are there any other ways to look at this issue?
from okhttp.
@yschimke Hello, like the message I mentioned above, the entire process of dns query should only take about 10ms.
from okhttp.
If you record the events with an event listener, it should confirm that.
That's usually easier to tie back to OkHttp stages than wireshark.
from okhttp.
@yschimke
How should I enable the DNS event listener to log events?
Can you provide guidance or send relevant documents?
from okhttp.
This is the time spent on dns query calculated by Wireshark based on existing packets~
from okhttp.
https://square.github.io/okhttp/features/events/
from okhttp.
@yschimke Thank you, I will add debugging
from okhttp.
@yschimke At the same time, what if the delay in the secureConnectEnd stage is high?
from okhttp.
@Endeavour233 Thank you for your reply.
Before requesting, my program will output the log to logger.info, so I can clearly see the time when this logic is entered. To find the corresponding request from the message.
Regarding the [SYN] request, I'm sorry, it should be that my NPM mirroring traffic is not mirrored. But this should not affect it.
Are there any other ways to look at this issue?
I was thinking that [SYN] marks the initialization of handshake, and since it was missing in the log, we could not assume that there was a delay as large as 800ms between DNS return and handshake initialization. Anyway, after using eventlistener to track the request, hopefully we'll find out where the delay happens~
from okhttp.
I'll update the progress~
I have added EventListener, below the output of EventListener:
2024-05-16T03:22:36.923379130Z 0046 https://test-rights-platform.e-buy.com/channel/watsons/codeStatusUpdate
2024-05-16T03:22:36.923517673Z 0046 0.000 callStart
2024-05-16T03:22:36.923665310Z 0046 0.000 proxySelectStart
2024-05-16T03:22:36.923701670Z 0046 0.000 proxySelectEnd
2024-05-16T03:22:36.923715849Z 0046 0.000 dnsStart
2024-05-16T03:22:36.923736751Z 0046 0.000 dnsEnd
2024-05-16T03:22:36.923807354Z 0046 0.000 connectStart
2024-05-16T03:22:36.952235332Z 0046 0.029 secureConnectStart
2024-05-16T03:22:37.792585640Z 0046 0.869 secureConnectEnd
2024-05-16T03:22:37.792607859Z 0046 0.869 connectEnd
2024-05-16T03:22:37.792711948Z 0046 0.869 connectionAcquired
2024-05-16T03:22:37.796580122Z 0046 0.873 requestHeadersStart
2024-05-16T03:22:37.796636533Z 0046 0.873 requestHeadersEnd
2024-05-16T03:22:37.796654404Z 0046 0.873 requestBodyStart
2024-05-16T03:22:37.796714463Z 0046 0.873 requestBodyEnd
2024-05-16T03:22:37.834815218Z 0046 0.911 responseHeadersStart
2024-05-16T03:22:37.834854752Z 0046 0.911 responseHeadersEnd
2024-05-16T03:22:37.835051185Z 0046 0.912 responseBodyStart
2024-05-16T03:22:37.863026980Z 0046 0.940 responseBodyEnd
2024-05-16T03:22:37.863047238Z 0046 0.940 connectionReleased
2024-05-16T03:22:37.863049606Z 0046 0.940 callEnd
I see that the time spent is all in the secureConnectEnd phase. I see that the time is spent in the secureConnectEnd phase.
from okhttp.
The following request processing time is: 678ms
from okhttp.
From my view, your last 2 logs both indicated that most time was spent on TLS handshake(as per my understanding of okhttp, when secureConnectStart
, TCP handshake has completed. connectEnd
is the mark of the establishment of the whole secure connection). However, it seems different from your initial issue, where I guess the bottleneck is TCP handshake.
from okhttp.
Test on Android emulator with two requests, forced to reconnect.
05-19 18:05:57.323 7595 7616 I System.out: 18:05:55.523743 [0 ms] callStart: Request{method=GET, url=https://test-rights-platform.e-buy.com/robots.txt}
05-19 18:05:57.325 7595 7616 I System.out: 18:05:55.583774 [68 ms] proxySelectStart: https://test-rights-platform.e-buy.com/
05-19 18:05:57.325 7595 7616 I System.out: 18:05:55.584795 [69 ms] proxySelectEnd: [DIRECT]
05-19 18:05:57.325 7595 7616 I System.out: 18:05:55.585059 [69 ms] dnsStart: test-rights-platform.e-buy.com
05-19 18:05:57.326 7595 7616 I System.out: 18:05:55.592838 [76 ms] dnsEnd: [test-rights-platform.e-buy.com/47.101.44.29]
05-19 18:05:57.326 7595 7616 I System.out: 18:05:55.608193 [92 ms] connectStart: test-rights-platform.e-buy.com/47.101.44.29:443 DIRECT
05-19 18:05:57.327 7595 7616 I System.out: 18:05:55.839102 [323 ms] secureConnectStart
05-19 18:05:57.328 7595 7616 I System.out: 18:05:56.322772 [807 ms] secureConnectEnd: Handshake{tlsVersion=TLS_1_2 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 peerCertificates=[CN=*.e-buy.com, O=易百信息技术(上海)股份有限公司, ST=上海市, C=CN, CN=GeoTrust CN RSA CA G1, OU=www.digicert.com, O=DigiCert Inc, C=US, CN=DigiCert Global Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US] localCertificates=[]}
05-19 18:05:57.329 7595 7616 I System.out: 18:05:56.331113 [815 ms] connectEnd: http/1.1
05-19 18:05:57.329 7595 7616 I System.out: 18:05:56.334553 [818 ms] connectionAcquired: Connection{test-rights-platform.e-buy.com:443, proxy=DIRECT hostAddress=test-rights-platform.e-buy.com/47.101.44.29:443 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 protocol=http/1.1}
05-19 18:05:57.330 7595 7616 I System.out: 18:05:56.349031 [833 ms] requestHeadersStart
05-19 18:05:57.330 7595 7616 I System.out: 18:05:56.350322 [834 ms] requestHeadersEnd
05-19 18:05:57.330 7595 7616 I System.out: 18:05:56.572177 [1056 ms] responseHeadersStart
05-19 18:05:57.332 7595 7616 I System.out: 18:05:56.577485 [1061 ms] responseHeadersEnd: Response{protocol=http/1.1, code=404, message=Not Found, url=https://test-rights-platform.e-buy.com/robots.txt}
05-19 18:05:57.332 7595 7616 I System.out: 18:05:56.594852 [1078 ms] responseBodyStart
05-19 18:05:57.333 7595 7616 I System.out: 18:05:56.595127 [1079 ms] responseBodyEnd: byteCount=0
05-19 18:05:57.334 7595 7616 I System.out: 18:05:56.595778 [1080 ms] connectionReleased
05-19 18:05:57.334 7595 7616 I System.out: 18:05:56.597847 [1081 ms] callEnd
05-19 18:05:57.335 7595 7616 I System.out: 18:05:56.600711 [0 ms] callStart: Request{method=GET, url=https://test-rights-platform.e-buy.com/robots.txt}
05-19 18:05:57.335 7595 7616 I System.out: 18:05:56.601934 [1 ms] proxySelectStart: https://test-rights-platform.e-buy.com/
05-19 18:05:57.336 7595 7616 I System.out: 18:05:56.603537 [2 ms] proxySelectEnd: [DIRECT]
05-19 18:05:57.336 7595 7616 I System.out: 18:05:56.603759 [3 ms] dnsStart: test-rights-platform.e-buy.com
05-19 18:05:57.336 7595 7616 I System.out: 18:05:56.604168 [3 ms] dnsEnd: [test-rights-platform.e-buy.com/47.101.44.29]
05-19 18:05:57.337 7595 7616 I System.out: 18:05:56.606141 [5 ms] connectStart: test-rights-platform.e-buy.com/47.101.44.29:443 DIRECT
05-19 18:05:57.337 7595 7616 I System.out: 18:05:56.853399 [252 ms] secureConnectStart
05-19 18:05:57.339 7595 7616 I System.out: 18:05:57.078881 [478 ms] secureConnectEnd: Handshake{tlsVersion=TLS_1_2 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 peerCertificates=[CN=*.e-buy.com, O=易百信息技术(上海)股份有限公司, ST=上海市, C=CN, CN=GeoTrust CN RSA CA G1, OU=www.digicert.com, O=DigiCert Inc, C=US, CN=DigiCert Global Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US] localCertificates=[]}
05-19 18:05:57.339 7595 7616 I System.out: 18:05:57.079178 [478 ms] connectEnd: http/1.1
05-19 18:05:57.341 7595 7616 I System.out: 18:05:57.080581 [479 ms] connectionAcquired: Connection{test-rights-platform.e-buy.com:443, proxy=DIRECT hostAddress=test-rights-platform.e-buy.com/47.101.44.29:443 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 protocol=http/1.1}
05-19 18:05:57.341 7595 7616 I System.out: 18:05:57.081082 [480 ms] requestHeadersStart
05-19 18:05:57.341 7595 7616 I System.out: 18:05:57.081888 [481 ms] requestHeadersEnd
05-19 18:05:57.342 7595 7616 I System.out: 18:05:57.293637 [692 ms] responseHeadersStart
05-19 18:05:57.342 7595 7616 I System.out: 18:05:57.294013 [693 ms] responseHeadersEnd: Response{protocol=http/1.1, code=404, message=Not Found, url=https://test-rights-platform.e-buy.com/robots.txt}
05-19 18:05:57.343 7595 7616 I System.out: 18:05:57.294677 [693 ms] responseBodyStart
05-19 18:05:57.343 7595 7616 I System.out: 18:05:57.294907 [694 ms] responseBodyEnd: byteCount=0
05-19 18:05:57.343 7595 7616 I System.out: 18:05:57.295584 [694 ms] connectionReleased
05-19 18:05:57.344 7595 7616 I System.out: 18:05:57.296040 [695 ms] callEnd
Similar time, so maybe it's just the handshake.
Going to close this out, as expected.
from okhttp.
@yschimke @Endeavour233 receive. Thank you, it looks like a server-side problem
from okhttp.
Related Issues (20)
- When I use EventListener, the same call is called back twice connectStart HOT 3
- okhttp3.sse.EventSourceListener should be an interface HOT 2
- SSL Certification error in Databricks HOT 1
- Thread pinned when use virtual threads and socks5 proxy, Version 5.0.0-alpha.14 HOT 2
- NullPointerException in okhttp3.internal.connection.RealConnection.isHealthy() HOT 1
- Fatal Exception: java.lang.IllegalStateException: Unable to load publicsuffixes.gz resource from the classpath.
- 🙉 When will OKHTTP 5. x release HOT 1
- Reenable connectionPreWarmingHttp2
- How To fully simulate Chrome's TLS fingerprint? How to break through ja3 or tls fingerprint HOT 1
- 🙉ja3指纹或tls指纹,怎么模拟和破解? HOT 2
- $ ./okcurl/build/graal/okcurl https://httpbin.org/post
- Tests | Develocity HOT 1
- RealEventSource lost control on Error
- java.net.ProtocolException: unexpected end of stream HOT 6
- Build issues trying to bump to AGP 8.5 HOT 1
- OKHTTP version 3.12.2 sets retryOnConnectionFailure to false, but will still automatically retry after failure HOT 1
- Is it possible to release 5.0.0-alpha.15, alpha 14 has a critical bug that makes virtual threads unusable.
- Incorrect retries on connection that still succeeded HOT 15
- Dns$Companion$DnsSystem.lookup No address associated with hostname
- NullPointerException with HandshakeCertificates - com.android.org.bouncycastle.jcajce.provider.keystore.bc.BcKeyStoreSpi.engineSetKeyEntry HOT 3
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from okhttp.