Skip to content

x/net/http2: server cannot process Trailer frames correctly after RST_STREAM #58286

New issue
New issue
Open
Open
x/net/http2: server cannot process Trailer frames correctly after RST_STREAM#58286
Labels
NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog
@wzekin

Description

@wzekin
wzekin
opened on Feb 3, 2023

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

$ go version
go version go1.20 darwin/arm64

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=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/bytedance/Library/Caches/go-build"
GOENV="/Users/bytedance/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/bytedance/.gvm/pkgsets/go1.20/global/pkg/mod"
GONOPROXY="*.byted.org,*.everphoto.cn,git.smartisan.com"
GONOSUMDB="*.byted.org,*.everphoto.cn,git.smartisan.com"
GOOS="darwin"
GOPATH="/Users/bytedance/.gvm/pkgsets/go1.20/global"
GOPRIVATE="*.byted.org,*.everphoto.cn,git.smartisan.com"
GOPROXY="https://go-mod-proxy.byted.org|https://goproxy.cn|https://proxy.golang.org|direct"
GOROOT="/Users/bytedance/.gvm/gos/go1.20"
GOSUMDB="sum.golang.google.cn"
GOTMPDIR=""
GOTOOLDIR="/Users/bytedance/.gvm/gos/go1.20/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.20"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/bytedance/IdeaProjects/go-test/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/c7/ywjd9qkj1k9cvhw4tnh266380000gn/T/go-build4253315927=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Run the following server and client，then I will get PROTOCOL_ERROR

client code:

package main

import (
	"bytes"
	"crypto/tls"
	"net/http"
	"time"

	"golang.org/x/net/http2"
)

var client *http.Client

func doRequest() {
	req, _ := http.NewRequest("GET", "https://127.0.0.1:8000", bytes.NewBufferString("1111122222"))
	req.Trailer = make(http.Header)
	req.Trailer.Set("hertz", "test")
	req.Trailer.Set("foo", "bar")
	_, err := client.Do(req)
	if err != nil {
		panic(err)
	}
}

func main() {
	client = &http.Client{Transport: &http2.Transport{
		TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
	}}

	for i := 0; i < 30; i++ {
		go func() {
			for {
				doRequest()
				time.Sleep(100 * time.Millisecond)
			}
		}()
	}

	time.Sleep(60 * time.Second)
}

server code:

package main

import (
        "log"
        "net/http"
)

func main() {
        srv := &http.Server{Addr: ":8000", Handler: http.HandlerFunc(handle)}

        log.Printf("Serving on https://0.0.0.0:8000")
        srv.ListenAndServeTLS("server.crt", "server.key")
}

func handle(w http.ResponseWriter, r *http.Request) {
        w.Write([]byte("Hello"))
}

What did you expect to see?

server processes the requests correctly

What did you see instead?

server print PROTOCOL_ERROR:

2023/02/03 11:29:11 http2: server connection error from 127.0.0.1:64729: connection error: PROTOCOL_ERROR

client return error:

panic: Get "https://127.0.0.1:8000": http2: server sent GOAWAY and closed the connection; LastStreamID=27, ErrCode=PROTOCOL_ERROR, debug=""

Additional Context

I try to send many requests with Trailer and some of them are returned directly by the server due to authentication issues. I found that the server sends RST_STREAM to close the request and throws PROTOCOL_ERROR after receiving the Header frame (Trailer)

server Running with GODEBUG=http2debug=2:

2023/02/03 11:44:13 http2: Framer 0x140005249a0: read HEADERS flags=END_HEADERS stream=3 len=8
2023/02/03 11:44:13 http2: decoded hpack field header field ":authority" = "127.0.0.1:8000"
2023/02/03 11:44:13 http2: decoded hpack field header field ":method" = "GET"
2023/02/03 11:44:13 http2: decoded hpack field header field ":path" = "/"
2023/02/03 11:44:13 http2: decoded hpack field header field ":scheme" = "https"
2023/02/03 11:44:13 http2: decoded hpack field header field "trailer" = "Foo,Hertz"
2023/02/03 11:44:13 http2: decoded hpack field header field "content-length" = "10"
2023/02/03 11:44:13 http2: decoded hpack field header field "accept-encoding" = "gzip"
2023/02/03 11:44:13 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
2023/02/03 11:44:13 http2: server read frame HEADERS flags=END_HEADERS stream=3 len=8
2023/02/03 11:44:13 http2: server encoding header ":status" = "200"
2023/02/03 11:44:13 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2023/02/03 11:44:13 http2: server encoding header "content-length" = "5"
2023/02/03 11:44:13 http2: server encoding header "date" = "Fri, 03 Feb 2023 03:44:13 GMT"
2023/02/03 11:44:13 http2: Framer 0x140005249a0: wrote HEADERS flags=END_HEADERS stream=1 len=48
2023/02/03 11:44:13 http2: server encoding header ":status" = "200"
2023/02/03 11:44:13 http2: server encoding header "content-type" = "text/plain; charset=utf-8"
2023/02/03 11:44:13 http2: server encoding header "content-length" = "5"
2023/02/03 11:44:13 http2: server encoding header "date" = "Fri, 03 Feb 2023 03:44:13 GMT"
2023/02/03 11:44:13 http2: Framer 0x140005249a0: wrote HEADERS flags=END_HEADERS stream=3 len=4
2023/02/03 11:44:13 http2: Framer 0x140005249a0: wrote DATA flags=END_STREAM stream=3 len=5 data="Hello"
2023/02/03 11:44:13 http2: Framer 0x140005249a0: read DATA stream=3 len=10 data="1111122222"
2023/02/03 11:44:13 http2: Framer 0x140005249a0: wrote RST_STREAM stream=3 len=4 ErrCode=NO_ERROR
2023/02/03 11:44:13 http2: Framer 0x140005249a0: wrote DATA flags=END_STREAM stream=1 len=5 data="Hello"
2023/02/03 11:44:13 http2: Framer 0x140005249a0: wrote WINDOW_UPDATE len=4 (conn) incr=10
2023/02/03 11:44:13 http2: server read frame DATA stream=3 len=10 data="1111122222"
2023/02/03 11:44:13 http2: Framer 0x140005249a0: read HEADERS flags=END_STREAM|END_HEADERS stream=3 len=2
2023/02/03 11:44:13 http2: decoded hpack field header field "hertz" = "test"
2023/02/03 11:44:13 http2: decoded hpack field header field "foo" = "bar"
2023/02/03 11:44:13 http2: Framer 0x140005249a0: wrote WINDOW_UPDATE len=4 (conn) incr=10
2023/02/03 11:44:13 http2: Framer 0x140005249a0: wrote RST_STREAM stream=3 len=4 ErrCode=STREAM_CLOSED
2023/02/03 11:44:13 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS stream=3 len=2
2023/02/03 11:44:13 http2: server connection error from 127.0.0.1:65204: connection error: PROTOCOL_ERROR

