net/http2: http.Flusher doesn't send data to the client

[libnat]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.8beta2 darwin/amd64

I am using HTTP/2, and want to push data to client.

w.Write([]byte("Hello"))
w.(http.Flusher).Flush()

The data won't reach the client. I read the doc, and make sure no http proxy is used in the client.

If I call it in a loop for 100 times, the client will receive the data.

for i := 0; i < 100; i++ {
w.Write([]byte("Hello"))
w.(http.Flusher).Flush()
}

[odeke-em]

@JustinTan are you inspecting the content from a browser or from a Go client?
If using a browser, you'll need to send a bunch of junk first to get the browser to render. I learnt about this from @bradfitz's code in the demo at https://http2.golang.org/clockstream
here
https://github.com/bradfitz/http2/blob/aa7658c0e9902e929a9ed0996ef949e59fc0f3ab/h2demo/h2demo.go#L176-L177

Otherwise if you are using a non-browser, I've made a standalone using HTTP2 that seems to function alright and stream content properly here https://github.com/odeke-em/bugs/tree/master/golang/18510
with the video demo here https://asciinema.org/a/9g86m7636l58hbq2f10kho0iz

Just run go run server.go and then go run client.go

/cc @bradfitz

[libnat]

@odeke-em
My client is implemented in Objective-C. NSURLSession support http/2 server push since iOS 10.
Now my solution is to send about 500 bytes to the client in the beginning in order to make the push stream work.
It seems Flush() doesn't really flush data to the client.

[AlekSi]

Do you run some reverse-proxy like nginx?
Can you create a small self-contained example repository so others can test it?

[rsc]

@odeke-em posted a complete program that works.
@JustinTan, can you post one that doesn't?

Thanks.

[bradfitz]

There are extensive tests for http.Flusher used in both http1 and http2 mode. Please share a minimal demo of your server code not flushing.

[libnat]

Thanks for your replies.
I deployed the program on a server.
You can visit via https://api.nexthot.net:7001/?num=500
If num is 1, no data reach the client.

http/2 server:

package main

import (
	"log"
	"net/http"
	"strconv"
	"strings"
)

func main() {
	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
		n, _ := strconv.Atoi(r.URL.Query().Get("num"))
		log.Println("new request:", n)
		w.Header().Set("Content-Type", "text/plain")
		s := strings.Repeat("hello,world", n) //
		w.Write([]byte(s))
		w.(http.Flusher).Flush()
		clientGone := w.(http.CloseNotifier).CloseNotify()
		<-clientGone
		log.Printf("Client %v closed", r.RemoteAddr)
	})
	http.ListenAndServeTLS(":7001", "cert.pem", "privkey.pem", nil)
}

Client is implemented in Objective-C:

NSURLSessionConfiguration *configuration = [NSURLSessionConfiguration defaultSessionConfiguration];
NSURLSession *session =  [NSURLSession sessionWithConfiguration:configuration delegate:self delegateQueue:NSOperationQueue.mainQueue];
NSURL *url = [NSURL URLWithString:@"https://api.nexthot.net:7001?num=500"];
self.task = [session dataTaskWithURL:url];
[self.task resume];

[fraenkel]

I have a feeling the connection is buffering the data but it is being flushed as far as the http2 stack is concerned. When n=373, some of the data will arrive on the client.

2017/01/05 11:04:06 new request: 1
2017/01/05 11:04:06 http2: server encoding header ":status" = "200"
2017/01/05 11:04:06 http2: server encoding header "content-type" = "text/plain"
2017/01/05 11:04:06 http2: server encoding header "date" = "Thu, 05 Jan 2017 16:04:06 GMT"
2017/01/05 11:04:06 http2: Framer 0xc4200811e0: wrote HEADERS flags=END_HEADERS stream=1 len=34
2017/01/05 11:04:06 http2: Framer 0xc4200811e0: wrote DATA stream=1 len=11 data="hello,world"

[bradfitz]

I verified this is working correctly on the Go server side. I added some more logging and sent it an HTTP/2 request while I ran the server with GODEBUG=http2debug=2 and saw:

2017/01/05 18:51:13 Request HTTP/2.0, map["num":["2"]]
2017/01/05 18:51:13 new request: 2
2017/01/05 18:51:13 http2: server encoding header ":status" = "200"
2017/01/05 18:51:13 http2: server encoding header "content-type" = "text/plain"
2017/01/05 18:51:13 http2: server encoding header "date" = "Thu, 05 Jan 2017 18:51:13 GMT"
2017/01/05 18:51:13 http2: Framer 0xc4201e49c0: wrote HEADERS flags=END_HEADERS stream=1 len=34
2017/01/05 18:51:13 http2: Framer 0xc4201e49c0: wrote DATA stream=1 len=24 data="hello,world\nhello,world\n"
2017/01/05 18:51:13 Flushed 24
2017/01/05 18:51:15 timeout
2017/01/05 18:51:15 http2: Framer 0xc4201e49c0: wrote DATA flags=END_STREAM stream=1 len=0 data=""

