x/net/http2: investigate data race in Transport Request.Body reuse when GetBody is not defined

[ictar]

What version of Go are you using (go version)?

$ go version
go version go1.10.1 linux/amd64

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/test/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GORACE=""
GOROOT="/home/test/go"
GOTMPDIR=""
GOTOOLDIR="/home/test/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build614182611=/tmp/go-build -gno-record-gcc-switches"

and nginx version: nginx/1.13.3

What did you do?

Here is my client:

package main

import (
    "fmt"
    "net/http"
    "sync"
    "time"
    "errors"
    "bytes"
    "io/ioutil"
)

type Client struct {
    urlBase    string
    httpClient *http.Client
}

func NewClient(url string) *Client {
    cc := &Client{
        urlBase:    url,
        httpClient: &http.Client{Transport: &http.Transport{MaxIdleConnsPerHost: 100, MaxIdleConns: 100, IdleConnTimeout: 90 * time.Second, ExpectContinueTimeout: 5 * time.Second}},
    }
    cc.httpClient.Timeout = 5 * time.Second
    return cc
}

func (self *Client) Send(content []byte) error {
    if content == nil {
        return errors.New("nil content")
    }

    body := &bytes.Buffer{}
    body.Write(content)

    begin := time.Now()
    req, err := http.NewRequest("POST", self.urlBase, body)
    if err != nil {
        return fmt.Errorf("Send %+v (from %v to %v)", err, begin, time.Now())
    }
    req.Header = make(http.Header)
    req.Header.Set("Content-Type", "application/json")
    begin = time.Now()
    resp, err := self.httpClient.Do(req)
    if err != nil {
        return fmt.Errorf("Send %+v (from %v to %v)", err, begin, time.Now())
    }
    defer resp.Body.Close()

    if resp.StatusCode >= http.StatusBadRequest {
        bs, _ := ioutil.ReadAll(resp.Body)
        return fmt.Errorf("Send : HTTP : %d , BODY : %s , REQ : %s", resp.StatusCode, string(bs), string(content))
    }

    bs, err := ioutil.ReadAll(resp.Body)
    if err != nil {
        return fmt.Errorf("Send : ERR : %v", err)
    }
    fmt.Println("Send : Resp : ", string(bs))
    return nil
}

func main() {
    client := NewClient(
        "https://test.cn", // I use /etc/hosts to bind the domain
    )
    var content = []byte(`{"test":1}`)
    var wg sync.WaitGroup
    for i := 0; i < 100; i++ {
        wg.Add(1)
        go func() {
            defer wg.Done()
            client.Send(content)
        }()
    }
    wg.Wait()
}

And here is my nginx configure of http2:

    http2_max_concurrent_streams 40960;
    http2_max_requests 3;
    http2_max_field_size  8k;
    http2_max_header_size  32k;
    http2_recv_buffer_size 1024k;
    http2_recv_timeout  120s;

What did you expect to see?

I expect all requests are successfully.

What did you see instead?

But I got 400 occasionally and found client prematurely closed stream: only 0 out of 10 bytes of request body received line in nginx log.

I used GODEBUG to try to figure out, and found data not sent after END_HEADERS：

2018/04/23 18:32:25 http2: Transport encoding header ":method" = "POST"
2018/04/23 18:32:25 http2: Transport encoding header ":path" = "/"
2018/04/23 18:32:25 http2: Transport encoding header ":scheme" = "https"
2018/04/23 18:32:25 http2: Transport encoding header "content-type" = "application/json"
2018/04/23 18:32:25 http2: Transport encoding header "content-length" = "10"
2018/04/23 18:32:25 http2: Transport encoding header "accept-encoding" = "gzip"
2018/04/23 18:32:25 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2018/04/23 18:32:25 http2: Framer 0xc4205480e0: wrote HEADERS flags=END_HEADERS stream=5 len=8
2018/04/23 18:32:25 http2: Framer 0xc4205480e0: wrote DATA flags=END_STREAM stream=5 len=0 data=""

That's the reason why nginx responsed 400 directly.

[agnivade]

Does this happen only with http2 ?

