Skip to content

Instantly share code, notes, and snippets.

@odeke-em

odeke-em/README.md Secret

Created May 20, 2019 03:45
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save odeke-em/b62737b89b91e71ffbf0545581976cbc to your computer and use it in GitHub Desktop.
Save odeke-em/b62737b89b91e71ffbf0545581976cbc to your computer and use it in GitHub Desktop.
Download ZIP
Raw
README.md

Purpose

Examining a hypothesis about bug googleapis/google-cloud-go#1380 about the HTTP/2 frontend getting flooded and not responding despite having established connections and those connections get stalled forever.

It sends itself SIGQUIT after say 6 seconds to produce a curious stacktrace that looks like this

goroutine 51 [select]:
io.(*pipe).Write(0xc000166500, 0xc0001ae090, 0x42, 0x82, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/pipe.go:87 +0x1dc
io.(*PipeWriter).Write(0xc000162020, 0xc0001ae090, 0x42, 0x82, 0x12f9620, 0x13476e0, 0x10cfc01)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/pipe.go:153 +0x4c
bytes.(*Buffer).WriteTo(0xc0000969c0, 0x13be9c0, 0xc000162020, 0x46350b0, 0xc0000969c0, 0x1)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/bytes/buffer.go:242 +0xb5
io.copyBuffer(0x13be9c0, 0xc000162020, 0x13be780, 0xc0000969c0, 0x0, 0x0, 0x0, 0x2, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:384 +0x33f
io.Copy(...)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:364
mime/multipart.(*Writer).CreatePart(0xc000096990, 0xc000064e48, 0x0, 0x0, 0x0, 0x0)
	/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/mime/multipart/writer.go:121 +0x3fa
main.main.func2(0xc000162020)
	/Users/emmanuelodeke/Desktop/openSrc/bugs/google-cloud-go/1380/main.go:51 +0x11f
created by main.main
	/Users/emmanuelodeke/Desktop/openSrc/bugs/google-cloud-go/1380/main.go:48 +0x3d3

How to run it

GODEBUG=http2debug=2 go run main.go

If it doesn't produce a core-dump in 6 seconds, manually hit Ctrl+Shift+\

Interpretation

The mothership HTTP/2 server stalled reads or got overflooded or the network is saturated/throttled unfairly and no reads are being performed on the client side hence that io.Pipe segment

Raw
main.go
package main
import (
"bytes"
"context"
"crypto/tls"
"fmt"
"io"
"io/ioutil"
"log"
"mime/multipart"
"net/http"
"net/http/httptest"
"net/textproto"
"net/url"
"os"
"syscall"
"time"
"golang.org/x/net/http2"
)
func main() {
cst := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
// Stalled server that takes forever to read or could be overloaded.
// It already established a connection though.
<-time.After(10 * time.Minute)
slurp, _ := ioutil.ReadAll(r.Body)
log.Printf("Request payload: %s\n", slurp)
w.Write(bytes.Repeat([]byte("a"), 3000))
}))
if err := http2.ConfigureServer(cst.Config, nil); err != nil {
log.Fatalf("http2.ConfigureServer: %v", err)
}
cst.StartTLS()
defer cst.Close()
tlsConfig := &tls.Config{InsecureSkipVerify: true}
u, _ := url.Parse(cst.URL)
tlsConn, err := tls.Dial("tcp", u.Host, tlsConfig)
if err != nil {
log.Fatalf("Failed to create a tls connection: %v", err)
}
prc, pwc := io.Pipe()
go func() {
h := make(textproto.MIMEHeader)
mpw := multipart.NewWriter(pwc)
w, err := mpw.CreatePart(h)
if err != nil {
mpw.Close()
pwc.CloseWithError(fmt.Errorf("CreatePart failed: %v", err))
return
}
n, _ := pwc.Write(bytes.Repeat([]byte("a"), 39<<20))
println("read ", n)
r := bytes.NewReader([]byte(`{"id": "1380", "type": "issue"}`))
if _, err := io.Copy(w, r); err != nil {
mpw.Close()
pwc.CloseWithError(fmt.Errorf("Copy failed: %v", err))
return
}
println("done read in goroutine")
mpw.Close()
pwc.Close()
}()
tr := &http2.Transport{TLSClientConfig: tlsConfig}
cc, err := tr.NewClientConn(tlsConn)
if err != nil {
log.Fatalf("(*http2.Transport).NewClientConn: %v", err)
}
// Find our own process and in the background send ourselves SIGQUIT.
selfProcess, err := os.FindProcess(os.Getpid())
if err != nil {
log.Fatalf("Failed to find own process: %v", err)
}
go func() {
<-time.After(6 * time.Second)
if err := selfProcess.Signal(syscall.SIGQUIT); err != nil {
log.Fatalf("Failed to send self SIGQUIT: %v", err)
}
}()
// Send that ping frame and ensure we have an established connection
// and that the server is one stalled and body reads are stalled.
if err := cc.Ping(context.Background()); err != nil {
log.Fatalf("(*http2.ClientConn).Ping: %v", err)
}
req, _ := http.NewRequest("GET", cst.URL, prc)
res, err := cc.RoundTrip(req)
if err != nil {
log.Fatalf("http.Transport.Roundtrip error: %v", err)
}
defer res.Body.Close()
blob, _ := ioutil.ReadAll(res.Body)
log.Printf("%s\n", blob)
}
Raw
target_stacktrace.txt
goroutine 35 [select]:
io.(*pipe).Write(0xc00015cd20, 0xc0001d0090, 0x42, 0x82, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/pipe.go:87 +0x1dc
io.(*PipeWriter).Write(0xc00013a028, 0xc0001d0090, 0x42, 0x82, 0x12f8720, 0x13465a0, 0x10cf201)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/pipe.go:153 +0x4c
bytes.(*Buffer).WriteTo(0xc0000ba240, 0x13bd460, 0xc00013a028, 0x26000d0, 0xc0000ba240, 0x1)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/bytes/buffer.go:242 +0xb5
io.copyBuffer(0x13bd460, 0xc00013a028, 0x13bd220, 0xc0000ba240, 0x0, 0x0, 0x0, 0x2, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:384 +0x33f
io.Copy(...)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:364
mime/multipart.(*Writer).CreatePart(0xc0000ba210, 0xc00005fe48, 0x0, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/mime/multipart/writer.go:121 +0x3fa
main.main.func2(0xc00013a028)
/Users/emmanuelodeke/Desktop/openSrc/bugs/google-cloud-go/1380/main.go:48 +0x11f
created by main.main
/Users/emmanuelodeke/Desktop/openSrc/bugs/google-cloud-go/1380/main.go:45 +0x3cd
Raw
whole_stacktrace.txt
$ GODEBUG=http2debug=2 go run main.go
2019/05/19 20:41:07 http2: Transport creating client conn 0xc000080c00 to 127.0.0.1:50501
2019/05/19 20:41:07 http2: Framer 0xc000206000: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2019/05/19 20:41:07 http2: Framer 0xc000206000: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2019/05/19 20:41:07 http2: Framer 0xc000206000: wrote PING len=8 ping="2\x99\xccf\xb9ܰ\r"
SIGQUIT: quit
PC=0x7fff5c4e886a m=0 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0x15cdcc8, 0x15cdc88, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/sys_darwin.go:368 +0x39
runtime.semasleep(0xffffffffffffffff, 0xc000080db8)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/os_darwin.go:63 +0x85
runtime.notesleep(0x15cda88)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/lock_sema.go:167 +0xe0
runtime.stopm()
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/proc.go:1928 +0xc0
runtime.findrunnable(0xc00003b900, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/proc.go:2391 +0x53f
runtime.schedule()
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/proc.go:2524 +0x2be
runtime.goexit0(0xc000080d80)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/proc.go:2727 +0x1d6
runtime.mcall(0x1058686)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/asm_amd64.s:318 +0x5b
goroutine 1 [select]:
golang.org/x/net/http2.(*ClientConn).Ping(0xc000080c00, 0x13c55e0, 0xc000020050, 0x0, 0xc000080c00)
/Users/emmanuelodeke/go/pkg/mod/golang.org/x/net@v0.0.0-20190320064053-1272bf9dcd53/http2/transport.go:2309 +0x40e
main.main()
/Users/emmanuelodeke/Desktop/openSrc/bugs/google-cloud-go/1380/main.go:93 +0x567
goroutine 18 [IO wait]:
internal/poll.runtime_pollWait(0x46760d8, 0x72, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc000128018, 0x72, 0x0, 0x0, 0x1357edd)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/internal/poll/fd_poll_runtime.go:87 +0x10b
internal/poll.(*pollDesc).waitRead(...)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000128000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/internal/poll/fd_unix.go:384 +0x1b6
net.(*netFD).accept(0xc000128000, 0xc0000ac410, 0xc90000000104ac8c, 0xc00005ee08)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc0000d62c0, 0xc0000ac498, 0x136f950, 0x133dc20)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc0000d62c0, 0xc00005ee78, 0xc0000ac498, 0x5ce22100, 0xc0000cc2a0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/tcpsock.go:261 +0x47
crypto/tls.(*listener).Accept(0xc0000d7260, 0xc00005eed8, 0x18, 0xc00012e480, 0x1238d02)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/crypto/tls/tls.go:57 +0x37
net/http.(*Server).Serve(0xc00012c000, 0x13c4b60, 0xc0000d7260, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:2894 +0x254
net/http/httptest.(*Server).goServe.func1(0xc0000cc2a0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/httptest/server.go:298 +0x6d
created by net/http/httptest.(*Server).goServe
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/httptest/server.go:296 +0x5c
goroutine 50 [chan receive]:
main.main.func1(0x13c4fe0, 0xc0001c81c0, 0xc000204000)
/Users/emmanuelodeke/Desktop/openSrc/bugs/google-cloud-go/1380/main.go:27 +0x4e
net/http.HandlerFunc.ServeHTTP(0x136f058, 0x13c4fe0, 0xc0001c81c0, 0xc000204000)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:2007 +0x44
net/http.serverHandler.ServeHTTP(0xc00012c000, 0x13c4fe0, 0xc0001c81c0, 0xc000204000)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:2800 +0xa4
net/http.(*conn).serve(0xc000168000, 0x13c55a0, 0xc0001220c0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:1890 +0x84c
created by net/http.(*Server).Serve
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:2925 +0x352
goroutine 51 [select]:
io.(*pipe).Write(0xc000166500, 0xc0001ae090, 0x42, 0x82, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/pipe.go:87 +0x1dc
io.(*PipeWriter).Write(0xc000162020, 0xc0001ae090, 0x42, 0x82, 0x12f9620, 0x13476e0, 0x10cfc01)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/pipe.go:153 +0x4c
bytes.(*Buffer).WriteTo(0xc0000969c0, 0x13be9c0, 0xc000162020, 0x46350b0, 0xc0000969c0, 0x1)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/bytes/buffer.go:242 +0xb5
io.copyBuffer(0x13be9c0, 0xc000162020, 0x13be780, 0xc0000969c0, 0x0, 0x0, 0x0, 0x2, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:384 +0x33f
io.Copy(...)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:364
mime/multipart.(*Writer).CreatePart(0xc000096990, 0xc000064e48, 0x0, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/mime/multipart/writer.go:121 +0x3fa
main.main.func2(0xc000162020)
/Users/emmanuelodeke/Desktop/openSrc/bugs/google-cloud-go/1380/main.go:51 +0x11f
created by main.main
/Users/emmanuelodeke/Desktop/openSrc/bugs/google-cloud-go/1380/main.go:48 +0x3d3
goroutine 6 [IO wait]:
internal/poll.runtime_pollWait(0x4676008, 0x72, 0xffffffffffffffff)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc00015a018, 0x72, 0x600, 0x6e0, 0xffffffffffffffff)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/internal/poll/fd_poll_runtime.go:87 +0x10b
internal/poll.(*pollDesc).waitRead(...)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00015a000, 0xc0001be000, 0x6e0, 0x6e0, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/internal/poll/fd_unix.go:169 +0x1ec
net.(*netFD).Read(0xc00015a000, 0xc0001be000, 0x6e0, 0x6e0, 0x203000, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000162000, 0xc0001be000, 0x6e0, 0x6e0, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/net.go:177 +0x68
crypto/tls.(*atLeastReader).Read(0xc0001ea060, 0xc0001be000, 0x6e0, 0x6e0, 0x0, 0x0, 0xc00005f9f0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/crypto/tls/conn.go:780 +0x60
bytes.(*Buffer).ReadFrom(0xc00009ccd8, 0x13be860, 0xc0001ea060, 0x100b645, 0x12f9420, 0x13438c0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/bytes/buffer.go:207 +0xb4
crypto/tls.(*Conn).readFromUntil(0xc00009ca80, 0x4851008, 0xc000162000, 0x5, 0xc000162000, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/crypto/tls/conn.go:802 +0xec
crypto/tls.(*Conn).readRecordOrCCS(0xc00009ca80, 0x136f900, 0xc00009cbb8, 0xc00016ec88)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/crypto/tls/conn.go:609 +0x124
crypto/tls.(*Conn).readRecord(...)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/crypto/tls/conn.go:577
crypto/tls.(*Conn).Read(0xc00009ca80, 0xc000203000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/crypto/tls/conn.go:1255 +0x139
bufio.(*Reader).Read(0xc0001b21e0, 0xc000206038, 0x9, 0x9, 0x20, 0x12e7420, 0x1)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/bufio/bufio.go:223 +0x23b
io.ReadAtLeast(0x13be740, 0xc0001b21e0, 0xc000206038, 0x9, 0x9, 0x9, 0x0, 0xc00000ca00, 0x12d4ce0)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:310 +0x87
io.ReadFull(...)
/Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:329
golang.org/x/net/http2.readFrameHeader(0xc000206038, 0x9, 0x9, 0x13be740, 0xc0001b21e0, 0x0, 0x0, 0x0, 0x0)
/Users/emmanuelodeke/go/pkg/mod/golang.org/x/net@v0.0.0-20190320064053-1272bf9dcd53/http2/frame.go:237 +0x87
golang.org/x/net/http2.(*Framer).ReadFrame(0xc000206000, 0x0, 0x0, 0x6a03020700000000, 0xc00016ee78)
/Users/emmanuelodeke/go/pkg/mod/golang.org/x/net@v0.0.0-20190320064053-1272bf9dcd53/http2/frame.go:492 +0x95
golang.org/x/net/http2.(*clientConnReadLoop).run(0xc00005ffb8, 0x136ee90, 0xc00016efb8)
/Users/emmanuelodeke/go/pkg/mod/golang.org/x/net@v0.0.0-20190320064053-1272bf9dcd53/http2/transport.go:1679 +0x8c
golang.org/x/net/http2.(*ClientConn).readLoop(0xc000080c00)
/Users/emmanuelodeke/go/pkg/mod/golang.org/x/net@v0.0.0-20190320064053-1272bf9dcd53/http2/transport.go:1607 +0x76
created by golang.org/x/net/http2.(*Transport).newClientConn
/Users/emmanuelodeke/go/pkg/mod/golang.org/x/net@v0.0.0-20190320064053-1272bf9dcd53/http2/transport.go:670 +0x62f
rax 0x0
rbx 0x2
rcx 0x7ffeefbfd408
rdx 0x0
rdi 0x15cdcc8
rsi 0x70100000800
rbp 0x7ffeefbfd490
rsp 0x7ffeefbfd408
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0x15cdcc8
r13 0x16
r14 0x70100000800
r15 0xa3fd5c0
rip 0x7fff5c4e886a
rflags 0x202
cs 0x7
fs 0x0
gs 0x0
exit status 2
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment