Hi all 👋 I'm having some issues getting the protobuf/gRPC plugin to work. I've been specifically getting these error messages when running a js consumer test:

ERROR ThreadId(01) pact_ffi::plugins: Failed to call out to plugin - Request to configure interaction failed: Failed to process protobuf: Failed to invoke protoc binary: exit code exit status: 1

ERROR ThreadId(01) pact_ffi::mock_server: Failed to start mock server - Mock server failed to start: Failed to start gRPC mock server: Pact file does not contain any Protobuf descriptors

I can imagine a number of things can be the cause of this (and I unfortunately can't post much more in the public channel), but I was wondering if there was a way to get more information on what specifically caused the protoc binary to exit? I set log levels to debug and trace but nothing really stood out to me. Thanks!

@Matt (pactflow.io / pact-js / pact-go) @Yousaf Nabi (pactflow.io)

You may need to clear our any pact files before a new run. There should be logs in the

~/.pact/plugins/protobuf-<version>/

folder

search the plugin logs for the word

protoc

there should be a line smth like

invoking protoc

or similar, it will print the exact command used to invoke

protoc

as well as its output. Also if you run your test with PACT_LOG_LEVEL=debug env variable it will print the same logs in the console, but they're quite verbose so it's usually easier to read them from the plugin's log file

thanks for the replies, for some reason nothing is getting written to the

plugin.log.2024-02-07

file (likely a separate issue), nor do I see the

protoc

binary getting invoked. Seems to fail before then thinking2 This is the debug output that gets written out along with that failed invocation:

2024-02-07T15:31:39.104258Z DEBUG ThreadId(01) pact_plugin_driver::content: Got response: ConfigureInteractionResponse { error: "Failed to process protobuf: Failed to invoke protoc binary: exit code exit status: 1", interaction: [], plugin_configuration: None }
2024-02-07T15:31:39.104275Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_write: send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
2024-02-07T15:31:39.104286Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::proto::connection: Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
2024-02-07T15:31:39.104369Z ERROR ThreadId(01) pact_ffi::plugins: Failed to call out to plugin - Request to configure interaction failed: Failed to process protobuf: Failed to invoke protoc binary: exit code exit status: 1
2024-02-07T15:31:39.104525Z DEBUG ThreadId(01) pact_ffi::mock_server: pact_ffi::mock_server::pactffi_create_mock_server_for_transport FFI function invoked

dumb question, but the same logs that get sent to the terminal output would be the same logs that would be sent to the that plugin log file, correct?

anything interesting in the logs before that? Also, do you have a single protobuf plugin under that folder or multiple versions? I had a case on my machine where I had multiple protobuf plugins installed and was looking for logs in a wrong one

Not anything in particular, if there was, I wasn't able to decipher them 😅

24-02-07T15:31:39.050631Z DEBUG ThreadId(01) pact_plugin_driver::plugin_models: IP6 connection failed, will try IP4 address - transport error
2024-02-07T15:31:39.050736Z DEBUG ThreadId(01) hyper::client::connect::http: connecting to 127.0.0.1:53033
2024-02-07T15:31:39.051238Z DEBUG ThreadId(01) hyper::client::connect::http: connected to 127.0.0.1:53033
2024-02-07T15:31:39.051316Z DEBUG ThreadId(01) h2::client: binding client connection
2024-02-07T15:31:39.051363Z DEBUG ThreadId(01) h2::client: client connection bound
2024-02-07T15:31:39.051380Z DEBUG ThreadId(01) h2::codec::framed_write: send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-02-07T15:31:39.051582Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2024-02-07T15:31:39.051718Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_read: received frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }
2024-02-07T15:31:39.051769Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) }
2024-02-07T15:31:39.051792Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
2024-02-07T15:31:39.051823Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK) }
2024-02-07T15:31:39.051837Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-02-07T15:31:39.051936Z DEBUG   ffi-setup_contents tower::buffer::worker: service.ready=true processing request
2024-02-07T15:31:39.052141Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2024-02-07T15:31:39.052224Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(1) }
2024-02-07T15:31:39.052246Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
2024-02-07T15:31:39.104147Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2024-02-07T15:31:39.104179Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
2024-02-07T15:31:39.104195Z DEBUG   ffi-setup_contents Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }

I do have multiple versions. But the others didn't have log files (this one was created, it was just empty). Also logs seem to show I'm using the correct one:

2024-02-07T15:31:38.536558Z DEBUG ThreadId(01) pact_plugin_driver::plugin_manager: Starting plugin using "/Users/<myuser>/.pact/plugins/protobuf-0.3.11/pact-protobuf-plugin"

yeah, I don't see anything suspicious here. Do you have

protoc

binary under ~/.pact/plugins/protobuf-version/bin ? I've had issues in the past where it was trying to download a version of protoc that's not compatible with arm macs. Alternatively it will try to invoke the protoc in your path

Can you check which version of protoc

protoc --version

you have running? it may be worth upgrading to the latest, assuming you installed with brew

brew upgrade protobuf

If you try and invoke the pact-protobuf-plugin executable directly, does that work

/Users/<myuser>/.pact/plugins/protobuf-0.3.11/pact-protobuf-plugin

dumb question, but the same logs that get sent to the terminal output would be the same logs that would be sent to the that plugin log file, correct?

Not a dumb question if you don’t know the answer! I had assumed that, but no, currently the plugins (executables in the plugin folder) , don’t send their logs to the plugin driver (in your pact client library), so the logs aren’t joined up. I tend to tail the logs inside the plugin folder, if I am diagnosing a test, so I can see the std output from the main test (which tells me its communicating with the plugin) and the plugins output from its own log file

I updated protoc by setting

"protocVersion":"25.1"

in the

pact-plugin.json

config

bin % pwd
/Users/<user>/.pact/plugins/protobuf-0.3.11/protoc/bin
bin % ./protoc --version
libprotoc 25.1

Plugin appears to work (I kept it running for a bit)

protobuf-0.3.11 % ./pact-protobuf-plugin
{"port":59464, "serverKey":"<maybe secret? redacted just in case>"}
2024-02-08T14:10:35.633062Z  INFO tokio-runtime-worker pact_protobuf_plugin: No activity for more than 600 seconds, sending shutdown signal
2024-02-08T14:10:35.633457Z  INFO                 main pact_protobuf_plugin: Received shutdown signal, shutting plugin down

I also have a m2 mac, not sure if that changes anything.

good idea on the caution, that server key is just a uuid which is sent to the pact plugin driver, so they can somewhat securely communicate without anything else listening in on your machine that looks promising on the plugin side (it executes) and we are on the same protoc version, I’m running a mac m1, shouldn’t make too much of a diff, I’ve got a machine with sip enabled, and one without. Do you see anything in your log files about being unable to find a protobuf descriptor, something like that, it usually means you’ve provided it a file but it can’t find it. You can share logs in a private PM if you prefer. I popped a JS example in the plugins repo, that you might like to try and run? https://github.com/pact-foundation/pact-plugins/tree/main/examples/gRPC/area_calculator/js

Thanks @Yousaf Nabi (pactflow.io) for the help, I was finally able to get past this issue with help internally. Turns out there was a secondary import in the provider .proto file. I didn't see the other proto file in the same directory but thought it might've been implicitly imported some other way so that I didn't need to add the extra

additionalIncludes

proto config (I don't have much context in the provider code base so I missed that). 😵‍💫 Adding the extra proto file via `additionalIncludes`fixed the issue! Thanks for helping walk through troubleshooting, I learned a couple things along the way. 🙇

I learned a couple things along the way. 🙇

nice!