net/http/httputil: DumpRequestOut has wrong headers on chunked body w/ ContentLength 0 (unknown)

[harshavardhana]

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

$ go version
go version go1.13 linux/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/harsha/.cache/go-build"
GOENV="/home/harsha/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/harsha/mygo"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/harsha/.gimme/versions/go1.13.linux.amd64"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/harsha/.gimme/versions/go1.13.linux.amd64/pkg/tool/linux_amd64"
GCCGO="/usr/bin/gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
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-build778517130=/tmp/go-build -gno-record-gcc-switches"

What did you do?

package main

import (
	"fmt"
	"io"
	"log"
	"net/http"
	"net/http/httputil"
	"os"
	"strings"
	"time"
)

type eofReader struct {
}

func (n eofReader) Close() error {
	return nil
}

func (n eofReader) Read([]byte) (int, error) {
	return 0, io.EOF
}

func testCase2(clnt *http.Client, debug bool) {
	req, err := http.NewRequest(http.MethodPut, "http://localhost:8080/hello", nil)
	if err != nil {
		log.Fatal(err)
	}
	req.Body = &eofReader{}
	req.ContentLength = 0

	if debug {
		reqBytes, err := httputil.DumpRequestOut(req, false)
		if err != nil {
			log.Fatal(err)
		}
		fmt.Println("############ REQUEST TestCase2")
		fmt.Println(string(reqBytes))
	}

	resp, err := clnt.Do(req)
	if err != nil {
		log.Fatal(err)
	}

	io.Copy(os.Stdout, resp.Body)
	resp.Body.Close()
}

func testCase1(clnt *http.Client, debug bool) {
	req, err := http.NewRequest(http.MethodPut, "http://localhost:8080/hello", nil)
	if err != nil {
		log.Fatal(err)
	}
	req.Body = http.NoBody
	req.ContentLength = -1

	if debug {
		reqBytes, err := httputil.DumpRequestOut(req, false)
		if err != nil {
			log.Fatal(err)
		}
		fmt.Println("############ REQUEST TestCase1")
		fmt.Println(string(reqBytes))
	}

	resp, err := clnt.Do(req)
	if err != nil {
		log.Fatal(err)
	}

	io.Copy(os.Stdout, resp.Body)
	resp.Body.Close()
}

func main() {
	// Hello world, the web server

	debug := os.Getenv("DEBUG") == "1"
	helloHandler := func(w http.ResponseWriter, req *http.Request) {
		if debug {
			fmt.Println("############ REQUEST-SERVER")
			fmt.Println("Transfer-Encoding:", strings.Join(req.TransferEncoding, ","))
			fmt.Println("Content-Length:", req.ContentLength)
			fmt.Println()
		}
		io.Copy(w, req.Body)
	}

	http.HandleFunc("/hello", helloHandler)
	go http.ListenAndServe(":8080", nil)

	time.Sleep(1 * time.Second)

	clnt := &http.Client{}
	testCase1(clnt, debug)
	testCase2(clnt, debug)
}

Based on this suggestion that req.ContentLength apparently should be honored but which isn't
#11493 (comment)

What did you expect to see?

~ DEBUG=1 go run /tmp/s.go 
############ REQUEST TestCase1
PUT /hello HTTP/1.1
Host: localhost:8080
User-Agent: Go-http-client/1.1
Content-Length: 0
Accept-Encoding: gzip


############ REQUEST-SERVER
Transfer-Encoding: 
Content-Length: 0

############ REQUEST TestCase2
PUT /hello HTTP/1.1
Host: localhost:8080
User-Agent: Go-http-client/1.1
Content-Length: 0
Accept-Encoding: gzip


############ REQUEST-SERVER
Transfer-Encoding: 
Content-Length: 0

What did you see instead?

~ DEBUG=1 go run /tmp/s.go
############ REQUEST TestCase1
PUT /hello HTTP/1.1
Host: localhost:8080
User-Agent: Go-http-client/1.1
Transfer-Encoding: chunked
Accept-Encoding: gzip


