Example : Ensure that http connection will be re-use #249

jerome-laforge · 2016-05-03T13:04:25Z

Hello,
It will be great into example to ensure that http connection will be re-use by ensuring that Body has be completely purged. That avoid performance problem for whom that use this example as primary guide.

For example for https://github.com/go-kit/kit/blob/master/examples/stringsvc3/transport.go#L50, add something like this :

func decodeUppercaseResponse(_ context.Context, r *http.Response) (interface{}, error) {
    // This defer ensures to reuse the tcp connection via HTTP/1.1
    defer io.Copy(ioutil.Discard, r.Body)

    var response uppercaseResponse

Thx.

peterbourgon · 2016-05-03T13:39:29Z

It's not obvious to me that this is necessary. Can you point to something which indicates it is?

jerome-laforge · 2016-05-03T14:11:00Z

of course :
http://stackoverflow.com/questions/17948827/reusing-http-connections-in-golang
and overall :
https://groups.google.com/forum/#!search/golang$20json$20decode$20$20io.Copy/golang-nuts/4Rr8BYVKrAI/ZrJJFTNleekJ

I have just tested in my own µservice (that uses gokit) and wireshark/tcpdump.
without this, the httpclient closes the tcp connection and open a new one for each http call.

I didn't test for the example, but I think that this example has to give the good way to do by re-using http connection.

peterbourgon · 2016-05-03T14:16:24Z

Huh, that's annoying! Yes, I agree it's a good idea. Can you please make a PR? Please visit the other examples too :)

jerome-laforge · 2016-05-03T14:28:11Z

ok, I will do it

ChrisHines · 2016-05-03T17:20:48Z

Is it worth pointing out that io.Copy could read forever from a malicious or broken service?

jerome-laforge · 2016-05-03T17:25:33Z

I agree with @ChrisHines, maybe the comment can be modified to indicate this potential risk?

ChrisHines · 2016-05-03T18:27:04Z

I don't think our examples should include this io.Copy. I believe the linked posts arguing for its need are incorrect. See the current net/http implementation for Close on the most common types of response bodies.

https://github.com/golang/go/blob/master/src/net/http/transfer.go#L612

https://github.com/golang/go/blob/master/src/net/http/transfer.go#L777

As long as we defer resp.Body.Close() package net/http already handles the situation appropriately and safely.

ChrisHines · 2016-05-03T18:42:02Z

@jerome-laforge I would be curious to learn why the connections were not reused in your tests. Maybe the server isn't returning a proper Content-Length or something.

jerome-laforge · 2016-05-03T18:44:14Z

Maybe, but as already wrote in my previous post without this defer, the httpclient closes the tcp connection and open a new one. I checked this at raw level with wireshark.
I don't at work right now, but tomorrow I will perform this test again to see if there are trailing characters.

jerome-laforge · 2016-05-03T18:46:03Z

@ChrisHines I will check tomorrow if the Content-Length is ok or not.
I'll keep you informed.

jerome-laforge · 2016-05-04T09:17:44Z

@ChrisHines I've just done a new test.
The server doesn't send Content-Length but it sends the response with chunked Transfer-Encoding: chunked.

As you can see:

GET /api/v1/state HTTP/1.1
Host: 10.130.145.94:8401
User-Agent: Go-http-client/1.1
Accept-Encoding: gzip
Connection: keep-alive

HTTP/1.1 200 OK
Server: Apache-Coyote/1.1
Content-Type: application/json;charset=UTF-8
Transfer-Encoding: chunked
Date: Wed, 04 May 2016 09:05:12 GMT

1b
{"state":"OK","message":""}
0

A weird thing is that JSON decoder reads all data from r.Body because if I put this to monitor what is actually read into response.Body

defer func() {
    b := new(bytes.Buffer)
    io.Copy(b, response.Body)

    fmt.Println("--------------->", b.Len())
    fmt.Println(hex.Dump(b.Bytes()))
    fmt.Println("###############>") 
}()

I have this into the console:

