Trying to understand HTTP connection pooling behaviour - new DNS lookup

[Amit Saha]

Hi, it seems that the http client automatically performs a DNS lookup when an existing connection is terminated by the server. I simulated it via changing the IP address in /etc/hosts.

Can someone point me to the code where this logic is checked?

I am looking at https://golang.org/src/net/http/transport.go but haven’t found something yet - quite a beginner here.

Thanks,

Amit.

[b.ca...@pobox.com]

Do you see a forward or reverse DNS lookup being made?

Can you provide a standalone program which demonstrates this behaviour?

I am wondering if either (a) something is logging when the connection is terminated, or (b) a new connection is automatically being made and put into a pool.

[Amit Saha]

> On 28 Nov 2020, at 8:14 pm, b.ca...@pobox.com <b.ca...@pobox.com> wrote:
>
> Do you see a forward or reverse DNS lookup being made?
>
> Can you provide a standalone program which demonstrates this behaviour?
>
> I am wondering if either (a) something is logging when the connection is terminated, or (b) a new connection is automatically being made and put into a pool.

Sure, please find my code here: https://gist.github.com/amitsaha/3963207e77f7537a5dcc3b3afa8e57ee

My experiment scenario:

1. Modify /etc/hosts to have this entry:

# 216.239.38.21 godoc.org #one of the actual IP addresses
<your local ip> godoc.org

2. Run godoc locally as: sudo ~/go/bin/godoc -http=<your local ip>:80

3. Build and run the above program:

$ go build -o application
$ ./application http://godoc.org
DNS Start Info: {Host:godoc.org}
DNS Done Info: {Addrs:[{IP:192.168.1.109 Zone:} {IP:2001:4860:4802:38::15 Zone:} {IP:2001:4860:4802:36::15 Zone:} {IP:2001:4860:4802:32::15 Zone:} {IP:2001:4860:4802:34::15 Zone:}] Err:<nil> Coalesced:false}
Got Conn: {Conn:0xc000186000 Reused:false WasIdle:false IdleTime:0s}
Put Idle Conn Error: <nil>
Resp protocol: "HTTP/1.1"
Sleeping now
--------
Got Conn: {Conn:0xc000186000 Reused:true WasIdle:true IdleTime:2.00444722s}
Put Idle Conn Error: <nil>
Resp protocol: "HTTP/1.1"
Sleeping now
--------


…

In a new terminal:

1. Update /etc/hosts to have:

216.239.38.21 godoc.org
#192.168.1.109 godoc.org

2. Kill the godoc server

Then in the terminal you had the application running, you should see:

Got Conn: {Conn:0xc000186000 Reused:true WasIdle:true IdleTime:2.001646523s}
Put Idle Conn Error: <nil>
Resp protocol: "HTTP/1.1"
Sleeping now
————

# This is where the switch to the new IP happens

DNS Start Info: {Host:godoc.org}
DNS Done Info: {Addrs:[{IP:216.239.38.21 Zone:} {IP:2001:4860:4802:32::15 Zone:} {IP:2001:4860:4802:36::15 Zone:} {IP:2001:4860:4802:38::15 Zone:} {IP:2001:4860:4802:34::15 Zone:}] Err:<nil> Coalesced:false}
Got Conn: {Conn:0xc0000b40b8 Reused:false WasIdle:false IdleTime:0s}
Put Idle Conn Error: <nil>
Resp protocol: "HTTP/1.1"
Sleeping now
--------
Got Conn: {Conn:0xc0000b40b8 Reused:true WasIdle:true IdleTime:2.002040265s}
Put Idle Conn Error: <nil>
Resp protocol: "HTTP/1.1"
Sleeping now

….


My go version:
$ go version
go version go1.15 darwin/amd64


Thank you,
Amit

>
> On Saturday, 28 November 2020 at 01:27:32 UTC amits...@gmail.com wrote:
> Hi, it seems that the http client automatically performs a DNS lookup when an existing connection is terminated by the server. I simulated it via changing the IP address in /etc/hosts.
>
> Can someone point me to the code where this logic is checked?
>
> I am looking at https://golang.org/src/net/http/transport.go but haven’t found something yet - quite a beginner here.
>
> Thanks,
> Amit.
>
>

> --
> You received this message because you are subscribed to the Google Groups "golang-nuts" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/86f347d0-862f-4922-b2e4-e8835858ae90n%40googlegroups.com.

[b.ca...@pobox.com]

Unless you timestamp those log lines, I don't see any evidence that the DNS query is done when the godoc server shuts down.  Could it not just be that after the 2 second sleep, when it's time to make a new connection, it finds that the pool is empty so has to do a lookup to establish a new connection?