Is it possible to for you to write a quick http2 server in Go and make this entire issue to be self-contained and fully reproducible ?

[ictar]

@agnivade Yes, it's fine with http1.1. Here is a quite simple server:

package main

import (
    "fmt"
    "log"
    "net/http"
)

func myHandler(w http.ResponseWriter, r *http.Request) {
    fmt.Fprintf(w, "Hello there!\n")
}

func main() {
    http.HandleFunc("/", myHandler)
    log.Fatal(http.ListenAndServe(":18800", nil))
}

And nginx is needed.

[agnivade]

And nginx is needed.

I don't understand. The whole point of having a Go server was to have the repro self-contained. If this is a client issue, why do we need nginx ? Is the Go client-server not enough to cause the repro ?

[ictar]

@agnivade Nginx is needed because it will check the body length against the header content-length. That's why nginx reponse 400 Bad Request directly. I don't think this is nginx issue because according to the tcpdump and GODEBUG, no body is sent indeed

And please note that in order to make this issue reproducible, http2_max_requests is set to 3 for nginx.

[agnivade]

The point of having a Go server is to allow us to reproduce the issue without nginx. You can simply add the equivalent check in the Go server so that it's behavior is same as nginx.

[odeke-em]

Thank you @ictar for the report, we'll investigate it.

@agnivade thank you for handling this. I just wanted to add that I can relate to @ictar's need to have nginx for a repro(many companies that I know heavily use it) and that the question of absolving the issue only because Go's servers can't reproduce it might be tricky. This is because many companies will usually put nginx or some other web server as their frontend to their web apps, and from there proxy the content to polyglot services on their backend e.g Go, Node.js, Python(etc) web server. Interoperability between protocols and servers matters a lot and discrepancies between Go clients talking to various servers creep in :)

[agnivade]

Yes I understand. I was trying to isolate the issue.

I did not mean to say to try to reproduce the issue with a plain Go HTTP server. Rather I meant to write equivalent code in Go to mimic nginx behavior so that we hit the bug. If that is hard to do, then we obviously need nginx. But if a simple check of verifying the content-length header and the body shows the issue, then we theoretically don't need nginx. Kind of like the test case that one will write if this indeed is a bug.

[ernado]

Seems like just verifying content-length to body length does not show the issue and we need nginx for that.

Also does not reproduce if http.Client is used just by single goroutine (in a non-concurrent way).

[agnivade]

/cc @bradfitz , @tombergan

[odeke-em]

@ictar I just got sometime this evening to try to reproduce this:

1. I have installed nginx on an Ubuntu server
2. I created a server in Go to put behind the nginx reverse proxy
3. I generated a certificate and key using https://github.com/odeke-em/ssg ssg --host localhost
4. I fired up nginx, the Go backend server and the Go client
   with my nginx file looking like this

