Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

http3 post request with body failed #2551

Closed
ggjjlldd opened this issue May 21, 2020 · 53 comments · Fixed by #2584
Closed

http3 post request with body failed #2551

ggjjlldd opened this issue May 21, 2020 · 53 comments · Fixed by #2584
Labels

Comments

@ggjjlldd
Copy link

this problem origin publish in caddy issue, but i think it is a quic go problems,
more info:caddyserver/caddy#3429

post request has body so can not return response. you can reference this link:
caddyserver/caddy#3429

i am a co-worker with @majc08149 , i find problem reason and code. But I do not know how to modify? @mholt

I paste problem code :
file->net/http/transfer.go:371

if t.BodyCloser != nil { if err := t.BodyCloser.Close(); err != nil { return err } }
the function BodyCloser.Close() call quic-go->http3->body.go Close() like :
`
func (r *body) Close() error {
// quic.Stream.Close() closes the write side, not the read side
if r.isRequest {
return r.str.Close()
}
r.requestDone()
r.str.CancelRead(quic.ErrorCode(errorRequestCanceled))
return nil
}

`

this call quic-go->stream.go function 👍
func (s *stream) Close() error { if err := s.sendStream.Close(); err != nil { return err } return nil }

the function s.sendStream.Close() will call func (s *sendStream) Close() error , this function call
s.ctxCancel() to cancel context.
so the request reverseproxy will be canceled.

please help me how to fix this bug?

@marten-seemann
Copy link
Member

I don't understand what you're trying to say here. Can you please

  1. Properly format your post, including code blocks.
  2. Explain what you think the problem is.

@ggjjlldd
Copy link
Author

I don't understand what you're trying to say here. Can you please

  1. Properly format your post, including code blocks.
  2. Explain what you think the problem is.
  1. Environment
    1a. Operating system and version
    Server: windows 7, Caddy runs on this machine
    Client: CentOS Linux release 8.1.1911 (Core),curl runs on this machine

1b. Caddy version (run caddy version or paste commit SHA)
D:\caddy\caddy-master\cmd\caddy>caddy.exe version
v2.0.0 h1:pQSaIJGFluFvu8KDGDODV8u4/QRED/OPyIR+MWYYse8=

1c. Go version (if building Caddy from source; run go version)
C:\Users\majc08149>go version
go version go1.14.2 windows/amd64

1d. curl version
curl --version
curl 7.70.0-DEV (x86_64-pc-linux-gnu) libcurl/7.70.0-DEV BoringSSL zlib/1.2.11 quiche/0.3.0
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HTTP3 HTTPS-proxy IPv6 Largefile libz NTLM NTLM_WB SSL UnixSockets

  1. Description
    2a. What happens (briefly explain what is wrong)
    Using caddy as a reverse proxy server,and upstream is a web server, which can return a 404 page. When configuring caddy to support http3, Using curl to send http1.1's Post request with body,I can get the correct 404 page, But the same environment using curl to send http3's post request with body, Return empty reply package.

2b. Why it's a bug (if it's not obvious)
Send using the following command :

curl -H "Content-Type:application/json" -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d '{"name":"mmm"}' -k
return correct results:
< HTTP/1.1 404 Not Found
< Alt-Svc: h3-27=":8080"; ma=2592000
< Content-Length: 155
< Content-Type: text/html
< Date: Wed, 20 May 2020 07:44:55 GMT
< Server: Caddy
< Server: hsiar/V1.2.0-1
<

<title>404 Not Found</title> 404 Not Found hsiar/V1.2.0-1 but Send using the following command :

curl --http3 -H "Content-Type:application/json" -X POST -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d "{"name":"mmm"}"
Return error results, Nothing came back,display following:
Empty reply from server
curl: (52) Empty reply from server

2c. Log output
ts=1589954061.6446605 level=info msg="handled request" requestError="unsupported value type" common_log="192.168.194.73 - - [20/May/2020:13:54:21 +0800] "POST /g/demo-def-t2-server/9.0/testField1k HTTP/3" 0 0" duration=0.007 size=0 status=0 resp_headersError="unsupported value type"

  1. Tutorial (minimal steps to reproduce the bug)
    3a.Create a config file:
    {
    http_port 8081
    debug
    experimental_http3
    local_certs
    }

:8080 {
tls cert/caddyserver.crt cert/caddyserver.key {
}
log {
output file logs/access.log
format logfmt
level DEBUG
}
encode gzip
reverse_proxy {
to http://192.168.36.61:8001
transport http {
keepalive 30s
keepalive_idle_conns 100
read_buffer 1MB
write_buffer 1MB
}
}
}
3b.Open terminal and run Caddy:
Run caddy ,commands:
Caddy.exe run

3c.Make an HTTP request:
`
curl -H "Content-Type:application/json" -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d '{"name":"mmm"}' -k

curl --http3 -H "Content-Type:application/json" -X POST -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d "{"name":"mmm"}"
`

