-
Notifications
You must be signed in to change notification settings - Fork 18.4k
Description
Go version
go version go1.25.2 linux/arm64
I did a binary search of go and determined that it was this commit from this issue that caused this change.
Output of go env
in your module/workspace:
AR='ar'
CC='gcc'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='g++'
GCCGO='gccgo'
GO111MODULE=''
GOARCH='arm64'
GOARM64='v8.0'
GOAUTH='netrc'
GOBIN=''
GOCACHE='/home/pivotal/.cache/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/home/pivotal/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build2837296816=/tmp/go-build -gno-record-gcc-switches'
GOHOSTARCH='arm64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/pivotal/go/pkg/mod'
GONOPROXY='github.gwd.broadcom.net/'
GONOSUMDB='github.gwd.broadcom.net/'
GOOS='linux'
GOPATH='/home/pivotal/go'
GOPRIVATE='github.gwd.broadcom.net/'
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/home/pivotal/workspace/go'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/home/pivotal/.config/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/home/pivotal/workspace/go/pkg/tool/linux_arm64'
GOVCS=''
GOVERSION='go1.25.2'
GOWORK=''
PKG_CONFIG='pkg-config'
What did you do?
- I ran an app that accepts websocket upgrades.
- I ran a reverse proxy that sends traffic to that app.
- I ran a client that sends websocket requests to the reverse proxy.
- I ctrl-C the client.
I was only able to duplicate this issue when running the app and reverse proxy separately. I will continue working on trying to minimize the reproduction steps into one file.
App + Client reproduction code is copied with minimal edits from gorilla/websocket examples.
App Code
package main
import (
"flag"
"fmt"
"net/http"
"strings"
"github.com/gorilla/websocket"
"golang.org/x/net/http/httpguts"
)
var upgrader = websocket.Upgrader{
ReadBufferSize: 1024,
WriteBufferSize: 1024,
}
func upgradeType(h http.Header) string {
if !httpguts.HeaderValuesContainsToken(h["Connection"], "Upgrade") {
return ""
}
return strings.ToLower(h.Get("Upgrade"))
}
var appPort = flag.String("appPort", "8888", "port")
func main() {
flag.Parse()
http.HandleFunc("/echo", func(w http.ResponseWriter, r *http.Request) {
if upgradeType(r.Header) != "websocket" {
http.Error(w, "unexpected request", 400)
return
}
conn, err := upgrader.Upgrade(w, r, nil)
if err != nil {
panic(err)
}
for {
// Read message
msgType, msg, err := conn.ReadMessage()
if err != nil {
return
}
// Print the message to the console
fmt.Printf("%s sent: %s\n", conn.RemoteAddr(), string(msg))
// Write same message back
if err = conn.WriteMessage(msgType, msg); err != nil {
return
}
}
})
portWithColon := fmt.Sprintf(":%s", *appPort)
fmt.Printf("app listening on %s", portWithColon)
http.ListenAndServe(portWithColon, nil)
}
Reverse Proxy Code
package main
import (
"flag"
"fmt"
"net/http"
"net/http/httputil"
"net/url"
)
var port = flag.String("reverseProxyPort", "9999", "port for reverse proxy")
var appPort = flag.String("appPort", "8888", "port for app to proxy to")
func main() {
flag.Parse()
remote, err := url.Parse(fmt.Sprintf("http://localhost:%s", *appPort))
if err != nil {
panic(err)
}
handler := func(p *httputil.ReverseProxy) func(http.ResponseWriter, *http.Request) {
return func(w http.ResponseWriter, r *http.Request) {
p.ServeHTTP(w, r)
}
}
proxy := httputil.NewSingleHostReverseProxy(remote)
http.HandleFunc("/", handler(proxy))
portWithColon := fmt.Sprintf(":%s", *port)
fmt.Printf("reverse proxy listening on %s", portWithColon)
err = http.ListenAndServe(portWithColon, nil)
if err != nil {
panic(err)
}
}
Client Code
package main
import (
"flag"
"log"
"net/url"
"os"
"os/signal"
"time"
"github.com/gorilla/websocket"
)
var addr = flag.String("addr", "localhost:9999", "http service address")
var path = flag.String("path", "/echo", "path")
func main() {
flag.Parse()
log.SetFlags(0)
interrupt := make(chan os.Signal, 1)
signal.Notify(interrupt, os.Interrupt)
u := url.URL{Scheme: "ws", Host: *addr, Path: *path}
log.Printf("connecting to %s", u.String())
c, _, err := websocket.DefaultDialer.Dial(u.String(), nil)
if err != nil {
log.Fatal("dial:", err)
}
defer c.Close()
done := make(chan struct{})
go func() {
defer close(done)
for {
_, message, err := c.ReadMessage()
if err != nil {
log.Println("read:", err)
return
}
log.Printf("recv: %s", message)
}
}()
err = c.WriteMessage(websocket.TextMessage, []byte(time.Now().String()))
if err != nil {
log.Println("write:", err)
return
}
ticker := time.NewTicker(time.Second)
defer ticker.Stop()
for {
select {
case <-done:
return
case t := <-ticker.C:
err := c.WriteMessage(websocket.TextMessage, []byte(t.String()))
if err != nil {
log.Println("write:", err)
return
}
case <-interrupt:
log.Println("interrupt")
// Cleanly close the connection by sending a close message and then
// waiting (with timeout) for the server to close the connection.
err := c.WriteMessage(websocket.CloseMessage, websocket.FormatCloseMessage(websocket.CloseNormalClosure, ""))
if err != nil {
log.Println("write close:", err)
return
}
select {
case <-done:
case <-time.After(time.Second):
}
return
}
}
}
What did you see happen?
99% of the time (but not always!!) the connection between the reverse proxy and the app is never closed and stays in a FIN_WAIT2 state forever. The reverse proxy and the app send acks forever.
Here are the ports in the below example:
- 52558: client
- 9999: reverse-proxy as a server
- 47662: reverse proxy as a client
- 8888: backend-app
annotated tcpdump output for what happens on go 1.25
# I CTRL-C on the client to kill it
# Client sends FIN to reverse proxy
15:36:28.728428 IP 127.0.0.1.52558 > 127.0.0.1.9999: Flags [F.], seq 318, ack 246, win 512, options [nop,nop,TS val 3606194590 ecr 3606194589], length 0
# Reverse proxy sends FIN to app
15:36:28.728470 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [F.], seq 369, ack 246, win 512, options [nop,nop,TS val 3606194590 ecr 3606194589], length 0
# Everyone ACKs everyone for a bit
# At this point both connections have state FIN_WAIT2
15:36:28.773847 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606194635 ecr 3606194590], length 0
15:36:28.773850 IP 127.0.0.1.9999 > 127.0.0.1.52558: Flags [.], ack 319, win 512, options [nop,nop,TS val 3606194635 ecr 3606194590], length 0
15:36:43.745859 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606209607 ecr 3606194590], length 0
15:36:43.745893 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606209607 ecr 3606194635], length 0
15:36:43.745859 IP 127.0.0.1.9999 > 127.0.0.1.52558: Flags [.], ack 319, win 512, options [nop,nop,TS val 3606209607 ecr 3606194590], length 0
15:36:43.745923 IP 127.0.0.1.52558 > 127.0.0.1.9999: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606209607 ecr 3606194635], length 0
15:36:58.754527 IP 127.0.0.1.9999 > 127.0.0.1.52558: Flags [.], ack 319, win 512, options [nop,nop,TS val 3606224616 ecr 3606209607], length 0
15:36:58.754527 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606224616 ecr 3606209607], length 0
15:36:58.754570 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606224616 ecr 3606194635], length 0
15:36:58.754584 IP 127.0.0.1.52558 > 127.0.0.1.9999: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606224616 ecr 3606194635], length 0
15:36:58.778199 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606224639 ecr 3606194635], length 0
15:36:58.778277 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606224639 ecr 3606224616], length 0
15:37:13.857800 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606239719 ecr 3606224616], length 0
15:37:13.857836 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606239719 ecr 3606224639], length 0
15:37:13.857800 IP 127.0.0.1.9999 > 127.0.0.1.52558: Flags [.], ack 319, win 512, options [nop,nop,TS val 3606239719 ecr 3606224616], length 0
15:37:13.858056 IP 127.0.0.1.52558 > 127.0.0.1.9999: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606239719 ecr 3606194635], length 0
15:37:28.961631 IP 127.0.0.1.9999 > 127.0.0.1.52558: Flags [.], ack 319, win 512, options [nop,nop,TS val 3606254823 ecr 3606239719], length 0
15:37:28.961631 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606254823 ecr 3606239719], length 0
15:37:28.961649 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606254823 ecr 3606224639], length 0
15:37:28.961635 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606254823 ecr 3606224639], length 0
15:37:28.961656 IP 127.0.0.1.52558 > 127.0.0.1.9999: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606254823 ecr 3606194635], length 0
15:37:28.961658 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606254823 ecr 3606254823], length 0
15:37:44.066569 IP 127.0.0.1.9999 > 127.0.0.1.52558: Flags [.], ack 319, win 512, options [nop,nop,TS val 3606269928 ecr 3606254823], length 0
# Client sends RST to reverse proxy (related to /proc/sys/net/ipv4/tcp_fin_timeout I think)
# Note that in here in go 1.25 it took >60s for the connection between the client and the reverse proxy to close.
# In go 1.24 it closes nearly instantaneously.
15:37:44.066656 IP 127.0.0.1.52558 > 127.0.0.1.9999: Flags [R], seq 997032030, win 0, length 0
# At this point the connection between the client and reverse proxy is gone.
# At this point the connection between the reverse proxy and the app is still in state FIN_WAIT2
# The Reverse Proxy and app send ACKs forever :(
# In go 1.24 the Reverse Proxy eventually sends a RST packet to the app which closes the connection.
15:37:44.066569 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606269928 ecr 3606254823], length 0
15:37:44.066942 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606269928 ecr 3606254823], length 0
15:37:59.169916 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606285031 ecr 3606269928], length 0
15:37:59.169968 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606285031 ecr 3606254823], length 0
15:37:59.170020 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606285031 ecr 3606254823], length 0
15:37:59.170043 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606285031 ecr 3606285031], length 0
15:38:14.274154 IP 127.0.0.1.8888 > 127.0.0.1.47662: Flags [.], ack 370, win 512, options [nop,nop,TS val 3606300135 ecr 3606285031], length 0
15:38:14.274176 IP 127.0.0.1.47662 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3606300135 ecr 3606285031], length 0
netstat output showing FIN_WAIT2 connection between reverse proxy and app
$ netstat -p | grep FIN
tcp 0 0 localhost:47662 localhost:8888 FIN_WAIT2 1116293/rprox
If I only run the client and kill it once, then the connection will hang open forever (99% of the time). If I continually run the client and kill it, then the open connections will accumulate, but only to a point. Once it reaches ~100-200 connections they all get cleaned up. I assume this is related to some settings on my reverse proxy or app or machine, but I don't know which.
What did you expect to see?
I expected all connections to close.
Here are the ports in the below example:
- 59942: client
- 9999: reverse-proxy as a server
- 38512: reverse proxy as a client
- 8888: backend-app
annotated tcpdump output for what happens on go 1.24.7
# I CTRL-C on the client to kill it
# Client sends FIN to reverse proxy
20:22:51.780826 IP 127.0.0.1.59942 > 127.0.0.1.9999: Flags [F.], seq 318, ack 246, win 512, options [nop,nop,TS val 3619481205 ecr 3619481204], length 0
# Reverse Proxy sends FIN back to the client (this does not happen in go 1.25)
20:22:51.781430 IP 127.0.0.1.9999 > 127.0.0.1.59942: Flags [F.], seq 246, ack 319, win 512, options [nop,nop,TS val 3619481205 ecr 3619481205], length 0
20:22:51.781442 IP 127.0.0.1.59942 > 127.0.0.1.9999: Flags [.], ack 247, win 512, options [nop,nop,TS val 3619481205 ecr 3619481205], length 0
# At this point the connection between the client and the reverse proxy is closed.
# Here in go 1.24 this happens almost immediately (about 0.001 seconds).
# In go 1.25 it takes ~60s for some setting to timeout for the client <-> reverse proxy connection to close.
# Reverse Proxy sends Fin to the app
20:22:51.781582 IP 127.0.0.1.38512 > 127.0.0.1.8888: Flags [F.], seq 369, ack 246, win 512, options [nop,nop,TS val 3619481205 ecr 3619481204], length 0
# Reverse Proxy and app ACK back and forth for a bit
20:22:51.822773 IP 127.0.0.1.8888 > 127.0.0.1.38512: Flags [.], ack 370, win 512, options [nop,nop,TS val 3619481247 ecr 3619481205], length 0
20:23:06.807097 IP 127.0.0.1.8888 > 127.0.0.1.38512: Flags [.], ack 370, win 512, options [nop,nop,TS val 3619496231 ecr 3619481205], length 0
20:23:06.807137 IP 127.0.0.1.38512 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3619496231 ecr 3619481247], length 0
20:23:21.847140 IP 127.0.0.1.8888 > 127.0.0.1.38512: Flags [.], ack 370, win 512, options [nop,nop,TS val 3619511271 ecr 3619496231], length 0
20:23:21.847192 IP 127.0.0.1.38512 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3619511271 ecr 3619481247], length 0
20:23:36.951288 IP 127.0.0.1.8888 > 127.0.0.1.38512: Flags [.], ack 370, win 512, options [nop,nop,TS val 3619526375 ecr 3619511271], length 0
20:23:36.951345 IP 127.0.0.1.38512 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3619526375 ecr 3619481247], length 0
20:23:52.059354 IP 127.0.0.1.8888 > 127.0.0.1.38512: Flags [.], ack 370, win 512, options [nop,nop,TS val 3619541483 ecr 3619526375], length 0
20:23:52.059409 IP 127.0.0.1.38512 > 127.0.0.1.8888: Flags [.], ack 246, win 512, options [nop,nop,TS val 3619541483 ecr 3619481247], length 0
20:24:07.159309 IP 127.0.0.1.8888 > 127.0.0.1.38512: Flags [.], ack 370, win 512, options [nop,nop,TS val 3619556583 ecr 3619541483], length 0
# Reverse Proxy sends a RST packet to the app and the connection is closed (this does not happen in go 1.25)
20:24:07.159346 IP 127.0.0.1.38512 > 127.0.0.1.8888: Flags [R], seq 2350419052, win 0, length 0