---------------> 0

###############>

However I see the httpclient that closed the TCP connection (it sends TCP FIN ACK to http server) and open a new one.

I think that I will describe this on golang nuts.

pwaller · 2016-05-04T11:28:21Z

As I replied on the go mailing list, I think you guys are hitting the same case as this nasty docker bug. In summary, Encode writes an extra newline, and Decode does not read this newline, so you have to read it yourself.

ChrisHines · 2016-05-04T16:02:39Z

I have tried to reproduce the issue with Go code and cannot get the described behavior. Take a look at this code, run it, and see if you agree: https://play.golang.org/p/XtCIhjL1z3

jerome-laforge · 2016-05-04T17:08:35Z

I run it with -race and the code is racy.

==================
WARNING: DATA RACE
Write by goroutine 8:
  bytes.(*Buffer).Write()
      /usr/lib/golang/src/bytes/buffer.go:130 +0x4b
  main.(*teeConn).Read()
      /tmp/test/src/main.go:84 +0x140
  net/http.noteEOFReader.Read()
      /usr/lib/golang/src/net/http/transport.go:1370 +0x74
  net/http.(*noteEOFReader).Read()
      <autogenerated>:126 +0xf7
  bufio.(*Reader).fill()
      /usr/lib/golang/src/bufio/bufio.go:97 +0x364
  bufio.(*Reader).Peek()
      /usr/lib/golang/src/bufio/bufio.go:132 +0x186
  net/http.(*persistConn).readLoop()
      /usr/lib/golang/src/net/http/transport.go:876 +0x14d

Previous write by goroutine 10:
  bytes.(*Buffer).Write()
      /usr/lib/golang/src/bytes/buffer.go:130 +0x4b
  main.(*teeConn).Write()
      /tmp/test/src/main.go:92 +0x140
  bufio.(*Writer).flush()
      /usr/lib/golang/src/bufio/bufio.go:562 +0x1a7
  bufio.(*Writer).Flush()
      /usr/lib/golang/src/bufio/bufio.go:551 +0x3a
  net/http.(*persistConn).writeLoop()
      /usr/lib/golang/src/net/http/transport.go:1017 +0x361

Goroutine 8 (running) created at:
  net/http.(*Transport).dialConn()
      /usr/lib/golang/src/net/http/transport.go:685 +0x11bf
  net/http.(*Transport).getConn.func4()
      /usr/lib/golang/src/net/http/transport.go:549 +0x73

Goroutine 10 (running) created at:
  net/http.(*Transport).dialConn()
      /usr/lib/golang/src/net/http/transport.go:686 +0x11e4
  net/http.(*Transport).getConn.func4()
      /usr/lib/golang/src/net/http/transport.go:549 +0x73
==================
...

I try to quickly fix the race with this : https://play.golang.org/p/0_Uq5C8Z3Y

I have this:

2016/05/04 18:45:20 
GET / HTTP/1.1
Host: 127.0.0.1:34056
User-Agent: Go-http-client/1.1
Connection: keep-alive
Accept-Encoding: gzip

HTTP/1.1 200 OK
Content-Type: application/json
Date: Wed, 04 May 2016 16:45:20 GMT
Transfer-Encoding: chunked

1b
{"State":"OK","Message":""}
2016/05/04 18:45:20 main.data{State:"OK", Message:""}

After this I tried two http request on the same test server without io.Copy(discard, r.Body). Plz find the code here:
https://play.golang.org/p/a8wl6zsmap

The result:

2016/05/04 18:59:49 ----------------
2016/05/04 18:59:49 First connection
2016/05/04 18:59:49 
GET / HTTP/1.1
Host: 127.0.0.1:42340
User-Agent: Go-http-client/1.1
Connection: keep-alive
Accept-Encoding: gzip

HTTP/1.1 200 OK
Content-Type: application/json
Date: Wed, 04 May 2016 16:59:49 GMT
Transfer-Encoding: chunked

1b
{"State":"OK","Message":""}
2016/05/04 18:59:49 main.data{State:"OK", Message:""}
2016/05/04 18:59:49 -----------------
2016/05/04 18:59:49 Second connection
2016/05/04 18:59:49 
GET / HTTP/1.1
Host: 127.0.0.1:42340
User-Agent: Go-http-client/1.1
Connection: keep-alive
Accept-Encoding: gzip

HTTP/1.1 200 OK
Content-Type: application/json
Date: Wed, 04 May 2016 16:59:49 GMT
Transfer-Encoding: chunked

1b
{"State":"OK","Message":""}
2016/05/04 18:59:49 main.data{State:"OK", Message:""}

In this case, I can see with wireshark the httpclient close 1st tcp conn with reset and open a new one for 2nd req that closes again with reset. As you can see.

429 256.601935000   127.0.0.1   127.0.0.1   TCP 66  37934→42340 [RST, ACK] Seq=121 Ack=155 Win=44800 Len=0 TSval=87597353 TSecr=87597352

If I do the same test (2 http request) but with purge of r.Body, plz find the code here:
https://play.golang.org/p/k9ukf2NN_z

In this case, I can see with wireshark that httpclient has reused the tcp conn for both http request, as expected.

ChrisHines · 2016-05-04T19:48:05Z

I get inconsistent results. Using your two-request code I can run it multiple times and get different results:

$ ./http-test
2016/05/04 14:12:10 ----------------
2016/05/04 14:12:10 First connection
2016/05/04 14:12:10 
GET / HTTP/1.1
Host: 127.0.0.1:51418
User-Agent: Go-http-client/1.1
Connection: keep-alive
Accept-Encoding: gzip

HTTP/1.1 200 OK
Content-Type: application/json
Date: Wed, 04 May 2016 18:12:10 GMT
Transfer-Encoding: chunked

1b
{"State":"OK","Message":""}
0

2016/05/04 14:12:10 main.data{State:"OK", Message:""}
2016/05/04 14:12:10 -----------------
2016/05/04 14:12:10 Second connection
2016/05/04 14:12:10 
GET / HTTP/1.1
Host: 127.0.0.1:51418
User-Agent: Go-http-client/1.1
Connection: keep-alive
Accept-Encoding: gzip

HTTP/1.1 200 OK
Content-Type: application/json
Date: Wed, 04 May 2016 18:12:10 GMT
Transfer-Encoding: chunked

1b
{"State":"OK","Message":""}
0

2016/05/04 14:12:10 main.data{State:"OK", Message:""}
$ ./http-test
2016/05/04 14:12:12 ----------------
2016/05/04 14:12:12 First connection
2016/05/04 14:12:12 
GET / HTTP/1.1
Host: 127.0.0.1:51422
User-Agent: Go-http-client/1.1
Connection: keep-alive
Accept-Encoding: gzip

HTTP/1.1 200 OK
Content-Type: application/json
Date: Wed, 04 May 2016 18:12:12 GMT
Transfer-Encoding: chunked

1b
{"State":"OK","Message":""}
2016/05/04 14:12:12 main.data{State:"OK", Message:""}
2016/05/04 14:12:12 -----------------
2016/05/04 14:12:12 Second connection
2016/05/04 14:12:12 
GET / HTTP/1.1
Host: 127.0.0.1:51422
User-Agent: Go-http-client/1.1
Connection: keep-alive
Accept-Encoding: gzip

HTTP/1.1 200 OK
Content-Type: application/json
Date: Wed, 04 May 2016 18:12:12 GMT
Transfer-Encoding: chunked

1b
{"State":"OK","Message":""}
2016/05/04 14:12:12 main.data{State:"OK", Message:""}
$

jerome-laforge · 2016-05-04T20:02:23Z

This code is not the core of the pb. It is just adaptation of your code without the race and that tries to point out that without the purge of the response.Body the httpclient doesn't reuse the tcp connection.
Did you also notice this behavior?
Thx again for your support.

ChrisHines · 2016-05-04T20:29:05Z

