FFI Message Interaction Methods Return False on MacOS Only

[adamrodger]

FFI Version: 0.3.5

I have a CI run where I've added code that ensures the FFI methods return true on those methods which return bool, whereas previously it didn't check the FFI response.

The CI for this change is failing, but only on MacOS. I've confirmed locally that it passes on Linux and Windows, plus the Linux CI is passing (Windows gets cancelled due to the MacOS failure) but I don't have a MacOS machine on which to confirm the problem. The CI run with trace logs is here though:

https://github.com/pact-foundation/pact-net/runs/7613866358

The test effectively does this sequence of calls via the FFI

pactffi_log_to_buffer

try
{
    pactffi_new_pact
    pactffi_new_message_interaction
    pactffi_message_expects_to_receive // this is the call which returns false
    pactffi_message_with_metadata
    pactffi_message_with_contents
    pactffi_message_reify
}
finally
{
    pactffi_fetch_log_buffer // and print the logs
}

If I remove pactffi_message_expects_to_receive then the next call to modify the interaction fails instead. It appears that any attempt to modify the interaction just returns false, but seemingly only on MacOS.

On Windows, the logs produce the following:

2022-08-01T14:56:03.320960Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact - ref = 1, keys = [1]
2022-08-01T14:56:03.321020Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact before - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "NativeDriverTests-Consumer-V3" }, provider: Provider { name: "NativeDriverTests-Producer" }, interactions: [], metadata: {"pactRust": Object({"ffi": String("0.3.5")})}, plugin_data: [] }, mock_server_started: false, specification_version: V3 } }
2022-08-01T14:56:03.321056Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact after - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "NativeDriverTests-Consumer-V3" }, provider: Provider { name: "NativeDriverTests-Producer" }, interactions: [], metadata: {"pactRust": Object({"ffi": String("0.3.5")})}, plugin_data: [] }, mock_server_started: false, specification_version: V3 } }
2022-08-01T14:56:03.322415Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact - ref = 1, keys = [1]
2022-08-01T14:56:03.322421Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact before - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "NativeDriverTests-Consumer-V3" }, provider: Provider { name: "NativeDriverTests-Producer" }, interactions: [], metadata: {"pactRust": Object({"ffi": String("0.3.5")})}, plugin_data: [] }, mock_server_started: false, specification_version: V3 } }
2022-08-01T14:56:03.322442Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact after - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "NativeDriverTests-Consumer-V3" }, provider: Provider { name: "NativeDriverTests-Producer" }, interactions: [AsynchronousMessage { id: None, key: None, description: "a message interaction", provider_states: [], contents: MessageContents { contents: Missing, metadata: {}, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pactRust": Object({"ffi": String("0.3.5")})}, plugin_data: [] }, mock_server_started: false, specification_version: V3 } }
2022-08-01T14:56:03.323495Z TRACE ThreadId(01) pact_ffi::mock_server::handles: pactffi_message_with_contents(message_handle: MessageHandle { interaction_ref: 65537 }, content_type: "application/json", body: 0xbe738fbb50, size: 0)
2022-08-01T14:56:03.323525Z TRACE ThreadId(01) pact_ffi::mock_server::bodies: process_json    
2022-08-01T14:56:03.323537Z TRACE ThreadId(01) pact_ffi::mock_server::bodies: >>> process_object(obj={"foo": Number(42)}, matching_rules=MatchingRuleCategory { name: BODY, rules: {} }, generators=Generators { categories: {} }, path=$, skip_matchers=false)    
2022-08-01T14:56:03.323550Z DEBUG ThreadId(01) pact_ffi::mock_server::bodies: Path = $    
2022-08-01T14:56:03.323552Z DEBUG ThreadId(01) pact_ffi::mock_server::bodies: Configuring a normal object    
2022-08-01T14:56:03.323731Z TRACE ThreadId(01) pact_ffi::mock_server::bodies: -> result = Object({"foo": Number(42)})    
2022-08-01T14:56:03.323913Z TRACE ThreadId(01) pact_ffi::mock_server::handles: pactffi_message_reify(message: AsynchronousMessage { id: None, key: None, description: "changed description", provider_states: [], contents: MessageContents { contents: Present(b"{\"foo\":42}", Some(ContentType { main_type: "application", sub_type: "json", attributes: {}, suffix: None }), None), metadata: {"foo": String("bar")}, matching_rules: MatchingRules { rules: {BODY: MatchingRuleCategory { name: BODY, rules: {} }} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }, spec_version: V3)
2022-08-01T14:56:03.324598Z TRACE ThreadId(01) pactffi_pact_handle_write_file{pact=PactHandle { pact_ref: 1 } directory=0xbe738fbb10 overwrite=true}: pact_ffi::mock_server::handles: with_pact - ref = 1, keys = [1]
2022-08-01T14:56:03.324610Z TRACE ThreadId(01) pactffi_pact_handle_write_file{pact=PactHandle { pact_ref: 1 } directory=0xbe738fbb10 overwrite=true}: pact_ffi::mock_server::handles: with_pact before - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "NativeDriverTests-Consumer-V3" }, provider: Provider { name: "NativeDriverTests-Producer" }, interactions: [AsynchronousMessage { id: None, key: None, description: "changed description", provider_states: [], contents: MessageContents { contents: Present(b"{\"foo\":42}", Some(ContentType { main_type: "application", sub_type: "json", attributes: {}, suffix: None }), None), metadata: {"foo": String("bar")}, matching_rules: MatchingRules { rules: {BODY: MatchingRuleCategory { name: BODY, rules: {} }} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pactRust": Object({"ffi": String("0.3.5")})}, plugin_data: [] }, mock_server_started: false, specification_version: V3 } }
2022-08-01T14:56:03.324976Z DEBUG ThreadId(01) pactffi_pact_handle_write_file{pact=PactHandle { pact_ref: 1 } directory=0xbe738fbb10 overwrite=true}: pact_models::pact: Writing new pact file to "C:\\dev\\github.com\\pact-net\\tests\\PactNet.Tests\\bin\\Debug\\net6.0\\NativeDriverTests-Consumer-V3-NativeDriverTests-Producer.json"
2022-08-01T14:56:03.325452Z TRACE ThreadId(01) pactffi_pact_handle_write_file{pact=PactHandle { pact_ref: 1 } directory=0xbe738fbb10 overwrite=true}: pact_models::file_utils: Attempt 0 of 3 to get an exclusive lock on '"C:\\dev\\github.com\\pact-net\\tests\\PactNet.Tests\\bin\\Debug\\net6.0\\NativeDriverTests-Consumer-V3-NativeDriverTests-Producer.json"'
2022-08-01T14:56:03.325491Z TRACE ThreadId(01) pactffi_pact_handle_write_file{pact=PactHandle { pact_ref: 1 } directory=0xbe738fbb10 overwrite=true}: pact_models::file_utils: Got exclusive file lock
2022-08-01T14:56:03.325585Z TRACE ThreadId(01) pactffi_pact_handle_write_file{pact=PactHandle { pact_ref: 1 } directory=0xbe738fbb10 overwrite=true}: pact_models::file_utils: Releasing exclusive file lock
2022-08-01T14:56:03.325780Z TRACE ThreadId(01) pactffi_pact_handle_write_file{pact=PactHandle { pact_ref: 1 } directory=0xbe738fbb10 overwrite=true}: pact_ffi::mock_server::handles: with_pact after - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "NativeDriverTests-Consumer-V3" }, provider: Provider { name: "NativeDriverTests-Producer" }, interactions: [AsynchronousMessage { id: None, key: None, description: "changed description", provider_states: [], contents: MessageContents { contents: Present(b"{\"foo\":42}", Some(ContentType { main_type: "application", sub_type: "json", attributes: {}, suffix: None }), None), metadata: {"foo": String("bar")}, matching_rules: MatchingRules { rules: {BODY: MatchingRuleCategory { name: BODY, rules: {} }} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pactRust": Object({"ffi": String("0.3.5")})}, plugin_data: [] }, mock_server_started: false, specification_version: V3 } }
2022-08-01T14:56:03.325796Z TRACE ThreadId(01) pactffi_pact_handle_write_file{pact=PactHandle { pact_ref: 1 } directory=0xbe738fbb10 overwrite=true}: pact_ffi::mock_server::handles: FFI function invoked output=0

but on the MacOS logs output, it stops before it gets to the line with pactffi_message_with_contents. There doesn't appear to be logging for pactffi_message_expects_to_receive or pactffi_message_with_metadata, and those are the calls which fail so it doesn't progress past that point to pactffi_message_with_contents

[adamrodger]

Confirmed that if I take the assertion for true out then the test passes, and the pact file is written correctly. So the FFI calls do work correctly, it's just that they return false on MacOS, and only on the message variety of calls.

On the request/response interaction calls they return true (as verified in other tests) and on both Windows and Linux the message interaction calls return true, just not on MacOS.

[adamrodger]

I've had to just disable the FFI return code checking on MacOS when using 0.3.5. That means any actual FFI failures won't be detected, which could cause hard-to-diagnose issues when everything looked like it worked but actually didn't.

[rholshausen]

There was an race condition I fixed with the Pact handles (852076025500), but I can't see how that would only trigger on the OSX agents. In my case, it only happened on my desktop because CI runs much slower.

I'll create a similar test to see if I can replicate it.

[rholshausen]

Oh, it might be that pactffi_new_message_interaction returns a InteractionHandle, while pactffi_message_expects_to_receive takes the older MessageHandle. I get an error in Rust, but in C those would just be type aliases and would look the same.

Actually, pactffi_message_expects_to_receive does not return a value (it is a void function), so maybe that is why it is different between OSX and Linux/Windows. pactffi_upon_receiving takes an InteractionHandle and returns a boolean result.

[TimothyJones]

How did you compile this? I don't know a way to assign or cast the value of a function that returns void.

[TimothyJones]

Anyway, the value of void expressions are explicitly defined as undefined. In J.2 of the public draft of the current C standard:

The behavior is undefined in the following circumstances: [...] An attempt is made to use the value of a void expression, or an implicit or explicit conversion (except to void) is applied to a void expression (6.3.2.2).

And if you're using the assert macro, it's also undefined if:

The argument to the assert macro does not have a scalar type (7.2).

[adamrodger]

So looking at the PactNet P/Invoke definitions, it looks like when the messaging FFI methods were added, they were incorrectly added with bool return types instead of void. I assume they were copied and pasted from existing ones that return bool, but I dunno because I didn't do that bit.

I assume they've not changed return type anyway, so they've probably always been wrong. As you say, it's undefined what should happen in that situation so perhaps Windows/Linux return true and MacOS returns false.

[adamrodger]

I've corrected the PactNet P/Invoke imports so that those messaging methods now return void instead of bool, and that appears to have fixed the issue on MacOS. Sorry for that! I'd never noticed that was originally written with the wrong return types.