Closed jasonltaylor closed 6 days ago
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.
👋 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.
Upgrading glibc to pull in a fix for go interoperability makes it go away in my debian container: https://github.com/bminor/glibc/commit/76b0c59e333da6fd4103e478b63522636d9d232b
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.
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. https://github.com/pact-foundation/pact-reference/commit/0af00359ddfa5e15176770e1c7ba74ec5964d415 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.
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) ✗
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.
Thanks Matt, sadly this has been a nasty one to try and chase down.
So the root cause comes from Tokio, see this linked issue
https://github.com/tokio-rs/tokio/issues/3520 - Signals do not add SA_ONSTACK which may cause linked Go applications to crash
We can switch to using std::process in rust, introduced in this commit for windows, which uses threads instead of tokio tasks, which
I've tested this out on my fork and it's resulting in stable ci runs
Huh - the saga continues!
This should now be sorted
https://github.com/pact-foundation/pact-go/releases/tag/v2.0.8
Thanks for bearing with us!
Thank you, thank you!
Software versions
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