@jerome-laforge Here is an updated version that is less racy: https://play.golang.org/p/aYFyASvAik

With this code I sometimes see the connection close. If I uncomment the io.Copy calls I don't see the connection close. I still don't understand why the io.Copy is needed, since resp.Body.Close seems to have code for doing the same thing internally.

peterbourgon · 2016-05-15T18:29:06Z

Forgive me, I became somewhat lost in the details. Is the current state here that we're seeing behavior we cannot currently explain?

ChrisHines · 2016-05-16T01:33:14Z

@peterbourgon That's where I am at. In my mind there seems to be a missing piece to the puzzle.

jerome-laforge · 2016-05-16T14:50:55Z

For my point of view, this problem occurs when response is sent with Transfer-Encoding: chunked.
And more precisely at this line:
https://github.com/golang/go/blob/master/src/net/http/internal/chunked.go#L61
The n := cr.r.Buffered() returns 0.

And so we don't read the last 0 that indicates the end of response that normally happens here:
https://github.com/golang/go/blob/master/src/net/http/internal/chunked.go#L56

ChrisHines · 2016-05-16T15:30:52Z

It would seem to me, from reading this code, https://github.com/golang/go/blob/master/src/net/http/transfer.go#L777, that net/http intends to read a reasonable amount of left over body content when we call resp.Body.Close() so that the connection may be reused.

I contend that if it does not do this, either it has a good reason, or there is a bug in net/http that someone should isolate and report. I don't think we should encourage others to add an io.Copy before calling resp.Body.Close unless we can verify that it is the idiomatic use of net/http.

basvanbeek · 2016-05-16T15:55:05Z

Looking at your results Chris it does seem that there is an issue with the payload received from the Server.

The first time the chunk length header is properly received being 0 meaning the request is done so the connection can be re-used safely.

The second time this empty chunk header identifying end of request is not shown. If no data is available for reception in a reasonable amount of time we can't assume this connection to be reusable as many large chunks could potentially be received afterwards.

jerome-laforge · 2016-05-16T17:11:11Z

@ChrisHines delve shows me that when https://github.com/golang/go/blob/master/src/net/http/internal/chunked.go#L61 returns 0, the https://github.com/golang/go/blob/master/src/net/http/transfer.go#L777 isn't called cause https://github.com/golang/go/blob/master/src/net/http/transport.go#L1870 is executed before https://github.com/golang/go/blob/master/src/net/http/transport.go#L1872.

ChrisHines · 2016-05-16T17:48:51Z

@jerome-laforge Then maybe you have found a bug. What version of Go are you testing this on?

See also this long discussion of pretty much the same issue: google/go-github#317.

This may already be fixed on tip: https://go-review.googlesource.com/#/c/21291.

jerome-laforge · 2016-05-16T17:56:30Z

@ChrisHines I use Go on Arch Linux, and my version of Go is:

go version
go version go1.6.2 linux/amd64

I will fetch Go tip, I will try the test with it.

jerome-laforge · 2016-05-16T18:49:21Z