@ggjjlldd
Copy link
Author

I don't understand what you're trying to say here. Can you please

  1. Properly format your post, including code blocks.
  2. Explain what you think the problem is.
  1. Environment
    1a. Operating system and version
    Server: windows 7, Caddy runs on this machine
    Client: CentOS Linux release 8.1.1911 (Core),curl runs on this machine

1b. Caddy version (run caddy version or paste commit SHA)
D:\caddy\caddy-master\cmd\caddy>caddy.exe version
v2.0.0 h1:pQSaIJGFluFvu8KDGDODV8u4/QRED/OPyIR+MWYYse8=

1c. Go version (if building Caddy from source; run go version)
C:\Users\majc08149>go version
go version go1.14.2 windows/amd64

1d. curl version
curl --version
curl 7.70.0-DEV (x86_64-pc-linux-gnu) libcurl/7.70.0-DEV BoringSSL zlib/1.2.11 quiche/0.3.0
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HTTP3 HTTPS-proxy IPv6 Largefile libz NTLM NTLM_WB SSL UnixSockets

  1. Description
    2a. What happens (briefly explain what is wrong)
    Using caddy as a reverse proxy server,and upstream is a web server, which can return a 404 page. When configuring caddy to support http3, Using curl to send http1.1's Post request with body,I can get the correct 404 page, But the same environment using curl to send http3's post request with body, Return empty reply package.

2b. Why it's a bug (if it's not obvious)
Send using the following command :

curl -H "Content-Type:application/json" -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d '{"name":"mmm"}' -k
return correct results:
< HTTP/1.1 404 Not Found
< Alt-Svc: h3-27=":8080"; ma=2592000
< Content-Length: 155
< Content-Type: text/html
< Date: Wed, 20 May 2020 07:44:55 GMT
< Server: Caddy
< Server: hsiar/V1.2.0-1
<

<title>404 Not Found</title> 404 Not Found hsiar/V1.2.0-1 but Send using the following command : curl --http3 -H "Content-Type:application/json" -X POST -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d "{"name":"mmm"}" Return error results, Nothing came back,display following: Empty reply from server curl: (52) Empty reply from server

2c. Log output
ts=1589954061.6446605 level=info msg="handled request" requestError="unsupported value type" common_log="192.168.194.73 - - [20/May/2020:13:54:21 +0800] "POST /g/demo-def-t2-server/9.0/testField1k HTTP/3" 0 0" duration=0.007 size=0 status=0 resp_headersError="unsupported value type"

  1. Tutorial (minimal steps to reproduce the bug)
    3a.Create a config file:
    {
    http_port 8081
    debug
    experimental_http3
    local_certs
    }

:8080 {
tls cert/caddyserver.crt cert/caddyserver.key {
}
log {
output file logs/access.log
format logfmt
level DEBUG
}
encode gzip
reverse_proxy {
to http://192.168.36.61:8001
transport http {
keepalive 30s
keepalive_idle_conns 100
read_buffer 1MB
write_buffer 1MB
}
}
}
3b.Open terminal and run Caddy:
Run caddy ,commands:
Caddy.exe run

3c.Make an HTTP request:
`
curl -H "Content-Type:application/json" -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d '{"name":"mmm"}' -k

curl --http3 -H "Content-Type:application/json" -X POST -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d "{"name":"mmm"}"
`

when I debug for problem reason, I found this:
I paste problem code :
file->net/http/transfer.go:371

if t.BodyCloser != nil { if err := t.BodyCloser.Close(); err != nil { return err } }
the function BodyCloser.Close() call quic-go->http3->body.go Close() like :
`
func (r *body) Close() error {
// quic.Stream.Close() closes the write side, not the read side
if r.isRequest {
return r.str.Close()
}
r.requestDone()
r.str.CancelRead(quic.ErrorCode(errorRequestCanceled))
return nil
}

`
this call quic-go->stream.go function 👍
func (s *stream) Close() error { if err := s.sendStream.Close(); err != nil { return err } return nil }

the function s.sendStream.Close() will call func (s *sendStream) Close() error , this function call
s.ctxCancel() to cancel context.
so the request reverseproxy will be canceled.

@marten-seemann
Copy link
Member

Sorry, this is getting even less comprehensible than it was before. I have literally no idea what you're trying to say here.

@francislavoie
Copy link

francislavoie commented May 21, 2020

@ggjjlldd To post code blocks, wrap the code with ``` on the lines before and after the code block.

like this

For inline code like this, only use a single ` around the code.

It's nearly impossible to read your post without proper formatting.

@ggjjlldd
Copy link
Author

ggjjlldd commented May 21, 2020

the problem description

