cmd/link: runtime crash, unexpected fault address 0xffffffffffffffff, h2_bundle.go, when using plugin

[parsley42]

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

$ go version
go version go1.16 linux/amd64

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="amd64"
GOBIN=""
GOCACHE="/home/parse/.cache/go-build"
GOENV="/home/parse/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/parse/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/parse/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.16"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build42897677=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I'm going to need some suggestions on figuring out what happened, but the gist is I ran my program and it crashed with a strange segfault.

What did you expect to see?

Program running as it did with Go 1.15.8.

What did you see instead?

My program crashed with a segmentation violation; I've pasted in the stack trace (in a details section) below.

./gopherbot stack trace

2021/02/24 13:38:50 Info: Listening for external plugin connections on http://127.0.0.1:41229
unexpected fault address 0xffffffffffffffff
fatal error: fault
[signal SIGSEGV: segmentation violation code=0x1 addr=0xffffffffffffffff pc=0xffffffffffffffff]
goroutine 71 [running]:

runtime.throw(0x9e75e8, 0x5)

/usr/local/go/src/runtime/panic.go:1117 +0x72 fp=0xc00004ac70 sp=0xc00004ac40 pc=0x56c752

runtime.sigpanic()

/usr/local/go/src/runtime/signal_unix.go:741 +0x268 fp=0xc00004aca8 sp=0xc00004ac70 pc=0x5836e8

net/http.(*http2clientStream).writeRequestBody.func1(0xc000130420, 0xc00004af90, 0x7f281410c638, 0xc000218708)

/usr/local/go/src/net/http/h2_bundle.go:7825 +0x5a fp=0xc00004acd0 sp=0xc00004aca8 pc=0x7f28158a6e9a

net/http.(*http2clientStream).writeRequestBody(0xc000130420, 0xa755e0, 0xc000218708, 0x7f281410c638, 0xc000218708, 0x0, 0x0)

/usr/local/go/src/net/http/h2_bundle.go:7903 +0xe04 fp=0xc00004af68 sp=0xc00004acd0 pc=0x7f281587ce64

net/http.(*http2Transport).getBodyWriterState.func1()

/usr/local/go/src/net/http/h2_bundle.go:9114 +0xcc fp=0xc00004afe0 sp=0xc00004af68 pc=0x7f28158a7d6c

runtime.goexit()

/usr/local/go/src/runtime/asm_amd64.s:1371 +0x1 fp=0xc00004afe8 sp=0xc00004afe0 pc=0x5a3d01

created by net/http.http2bodyWriterState.scheduleBodyWrite

/usr/local/go/src/net/http/h2_bundle.go:9163 +0xa6
goroutine 1 [chan receive]:

github.com/lnxjedi/gopherbot/connectors/slack.Initialize(0xa80868, 0xcdf0d8, 0xc00006ee60, 0x5, 0xc00007b418)

/home/parse/git/gopher/gopherbot/connectors/slack/connect.go:76 +0x2ce

github.com/lnxjedi/gopherbot/bot.Start(0x9e6ea7, 0x2, 0xa6c530, 0x8)

/home/parse/git/gopher/gopherbot/bot/start.go:370 +0x1482

main.main()

/home/parse/git/gopher/gopherbot/main.go:16 +0x51
goroutine 10 [IO wait]:

internal/poll.runtime_pollWait(0x7f2815e50858, 0x72, 0x0)

/usr/local/go/src/runtime/netpoll.go:222 +0x55

internal/poll.(*pollDesc).wait(0xc000224118, 0x72, 0x0, 0x0, 0x9e7df8)

/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45

internal/poll.(*pollDesc).waitRead(...)

/usr/local/go/src/internal/poll/fd_poll_runtime.go:92

internal/poll.(*FD).Accept(0xc000224100, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)

/usr/local/go/src/internal/poll/fd_unix.go:401 +0x212

net.(*netFD).accept(0xc000224100, 0x30, 0x30, 0x7f283eb06a68)

/usr/local/go/src/net/fd_unix.go:172 +0x45

net.(*TCPListener).accept(0xc000218048, 0xc000048db0, 0x7f28145e163a, 0x30)

/usr/local/go/src/net/tcpsock_posix.go:139 +0x32

net.(*TCPListener).Accept(0xc000218048, 0x9b8460, 0xc000207230, 0x975940, 0xc66a90)

/usr/local/go/src/net/tcpsock.go:261 +0x65

net/http.(*Server).Serve(0xc000232000, 0xa7b220, 0xc000218048, 0x0, 0x0)

/usr/local/go/src/net/http/server.go:2981 +0x2a3

net/http.(*Server).ListenAndServe(0xc000232000, 0xc000232000, 0xc000208290)

