tcnksm / go-httpstat

Tracing golang HTTP request latency
MIT License
421 stars 72 forks source link

Same total request time when using a Transport #4

Closed dewey closed 7 years ago

dewey commented 7 years ago

This is similar to #2 and results in the same (9223372036854).

I'm trying to test the request time of a bunch of proxies by calling https://ipinfo.io/json with a proxy in the transport of the client.

When I'm running that code the request always has the exact same total time even though its proxies in other continents. Anything I'm missing? Code is basically the same as this one: https://github.com/tcnksm/go-httpstat/blob/master/_example/main.go except that I'm using a transport. I also added the output of the code from GoDoc which looks as expected

https://play.golang.org/p/RxhH0r236p

tcnksm commented 7 years ago

Thank you for submitting issue. Let me run your code and investigate.

tcnksm commented 7 years ago

Basically, there are 2 problems.

One is it shows non-zero time.Duration(9223372036854). The other is Proxy time problem.

Let's solve one by one. The first problem is because you old Dial. httptrace is enabled when you use DialContext. Could you update your code to use newer function?

And now I fix not to show non-zero time.Duration(9223372036854) on https://github.com/tcnksm/go-httpstat/pull/5

dewey commented 7 years ago

I updated the http.Transport to use the new DialContext and updated go-httpstat to the latest version but the result still doesn't look right. Can you replicate this problem?

    t := &http.Transport{
        DialContext: (&net.Dialer{
            Timeout: 5 * time.Second,
        }).DialContext,
        TLSHandshakeTimeout: 5 * time.Second,
        Proxy:               http.ProxyURL(u),
    }
    c := &http.Client{
        Timeout:   time.Second * 10,
        Transport: t,
    }

Result:

2016/10/21 11:08:51 DNS lookup: 0 ms
2016/10/21 11:08:51 TCP connection: 582 ms
2016/10/21 11:08:51 TLS handshake: 0 ms
2016/10/21 11:08:51 Server processing: 98 ms
2016/10/21 11:08:51 Content transfer: 0 ms
2016/10/21 11:08:51 Name Lookup: 0 ms
2016/10/21 11:08:51 Connect: 9223372036854 ms
2016/10/21 11:08:51 Pre Transfer: 9223372036854 ms
2016/10/21 11:08:51 Start Transfer: 9223372036854 ms
2016/10/21 11:08:51 Total: 9223372036854 ms
tcnksm commented 7 years ago

I reproduced it and found it's because of DNSLookup part. Fix is on feature/when-connecting-ip-proxy branch. Can you try it ?

tcnksm commented 7 years ago

I will merge. Report again if still broken.

dewey commented 7 years ago

Sorry for the late reply, this fixed the issue. Thanks!

tcnksm commented 7 years ago

Great! Thank you for reporting !

ysb commented 4 years ago

Hi, i'm getting same error on aws lambda, it works fine on my local env, but having issue on lambda. Do you have any idea about that?

Thanks.