############ REQUEST-SERVER
Transfer-Encoding: 
Content-Length: 0

############ REQUEST TestCase2
PUT /hello HTTP/1.1
Host: localhost:8080
User-Agent: Go-http-client/1.1
Content-Length: 0
Accept-Encoding: gzip


############ REQUEST-SERVER
Transfer-Encoding: chunked
Content-Length: -1

A relevant PR was also sent https://go-review.googlesource.com/c/go/+/196965 which should fix this issue

[bradfitz]

I don't see any bug.

Everything seems to be working as intended and documented at https://golang.org/pkg/net/http/#Request.ContentLength

If you want to send a "Content-Length: 0" on the wire, set Request.Body to nil or NoBody.

[harshavardhana]

@bradfitz the issue is here because of r.ContentLength is not honored instead the server sees ContentLength as -1 but the intention was to send a 0-byte body.

func testCase2(clnt *http.Client, debug bool) {
	req, err := http.NewRequest(http.MethodPut, "http://localhost:8080/hello", nil)
	if err != nil {
		log.Fatal(err)
	}
	req.Body = &eofReader{}
	req.ContentLength = 0

	if debug {
		reqBytes, err := httputil.DumpRequestOut(req, false)
		if err != nil {
			log.Fatal(err)
		}
		fmt.Println("############ REQUEST TestCase2")
		fmt.Println(string(reqBytes))
	}

	resp, err := clnt.Do(req)
	if err != nil {
		log.Fatal(err)
	}

	io.Copy(os.Stdout, resp.Body)
	resp.Body.Close()
}

    // ContentLength records the length of the associated content.
    // The value -1 indicates that the length is unknown.
    // Values >= 0 indicate that the given number of bytes may
    // be read from Body.
    //
    // For client requests, a value of 0 with a non-nil Body is
    // also treated as unknown.

The reason is why do we need to rely on the fact that we have to set http.NoBody? - this style of communication adds additional code and complications. There is no good reason to have code like this.

if contentLength == 0 {
   r.Body = nil or r.Body = http.NoBody
}

My suggestion is to avoid this altogether and simply return what was set by the caller..

There are other issues here too which is basically the fact that if we need to trace the request seen by the server v/s what was traced as request set by the client are a different for example here

############ REQUEST TestCase2
PUT /hello HTTP/1.1
Host: localhost:8080
User-Agent: Go-http-client/1.1
Content-Length: 0
Accept-Encoding: gzip


############ REQUEST-Seen-By-SERVER
Transfer-Encoding: chunked
Content-Length: -1

This is odd from a debugging point of view for us any Go client with request dumping will give one value and server sees some other value. Either we should fix httputil to dump the exact request the server will see or fix it appropriately.

[harshavardhana]

This is odd from a debugging point of view for us any Go client with request dumping will give one value and server sees some other value. Either we should fix httputil to dump the exact request the server will see or fix it appropriately.

I see now why it is done intentionally and it's not easy to fix in any meaningful way. What I would like is to fix the httputil.RequestOut()'s output such that it tells us exactly what the underlying transport is going to send to the server. Keeping in line with the req.ContentLength documentation and behavior.

Let me update my PR to reflect that.

[bradfitz]

I think you're confused about zero values in Go.

There's no difference between:

r := new(http.Request)
r.Body = &yourReader{}

And:

r := new(http.Request)
r.Body = &yourReader{}
r.ContentLength = 0

So we can't assume that 0 means it's actually zero. It might just be implicitly zero.

Also, httputil.DumpRequestOut does use the real http.Transport to generate its output.

Again, I see no bug here. This is all working as intended, documented, and tested.

If you think the docs could be more clear somewhere, do let me know where they fell short or were confusing.

[harshavardhana]

I think you're confused about zero values in Go.

Not really, I didn't clearly understand why it might have been needed internally in the way its being assumed here.

So we can't assume that 0 means it's actually zero. It might just be implicitly zero.

This is what I understood after reading the code. Thank you for clarifying that.