/usr/local/go/src/net/http/server.go:2910 +0xbc

net/http.ListenAndServe(...)

/usr/local/go/src/net/http/server.go:3164

github.com/lnxjedi/gopherbot/history/file.provider.func1()

/home/parse/git/gopher/gopherbot/history/file/filehistory.go:185 +0x15d

created by github.com/lnxjedi/gopherbot/history/file.provider

/home/parse/git/gopher/gopherbot/history/file/filehistory.go:183 +0x3a8
goroutine 98 [IO wait]:

internal/poll.runtime_pollWait(0x7f2815e50688, 0x72, 0x0)

/usr/local/go/src/runtime/netpoll.go:222 +0x55

internal/poll.(*pollDesc).wait(0xc0002df398, 0x72, 0x0, 0x0, 0x9e7df8)

/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45

internal/poll.(*pollDesc).waitRead(...)

/usr/local/go/src/internal/poll/fd_poll_runtime.go:92

internal/poll.(*FD).Accept(0xc0002df380, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)

/usr/local/go/src/internal/poll/fd_unix.go:401 +0x212

net.(*netFD).accept(0xc0002df380, 0x30, 0x30, 0x7f283eb06a68)

/usr/local/go/src/net/fd_unix.go:172 +0x45

net.(*TCPListener).accept(0xc000218630, 0xc000049e08, 0x5445b8, 0x30)

/usr/local/go/src/net/tcpsock_posix.go:139 +0x32

net.(*TCPListener).Accept(0xc000218630, 0x9b8460, 0xc0004091a0, 0x975940, 0xc66a90)

/usr/local/go/src/net/tcpsock.go:261 +0x65

net/http.(*Server).Serve(0xc0002320e0, 0xa7b220, 0xc000218630, 0x0, 0x0)

/usr/local/go/src/net/http/server.go:2981 +0x285

net/http.Serve(...)

/usr/local/go/src/net/http/server.go:2529

github.com/lnxjedi/gopherbot/bot.initBot.func1(0xa7b220, 0xc000218630)

/home/parse/git/gopher/gopherbot/bot/bot_process.go:227 +0x158

created by github.com/lnxjedi/gopherbot/bot.initBot

/home/parse/git/gopher/gopherbot/bot/bot_process.go:222 +0x615
goroutine 99 [select]:

net/http.(*http2ClientConn).roundTrip(0xc000244480, 0xc00016c200, 0x0, 0x0, 0x0, 0x0)

/usr/local/go/src/net/http/h2_bundle.go:7668 +0x9bc

net/http.(*http2Transport).RoundTripOpt(0xc0000fbc70, 0xc00016c200, 0x7f2815af4900, 0xc0006e4f20, 0x7f2815af49f0, 0xa0e670)

/usr/local/go/src/net/http/h2_bundle.go:6981 +0x1a5

net/http.(*http2Transport).RoundTrip(0xc0000fbc70, 0xc00016c200, 0x0, 0xc000699170, 0x5)

/usr/local/go/src/net/http/h2_bundle.go:6942 +0x3c

net/http.(*Transport).roundTrip(0x7f2815af49c0, 0xc00016c100, 0xc0006e66e0, 0x160, 0x150)

/usr/local/go/src/net/http/transport.go:590 +0x845

net/http.(*Transport).RoundTrip(0x7f2815af49c0, 0xc00016c100, 0x7f2815af49c0, 0x0, 0x0)

/usr/local/go/src/net/http/roundtrip.go:17 +0x37

net/http.send(0xc00016c100, 0x7f281599cec8, 0x7f2815af49c0, 0x0, 0x0, 0x0, 0xc0002f03a8, 0x9e8e25, 0x1, 0x0)

/usr/local/go/src/net/http/client.go:251 +0x466

net/http.(*Client).send(0xc0000793b0, 0xc00016c100, 0x0, 0x0, 0x0, 0xc0002f03a8, 0x0, 0x1, 0xe)

/usr/local/go/src/net/http/client.go:175 +0xff

net/http.(*Client).do(0xc0000793b0, 0xc00016c100, 0x0, 0x0, 0x0)

/usr/local/go/src/net/http/client.go:717 +0x46f

net/http.(*Client).Do(0xc0000793b0, 0xc00016c100, 0xc0006f9810, 0x7f2814dc861a, 0x18)

/usr/local/go/src/net/http/client.go:585 +0x37

github.com/slack-go/slack.doPost(0xa7bfe8, 0xc0004c9500, 0x7f2815213a58, 0xc0000793b0, 0xc00016c000, 0xc0002186d8, 0x7f28152190f0, 0xc00019fee0, 0x0, 0x0)

/home/parse/git/gopher/gopherbot/vendor/github.com/slack-go/slack/misc.go:220 +0x10a

