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

random panics when performing provider verification #269

Open
jasonltaylor opened this issue Feb 10, 2023 · 7 comments
Open

random panics when performing provider verification #269

jasonltaylor opened this issue Feb 10, 2023 · 7 comments
Labels
bug Indicates an unexpected problem or unintended behavior

Comments

@jasonltaylor
Copy link

Software versions

  • OS: Ubuntu Linux
  • Consumer Pact library: Pact Go v2.0.0-beta.17.0.20221222235702-6e805a539d1b
  • Provider Pact library: Pact Go v2.0.0-beta.17.0.20221222235702-6e805a539d1b
  • Golang Version: go version go1.19.2 linux/amd64
  • Golang environment:
    GO111MODULE=""
    GOARCH="amd64"
    GOBIN=""
    GOCACHE="/home/dev/.cache/go-build"
    GOENV="/home/dev/.config/go/env"
    GOEXE=""
    GOEXPERIMENT=""
    GOFLAGS=""
    GOHOSTARCH="amd64"
    GOHOSTOS="linux"
    GOINSECURE=""
    GOMODCACHE="/home/dev/go/pkg/mod"
    GONOPROXY="github.hpe.com"
    GONOSUMDB="github.hpe.com"
    GOOS="linux"
    GOPATH="/home/dev/go"
    GOPRIVATE="github.hpe.com"
    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.19.2"
    GCCGO="gccgo"
    GOAMD64="v1"
    AR="ar"
    CC="gcc"
    CXX="g++"
    CGO_ENABLED="1"
    GOMOD="/home/dev/ws/sc-authz/go.mod"
    GOWORK=""
    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 -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build4109696144=/tmp/go-build -gno-record-gcc-switches"

Expected behaviour

Pact provider verification for gRPC contract runs successfully.

Actual behaviour

Randomly fails due to uncaught signal 17.

Steps to reproduce

Run go test -count=1 . in 2.x.x branch under folder examples/grpc repeatedly until you see the panic.

Relevent log files

signal 17 received but handler not on signal stack
fatal error: non-Go code set up signal handler without SA_ONSTACK flag

runtime stack:
runtime.throw({0xee889c?, 0xc00006c000?})
        /usr/local/go/src/runtime/panic.go:1047 +0x5d fp=0xc000155020 sp=0xc000154ff0 pc=0x43c89d
runtime.sigNotOnStack(0x11)
        /usr/local/go/src/runtime/signal_unix.go:1020 +0x65 fp=0xc000155040 sp=0xc000155020 pc=0x453a85
runtime.adjustSignalStack(0x11, 0xc000100000, 0xc0001550d0)
        /usr/local/go/src/runtime/signal_unix.go:581 +0x28b fp=0xc0001550a8 sp=0xc000155040 pc=0x45262b
runtime.sigtrampgo(0x11, 0xc0001552f0, 0xc0001551c0)
        /usr/local/go/src/runtime/signal_unix.go:469 +0x15b fp=0xc000155120 sp=0xc0001550a8 pc=0x45219b
runtime.sigtramp()
        /usr/local/go/src/runtime/sys_linux_amd64.s:359 +0x46 fp=0xc000155170 sp=0xc000155120 pc=0x472826

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc00007afe8 sp=0xc00007afe0 pc=0x470be1