@ChrisHines I have just tested with tip version: devel +b66b97e Mon May 16 15:05:04 2016 +0000. And it the same behavior.
If n := cr.r.Buffered() returns 0 (https://github.com/golang/go/blob/master/src/net/http/internal/chunked.go#L61), then delve shows me that https://github.com/golang/go/blob/master/src/net/http/transfer.go#L777 isn't called, and the tcp connection isn't reused...

ChrisHines · 2016-05-16T18:58:43Z

@jerome-laforge I recommend opening an issue against Go net/http package.

ChrisHines · 2016-05-23T01:28:28Z

@jerome-laforge The issue you filed against Go was closed. See the Go issue to see if you are satisfied with the explanation. Please let us know if we can close this issue.

jerome-laforge · 2016-05-29T10:03:54Z

Yes, you can close it. I will keep drain of response.Body to ensure the reuse of connection.
thx again for your support.

peterbourgon added the question label May 15, 2016

jerome-laforge mentioned this issue May 16, 2016

net/http: with Transfer-Encoding: chunked, Transport doesn't reuse the tcp connection golang/go#15703

Closed

ChrisHines closed this as completed May 29, 2016

dropwhile mentioned this issue Jan 17, 2017

Potential resource leak by not closing the response body cactus/go-camo#14

Merged

at15 mentioned this issue Jan 31, 2018

Client, Request, Response at15/go-solr#2

Open

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Example : Ensure that http connection will be re-use #249

Example : Ensure that http connection will be re-use #249

jerome-laforge commented May 3, 2016

peterbourgon commented May 3, 2016 •

edited

Loading

jerome-laforge commented May 3, 2016

peterbourgon commented May 3, 2016

jerome-laforge commented May 3, 2016 •

edited

Loading

ChrisHines commented May 3, 2016

jerome-laforge commented May 3, 2016

ChrisHines commented May 3, 2016 •

edited

Loading

ChrisHines commented May 3, 2016 •

edited

Loading

jerome-laforge commented May 3, 2016

jerome-laforge commented May 3, 2016

jerome-laforge commented May 4, 2016

pwaller commented May 4, 2016 •

edited

Loading

ChrisHines commented May 4, 2016

jerome-laforge commented May 4, 2016 •

edited

Loading

ChrisHines commented May 4, 2016

jerome-laforge commented May 4, 2016 •

edited

Loading

ChrisHines commented May 4, 2016

peterbourgon commented May 15, 2016 •

edited

Loading

ChrisHines commented May 16, 2016

jerome-laforge commented May 16, 2016

ChrisHines commented May 16, 2016

basvanbeek commented May 16, 2016

jerome-laforge commented May 16, 2016

ChrisHines commented May 16, 2016

jerome-laforge commented May 16, 2016

jerome-laforge commented May 16, 2016

ChrisHines commented May 16, 2016

ChrisHines commented May 23, 2016

jerome-laforge commented May 29, 2016

Example : Ensure that http connection will be re-use #249

Example : Ensure that http connection will be re-use #249

Comments

jerome-laforge commented May 3, 2016

peterbourgon commented May 3, 2016 • edited Loading

jerome-laforge commented May 3, 2016

peterbourgon commented May 3, 2016

jerome-laforge commented May 3, 2016 • edited Loading

ChrisHines commented May 3, 2016

jerome-laforge commented May 3, 2016

ChrisHines commented May 3, 2016 • edited Loading

ChrisHines commented May 3, 2016 • edited Loading

jerome-laforge commented May 3, 2016

jerome-laforge commented May 3, 2016

jerome-laforge commented May 4, 2016

pwaller commented May 4, 2016 • edited Loading

ChrisHines commented May 4, 2016

jerome-laforge commented May 4, 2016 • edited Loading

ChrisHines commented May 4, 2016

jerome-laforge commented May 4, 2016 • edited Loading

ChrisHines commented May 4, 2016

peterbourgon commented May 15, 2016 • edited Loading

ChrisHines commented May 16, 2016

jerome-laforge commented May 16, 2016

ChrisHines commented May 16, 2016

basvanbeek commented May 16, 2016

jerome-laforge commented May 16, 2016

ChrisHines commented May 16, 2016

jerome-laforge commented May 16, 2016

jerome-laforge commented May 16, 2016

ChrisHines commented May 16, 2016

ChrisHines commented May 23, 2016

jerome-laforge commented May 29, 2016

peterbourgon commented May 3, 2016 •

edited

Loading

jerome-laforge commented May 3, 2016 •

edited

Loading

ChrisHines commented May 3, 2016 •

edited

Loading

ChrisHines commented May 3, 2016 •

edited

Loading

pwaller commented May 4, 2016 •

edited

Loading

jerome-laforge commented May 4, 2016 •

edited

Loading

jerome-laforge commented May 4, 2016 •

edited

Loading

peterbourgon commented May 15, 2016 •

edited

Loading