github.com/slack-go/slack.postForm(0xa7bfe8, 0xc0004c9500, 0x7f2815213a58, 0xc0000793b0, 0xc000699170, 0x21, 0xc00004f9a0, 0x7f28151ccee0, 0xc0004b6fc0, 0x7f28152190f0, ...)

/home/parse/git/gopher/gopherbot/vendor/github.com/slack-go/slack/misc.go:255 +0x27a

github.com/slack-go/slack.(*Client).postMethod(...)

/home/parse/git/gopher/gopherbot/vendor/github.com/slack-go/slack/slack.go:147

github.com/slack-go/slack.(*Client).ConnectRTMContext(0xc00019fee0, 0xa7bfe8, 0xc0004c9500, 0xa7bfe8, 0xc0004c9500, 0xc000209640, 0x54b6cc, 0x7f2816e85868)

/home/parse/git/gopher/gopherbot/vendor/github.com/slack-go/slack/rtm.go:65 +0x225

github.com/slack-go/slack.(*Client).ConnectRTM(0xc00019fee0, 0x0, 0x0, 0x0, 0x0, 0x0)

/home/parse/git/gopher/gopherbot/vendor/github.com/slack-go/slack/rtm.go:56 +0xac

github.com/slack-go/slack.(*RTM).startRTMAndDial(0xc00019fee0, 0xc0005af600, 0x0, 0x0, 0x0, 0x0)

/home/parse/git/gopher/gopherbot/vendor/github.com/slack-go/slack/websocket_managed_conn.go:178 +0x5c5

github.com/slack-go/slack.(*RTM).connect(0xc00019fee0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)

/home/parse/git/gopher/gopherbot/vendor/github.com/slack-go/slack/websocket_managed_conn.go:111 +0x127

github.com/slack-go/slack.(*RTM).ManageConnection(0xc00019fee0)

/home/parse/git/gopher/gopherbot/vendor/github.com/slack-go/slack/websocket_managed_conn.go:40 +0x65

created by github.com/lnxjedi/gopherbot/connectors/slack.Initialize

/home/parse/git/gopher/gopherbot/connectors/slack/connect.go:69 +0x258
goroutine 70 [IO wait]:

internal/poll.runtime_pollWait(0x7f2815e50770, 0x72, 0xffffffffffffffff)

/usr/local/go/src/runtime/netpoll.go:222 +0x55

internal/poll.(*pollDesc).wait(0xc0002df798, 0x72, 0x1000, 0x1010, 0xffffffffffffffff)

/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45

internal/poll.(*pollDesc).waitRead(...)

/usr/local/go/src/internal/poll/fd_poll_runtime.go:92

internal/poll.(*FD).Read(0xc0002df780, 0xc0000da000, 0x1010, 0x1010, 0x0, 0x0, 0x0)

/usr/local/go/src/internal/poll/fd_unix.go:166 +0x1d5

net.(*netFD).Read(0xc0002df780, 0xc0000da000, 0x1010, 0x1010, 0xc0006964c8, 0x18, 0x155)

/usr/local/go/src/net/fd_posix.go:55 +0x4f

net.(*conn).Read(0xc000204228, 0xc0000da000, 0x1010, 0x1010, 0x0, 0x0, 0x0)

/usr/local/go/src/net/net.go:183 +0x91

crypto/tls.(*atLeastReader).Read(0xc00041c000, 0xc0000da000, 0x1010, 0x1010, 0x0, 0xc00003e800, 0x0)

/usr/local/go/src/crypto/tls/conn.go:776 +0x63

bytes.(*Buffer).ReadFrom(0xc00007e978, 0xa74f80, 0xc00041c000, 0x541be5, 0x983760, 0x9d14c0)

/usr/local/go/src/bytes/buffer.go:204 +0xbe

crypto/tls.(*Conn).readFromUntil(0xc00007e700, 0xa75460, 0xc000204228, 0x5, 0xc000204228, 0x0)

/usr/local/go/src/crypto/tls/conn.go:798 +0xf3

crypto/tls.(*Conn).readRecordOrCCS(0xc00007e700, 0x0, 0x0, 0x7f2815636955)

/usr/local/go/src/crypto/tls/conn.go:605 +0x115

crypto/tls.(*Conn).readRecord(...)

/usr/local/go/src/crypto/tls/conn.go:573

crypto/tls.(*Conn).Read(0xc00007e700, 0xc000478000, 0x1000, 0x1000, 0x0, 0x0, 0x0)

/usr/local/go/src/crypto/tls/conn.go:1276 +0x165

bufio.(*Reader).Read(0xc00020cd20, 0xc0002323b8, 0x9, 0x9, 0xc0005b3458, 0x7f281562e20f, 0x9ca320)