Now coming back to the problem is this - We have a code which traces the incoming request and response from the server point of view and also a client-side code to trace the outgoing client requests. But I see differences here in terms of what is being shown in the Trace output debugging which led me to this issue.

For example server sees the request like this form

localhost [REQUEST s3.PutObject] 08:29:37.937
localhost PUT /testbucket/0byte
localhost Host: localhost:9001
localhost Transfer-Encoding: chunked
localhost User-Agent: Go-http-client/1.1
localhost Accept-Encoding: gzip
localhost Content-Length: -1
localhost <BODY>

Whereas the client only sees this

~ DEBUG=1 go run /tmp/u.go 
############ REQUEST TestCase1
PUT /testbucket/0byte HTTP/1.1
Host: localhost:9001
User-Agent: Go-http-client/1.1
Content-Length: 0
Accept-Encoding: gzip

This was the confusion on why even if the trace output says that

Content-Length: 0

is set and no Transfer-Encoding is set why does server see

localhost Transfer-Encoding: chunked
localhost Content-Length: -1

This AFAICS happens because newTransferWriter() is not yet called or initialized until httputil.DumpRequestOut() would have been used by the caller, so this leads to incorrect HTTP headers as seen from client v/s seen by the server.

@bradfitz don't you think this is an issue?

The code used is here

package main

import (
	"fmt"
	"io"
	"log"
	"net/http"
	"net/http/httputil"
	"os"
)

type eofReader struct {
}

func (n eofReader) Close() error {
	return nil
}

func (n eofReader) Read([]byte) (int, error) {
	return 0, io.EOF
}

func testCase1(clnt *http.Client, debug bool) {
	req, err := http.NewRequest(http.MethodPut, "http://localhost:9001/testbucket/0byte", nil)
	if err != nil {
		log.Fatal(err)
	}
	req.Body = &eofReader{}
	req.ContentLength = 0

	if debug {
		reqBytes, err := httputil.DumpRequestOut(req, false)
		if err != nil {
			log.Fatal(err)
		}
		fmt.Println("############ REQUEST TestCase1")
		fmt.Println(string(reqBytes))
	}

	resp, err := clnt.Do(req)
	if err != nil {
		log.Fatal(err)
	}

	io.Copy(os.Stdout, resp.Body)
	resp.Body.Close()
}

func main() {
	debug := os.Getenv("DEBUG") == "1"
	clnt := &http.Client{}
	testCase1(clnt, debug)
}

[bradfitz]

Content-Length: -1 should never be sent over the network. Are you seeing that actually happen?

But an http.Handler can see *http.Request.ContentLength == -1, which means the length is unknown. That's how Go's net/http package maps a chunked encoding to a length. The documentation of Request.ContentLength makes clear that the fields mean different things in client vs server context.

[harshavardhana]

Content-Length: -1 should never be sent over the network. Are you seeing that actually happen?

No, I am not saying that it did what I am specifically saying is client httputil.DumpRequestOut() didn't say that it's going to set "Transfer-Encoding: chunked" instead of server seeing that.

~ 
~ DEBUG=1 go run /tmp/u.go 
############ REQUEST TestCase1
PUT /testbucket/0byte HTTP/1.1
Host: localhost:9001
User-Agent: Go-http-client/1.1
Content-Length: 0
Accept-Encoding: gzip

Here its

Content-Length: 0

But server actually saw the request without Content-Length

Transfer-Encoding: chunked

From what I understood httputil.DumpRequestOut() should ideally print what it's going to write on the wire. This confusion led me to spend quite a bit of time understanding what is going on. Because the traces on client are not showing the same info as seen by the server.

[harshavardhana]

Right now I am trying to fix httputil.DumpRequestOut() to print Transfer-Encoding: chunked instead of printing Content-Length: 0

NOTE: This inconsistency only happens when the body is of 0 bytes.

[bradfitz]

Okay, retitled the bug then.

[gopherbot]

Change https://golang.org/cl/197898 mentions this issue: net/http/httputil: Fix missing Transfer-Encoding header