user www-data;
worker_processes auto;
pid /run/nginx.pid;
include /etc/nginx/modules-enabled/*.conf;

events {
        worker_connections 768;
        # multi_accept on;
}

http {
        http2_max_concurrent_streams 40960;
        http2_max_requests 3;
        http2_max_field_size 8k;
        http2_max_header_size 32k;
        http2_recv_buffer_size 1024k;
        http2_recv_timeout 120s;

        sendfile on;
        tcp_nopush on;
        tcp_nodelay on;
        keepalive_timeout 65;
        types_hash_max_size 2048;

        include /etc/nginx/mime.types;
        default_type application/octet-stream;

        ##
        # SSL Settings
        ##
        ssl_protocols TLSv1 TLSv1.1 TLSv1.2; # Dropping SSLv3, ref: POODLE
        ssl_prefer_server_ciphers on;

        ##
        # Logging Settings
        ##

        access_log /var/log/nginx/access.log;
        error_log /var/log/nginx/error.log;

        ##
        # Gzip Settings
        ##

        gzip on;

        # gzip_vary on;
        # gzip_proxied any;
        # gzip_comp_level 6;
        # gzip_buffers 16 8k;
        # gzip_http_version 1.1;
        # gzip_types text/plain text/css application/json application/javascript text/xml application/xml application/xml+rss text/javascript;

        ##
        # Virtual Host Configs
        ##

        include /etc/nginx/conf.d/*.conf;
        include /etc/nginx/sites-enabled/*;

        server {
            listen 9889;
            ssl_certificate     /home/emmanuel/Desktop/opensrc/bugs/golang/24763/cert.pem;
            ssl_certificate_key /home/emmanuel/Desktop/opensrc/bugs/golang/24763/key.pem;
            ssl on;
            location / {
                proxy_pass    https://127.0.0.1:9789;
            }
        }
}

and I ran it 50 times in a row for ((i=0; i<50; i++)) do go run client.go >> output;done
and even with curl as a control

$ curl -i -k -X POST https://localhost:9889
HTTP/1.1 200 OK
Server: nginx/1.14.0 (Ubuntu)
Date: Fri, 15 Jun 2018 06:45:44 GMT
Content-Type: text/plain; charset=utf-8
Content-Length: 12
Connection: keep-alive

Hello world!
$ curl -i -k -X POST https://localhost:9889
HTTP/1.1 200 OK
Server: nginx/1.14.0 (Ubuntu)
Date: Fri, 15 Jun 2018 06:45:46 GMT
Content-Type: text/plain; charset=utf-8
Content-Length: 12
Connection: keep-alive

Hello world!

but no failures and the client and server look like this

Client

package main

import (
        "bytes"
        "crypto/tls"
        "errors"
        "fmt"
        "io/ioutil"
        "net/http"
        "sync"
        "time"
)

type client struct {
        base string
        hc   *http.Client
}

func newClient(baseURL string) *client {
        return &client{
                base: baseURL,
                hc: &http.Client{
                        Timeout: 5 * time.Second,
                        Transport: &http.Transport{
                                MaxIdleConnsPerHost:   100,
                                MaxIdleConns:          100,
                                IdleConnTimeout:       90 * time.Second,
                                ExpectContinueTimeout: 5 * time.Second,
                                TLSClientConfig: &tls.Config{
                                        InsecureSkipVerify: true,
                                },
                        },
                },
        }
}

func (c *client) send(content []byte) error {
        if content == nil {
                return errors.New("nil content")
        }

        body := new(bytes.Buffer)
        body.Write(content)

        start := time.Now()
        req, err := http.NewRequest("POST", c.base, body)
        if err != nil {
                return fmt.Errorf("Send %+v (from %s)", err, time.Since(start))
        }
        req.Header = make(http.Header)
        req.Header.Set("Content-Type", "application/json")
        resp, err := c.hc.Do(req)
        if err != nil {
                return fmt.Errorf("Send: HTTPClient.Do: %+v (from %s)", err, time.Since(start))
        }
        defer resp.Body.Close()

        blob, err := ioutil.ReadAll(resp.Body)
        if err != nil {
                return fmt.Errorf("Send: Read: %+v (from %s)", err, time.Since(start))
        }
        fmt.Printf("Send: Resp: %s\n", blob)
        return nil
}

func main() {
        client := newClient("https://localhost:9889/")
        content := []byte(`{"test":1}`)
        var wg sync.WaitGroup
        for i := 0; i < 100; i++ {
                wg.Add(1)
                go func(i int) {
                        defer wg.Done()
                        if err := client.send(content); err != nil {
                                fmt.Printf("#%d: err: %v\n", i, err)
                        }
                }(i)
        }
        wg.Wait()
}

server.go

package main

import (
        "io/ioutil"
        "log"
        "net/http"
)

func main() {
        addr := ":9789"
        log.Printf("Serving at: %s", addr)
        http.HandleFunc("/", helloWorld)
        if err := http.ListenAndServeTLS(addr, "cert.pem", "key.pem", nil); err != nil {
                log.Fatalf("Failed to serve: %v", err)
        }
}

func helloWorld(w http.ResponseWriter, r *http.Request) {
        _, _ = ioutil.ReadAll(r.Body)
        defer r.Body.Close()
        w.Write([]byte("Hello world!"))
}

@ictar with the setup that I've provided above, could you please try it locally too and see if this can reproduce the bug? Thank you.