goroutine 1 [chan receive]:
runtime.gopark(0x1799780?, 0xc00063faa8?, 0x9f?, 0x23?, 0x7f4fa221ba68?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc00063fa28 sp=0xc00063fa08 pc=0x43f4b6
runtime.chanrecv(0xc00003ea10, 0xc00063fb27, 0x1)
        /usr/local/go/src/runtime/chan.go:583 +0x49b fp=0xc00063fab8 sp=0xc00063fa28 pc=0x40b91b
runtime.chanrecv1(0xc00001e2a0?, 0x1?)
        /usr/local/go/src/runtime/chan.go:442 +0x18 fp=0xc00063fae0 sp=0xc00063fab8 pc=0x40b418
testing.(*T).Run(0xc000582d00, {0xeb708e?, 0x520f85?}, 0xf10e18)
        /usr/local/go/src/testing/testing.go:1494 +0x37a fp=0xc00063fb80 sp=0xc00063fae0 pc=0x52239a
testing.runTests.func1(0xc000582d00?)
        /usr/local/go/src/testing/testing.go:1846 +0x6e fp=0xc00063fbd0 sp=0xc00063fb80 pc=0x5242ee
testing.tRunner(0xc000582d00, 0xc00063fcd8)
        /usr/local/go/src/testing/testing.go:1446 +0x10b fp=0xc00063fc20 sp=0xc00063fbd0 pc=0x5215ab
testing.runTests(0xc00013ba40?, {0x16ed630, 0x1, 0x1}, {0x7f4fa221ba68?, 0x40?, 0x1766660?})
        /usr/local/go/src/testing/testing.go:1844 +0x456 fp=0xc00063fd08 sp=0xc00063fc20 pc=0x524196
testing.(*M).Run(0xc00013ba40)
        /usr/local/go/src/testing/testing.go:1726 +0x5d9 fp=0xc00063ff00 sp=0xc00063fd08 pc=0x522c79
main.main()
        _testmain.go:47 +0x1aa fp=0xc00063ff80 sp=0xc00063ff00 pc=0xcb6d6a
runtime.main()
        /usr/local/go/src/runtime/proc.go:250 +0x212 fp=0xc00063ffe0 sp=0xc00063ff80 pc=0x43f0f2
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc00063ffe8 sp=0xc00063ffe0 pc=0x470be1

goroutine 2 [force gc (idle)]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000068fb0 sp=0xc000068f90 pc=0x43f4b6
runtime.goparkunlock(...)
        /usr/local/go/src/runtime/proc.go:369
runtime.forcegchelper()
        /usr/local/go/src/runtime/proc.go:302 +0xad fp=0xc000068fe0 sp=0xc000068fb0 pc=0x43f34d
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000068fe8 sp=0xc000068fe0 pc=0x470be1
created by runtime.init.6
        /usr/local/go/src/runtime/proc.go:290 +0x25

goroutine 3 [GC sweep wait]:
runtime.gopark(0x1?, 0x0?, 0x0?, 0x0?, 0x0?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000069790 sp=0xc000069770 pc=0x43f4b6
runtime.goparkunlock(...)
        /usr/local/go/src/runtime/proc.go:369
runtime.bgsweep(0x0?)
        /usr/local/go/src/runtime/mgcsweep.go:297 +0xd7 fp=0xc0000697c8 sp=0xc000069790 pc=0x429dd7
runtime.gcenable.func1()
        /usr/local/go/src/runtime/mgc.go:178 +0x26 fp=0xc0000697e0 sp=0xc0000697c8 pc=0x41ea46
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc0000697e8 sp=0xc0000697e0 pc=0x470be1
created by runtime.gcenable
        /usr/local/go/src/runtime/mgc.go:178 +0x6b

goroutine 4 [GC scavenge wait]:
runtime.gopark(0xc00003e230?, 0x1158b60?, 0x0?, 0x0?, 0x0?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000069f70 sp=0xc000069f50 pc=0x43f4b6
runtime.goparkunlock(...)
        /usr/local/go/src/runtime/proc.go:369
runtime.(*scavengerState).park(0x17666e0)
        /usr/local/go/src/runtime/mgcscavenge.go:389 +0x53 fp=0xc000069fa0 sp=0xc000069f70 pc=0x427e33
runtime.bgscavenge(0x0?)
        /usr/local/go/src/runtime/mgcscavenge.go:622 +0x65 fp=0xc000069fc8 sp=0xc000069fa0 pc=0x428425
runtime.gcenable.func2()
        /usr/local/go/src/runtime/mgc.go:179 +0x26 fp=0xc000069fe0 sp=0xc000069fc8 pc=0x41e9e6
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000069fe8 sp=0xc000069fe0 pc=0x470be1
created by runtime.gcenable
        /usr/local/go/src/runtime/mgc.go:179 +0xaa

goroutine 18 [finalizer wait]:
runtime.gopark(0x1767020?, 0xc0001024e0?, 0x0?, 0x0?, 0xc000068770?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000068628 sp=0xc000068608 pc=0x43f4b6
runtime.goparkunlock(...)
        /usr/local/go/src/runtime/proc.go:369
runtime.runfinq()
        /usr/local/go/src/runtime/mfinal.go:180 +0x10f fp=0xc0000687e0 sp=0xc000068628 pc=0x41db4f
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc0000687e8 sp=0xc0000687e0 pc=0x470be1
created by runtime.createfing
        /usr/local/go/src/runtime/mfinal.go:157 +0x45

goroutine 19 [select]:
runtime.gopark(0xc000064788?, 0x3?, 0xe0?, 0x67?, 0xc000064772?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc0000645f8 sp=0xc0000645d8 pc=0x43f4b6
runtime.selectgo(0xc000064788, 0xc00006476c, 0xc00015eb00?, 0x0, 0x0?, 0x1)
        /usr/local/go/src/runtime/select.go:328 +0x7bc fp=0xc000064738 sp=0xc0000645f8 pc=0x44f33c
go.opencensus.io/stats/view.(*worker).start(0xc00015eb00)
        /home/dev/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:276 +0xad fp=0xc0000647c8 sp=0xc000064738 pc=0x9d564d
go.opencensus.io/stats/view.init.0.func1()
        /home/dev/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:34 +0x26 fp=0xc0000647e0 sp=0xc0000647c8 pc=0x9d48c6
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc0000647e8 sp=0xc0000647e0 pc=0x470be1
created by go.opencensus.io/stats/view.init.0
        /home/dev/go/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:34 +0x8d

goroutine 20 [GC worker (idle)]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000064f50 sp=0xc000064f30 pc=0x43f4b6
runtime.gcBgMarkWorker()
        /usr/local/go/src/runtime/mgc.go:1235 +0xf1 fp=0xc000064fe0 sp=0xc000064f50 pc=0x420b91
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000064fe8 sp=0xc000064fe0 pc=0x470be1
created by runtime.gcBgMarkStartWorkers
        /usr/local/go/src/runtime/mgc.go:1159 +0x25

goroutine 5 [GC worker (idle)]:
runtime.gopark(0x87b164f61596?, 0x0?, 0x0?, 0x0?, 0x0?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc00006a750 sp=0xc00006a730 pc=0x43f4b6
runtime.gcBgMarkWorker()
        /usr/local/go/src/runtime/mgc.go:1235 +0xf1 fp=0xc00006a7e0 sp=0xc00006a750 pc=0x420b91
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc00006a7e8 sp=0xc00006a7e0 pc=0x470be1
created by runtime.gcBgMarkStartWorkers
        /usr/local/go/src/runtime/mgc.go:1159 +0x25

goroutine 34 [GC worker (idle)]:
runtime.gopark(0x87b164f614dc?, 0x0?, 0x0?, 0x0?, 0x0?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000588750 sp=0xc000588730 pc=0x43f4b6
runtime.gcBgMarkWorker()
        /usr/local/go/src/runtime/mgc.go:1235 +0xf1 fp=0xc0005887e0 sp=0xc000588750 pc=0x420b91
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc0005887e8 sp=0xc0005887e0 pc=0x470be1
created by runtime.gcBgMarkStartWorkers
        /usr/local/go/src/runtime/mgc.go:1159 +0x25

goroutine 35 [GC worker (idle)]:
runtime.gopark(0x87b164f61b65?, 0x0?, 0x0?, 0x0?, 0x0?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000588f50 sp=0xc000588f30 pc=0x43f4b6
runtime.gcBgMarkWorker()
        /usr/local/go/src/runtime/mgc.go:1235 +0xf1 fp=0xc000588fe0 sp=0xc000588f50 pc=0x420b91
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000588fe8 sp=0xc000588fe0 pc=0x470be1
created by runtime.gcBgMarkStartWorkers
        /usr/local/go/src/runtime/mgc.go:1159 +0x25

goroutine 36 [running]:
        goroutine running on other thread; stack unavailable
created by testing.(*T).Run
        /usr/local/go/src/testing/testing.go:1493 +0x35f

goroutine 37 [IO wait]:
runtime.gopark(0x200000003?, 0xc0005831e0?, 0x0?, 0x60?, 0xc0000d9c68?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc0000d9bf8 sp=0xc0000d9bd8 pc=0x43f4b6
runtime.netpollblock(0xc0000d9c48?, 0xd9cc0?, 0xc0?)
        /usr/local/go/src/runtime/netpoll.go:526 +0xf7 fp=0xc0000d9c30 sp=0xc0000d9bf8 pc=0x437d57
internal/poll.runtime_pollWait(0x7f4f793efef0, 0x72)
        /usr/local/go/src/runtime/netpoll.go:305 +0x89 fp=0xc0000d9c50 sp=0xc0000d9c30 pc=0x46aec9
internal/poll.(*pollDesc).wait(0xc00015e000?, 0x6?, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32 fp=0xc0000d9c78 sp=0xc0000d9c50 pc=0x4a8232
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc00015e000)
        /usr/local/go/src/internal/poll/fd_unix.go:614 +0x234 fp=0xc0000d9d10 sp=0xc0000d9c78 pc=0x4ad4b4
net.(*netFD).accept(0xc00015e000)
        /usr/local/go/src/net/fd_unix.go:172 +0x35 fp=0xc0000d9dc8 sp=0xc0000d9d10 pc=0x5ecd95
net.(*TCPListener).accept(0xc000012048)
        /usr/local/go/src/net/tcpsock_posix.go:142 +0x28 fp=0xc0000d9df8 sp=0xc0000d9dc8 pc=0x605ce8
net.(*TCPListener).Accept(0xc000012048)
        /usr/local/go/src/net/tcpsock.go:288 +0x3d fp=0xc0000d9e28 sp=0xc0000d9df8 pc=0x604b7d
google.golang.org/grpc.(*Server).Serve(0xc0000cc000, {0x11649b0?, 0xc000012048})
        /home/dev/go/pkg/mod/google.golang.org/grpc@v1.46.2/server.go:780 +0x475 fp=0xc0000d9f70 sp=0xc0000d9e28 pc=0x938cb5
github.com/pact-foundation/pact-go/v2/examples/grpc.startProvider()
        /home/dev/ws/pact-go/examples/grpc/grpc_provider_test.go:54 +0x145 fp=0xc0000d9fe0 sp=0xc0000d9f70 pc=0xcb69e5
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc0000d9fe8 sp=0xc0000d9fe0 pc=0x470be1
created by github.com/pact-foundation/pact-go/v2/examples/grpc.TestGrpcProvider
        /home/dev/ws/pact-go/examples/grpc/grpc_provider_test.go:24 +0x3d

goroutine 38 [IO wait]:
runtime.gopark(0x200000003?, 0xc000583380?, 0x0?, 0xaa?, 0xc000076c50?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000076be0 sp=0xc000076bc0 pc=0x43f4b6
runtime.netpollblock(0xc000076c30?, 0x4?, 0x0?)
        /usr/local/go/src/runtime/netpoll.go:526 +0xf7 fp=0xc000076c18 sp=0xc000076be0 pc=0x437d57
internal/poll.runtime_pollWait(0x7f4f793effe0, 0x72)
        /usr/local/go/src/runtime/netpoll.go:305 +0x89 fp=0xc000076c38 sp=0xc000076c18 pc=0x46aec9
internal/poll.(*pollDesc).wait(0xc0000a8d80?, 0x6?, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32 fp=0xc000076c60 sp=0xc000076c38 pc=0x4a8232
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0000a8d80)
        /usr/local/go/src/internal/poll/fd_unix.go:614 +0x234 fp=0xc000076cf8 sp=0xc000076c60 pc=0x4ad4b4
net.(*netFD).accept(0xc0000a8d80)
        /usr/local/go/src/net/fd_unix.go:172 +0x35 fp=0xc000076db0 sp=0xc000076cf8 pc=0x5ecd95
net.(*TCPListener).accept(0xc00012c4e0)
        /usr/local/go/src/net/tcpsock_posix.go:142 +0x28 fp=0xc000076de0 sp=0xc000076db0 pc=0x605ce8
net.(*TCPListener).Accept(0xc00012c4e0)
        /usr/local/go/src/net/tcpsock.go:288 +0x3d fp=0xc000076e10 sp=0xc000076de0 pc=0x604b7d
net/http.(*onceCloseListener).Accept(0xc00013bb80?)
        <autogenerated>:1 +0x2a fp=0xc000076e28 sp=0xc000076e10 pc=0x872daa
net/http.(*Server).Serve(0xc0001d00f0, {0x11649b0, 0xc00012c4e0})
        /usr/local/go/src/net/http/server.go:3070 +0x385 fp=0xc000076f58 sp=0xc000076e28 pc=0x84e1e5
net/http.(*Server).ListenAndServe(0xc0001d00f0)
        /usr/local/go/src/net/http/server.go:2999 +0x7d fp=0xc000076f88 sp=0xc000076f58 pc=0x84de1d
net/http.ListenAndServe({0xc00003a2c0, 0x6}, {0x11607a0?, 0xc00001e420})
        /usr/local/go/src/net/http/server.go:3255 +0x96 fp=0xc000076fb0 sp=0xc000076f88 pc=0x84f1b6
github.com/pact-foundation/pact-go/v2/proxy.HTTPReverseProxy.func1()
        /home/dev/ws/pact-go/proxy/http.go:100 +0x32 fp=0xc000076fe0 sp=0xc000076fb0 pc=0xc7afd2
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000076fe8 sp=0xc000076fe0 pc=0x470be1
created by github.com/pact-foundation/pact-go/v2/proxy.HTTPReverseProxy
        /home/dev/ws/pact-go/proxy/http.go:100 +0x456

goroutine 39 [IO wait]:
runtime.gopark(0x0?, 0xb?, 0x0?, 0x0?, 0x9?)
        /usr/local/go/src/runtime/proc.go:363 +0xd6 fp=0xc000077540 sp=0xc000077520 pc=0x43f4b6
runtime.netpollblock(0x4850c5?, 0x3?, 0x0?)
        /usr/local/go/src/runtime/netpoll.go:526 +0xf7 fp=0xc000077578 sp=0xc000077540 pc=0x437d57
internal/poll.runtime_pollWait(0x7f4f793efd10, 0x72)
        /usr/local/go/src/runtime/netpoll.go:305 +0x89 fp=0xc000077598 sp=0xc000077578 pc=0x46aec9
internal/poll.(*pollDesc).wait(0xc0000a8e00?, 0xc0005ff000?, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32 fp=0xc0000775c0 sp=0xc000077598 pc=0x4a8232
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0000a8e00, {0xc0005ff000, 0x1000, 0x1000})
        /usr/local/go/src/internal/poll/fd_unix.go:167 +0x25a fp=0xc000077640 sp=0xc0000775c0 pc=0x4a959a
net.(*netFD).Read(0xc0000a8e00, {0xc0005ff000?, 0xc0000776c0?, 0x842de5?})
        /usr/local/go/src/net/fd_posix.go:55 +0x29 fp=0xc000077688 sp=0xc000077640 pc=0x5eac89
net.(*conn).Read(0xc000120260, {0xc0005ff000?, 0x203000?, 0x203000?})
        /usr/local/go/src/net/net.go:183 +0x45 fp=0xc0000776d0 sp=0xc000077688 pc=0x5fcb85
net/http.(*connReader).Read(0xc00001e690, {0xc0005ff000, 0x1000, 0x1000})
        /usr/local/go/src/net/http/server.go:786 +0x171 fp=0xc000077720 sp=0xc0000776d0 pc=0x8435d1
bufio.(*Reader).fill(0xc000090600)
        /usr/local/go/src/bufio/bufio.go:106 +0xff fp=0xc000077758 sp=0xc000077720 pc=0x526a5f
bufio.(*Reader).ReadSlice(0xc000090600, 0x0?)
        /usr/local/go/src/bufio/bufio.go:372 +0x2f fp=0xc0000777a8 sp=0xc000077758 pc=0x52764f
bufio.(*Reader).ReadLine(0xc000090600)
        /usr/local/go/src/bufio/bufio.go:401 +0x27 fp=0xc0000777f8 sp=0xc0000777a8 pc=0x5278a7
net/textproto.(*Reader).readLineSlice(0xc00001e6c0)
        /usr/local/go/src/net/textproto/reader.go:56 +0x99 fp=0xc0000778e8 sp=0xc0000777f8 pc=0x7e1b19
net/textproto.(*Reader).ReadLine(...)
        /usr/local/go/src/net/textproto/reader.go:37
net/http.readRequest(0xc000120260?)
        /usr/local/go/src/net/http/request.go:1036 +0x79 fp=0xc0000779f0 sp=0xc0000778e8 pc=0x83e959
net/http.(*conn).readRequest(0xc00013bb80, {0x1165628, 0xc0003e3540})
        /usr/local/go/src/net/http/server.go:994 +0x24a fp=0xc000077b78 sp=0xc0000779f0 pc=0x844b6a
net/http.(*conn).serve(0xc00013bb80, {0x11656d0, 0xc00001e5a0})
        /usr/local/go/src/net/http/server.go:1916 +0x345 fp=0xc000077fb8 sp=0xc000077b78 pc=0x8490a5
net/http.(*Server).Serve.func3()
        /usr/local/go/src/net/http/server.go:3102 +0x2e fp=0xc000077fe0 sp=0xc000077fb8 pc=0x84e5ce
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000077fe8 sp=0xc000077fe0 pc=0x470be1
created by net/http.(*Server).Serve
        /usr/local/go/src/net/http/server.go:3102 +0x4db
FAIL    github.com/pact-foundation/pact-go/v2/examples/grpc     0.308s
FAIL
@mefellows
Copy link
Member

OK, so I’ve been seeing them indeterminately also but have never been able to put my finger on why.

I’ve shared with my colleague who has more experience with low level stuff like this, and might have some thoughts on it also.

For context, i’ve not seen this problem in other languages (e.g. JS, which I also maintain). This seems to suggest why: https://docs.studygolang.com/pkg/os/signal/#hdr-Go_programs_that_use_cgo_or_SWIG

I can’t see how we can configure the SA_ONSTACK flag in the rust core (the core engine we ship to all languages), which would be great to be able to test to see if it does resolve.

@mefellows mefellows added bug Indicates an unexpected problem or unintended behavior smartbear-supported labels Mar 7, 2023
@github-actions
Copy link

github-actions bot commented Mar 7, 2023

👋 Hi! The 'smartbear-supported' label has just been added to this issue, which will create an internal tracking ticket in PactFlow's Jira (PACT-813). We will use this to prioritise and assign a team member to this task. All activity will be public on this ticket. For now, sit tight and we'll update this ticket once we have more information on the next steps.

See our documentation for more information.

@jasonltaylor
Copy link
Author

Upgrading glibc to pull in a fix for go interoperability makes it go away in my debian container:
bminor/glibc@76b0c59

The native rust code seems to set the flag. Could use something like eBPF to grab a stack trace when pthread_create is called to further narrow down the culprit.

@mefellows
Copy link
Member

Some further debugging notes.

It only seems to affect plugins, and only during verification. If I run the make fake_pact suite with the grpc/matt plugin verification tests disabled, I don't seem to be able to reproduce the issue.

I was hoping a fix (e.g. pact-foundation/pact-reference@0af0035 and those just after) might have helped here, but it seems like the issue is separate.

2023-04-06T00:59:48.567996Z  INFO ThreadId(11) pact_verifier: Running setup provider state change handler 'the world exists' for 'Matt message'
2023-04-06T00:59:48.568030Z  WARN ThreadId(11) pact_verifier::callback_executors: State Change ignored as there is no state change URL provided for interaction
2023-04-06T00:59:48.568041Z  INFO ThreadId(11) pact_verifier: Running provider verification for 'Matt message'
2023/04/06 10:59:48 TCP connection established with: [::1]:61012
2023/04/06 10:59:48 Handling TCP connection
2023/04/06 10:59:48 Data received from connection MATThellotcpMATT
2023/04/06 10:59:48 TCP Server received request MATThellotcpMATT on connection &{{0xc00013e380}}
2023/04/06 10:59:48 TCP Server received valid request, responding
2023-04-06T00:59:48.574940Z  WARN ThreadId(11) pact_matching::metrics:

Please note:
We are tracking events anonymously to gather important usage statistics like Pact version and operating system. To disable tracking, set the 'PACT_DO_NOT_TRACK' environment variable to 'true'.



Verifying a pact between MattConsumer and MattProvider

  A request to do a matt (0s loading, 305ms verification)
    returns a response which
      has status code 200 (OK)
      includes headers
        "content-type" with value "application/matt" (OK)
      has a matching body (OK)


Verifying a pact between matttcpconsumer and matttcpprovider

  Matt message (0s loading, 282ms verification)
     Given the world exists


=== RUN   TestPluginProvider/Provider_pact_verification
signal 20 received but handler not on signal stack
fatal error: non-Go code set up signal handler without SA_ONSTACK flag

runtime stack:
runtime: unexpected return pc for runtime.sigtramp called from 0x89167a2
stack: frame={sp:0xc0001c9cc0, fp:0xc0001c9d10} stack=[0xc0001c1bb8,0xc0001c9fb8)
0x000000c0001c9bc0:  0x000000c0001c9bf8  0x000000c0001c9c20
0x000000c0001c9bd0:  0x0000000000000000  0x0000000000000000
0x000000c0001c9be0:  0x0000000000000000  0x0000000000000000
0x000000c0001c9bf0:  0x0000000000000000  0x000000c000004000
0x000000c0001c9c00:  0x0000000000008000  0x0000000000000000
0x000000c0001c9c10:  0x000000c0001c9c88  0x000000000404ef3b <runtime.sigtrampgo+0x000000000000013b>

or in the case of the grpc tests:

2023-04-06T01:09:25.136029Z DEBUG ThreadId(01) h2::client: client connection bound
2023-04-06T01:09:25.136035Z DEBUG ThreadId(01) h2::codec::framed_write: send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2023-04-06T01:09:25.136106Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2023-04-06T01:09:25.136128Z DEBUG ThreadId(01) hyper::client::pool: pooling idle connection for ("https", www.google-analytics.com)
2023-04-06T01:09:25.136200Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2023-04-06T01:09:25.136220Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
2023-04-06T01:09:25.145716Z DEBUG tokio-runtime-worker Connection{peer=Client}: rustls::client::tls13: Ticket saved
2023-04-06T01:09:25.145730Z DEBUG tokio-runtime-worker Connection{peer=Client}: rustls::client::tls13: Ticket saved
2023-04-06T01:09:25.145742Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_read: received frame=Settings { flags: (0x0), max_concurrent_streams: 100, initial_window_size: 1048576, max_header_list_size: 65536 }
2023-04-06T01:09:25.145748Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) }
2023-04-06T01:09:25.145754Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
2023-04-06T01:09:25.151233Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK) }
2023-04-06T01:09:25.151243Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2023-04-06T01:09:25.239134Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2023-04-06T01:09:25.239168Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
2023-04-06T01:09:25.239174Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
2023-04-06T01:09:25.239346Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_write: send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
2023-04-06T01:09:25.239357Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::proto::connection: Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
2023-04-06T01:09:25.239424Z DEBUG tokio-runtime-worker Connection{peer=Client}: rustls::conn: Sending warning alert CloseNotify

Verifying a pact between grpcconsumer and grpcprovider

  Route guide - GetFeature (1ms loading, 314ms verification)
     Given feature 'Big Tree' exists

  Given a RouteGuide/GetFeature request
      with an input .routeguide.Point message
      will return an output .routeguide.Feature message (OK)
        with metadata


2023-04-06T01:09:25.239508Z DEBUG ThreadId(01) pact_plugin_driver::plugin_manager: Shutting down all plugins
2023-04-06T01:09:25.239516Z DEBUG ThreadId(01) pact_plugin_driver::plugin_manager: Shutting down plugin PactPlugin { manifest: PactPluginManifest { plugin_dir: "/Users/matthew.fellows/.pact/plugins/protobuf-0.3.0", plugin_interface_version: 1, name: "protobuf", version: "0.3.0", executable_type: "exec", minimum_required_version: None, entry_point: "pact-protobuf-plugin", entry_points: {}, args: None, dependencies: None, plugin_config: {"hostToBindTo": String("127.0.0.1"), "downloadUrl": String("https://github.com/protocolbuffers/protobuf/releases/download"), "protocVersion": String("3.19.1")} }, child: ChildPluginProcess { child_pid: 38101, plugin_info: RunningPluginInfo { port: 61581, server_key: "cdfd0a3a-3791-45f5-957d-3be30e881135" } }, access_count: 1, channel: Some(Channel), client: Mutex { data: Some(PactPluginClient { inner: Grpc { inner: InterceptedService { inner: Channel, f: pact_plugin_driver::plugin_models::PactPluginInterceptor }, origin: /, compression_encoding: None, accept_compression_encodings: EnabledCompressionEncodings, max_decoding_message_size: None, max_encoding_message_size: None } }) } }
2023-04-06T01:09:25.251031Z DEBUG ThreadId(01) pact_plugin_driver::catalogue_manager: Removed all catalogue entries for plugin protobuf
2023-04-06T01:09:25.251148Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_write: send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
2023-04-06T01:09:25.251202Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::proto::connection: Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
2023-04-06T01:09:25.251507Z DEBUG ThreadId(01) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_shutdown FFI function invoked
=== RUN   TestGrpcProvider/Provider_pact_verification
--- PASS: TestGrpcProvider (1.02s)
    --- PASS: TestGrpcProvider/Provider_pact_verification (0.00s)
signal 20 received but handler not on signal stack
fatal error: non-Go code set up signal handler without SA_ONSTACK flag

runtime stack:
runtime: unexpected return pc for runtime.sigtramp called from 0x893f7a2
stack: frame={sp:0xc00073ec50, fp:0xc00073eca0} stack=[0xc000736b48,0xc00073ef48)
0x000000c00073eb50:  0x000000c00073eb88  0x000000c00073ebb0
0x000000c00073eb60:  0x000000000417aa65 <regexp/syntax.(*compiler).compile+0x0000000000001165>  0x000000c00073f810
0x000000c00073eb70:  0x000000c0003216c0  0x0000000000000001
0x000000c00073eb80:  0x0000000000000000  0x000000c000004000
0x000000c00073eb90:  0x0000000000008000  0x0000000000000000
0x000000c00073eba0:  0x000000c00073ec18  0x000000000404ec7b <runtime.sigtrampgo+0x000000000000013b>
0x000000c00073ebb0:  0x000000c000000014  0x0000000005339a00

NOTE: I've tried not calling pactffi_verifier_shutdown but I can still reproduce a crash.

@mefellows
Copy link
Member

mefellows commented Apr 6, 2023

Further update - I attempted to trace this using dtrace/dtruss, however you can't instrument rosetta runs.

I then installed go in a native Apple environment and ran into permission issues, but I thought before I boot into recovery and see if I can work around that, I would see if the problem is replicated - alas, running the examples on a loop I couldn't get it to repro in > 100 iterations.

So I think plausible some rosetta translation magic is part of this issue, or there is a separate issue with the x86_64 shared library.

It's interesting that both variants link the same libraries (presumably because Rosetta is just an emulation layer):

arm

➜  grpc git:(chore/upgrade-ffi-to-0.4.3) ✗ uname -m
arm64
➜  grpc git:(chore/upgrade-ffi-to-0.4.3) ✗ otool -L /usr/local/lib/libpact_ffi.dylib
/usr/local/lib/libpact_ffi.dylib:
	libpact_ffi.dylib (compatibility version 0.0.0, current version 0.0.0)
	/System/Library/Frameworks/IOKit.framework/Versions/A/IOKit (compatibility version 1.0.0, current version 275.0.0)
	/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation (compatibility version 150.0.0, current version 1953.255.0)
	/System/Library/Frameworks/Security.framework/Versions/A/Security (compatibility version 1.0.0, current version 60420.60.24)
	/usr/lib/libiconv.2.dylib (compatibility version 7.0.0, current version 7.0.0)
	/usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1319.0.0)
➜  grpc git:(chore/upgrade-ffi-to-0.4.3) ✗ file /usr/local/lib/libpact_ffi.dylib
/usr/local/lib/libpact_ffi.dylib: Mach-O 64-bit dynamically linked shared library arm64
➜  grpc git:(chore/upgrade-ffi-to-0.4.3) ✗

x86_64

➜  pact-go git:(chore/upgrade-ffi-to-0.4.3) ✗ uname -m
x86_64
➜  pact-go git:(chore/upgrade-ffi-to-0.4.3) ✗ otool -L /usr/local/lib/libpact_ffi.dylib
/usr/local/lib/libpact_ffi.dylib:
	libpact_ffi.dylib (compatibility version 0.0.0, current version 0.0.0)
	/System/Library/Frameworks/IOKit.framework/Versions/A/IOKit (compatibility version 1.0.0, current version 275.0.0)
	/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation (compatibility version 150.0.0, current version 1953.255.0)
	/System/Library/Frameworks/Security.framework/Versions/A/Security (compatibility version 1.0.0, current version 60420.60.24)
	/usr/lib/libiconv.2.dylib (compatibility version 7.0.0, current version 7.0.0)
	/usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1319.0.0)
➜  pact-go git:(chore/upgrade-ffi-to-0.4.3) ✗ file /usr/local/lib/libpact_ffi.dylib
/usr/local/lib/libpact_ffi.dylib: Mach-O 64-bit dynamically linked shared library x86_64
➜  pact-go git:(chore/upgrade-ffi-to-0.4.3) ✗

@matt-forster
Copy link

Just reporting that we are piloting Pact for our Go GRPC services and are running into the same error. Currently CI is executing on x86_64;

Operating System
  Distribution: Amazon Linux release 2023.4.20240401 (Amazon Linux)
  Architecture: x86_64
2024-04-04T21:00:16.052925Z  INFO ThreadId(08) pact_mock_server: Writing pact out to '...'
signal 17 received but handler not on signal stack
mp.gsignal stack [0xc000008000 0xc000010000], mp.g0 stack [0x7ffd0e482110 0x7ffd0ee81120], sp=0xc000148d28
fatal error: non-Go code set up signal handler without SA_ONSTACK flag
2024-04-04T21:00:16.056583Z ERROR ThreadId(08) pact_mock_server::server_manager: Failed to shutdown plugin mock server with ID 5144ffcd-98a4-40de-a2e7-a2bae8bfc235 - status: Unknown, message: "transport error", details: [], metadata: MetadataMap { headers: {} }
--- PASS: ... (2.56s)

runtime stack:
runtime.throw({0xebbd38?, 0x8?})
	/usr/local/go/src/runtime/panic.go:1077 +0x5c fp=0xc000148c80 sp=0xc000148c50 pc=0x43ecfc
runtime.sigNotOnStack(0x11, 0xc000148d00?, 0x15871e0)
	/usr/local/go/src/runtime/signal_unix.go:1045 +0x145 fp=0xc000148cb8 sp=0xc000148c80 pc=0x456445
runtime.adjustSignalStack(0x11, 0x15871e0, 0xc000148d50)
	/usr/local/go/src/runtime/signal_unix.go:592 +0x291 fp=0xc000148d28 sp=0xc000148cb8 pc=0x455291
runtime.sigtrampgo(0x11, 0xc000148f70, 0xc000148e40)
	/usr/local/go/src/runtime/signal_unix.go:480 +0xd5 fp=0xc000148da0 sp=0xc000148d28 pc=0x454d75
runtime.sigtramp()
	/usr/local/go/src/runtime/sys_linux_amd64.s:352 +0x46 fp=0xc000148df0 sp=0xc000148da0 pc=0x476ac6

...

It happens relatively often, so I am worried that if devs have to continually re-run jobs, it will impact our CI flows' reliability/DX.

@mefellows
Copy link
Member

Thanks Matt, sadly this has been a nasty one to try and chase down.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Indicates an unexpected problem or unintended behavior
Projects
None yet
Development

No branches or pull requests

3 participants