1. Environment

  • Operating system and version
    Server: windows 7
    Client: CentOS Linux release 8.1.1911 (Core)

  • Caddy version (run caddy version or paste commit SHA)
    D:\caddy\caddy-master\cmd\caddy>caddy.exe version
    v2.0.0 h1:pQSaIJGFluFvu8KDGDODV8u4/QRED/OPyIR+MWYYse8=

  • Go version (if building Caddy from source; run go version)
    C:\Users\majc08149>go version
    go version go1.14.2 windows/amd64

  • curl version

curl --version
curl 7.70.0-DEV (x86_64-pc-linux-gnu) libcurl/7.70.0-DEV BoringSSL zlib/1.2.11 quiche/0.3.0
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HTTP3 HTTPS-proxy IPv6 Largefile libz NTLM NTLM_WB SSL UnixSockets

2. Description

  • What happens (briefly explain what is wrong)**

When I config http3, use curl send post request with body, response an empty body. the same environment send http1.1 post request,I can get the right body

  • Why it's a bug (if it's not obvious)

Use http1.1 such as:
curl -H "Content-Type:application/json" -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d '{"name":"mmm"}' -k

result is :

Trying 192.168.94.48:8080...
Connected to 192.168.94.48 (192.168.94.48) port 8080 (#0)
ALPN, offering http/1.1
successfully set certificate verify locations:
CAfile: /etc/pki/tls/certs/ca-bundle.crt
CApath: none
TLSv1.2 (OUT), TLS handshake, Client hello (1):
TLSv1.2 (IN), TLS handshake, Server hello (2):
TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
TLSv1.3 (IN), TLS handshake, Certificate (11):
TLSv1.3 (IN), TLS handshake, CERT verify (15):
TLSv1.3 (IN), TLS handshake, Finished (20):
TLSv1.3 (OUT), TLS handshake, Finished (20):
SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
ALPN, server accepted to use http/1.1
Server certificate:
subject: [NONE]
start date: May 20 07:34:21 2020 GMT
expire date: May 20 19:35:21 2020 GMT
issuer: CN=Caddy Local Authority - ECC Intermediate
SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
POST /g/demo-def-t2-server/9.0/testField1k HTTP/1.1
Host: 192.168.94.48:8080
User-Agent: curl/7.70.0-DEV
Accept: /
Content-Type:application/json
Content-Length: 14
upload completely sent off: 14 out of 14 bytes
response:

< HTTP/1.1 404 Not Found
< Alt-Svc: h3-27=":8080"; ma=2592000
< Content-Length: 155
< Content-Type: text/html
< Date: Wed, 20 May 2020 07:44:55 GMT
< Server: Caddy
< Server: hsiar/V1.2.0-1
<

<title>404 Not Found</title> 404 Not Found hsiar/V1.2.0-1

but use http3 such as

curl --http3 -H "Content-Type:application/json" -X POST -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d "{"name":"mmm"}"

result is :

Trying 192.168.94.48:8080...
Sent QUIC client Initial, ALPN: h3-27h3-25h3-24h3-23
Connected to 192.168.94.48 (192.168.94.48) port 8080 (#0)
h3 [:method: POST]
h3 [:path: /g/demo-def-t2-server/9.0/testField1k]
h3 [:scheme: https]
h3 [:authority: 192.168.94.48:8080]
h3 [user-agent: curl/7.70.0-DEV]
h3 [accept: /]
h3 [content-type: application/json]
h3 [content-length: 14]
Using HTTP/3 Stream ID: 0 (easy handle 0x6b4530)
POST /g/demo-def-t2-server/9.0/testField1k HTTP/3
Host: 192.168.94.48:8080
user-agent: curl/7.70.0-DEV
accept: /
content-type:application/json
content-length: 14

upload completely sent off: 14 out of 14 bytes
Empty reply from server
Connection #0 to host 192.168.94.48 left intact
curl: (52) Empty reply from server

the different is here, http3 no response body return

  • ** Log output**

ts=1589954061.6446605 level=info msg="handled request" requestError="unsupported value type" common_log="192.168.194.73 - - [20/May/2020:13:54:21 +0800] "POST /g/demo-def-t2-server/9.0/testField1k HTTP/3" 0 0" duration=0.007 size=0 status=0 resp_headersError="unsupported value type"

  • Workaround(s)
  • Relevant links

3. Tutorial (minimal steps to reproduce the bug)

  • Step 1:
    Use the caddyfile such as:

{
http_port 8081
debug
experimental_http3
local_certs
}

:8080 {
tls cert/caddyserver.crt cert/caddyserver.key {
}
log {
output file logs/access.log
format logfmt
level DEBUG
}
encode gzip
reverse_proxy {
to http://192.168.36.61:8001
transport http {
keepalive 30s
keepalive_idle_conns 100
read_buffer 1MB
write_buffer 1MB
}
}
}
  • Step 2:

Run caddy commands:
Caddy.exe run

  • Step 3

Send curl request As described at the beginning
curl --http3 -H "Content-Type:application/json" -X POST -v "https://192.168.94.48:8080/g/demo-def-t2-server/9.0/testField1k" -d "{"name":"mmm"}"

@francislavoie
Copy link

francislavoie commented May 21, 2020

Please go read https://guides.github.com/features/mastering-markdown/ this is killing me

You're using > for quotes. Don't do that. Quotes don't preserve whitespace. Use ``` for code blocks.

@ggjjlldd
Copy link
Author

ggjjlldd commented May 21, 2020

the reason

when I debug this problem , I found reason:
I paste problem code :

Breakpoint reached: send_stream.go:322
Stack: 
	github.com/lucas-clemente/quic-go.(*sendStream).Close at send_stream.go:322
	github.com/lucas-clemente/quic-go.(*stream).Close at stream.go:132
	github.com/lucas-clemente/quic-go/http3.(*body).Close at body.go:99
	net/http.(*transferWriter).writeBody at transfer.go:375
	net/http.(*Request).write at request.go:685
	net/http.(*persistConn).writeLoop at transport.go:2280
	runtime.goexit at asm_amd64.s:1373

send_stream.go function:

func (s *sendStream) Close() error {
	s.mutex.Lock()
	if s.closedForShutdown {
		s.mutex.Unlock()
		return nil
	}
	if s.canceledWrite {
		s.mutex.Unlock()
		return fmt.Errorf("close called for canceled stream %d", s.streamID)
	}
	
	s.ctxCancel() // this is problem.the context canceled, So i can not get response from back server
	
	s.finishedWriting = true
	s.mutex.Unlock()

	s.sender.onHasStreamData(s.streamID) // need to send the FIN, must be called without holding the mutex
	return nil
}

@ggjjlldd
Copy link
Author

the reason

when I debug this problem , I found reason:
I paste problem code :

Breakpoint reached: send_stream.go:322
Stack: 
	github.com/lucas-clemente/quic-go.(*sendStream).Close at send_stream.go:322
	github.com/lucas-clemente/quic-go.(*stream).Close at stream.go:132
	github.com/lucas-clemente/quic-go/http3.(*body).Close at body.go:99
	net/http.(*transferWriter).writeBody at transfer.go:375
	net/http.(*Request).write at request.go:685
	net/http.(*persistConn).writeLoop at transport.go:2280
	runtime.goexit at asm_amd64.s:1373

send_stream.go function:

func (s *sendStream) Close() error {
	s.mutex.Lock()
	if s.closedForShutdown {
		s.mutex.Unlock()
		return nil
	}
	if s.canceledWrite {
		s.mutex.Unlock()
		return fmt.Errorf("close called for canceled stream %d", s.streamID)
	}
	
	s.ctxCancel() // this is problem.the context canceled, So i can not get response from back server
	
	s.finishedWriting = true
	s.mutex.Unlock()

	s.sender.onHasStreamData(s.streamID) // need to send the FIN, must be called without holding the mutex
	return nil
}

@francislavoie please help me!

@marten-seemann
Copy link
Member

@ggjjlldd I don't see anything wrong with that code. That's how we close a stream in quic-go.

Your "minimal" example is not really minimal either. I doubt that you need to set keep-alives, buffer sizes, gzip encoding and certificates to make this work (self-signed cert should be fine here). Can you please clean it up to make it actually a minimal example, so we can run this locally?

@ggjjlldd
Copy link
Author

It not "minimal" example, you can use curl to test. My quiche client has some result with curl. May be it is not problems with quic-go, But use quic-go in caddy will make error.

@marten-seemann
Copy link
Member

Your Caddyfile is far from minimal, and requires more preparation than necessary (for example, I'd have to generate a certificate first). Can you please post a minimal Caddyfile that reproduces the problem?

@marten-seemann
Copy link
Member

Just tried to set it up despite the totally messy Caddyfile, and noticed that there's a reverse proxy directive in that file. @ggjjlldd You need to provide us a minimal configuration, otherwise we can't help you.

@mholt
Copy link
Contributor

mholt commented May 21, 2020

Yeah, sorry, I'm with @marten-seemann on this one -- I don't really understand how to continue debugging this.

For a minimal example, we need to reproduce the problem without reverse proxy.

If you do make a change to the code that fixes it, we'd be happy to see it, but a reason explaining the change would be needed too.

@ziddey
Copy link

ziddey commented May 21, 2020

Thanks for this. Testing http3 with firefox and seeing the same behavior. Reverse proxying various services and while http3 get requests are working, http3 posts are not. Consequently, I'm not able to login to any of these services.

Hard to imagine a scenario without a reverse proxy that would involve a post request..

@mholt
Copy link
Contributor

mholt commented May 21, 2020

How can we minimally reproduce it?

@ziddey
Copy link

ziddey commented May 21, 2020

May require reverse proxying to something that has an endpoint that accepts a post request. I did a test in firefox posting to a static html endpoint (default caddy index), which worked fine.

I'll need to compile curl with http3 support to do more testing.

@ggjjlldd
Copy link
Author

@marten-seemann @mholt The post request failed must use reverse proxy directive. Because caddy use golang HTTP library will result such problems. So I can not give you a minimal caddyfile. It must include reverse proxy directive.

@mholt
Copy link
Contributor

mholt commented May 22, 2020

Okay, so help me catch myself up on the current state of the issue:

Is it a bug in the reverse proxy or the quic library? If it works over http2 and http1, why does http3 break it?

@ggjjlldd
Copy link
Author

So I debug for reason. Find quic-go body.Close() function will close send stream and cancel context. It will result the request be canceled.

@ggjjlldd
Copy link
Author

But golang http library will use body.Closer when read body done. It call quic-go body.Close() will result cancel context.

@mholt
Copy link
Contributor

mholt commented May 22, 2020

@ggjjlldd I see, so you're saying that body.Close() is being called too early and/or unnecessarily by quic-go, because the go standard library will (indirectly) do it later when the response body is closed. Did I get that right?

I'm not very familiar with this part of the quic-go code base, maybe @marten-seemann would have some intuition there.

If you remove the extra call to Close() in quic-go and try again, does that solve the problem? (Even if it is the wrong solution, I'm interested if you can confirm that fixes it for you.)

@ggjjlldd
Copy link
Author

file: go/src/net/http/transfer.go

func (t *transferWriter) writeBody(w io.Writer) error {
	var err error
	var ncopy int64

	// Write body. We "unwrap" the body first if it was wrapped in a
	// nopCloser. This is to ensure that we can take advantage of
	// OS-level optimizations in the event that the body is an
	// *os.File.
	if t.Body != nil {
		var body = t.unwrapBody()
		if chunked(t.TransferEncoding) {
			if bw, ok := w.(*bufio.Writer); ok && !t.IsResponse {
				w = &internal.FlushAfterChunkWriter{Writer: bw}
			}
			cw := internal.NewChunkedWriter(w)
			_, err = t.doBodyCopy(cw, body)
			if err == nil {
				err = cw.Close()
			}
		} else if t.ContentLength == -1 {
			dst := w
			if t.Method == "CONNECT" {
				dst = bufioFlushWriter{dst}
			}
			ncopy, err = t.doBodyCopy(dst, body)
		} else {
			ncopy, err = t.doBodyCopy(w, io.LimitReader(body, t.ContentLength))
			if err != nil {
				return err
			}
			var nextra int64
			nextra, err = t.doBodyCopy(ioutil.Discard, body)
			ncopy += nextra
		}
		if err != nil {
			return err
		}
	}
	if t.BodyCloser != nil {   // here, will call body.close to cancel context
		if err := t.BodyCloser.Close(); err != nil {
			return err
		}
	}

	if !t.ResponseToHEAD && t.ContentLength != -1 && t.ContentLength != ncopy {
		return fmt.Errorf("http: ContentLength=%d with Body length %d",
			t.ContentLength, ncopy)
	}

@mholt if I remove the extra call to Close() in quic-go, it be fine. and I solve my problems.

@mholt
Copy link
Contributor

mholt commented May 22, 2020

@ggjjlldd Great, thanks for confirming.

@marten-seemann Is it possible that quic-go is closing a stream that should be closed later by the Go standard library when the response body is closed?

@marten-seemann
Copy link
Member

@mholt if I remove the extra call to Close() in quic-go, it be fine. and I solve my problems.

Which Close() call is that? Can you give me the file and line number?

@mholt
Copy link
Contributor

mholt commented May 22, 2020

@marten-seemann I dunno if this is what @ggjjlldd was referring to, but I'm guessing it's this stack:

Breakpoint reached: send_stream.go:322
Stack: 
	github.com/lucas-clemente/quic-go.(*sendStream).Close at send_stream.go:322
	github.com/lucas-clemente/quic-go.(*stream).Close at stream.go:132
	github.com/lucas-clemente/quic-go/http3.(*body).Close at body.go:99
	net/http.(*transferWriter).writeBody at transfer.go:375
	net/http.(*Request).write at request.go:685
	net/http.(*persistConn).writeLoop at transport.go:2280
	runtime.goexit at asm_amd64.s:1373

on v0.15.7 (or at least, that's what my go.mod shows currently).

However, I too would like to know exactly which Close() call is removed that makes it work.

Of course, the trick is to remove the right Close() call...

Or, maybe it's just a matter of not cancelling a context (again, judging from above posts)?

s.ctxCancel() // this is problem.the context canceled, So i can not get response from back server

@marten-seemann
Copy link
Member

However, I too would like to know exactly which Close() call is removed that makes it work.

Of course, the trick is to remove the right Close() call...

Yeah right, if you remove the call to Close(), then the stream doesn't get closed. But that's not a solution. The stream will never get garbage-collected and your connection will stop working once the stream limit is reached...

@ggjjlldd
Copy link
Author

ggjjlldd commented May 22, 2020

@marten-seemann you are right. So I need your help to fix . Maybe close quic-go stream later.

@marten-seemann
Copy link
Member

@ggjjlldd I still don't understand the problem, and you're not helping me understand it. I'm sorry, but I can't help you with this kind of information you're giving me.

@ggjjlldd
Copy link
Author

the problems happened because use caddy reverseproxy directive. reverseproxy module call net/http library to transport request. But when call transport file use function writeBody will result close body.Close body will result close quic-go stream . It will result canceled context. and request will be canceled. @marten-seemann

@ggjjlldd
Copy link
Author

And any other you do not understand? @marten-seemann

@mholt
Copy link
Contributor

mholt commented May 22, 2020

@ggjjlldd I think Marten is saying that we can't just remove the Close() call -- doing so might hide the error you're seeing, but not closing it probably results in a resource leak.

Since we still don't fulllllly understand the problem (since it is hard for us to reproduce it), can you suggest another solution that doesn't leak resources?

@ggjjlldd
Copy link
Author

ggjjlldd commented May 22, 2020

@mholt @marten-seemann
Yes, I make bug fix for here:
file: go/src/net/http/transfer.go

func newTransferWriter(r interface{}) (t *transferWriter, err error) {
	t = &transferWriter{}

	// Extract relevant fields
	atLeastHTTP11 := false
	switch rr := r.(type) {
	case *Request:
		if rr.ContentLength != 0 && rr.Body == nil {
			return nil, fmt.Errorf("http: Request.ContentLength=%d with nil Body", rr.ContentLength)
		}
		t.Method = valueOrDefault(rr.Method, "GET")
		t.Close = rr.Close
		t.TransferEncoding = rr.TransferEncoding
		t.Header = rr.Header
		t.Trailer = rr.Trailer
		t.Body = rr.Body

// here. I add http/3 check to assgin t.BodyCloser.
		if rr.Proto == "HTTP/3" {  //add bug fix for http3 post
			//t.BodyCloser = rr.Body
			t.BodyCloser = nil
		}


		t.ContentLength = rr.outgoingLength()
		if t.ContentLength < 0 && len(t.TransferEncoding) == 0 && t.shouldSendChunkedRequestBody() {
			t.TransferEncoding = []string{"chunked"}
		}

@ggjjlldd
Copy link
Author

ggjjlldd commented May 22, 2020

why quic-go close stream when body read done??? I think it is not reasonable. When connection timeout or fin stream arrive, It will be close stream. @marten-seemann @mholt

@ggjjlldd
Copy link
Author

ggjjlldd commented May 22, 2020

you can use quiche client to reproduce it. the quiche link : https://github.com/cloudflare/quiche, it is a http3 library and include http3 client tool @mholt @marten-seemann

git clone --recursive https://github.com/cloudflare/quiche
cd quiche
cargo run --manifest-path=tools/apps/Cargo.toml --bin quiche-client -- http://127.0.0.1:8080/bbb.txt  --no-verify --method
 POST --body D:\mysdk\quiche1\tools\apps\target\debug\testbody

[2020-05-22T05:33:11.940792500Z ERROR quiche_apps] connection timed out after 5.0243821s and only completed 0

use caddy version:2.0.0
caddy file:

{

    experimental_http3
    debug
}


:8080 {
    tls test.pem test.key
	log {
		output stdout
		output stderr
		format single_field logfmt
        }

	reverse_proxy {
	  to http://192.168.194.73:8001
	  transport http {
	  	keepalive 30s
	  	keepalive_idle_conns 100
	  }
	}
}

@ggjjlldd
Copy link
Author

ggjjlldd commented May 22, 2020

But without body is ok

tools\apps\target\debug\quiche-client.exe http://127.0.0.1:8080/bbb.txt --no-verify --method
 POST
test return result OK  // server return value is ok

@marten-seemann
Copy link
Member

marten-seemann commented May 23, 2020

Hi @mholt, I think I'll need your help on this one. I used @ggjjlldd's Caddyfile in #2551 (comment) (thank you, @ggjjlldd!). For the backend server I used a simple PHP script:

<?php
print_r($_POST);
print_r($_SERVER);
?>

Making a HTTP/3 request including a body indeed leads to a connection timeout, but I'm not exactly sure why. It looks like http.Request.Body is closed:
https://github.com/lucas-clemente/quic-go/blob/fa69438124b76e9ad4c3307714e93097cb3b36c9/http3/body.go#L96-L100

Close() is called from the standard library in https://github.com/golang/go/blob/f296b7a6f045325a230f77e9bda1470b1270f817/src/net/http/transfer.go#L371-L375. As far as I can see, there's no context cancelation involved here.

@mholt Do you have any idea what is going wrong here? Closing the stream seems like the right thing to do, when the application is done writing the response body and calls Close().

@marten-seemann marten-seemann added this to the v0.16 milestone May 23, 2020
@mholt
Copy link
Contributor

mholt commented May 24, 2020

I'll take a look -- at first pass, ctxCancel would only cancel a Background context, not any context that Caddy passes in. So that might be a red herring.

@marten-seemann You're seeing a connection timeout -- isn't that something different than what is being reported initially (I'll be honest, I dunno -- I think the fundamental symptom is an empty POST body, but it's not clear to me if it's the upstream request body that's empty or if it's the reply to downstream that is empty.)

@ggjjlldd You posted this at the very top:

2c. Log output
ts=1589954061.6446605 level=info msg="handled request" requestError="unsupported value type" common_log="192.168.194.73 - - [20/May/2020:13:54:21 +0800] "POST /g/demo-def-t2-server/9.0/testField1k HTTP/3" 0 0" duration=0.007 size=0 status=0 resp_headersError="unsupported value type"

This looks like a Caddy log but logfmt doesn't support nested objects. Can you please disable the logfmt encoding and use the default log formatting so we can get the full output, then please post the full log output (it should look like JSON)?

@marten-seemann
Copy link
Member

I wrote a client to reproduce the bug in Go, so we don't have to rely on quiche here. I don't know how sophisticated their client implementation is - there's no reason to time out on in the situation, and in fact quic-go wouldn't do that.

The client is here: https://gist.github.com/marten-seemann/1cb0d87a43935c377c9e59a49c3dbc71. You should be able to just go run this file.

Usage:

go run main.go <url>

Performs a POST request via HTTP/2 / HTTP/1.1.

go run main.go -quic <url>

Performs the same POST request via HTTP/3. It also outputs a qlog. qlogs can be loaded in qvis to inspect the trace. Not sure if that really helps us debug this issue though, all I see is the client sending the request (on stream 0) and then sending a FIN, whereas the server sends a FIN at offset 0.

@mholt Any idea how to further debug this?

@mholt
Copy link
Contributor

mholt commented May 25, 2020

@marten-seemann Thanks for doing this, I'll try to take a look after the holiday!

@marten-seemann
Copy link
Member

@mholt Any update on this?

@mholt
Copy link
Contributor

mholt commented May 28, 2020

@marten-seemann That custom client you whipped up is really handy. I was able to make it more minimally reproducible, all you need is this Caddyfile (no external backend required):

{
	experimental_http3
	debug
}

localhost {
	log
	reverse_proxy 127.0.0.1:8001
}

:8001 {
	respond "Content-Type: {http.request.header.Content-Type}  Content-Length: {http.request.header.Content-Length}"
}

I confirmed that the Go standard libarary's http.Transport is returning a context canceled error, originating beyond the boundary between Caddy code and the standard lib's code: https://sourcegraph.com/github.com/caddyserver/caddy@9415feca7cf0fe14b9d881c7318be2da20b2985f/-/blob/modules/caddyhttp/reverseproxy/httptransport.go#L218

I have also confirmed that it works with HTTP/1 and HTTP/2 but does not work with HTTP/3.

If it helps to know, this is where we set up the HTTP/3 server: https://sourcegraph.com/github.com/caddyserver/caddy@9415feca7cf0fe14b9d881c7318be2da20b2985f/-/blob/modules/caddyhttp/app.go#L325-347 - feel free to let me know if I did anything wrong there.

@marten-seemann
Copy link
Member

@mholt That's neat. Hadn't thought of using Caddy-run backend. But of course, why not...

I confirmed that the Go standard libarary's http.Transport is returning a context canceled error, originating beyond the boundary between Caddy code and the standard lib's code: https://sourcegraph.com/github.com/caddyserver/caddy@9415feca7cf0fe14b9d881c7318be2da20b2985f/-/blob/modules/caddyhttp/reverseproxy/httptransport.go#L218

I don't see any context in that code snippet. Which context is causing the problem?

If it helps to know, this is where we set up the HTTP/3 server: https://sourcegraph.com/github.com/caddyserver/caddy@9415feca7cf0fe14b9d881c7318be2da20b2985f/-/blob/modules/caddyhttp/app.go#L325-347 - feel free to let me know if I did anything wrong there.

That looks correct, as far as I can tell.

@mholt
Copy link
Contributor

mholt commented May 29, 2020

I don't see any context in that code snippet. Which context is causing the problem?

I don't know. The context wouldn't be in that code snippet, since it's an http.RoundTripper interface, which doesn't have a context passed in. Requests have contexts though. Maybe this one? https://golang.org/pkg/net/http/#Request.Context

@marten-seemann
Copy link
Member

We set a request context:
https://github.com/lucas-clemente/quic-go/blob/85c19fbb5ae34fd81238c424fe1e11cd30646f72/http3/server.go#L268-L271

But we don't cancel any contexts in the entire HTTP/3 package.

We do cancel (and close) the underlying QUIC streams at various locations though. I'm wondering if this is getting translated into a request cancellation by the standard library somehow?

@mholt
Copy link
Contributor

mholt commented May 29, 2020

Maybe; child contexts get canceled when their parent contexts do. So if the stream context is canceled, it will cancel the request, and the standard lib http.Transport will stop using it, I guess.

@marten-seemann
Copy link
Member

Yes, the stream context is cancel when the send side of the stream is closed (or canceled). So that means we're back to a too early Stream.Close() call?

@mholt
Copy link
Contributor

mholt commented May 29, 2020

Perhaps -- either too early, or if it's not too early, it's possible that a second context is needed (one for send, one for receive sides of the stream). Traditionally, as you know, duplexed TCP has just 1 context: if the sender closes, the receiver does too. But in UDP that is not always the case. I don't know enough about it, but maybe cancelling the context for a send side should not also close the context for the receive side.

But maybe that is more complicated. Hopefully it is as simple as a close too early :)

@marten-seemann
Copy link
Member

I don't think the request context has anything to do with this. Even if I remove these 4 lines
https://github.com/lucas-clemente/quic-go/blob/fe85b52eed3ec086824bd97aa1dedc5ca5b79e6b/http3/server.go#L268-L271
the same problem occurs.

So I guess the cancelation of the context was a result of the closing of the stream, not the cause. So the question remains: Why is the stream closed too early?

Unfortunately, I don't really know how the reverse proxy is implemented in Caddy, so I'm a bit lost at this point. @mholt Can you help me out here? What's the expected data flow when a request comes in?

@marten-seemann marten-seemann removed this from the v0.16 milestone May 31, 2020
@mholt
Copy link
Contributor

mholt commented Jun 1, 2020

@marten-seemann It has less to do with how Caddy works and more to do with how the Go standard lib and quic-go interoperate; all the same requests work over HTTP/1 and HTTP/2.

I think your guess is as good as mine at this point.

Doing a little "binary search" through net/http/transport.go, I have confirmed that the request gets to this point: https://sourcegraph.com/github.com/golang/[email protected]/-/blob/src/net/http/transport.go#L571 with the error "context canceled."

The error comes through this line: https://sourcegraph.com/github.com/golang/[email protected]/-/blob/src/net/http/transport.go#L565

Further bisecting leads to: https://sourcegraph.com/github.com/golang/[email protected]/-/blob/src/net/http/transport.go#L2471

Which comes from here: https://sourcegraph.com/github.com/golang/[email protected]/-/blob/src/net/http/transport.go#L2540-2543

Which of course comes from: https://sourcegraph.com/github.com/golang/[email protected]/-/blob/src/net/http/transport.go#L2495

So, it is simply a matter of the request's context being cancelled, likely somewhere in quic-go (since it doesn't happen with H2 or H1). I even tried adding req = req.WithContext(context.Background()) just before we call RoundTrip() in Caddy to make sure it's impossible for Caddy to have a handle to some context that it is cancelling. And indeed, the error still happens. So something else is cancelling it.

@marten-seemann
Copy link
Member

marten-seemann commented Jun 2, 2020

Now I really don't understand any more what's going on here. You're linking to net/http/transport.go, but we're dealing with a QUIC request. I still don't where this request is issued in the first place. To be honest, I don't understand how the reverse proxy function of Caddy works.

I even tried adding req = req.WithContext(context.Background()) just before we call RoundTrip() in Caddy to make sure it's impossible for Caddy to have a handle to some context that it is cancelling.

I removed the only place where we're creating a request context in quic-go (see #2551 (comment)), so I doubt that a context cancellation is the cause of the issue.

So, it is simply a matter of the request's context being cancelled, likely somewhere in quic-go (since it doesn't happen with H2 or H1).

I agree that it's probably a problem somewhere in quic-go (probably not context cancelation though), but with my limited understanding of what Caddy is actually doing here, I have no way of debugging this any further.

@mholt
Copy link
Contributor

mholt commented Jun 2, 2020

@marten-seemann The request to the backend is not http3, the request to the proxy is. I don't understand why how caddy's reverse proxy works is relevant here at all. It proxies http, regardless of protocol version or underlying transport layer.

@majc08149
Copy link

majc08149 commented Jun 12, 2020

@marten-seemann @mholt The request to the backend is not http3, the request to the proxy is. I don't understand why how caddy's reverse proxy works is relevant here at all. It proxies http, regardless of protocol version or underlying transport layer.

hi,How is the problem?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants