net/http: Cannot flush HTTP request headers before writing the request body

[CSEMike]

go version go1.9rc2_cl165246139 linux/amd64

It appears impossible to flush HTTP request headers for an HTTP POST before the body is written. For reasons specific to my client and server, it's important that the client be able to flush its request headers before the POST body is available.

The test below reproduces the problem.

What appears to be happening is that RoundTrip is blocked in WriteBody.
https://golang.org/src/net/http/request.go#L618

Headers have been written, but not flushed, presumably because FlushHeaders is false. I can't figure out how to induce FlushHeaders to be true, or to otherwise flush the pending request headers.
https://golang.org/src/net/http/request.go#L611

Writing anything to the request body flushes. But, a zero byte write is ignored and doesn't result in the flush I was hoping for.
https://golang.org/src/net/http/internal/chunked.go#L196

In my case, the result of this behavior is a bug. The server receiving the request times out attempting to read request headers that are delayed until the request body is available. And, the body takes ~30s to arrive since it's a hanging poll.

Test code follows.

package postflush

import (
  "io"
  "log"
  "net/http"
  "net/http/httptest"
  "net/http/httptrace"
  "runtime"
  "testing"
  "time"
)

func TestPOSTFlush(t *testing.T) {
  received := make(chan bool)
  srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    close(received)
  }))
  defer srv.Close()

  pr, pw := io.Pipe()
  req, err := http.NewRequest(http.MethodPost, srv.URL, pr)
  if err != nil {
    t.Fatalf("NewRequest: %v", err)
  }

  // Extra debugging info.
  req = req.WithContext(httptrace.WithClientTrace(req.Context(),
    &httptrace.ClientTrace{
      GetConn: func(hostport string) {
        log.Print("GetConn: ", hostport)
      },
      GotConn: func(i httptrace.GotConnInfo) {
        log.Print("reverse path: got conn: ", i)
      },
      WroteHeaders: func() {
        log.Print("reverse path: wrote headers")
      },
    }))

  go func() {
    resp, err := http.DefaultTransport.RoundTrip(req)
    if err != nil {
      t.Errorf("RoundTrip: %v", err)
      return
    }
    resp.Body.Close()
  }()

  // Writing anything unbreaks the test.
  // pw.Write([]byte("abc123"))

  select {
  case <-received:
  case <-time.After(5 * time.Second):
    t.Errorf("timed out waiting for origin to receive POST")
    buf := make([]byte, 32*1024)
    runtime.Stack(buf, true)
    t.Errorf("stacks:\n%s", string(buf))
  }
  pw.Close()
}

[CSEMike]

A related and comparatively minor issue is that the httptrace WroteHeaders callback for the POST is incorrect.

Modifying the test above to report header delivery via a WroteHeaders callback shows that the headers are written ~immediately when RoundTrip is called. In fact, they are delayed until part of the request body is written.

[bradfitz]

/cc @tombergan

Sorry, I've been away on leave and just got back to work.