/usr/local/go/src/bufio/bufio.go:227 +0x222

io.ReadAtLeast(0xa74e40, 0xc00020cd20, 0xc0002323b8, 0x9, 0x9, 0x9, 0x0, 0x0, 0x0)

/usr/local/go/src/io/io.go:328 +0x89

io.ReadFull(...)

/usr/local/go/src/io/io.go:347

net/http.http2readFrameHeader(0xc0002323b8, 0x9, 0x9, 0xa74e40, 0xc00020cd20, 0x0, 0x0, 0x0, 0x0)

/usr/local/go/src/net/http/h2_bundle.go:1477 +0x89

net/http.(*http2Framer).ReadFrame(0xc000232380, 0x0, 0x0, 0x0, 0x0)

/usr/local/go/src/net/http/h2_bundle.go:1735 +0xa7

net/http.(*http2clientConnReadLoop).run(0xc0000d5fa8, 0x0, 0x0)

/usr/local/go/src/net/http/h2_bundle.go:8322 +0xda

net/http.(*http2ClientConn).readLoop(0xc000244480)

/usr/local/go/src/net/http/h2_bundle.go:8244 +0x71

created by net/http.(*http2Transport).newClientConn

/usr/local/go/src/net/http/h2_bundle.go:7208 +0x6f7

Note that if I run the same program with a different configuration (connecting to Slack or not, but so far I've had no luck in finding a the causal link), it doesn't crash. Hopefully someone more knowledgeable than I can make some sense of the dump and suggest something to look for in my code - but the actual thread that crashed appears to have been created entirely within the runtime, so I'm at a loss.

[cherrymui]

One possibility where this address can come up is that a method is called which the linker decided unreachable, possibly a linker bug. At h2_bundle.go:7825 it seems an interface method call of the Close method. Do you know what the concrete type that interface value is? Is it possible to share the whole program? Thanks.

[parsley42]

Well, the whole program is Gopherbot - https://github.com/lnxjedi/gopherbot

All the http code is either in the /bot subdirectory or vendor/github.com/slack-go/slack.

Is there a debug flag I can pass during build that might catch this during linking?

[cherrymui]

At the moment it is probably most useful to know what the concrete type is. Maybe you can add a print, something like

diff --git a/src/net/http/h2_bundle.go b/src/net/http/h2_bundle.go
index 6bef310feb..0588d6e5cb 100644
--- a/src/net/http/h2_bundle.go
+++ b/src/net/http/h2_bundle.go
@@ -7820,6 +7820,7 @@ func (cs *http2clientStream) writeRequestBody(body io.Reader, bodyCloser io.Clos
                // Request.Body is closed by the Transport,
                // and in multiple cases: server replies <=299 and >299
                // while still writing request body
+               fmt.Printf("XXX bodyCloser type %T\n", bodyCloser)
                cerr := bodyCloser.Close()
                if err == nil {
                        err = cerr

There are linker debug flags but it is not that helpful without knowing the type.

Also, it would be helpful to know how the program is built, e.g. a static executable, or with shared libraries, or plugins. Thanks.

[parsley42]

Huh. Never realized I could just edit files in /usr/local/go/src/..., but yeah, that worked:

XXX bodyCloser type *http.readTrackingBody
unexpected fault address 0xffffffffffffffff
...

Here's an excerpt from make showing how it's compiled (with plugins):

# Compling the main binary
CGO_ENABLED=1 GOOS=linux GOARCH=amd64 go build -mod vendor -ldflags "-s -w -X main.Commit=9f2aab10" -tags "netgo osusergo static_build modular" -o gopherbot
# Compiling the "slack" module
GOOS=linux GOARCH=amd64 go build -mod vendor -ldflags "-s -w" -o connectors/slack.so -buildmode=plugin -tags 'netgo osusergo static_build module' connectors/slack-mod.go

Thanks for digging in to this.

[cherrymui]

Thanks for the information. This is helpful. Could you try CL https://golang.org/cl/296709 ? It should apply cleanly to Go 1.16. Thanks.

[gopherbot]

Change https://golang.org/cl/296709 mentions this issue: cmd/link: handle types as converted to interface when dynlink

[parsley42]

Ok, I ended up cloning & building go from source (after git checkout go1.16), and indeed this fixes it. Thanks.

I assume this will eventually show up in a merged PR with fixes #..., so I'll leave this open for automatic close.

[cherrymui]

Thanks for confirming. Yes, it will.

[cherrymui]

@gopherbot please backport this to Go 1.16. This is a regression causing runtime crash without easy workaround.

[gopherbot]

Backport issue(s) opened: #44638 (for 1.16).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.