Note the 24 bytes of DATA gets written two seconds before the DATA w/ END_STREAM.

And I saw the DATA arrive on the client side immediately (with curl or a modified h2i client).

Your issue is in your client library somewhere.

[rsc]

@bradfitz, do you have a command that can be run against @JustinTan's live server to tell whether it is sending the data immediately? All I have is Chrome, and it's true that for Chrome I don't see output for ?num=1.

[bradfitz]

@rsc, the golang.org/x/net/http2/h2i interactive tool confirms it works against @JustinTan's live site:

bradfitz@gdev:~$ h2i -insecure api.nexthot.net:7001
Connecting to api.nexthot.net:7001 ...
Connected to 58.96.176.63:7001
Negotiated protocol "h2"
Sending: []
[FrameHeader SETTINGS len=18]
  [MAX_FRAME_SIZE = 1048576]
  [MAX_CONCURRENT_STREAMS = 250]
  [MAX_HEADER_LIST_SIZE = 1048896]
[FrameHeader SETTINGS flags=ACK len=0]
h2i> headers
(as HTTP/1.1)> GET /?num=2 HTTP/1.1
(as HTTP/1.1)> Host: foo.com
(as HTTP/1.1)> 
Opening Stream-ID 1:
 :authority = foo.com
 :method = GET
 :path = /?num=2
 :scheme = https
[FrameHeader HEADERS flags=END_HEADERS stream=1 len=34]
  :status = "200"
  content-type = "text/plain"
  date = "Thu, 05 Jan 2017 19:36:05 GMT"
[FrameHeader DATA stream=1 len=22]
  "hello,worldhello,world"
h2i> 

The h2i tool needs a patch to send query arguments correctly, though. I sent https://go-review.googlesource.com/34820

[libnat]

@bradfitz Thanks for your reply.
My client is implemented in iOS official system SDK NSURLSession. I will report this issue to them.
If I use Chrome to open https://api.nexthot.net:7001/?num=1 , still no output. I am confused how to push a short string to Chrome?

[odeke-em]

Just trying out with different clients: curl, python3-with-requests, wget, go client

• curl and python3-with-requests don't seem to be responding ASAP either, only wget seems to respond ASAP:

curl hangs

$ curl -k -i -X GET https://api.nexthot.net:7001/?num=1
HTTP/1.1 200 OK
Content-Type: text/plain
Date: Fri, 06 Jan 2017 08:40:13 GMT
Transfer-Encoding: chunked

^C

curl version

$ curl --version
curl 7.43.0 (x86_64-apple-darwin15.0) libcurl/7.43.0 SecureTransport zlib/1.2.5
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz UnixSockets 

Python3 with requests hangs

$ python3 -c 'import requests;req = requests.get("https://api.nexthot.net:7001/?num=1", verify=False);print(req.text)'

wget works

$ wget --server-response --no-check-certificate 'https://api.nexthot.net:7001/?num=1' -O -
--2017-01-06 03:10:13--  https://api.nexthot.net:7001/?num=1
Resolving api.nexthot.net... 58.96.176.63
Connecting to api.nexthot.net|58.96.176.63|:7001... connected.
WARNING: cannot verify api.nexthot.net's certificate, issued by 'CN=Let\'s Encrypt Authority X3,O=Let\'s Encrypt,C=US':
  Unable to locally verify the issuer's authority.
HTTP request sent, awaiting response... 
  HTTP/1.1 200 OK
  Content-Type: text/plain
  Date: Fri, 06 Jan 2017 10:10:14 GMT
  Transfer-Encoding: chunked
Length: unspecified [text/plain]
Saving to: 'STDOUT'

-                       [<=>                   ]       0  --.-KB/s             hello,world

$ wget --version
GNU Wget 1.17 built on darwin15.0.0.

+digest +https +ipv6 -iri +large-file -nls +ntlm +opie -psl +ssl/openssl

Go client works

@bradfitz this might be irrelevant, but the Go client is gucci straight out of the box
ie keeping or removing http2.ConfigureTransport gives different HTTP/X.Y responses but it returns the flushed body ASAP(which is what we want)

remove http2.ConfigureTransport

diff --git a/golang/18510/client.go b/golang/18510/client.go
index 9410dc8..9a700aa 100644
--- a/golang/18510/client.go
+++ b/golang/18510/client.go
@@ -26,7 +26,9 @@ func main() {
 			InsecureSkipVerify: true,
 		},
 	}
-	http2.ConfigureTransport(tr)
+	if false {
+		http2.ConfigureTransport(tr)
+	}
 
 	client := &http.Client{
 		Transport: tr,

I get back

HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: text/plain
Date: Fri, 06 Jan 2017 09:53:22 GMT

Keeping http2.ConfigureTransport

HTTP/2.0 200 OK
Connection: close
Content-Type: text/plain
Date: Fri, 06 Jan 2017 09:55:53 GMT

[bradfitz]

If you make the output have newlines, some of these CLI http client tools show the output more aggressively.