I've tested this myself, using your code and apache running on the local server.

$ go run httpclient.go http://localhost:80/

DNS Start Info: {Host:localhost}

DNS Done Info: {Addrs:[{IP:127.0.0.1 Zone:}] Err:<nil> Coalesced:false}

Got Conn: {Conn:0xc000010070 Reused:false WasIdle:false IdleTime:0s}

Put Idle Conn Error: <nil>

Resp protocol: "HTTP/1.1"

Sleeping now

--------

Got Conn: {Conn:0xc000010070 Reused:true WasIdle:true IdleTime:2.000554686s}

Put Idle Conn Error: <nil>

Resp protocol: "HTTP/1.1"

Sleeping now

<< at this point I "systemctl stop apache2" in another terminal >>

<< nothing happens until the 2 seconds is up, and then I see: >>

--------

DNS Start Info: {Host:localhost}

DNS Done Info: {Addrs:[{IP:127.0.0.1 Zone:}] Err:<nil> Coalesced:false}

Got error in making request: Get "http://localhost:80/": dial tcp 127.0.0.1:80: connect: connection refused

Sleeping now

--------

DNS Start Info: {Host:localhost}

DNS Done Info: {Addrs:[{IP:127.0.0.1 Zone:}] Err:<nil> Coalesced:false}

Got error in making request: Get "http://localhost:80/": dial tcp 127.0.0.1:80: connect: connection refused

Sleeping now

^Csignal: interrupt

So as far as I can tell, the client tries to re-use the existing connection from the pool, finds there isn't one (or it's broken), and therefore tries to establish a new connection - which of course requires a lookup of the hostname in the URL.

Aside: I'd say the trace hooks "DNSStart" and "DNSDone" are somewhat misnamed, because the hostname resolution isn't necessarily done via DNS - in both your example and mine it's done via /etc/hosts.  But the intention is clear.

[Amit Saha]

On 28 Nov 2020, at 10:36 pm, b.ca...@pobox.com <b.ca...@pobox.com> wrote:

Unless you timestamp those log lines, I don't see any evidence that the DNS query is done when the godoc server shuts down.  Could it not just be that after the 2 second sleep, when it's time to make a new connection, it finds that the pool is empty so has to do a lookup to establish a new connection?

Yes, that’s correct. I inferred the same. What I wanted to learn was to see the code where the detection that the remote server had gone/connection had gone bad and it was removed from the pool.

That’s correct and matches my understanding which is great. My actual query was to learn how the removal of the broken connection is done.

Aside: I'd say the trace hooks "DNSStart" and "DNSDone" are somewhat misnamed, because the hostname resolution isn't necessarily done via DNS - in both your example and mine it's done via /etc/hosts.  But the intention is clear.

Agree.

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/bb366eb5-c7df-452a-9549-281543b1b6d4n%40googlegroups.com.

[b.ca...@pobox.com]

> My actual query was to learn how the removal of the broken connection is done.

Ah OK.  I'm not familiar with this code (net/http/transport.go), and you've already shown that the PutIdleConn trace action isn't called.  Maybe this comment is helpful:

                        if pconn.isBroken() || tooOld {

                                // If either persistConn.readLoop has marked the connection

                                // broken, but Transport.removeIdleConn has not yet removed it

                                // from the idle list, or if this persistConn is too old (it was

                                // idle too long), then ignore it and look for another. In both

                                // cases it's already in the process of being closed.

                                list = list[:len(list)-1]

                                continue

                        }

Otherwise someone else can answer more specifically.

[Amit Saha]

On 28 Nov 2020, at 11:22 pm, b.ca...@pobox.com <b.ca...@pobox.com> wrote:

> My actual query was to learn how the removal of the broken connection is done.

Ah OK.  I'm not familiar with this code (net/http/transport.go), and you've already shown that the PutIdleConn trace action isn't called.  Maybe this comment is helpful:

No worries at all. The PutIdleConn is not called for HTTP/2 connections which I found to be the case for https://godoc.org, but when I used http://godoc.org (in my example that I shared), it was called and the error was nil.

                        if pconn.isBroken() || tooOld {

                                // If either persistConn.readLoop has marked the connection

                                // broken, but Transport.removeIdleConn has not yet removed it

                                // from the idle list, or if this persistConn is too old (it was

                                // idle too long), then ignore it and look for another. In both

                                // cases it's already in the process of being closed.

                                list = list[:len(list)-1]

                                continue

                        }

Otherwise someone else can answer more specifically.

No problems. I did start looking at the above isBroken() method, but sort of got lost.

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/613e3778-7892-4ab9-8cc8-6db1a3e8f966n%40googlegroups.com.