@CSEMike, would it be okay if this header write flush only happened after N milliseconds of request.Body.Read blockage? (I'd prefer if we could do this without adding any new API, ideally.)

Alternatively, do you need control over this at a per-request level?

Ideas, including gross ones:

• flush headers after N milliseconds, without API change
• Request context variable
• interface check whether Request.Body implements some FlushEarly() interface.
• new Transport-level bool
• magic request header to force flushing that's not written because it's illegal (like https://golang.org/pkg/net/http/#TrailerPrefix)

A related and comparatively minor issue is that the httptrace WroteHeaders callback for the POST is incorrect.

Fun. Looks like we'll have to get more intimate with the bufio.Writer.

[bradfitz]

The freeze was yesterday, so I tagged this Go1.11, but it's possible we could fix the httptrace bug for Go 1.10 if it's causing you problems.

[tombergan]

It appears impossible to flush HTTP request headers for an HTTP POST before the body is written. For reasons specific to my client and server, it's important that the client be able to flush its request headers before the POST body is available.

Can you send Expect: 100-continue with the request? I believe that's what 100-continue is for.
https://tools.ietf.org/html/rfc7231#section-5.1.1
https://tools.ietf.org/html/rfc7231#section-6.2.1

Headers have been written, but not flushed, presumably because FlushHeaders is false. I can't figure out how to induce FlushHeaders to be true, or to otherwise flush the pending request headers.

flush headers after N milliseconds, without API change

I think this already happens? It looks like N=200. See transfer.go:transferWriter.probeRequestBody. As a hack, you could wrap the request body with an io.Reader that sleeps for 201ms on the first call.

A related and comparatively minor issue is that the httptrace WroteHeaders callback for the POST is incorrect.

Fun. Looks like we'll have to get more intimate with the bufio.Writer.

Well, I guess we never documented what "wrote" means in httptrace :-) We could call WroteHeaders after net/http's buffer is flushed, but it's not clear that's much of an improvement, since the data can still sit in the kernel buffer for an arbitrary amount of time after net/http's buffer is flushed.

[CSEMike]

@tombergan Adding `req.Header.Set("Expect", "100-continue") does indeed unbreak the test. Thanks.

It's a bit magical, but it works.

I'll defer to your collective judgement on whether or not a lower-level fix is warranted. This is a corner case, but a very subtle one to debug, particularly in the case of timeouts. I suspect others will share my intuitive expectation that POST headers will be flushed. I'm not sure how someone else in this situation could discover the Expect header work-around, effective though it is.

Revised test code follows.

package postflush

import (
	"io"
	"net/http"
	"net/http/httptest"
	"runtime"
	"testing"
	"time"
)

func TestPOSTFlush(t *testing.T) {
	received := make(chan bool)
	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		close(received)
	}))
	defer srv.Close()

	pr, pw := io.Pipe()
	req, err := http.NewRequest(http.MethodPost, srv.URL, pr)
	if err != nil {
		t.Fatalf("NewRequest: %v", err)
	}
	req.Header.Set("Expect", "100-continue")

	go func() {
		resp, err := http.DefaultTransport.RoundTrip(req)
		if err != nil {
			t.Errorf("RoundTrip: %v", err)
			return
		}
		resp.Body.Close()
	}()

	select {
	case <-received:
	case <-time.After(5 * time.Second):
		t.Errorf("timed out waiting for origin to receive POST")
		buf := make([]byte, 32*1024)
		runtime.Stack(buf, true)
		t.Errorf("stacks:\n%s", string(buf))
	}
	pw.Close()
}

[tombergan]

That looks like a bug. transferWriter.probeRequestBody is supposed to flush the headers if req.Body.Read doesn't return within 200ms (at least, I think that's what it's supposed to do).

Stepping back a bit, there are two things you could be trying to do:

1. Let the server process the request headers before sending the request body. The only solution to this is Expect 100-continue. Admittedly, this is pretty obscure.

2. Setup a long-running POST where it may take a while to generate the first byte of the request body. For example, it takes 10s to generate the first byte. The server is OK with this as long as it receives the headers in a timely fashion, say, within 5s.

I'm just guessing here ... I think you're in the second case? If so, everything should "just work" as long as the server's initial timeout is greater than 200ms, but obviously this isn't working properly. We could add a FlushRequestHeadersTimeout to http.Transport, as Brad suggested, but the more immediate problem is to figure out why the 200ms flush is not working.

One last question: Do you know if your actual production code is using HTTP/1 or HTTP/2?

[bradfitz]

That looks like a bug. transferWriter.probeRequestBody is supposed to flush the headers if req.Body.Read doesn't return within 200ms

But that's only used for certain requests:

func (t *transferWriter) shouldSendChunkedRequestBody() bool { 
        // Note that t.ContentLength is the corrected content length                                                      
        // from rr.outgoingLength, so 0 actually means zero, not unknown.                                                 
        if t.ContentLength >= 0 || t.Body == nil { // redundant checks; caller did them                                   
                return false 
        }  
        if requestMethodUsuallyLacksBody(t.Method) { 
                // Only probe the Request.Body for GET/HEAD/DELETE/etc                                                    
                // requests, because it's only those types of requests                                                    
                // that confuse servers.                                                                                  
                t.probeRequestBody() // adjusts t.Body, t.ContentLength                                                   
                return t.Body != nil 
        } 
        // For all other request types (PUT, POST, PATCH, or anything                                                     
        // made-up we've never heard of), assume it's normal and the server                                               
        // can deal with a chunked request body. Maybe we'll adjust this                                                  
        // later.                                                                                                         
        return true 
} 

[tombergan]

Oh, not sure how I missed that. Seems like we should do a delayed header flush for all requests.

[gopherbot]

Change https://golang.org/cl/114316 mentions this issue: net/http: conservatively flush Transport request headers by default