client Running with GODEBUG=http2debug=2:

2023/02/03 11:44:13 http2: Transport encoding header ":authority" = "127.0.0.1:8000"
2023/02/03 11:44:13 http2: Transport encoding header ":method" = "GET"
2023/02/03 11:44:13 http2: Transport encoding header ":path" = "/"
2023/02/03 11:44:13 http2: Transport encoding header ":scheme" = "https"
2023/02/03 11:44:13 http2: Transport encoding header "trailer" = "Foo,Hertz"
2023/02/03 11:44:13 http2: Transport encoding header "content-length" = "10"
2023/02/03 11:44:13 http2: Transport encoding header "accept-encoding" = "gzip"
2023/02/03 11:44:13 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2023/02/03 11:44:13 http2: Framer 0x140005d6000: wrote HEADERS flags=END_HEADERS stream=3 len=8
2023/02/03 11:44:13 http2: Framer 0x140005d6000: wrote DATA stream=3 len=10 data="1111122222"
2023/02/03 11:44:13 http2: Transport encoding header "hertz" = "test"
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read SETTINGS len=30, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, HEADER_TABLE_SIZE=4096, INITIAL_WINDOW_SIZE=1048576
2023/02/03 11:44:13 http2: Transport received SETTINGS len=30, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, HEADER_TABLE_SIZE=4096, INITIAL_WINDOW_SIZE=1048576
2023/02/03 11:44:13 http2: Transport encoding header "foo" = "bar"
2023/02/03 11:44:13 http2: Framer 0x140005d6000: wrote HEADERS flags=END_STREAM|END_HEADERS stream=3 len=2
2023/02/03 11:44:13 http2: Framer 0x140005d6000: wrote SETTINGS flags=ACK len=0
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read SETTINGS flags=ACK len=0
2023/02/03 11:44:13 http2: Transport received SETTINGS flags=ACK len=0
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read WINDOW_UPDATE len=4 (conn) incr=983041
2023/02/03 11:44:13 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read HEADERS flags=END_HEADERS stream=1 len=48
2023/02/03 11:44:13 http2: decoded hpack field header field ":status" = "200"
2023/02/03 11:44:13 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2023/02/03 11:44:13 http2: decoded hpack field header field "content-length" = "5"
2023/02/03 11:44:13 http2: decoded hpack field header field "date" = "Fri, 03 Feb 2023 03:44:13 GMT"
2023/02/03 11:44:13 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=48
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read HEADERS flags=END_HEADERS stream=3 len=4
2023/02/03 11:44:13 http2: decoded hpack field header field ":status" = "200"
2023/02/03 11:44:13 http2: decoded hpack field header field "content-type" = "text/plain; charset=utf-8"
2023/02/03 11:44:13 http2: decoded hpack field header field "content-length" = "5"
2023/02/03 11:44:13 http2: decoded hpack field header field "date" = "Fri, 03 Feb 2023 03:44:13 GMT"
2023/02/03 11:44:13 http2: Transport received HEADERS flags=END_HEADERS stream=3 len=4
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read DATA flags=END_STREAM stream=3 len=5 data="Hello"
2023/02/03 11:44:13 http2: Transport received DATA flags=END_STREAM stream=3 len=5 data="Hello"
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read RST_STREAM stream=3 len=4 ErrCode=NO_ERROR
2023/02/03 11:44:13 http2: Transport received RST_STREAM stream=3 len=4 ErrCode=NO_ERROR
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read DATA flags=END_STREAM stream=1 len=5 data="Hello"
2023/02/03 11:44:13 http2: Transport received DATA flags=END_STREAM stream=1 len=5 data="Hello"
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read WINDOW_UPDATE len=4 (conn) incr=10
2023/02/03 11:44:13 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=10
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read WINDOW_UPDATE len=4 (conn) incr=10
2023/02/03 11:44:13 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=10
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read RST_STREAM stream=3 len=4 ErrCode=STREAM_CLOSED
2023/02/03 11:44:13 http2: Transport received RST_STREAM stream=3 len=4 ErrCode=STREAM_CLOSED
2023/02/03 11:44:13 http2: Framer 0x140005d6000: read GOAWAY len=8 LastStreamID=3 ErrCode=PROTOCOL_ERROR Debug=""
2023/02/03 11:44:13 http2: Transport received GOAWAY len=8 LastStreamID=3 ErrCode=PROTOCOL_ERROR Debug=""
2023/02/03 11:44:13 transport got GOAWAY with error code = PROTOCOL_ERROR

Metadata

Metadata

Assignees

No one assigned

    Labels

    NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions