Message provider verification error: "Caught panic with error: failed printing to stdout"

qmg-rbass commented 6 months ago

Software versions

OS: Mac OSX 14.4.1
Consumer Pact library: Pact JS 12.3.0
Provider Pact library: Pact JS 12.3.0
Node Version: v16.20.2

Issue Checklist

Please confirm the following:

[x] I have upgraded to the latest
[x] I have the read the FAQs in the Readme
[x] I have triple checked, that there are no unhandled promises in my code and have read the section on intermittent test failures
[x] I have set my log level to debug and attached a log file showing the complete request/response cycle
[x] For bonus points and virtual high fives, I have created a reproduceable git repository (see below) to illustrate the problem

Expected behaviour

Pact verification is successful.

Actual behaviour

Pact verification is unsuccessful with error:

thread '<unnamed>' panicked at library/std/src/io/stdio.rs:1021:9:
failed printing to stdout: Resource temporarily unavailable (os error 35)
stack backtrace:
   0:        0x11643b088 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hb478ebbfb46e27ce
   1:        0x11645d588 - core::fmt::write::he4d5fa2daff1f531
   2:        0x116437ccc - std::io::Write::write_fmt::hc5a47a68eba63d9f
   3:        0x11643aebc - std::sys_common::backtrace::print::h79bd952cc5812e7a
   4:        0x11643c5e0 - std::panicking::default_hook::{{closure}}::h82301f6222887737
   5:        0x11643c328 - std::panicking::default_hook::h1e49abbb3f1d7dbf
   6:        0x11643ca28 - std::panicking::rust_panic_with_hook::h1e70c5d905e30e9d
   7:        0x11643c91c - std::panicking::begin_panic_handler::{{closure}}::h399e32952efd26a4
   8:        0x11643b50c - std::sys_common::backtrace::__rust_end_short_backtrace::h2ab87f841a2323e7
   9:        0x11643c6a4 - _rust_begin_unwind
  10:        0x1164bc61c - core::panicking::panic_fmt::h33e40d2a93cab78f
  11:        0x116436ce0 - std::io::stdio::_print::h2c869062e4130656
  12:        0x1157da3cc - pact_verifier::verify_provider_async::{{closure}}::{{closure}}::hc20d3590fb2780e7
  13:        0x115812b4c - <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll::h6192e06b5541dff5
  14:        0x1158852f8 - <tokio::task::task_local::TaskLocalFuture<T,F> as core::future::future::Future>::poll::h15b2b04a4836487e
  15:        0x11588c490 - pact_verifier::verify_provider_async::{{closure}}::hdfb4a205a57c5fce
  16:        0x1158b0df8 - tokio::runtime::park::CachedParkThread::block_on::hbe826fd4bc423331
  17:        0x11595eea4 - tokio::runtime::context::runtime::enter_runtime::hcc547b869e4394a4
  18:        0x1159dc5e8 - tokio::runtime::runtime::Runtime::block_on::h125b509c5d36c1d2
  19:        0x115967a48 - pact_ffi::verifier::handle::VerifierHandle::execute::hf5436875cfce2f47
  20:        0x115a01978 - pact_ffi::error::panic::catch_panic::h1a10465fee822ae2
  21:        0x11598758c - _pactffi_verifier_execute
  22:        0x104faa964 - __ZN18VerificationWorker7ExecuteEv
  23:        0x104faa6a4 - __ZN4Napi11AsyncWorker9OnExecuteENS_3EnvE
  24:        0x100d39ed8 - _worker
  25:        0x197bc6f94 - __pthread_joiner_wake
Caught panic with error: failed printing to stdout: Resource temporarily unavailable (os error 35)
[15:31:20.709] ERROR (40657): pact-core@14.3.0: Verification unsuccessful

Steps to reproduce

Minimal example below, instructions in README:

https://github.com/qmg-rbass/pact-bug-2

Looks to me like it is caused by having a large number of messages to verify. This minimal example uses 128 dummy messages in the same pact file. But we see the same error in a real project with ~45 different messages, spread across several files on a pact broker.

The minimal example fails every time. In the case of the real project it is based on, we interestingly see the error ~80% of the time, with verification eventually successful after multiple retries.

Relevant log files

[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: Resource temporarily unavailablethread '<unnamed>' panicked at library/std/src/io/stdio.rs:1021:9 (os error 35)
:
failed printing to stdout: Resource temporarily unavailable (os error 35)
[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: Resource temporarily unavailable (os error 35)
stack backtrace:
   0:        0x112253088 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hb478ebbfb46e27ce
   1:        0x112275588 - core::fmt::write::he4d5fa2daff1f531
   2:        0x11224fccc - std::io::Write::write_fmt::hc5a47a68eba63d9f
   3:        0x112252ebc - std::sys_common::backtrace::print::h79bd952cc5812e7a
   4:        0x1122545e0 - std::panicking::default_hook::{{closure}}::h82301f6222887737
   5:        0x112254328 - std::panicking::default_hook::h1e49abbb3f1d7dbf
   6:        0x112254a28 - std::panicking::rust_panic_with_hook::h1e70c5d905e30e9d
   7:        0x11225491c - std::panicking::begin_panic_handler::{{closure}}::h399e32952efd26a4
   8:        0x11225350c - std::sys_common::backtrace::__rust_end_short_backtrace::h2ab87f841a2323e7
   9:        0x1122546a4 - _rust_begin_unwind
  10:        0x1122d461c - core::panicking::panic_fmt::h33e40d2a93cab78f
  11:        0x11224ece0 - std::io::stdio::_print::h2c869062e4130656
  12:        0x1115f23cc - pact_verifier::verify_provider_async::{{closure}}::{{closure}}::hc20d3590fb2780e7
  13:        0x11162ab4c - <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll::h6192e06b5541dff5
  14:        0x11169d2f8 - <tokio::task::task_local::TaskLocalFuture<T,F> as core::future::future::Future>::poll::h15b2b04a4836487e
  15:        0x1116a4490 - pact_verifier::verify_provider_async::{{closure}}::hdfb4a205a57c5fce
  16:        0x1116c8df8 - tokio::runtime::park::CachedParkThread::block_on::hbe826fd4bc423331
  17:        0x111776ea4 - tokio::runtime::context::runtime::enter_runtime::hcc547b869e4394a4
  18:        0x1117f45e8 - tokio::runtime::runtime::Runtime::block_on::h125b509c5d36c1d2
  19:        0x11177fa48 - pact_ffi::verifier::handle::VerifierHandle::execute::hf5436875cfce2f47
  20:        0x111819978 - pact_ffi::error::panic::catch_panic::h1a10465fee822ae2
  21:        0x11179f58c - _pactffi_verifier_execute
  22:        0x1079fe964 - __ZN18VerificationWorker7ExecuteEv
  23:        0x1079fe6a4 - __ZN4Napi11AsyncWorker9OnExecuteENS_3EnvE
  24:        0x103791ed8 - _worker
  25:        0x197bc6f94 - __pthread_joiner_wake
Caught panic with error: failed printing to stdout: Resource temporarily unavailable (os error 35)
[15:34:07.729] DEBUG (40817): pact-core@14.3.0: shutting down verifier with handle 0
  foo message (0s loading, 86ms verification)
2024-05-08T14:34:07.704745Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::codec::framed_write: send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
2024-05-08T14:34:07.705403Z DEBUG tokio-runtime-worker Connection{peer=Client}: h2::proto::connection: Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
2024-05-08T14:34:07.729598Z DEBUG ThreadId(01) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_shutdown FFI function invoked
[15:34:07.729] DEBUG (40817): pact-core@14.3.0: response from verifier: null, 1
[15:34:07.729] ERROR (40817): pact-core@14.3.0: Verification unsuccessful

mefellows commented 6 months ago

Thank you for raising it and for the repro, is has reproduced the error for me also.

@rholshausen I'll move this to the core project as it looks to be in the core.

github-actions[bot] commented 6 months ago

🤖 Great news! We've labeled this issue as smartbear-supported and created a tracking ticket in PactFlow's Jira (PACT-1985). We'll keep work public and post updates here. Meanwhile, feel free to check out our docs. Thanks for your patience!

rholshausen commented 6 months ago

Moving this back to pact-js, it is a Node issue.

Looks like process.stdout._handle.setBlocking(true) before calling the FFI methods resolves the issue.

mefellows commented 6 months ago

Nice find - thanks Ron!

santhosh-r-urs commented 6 months ago

Thanks. I face this issue only when the number of tests in the suite is around 20+, the suites with less number of tests does not have this issue. Is there any workaround I can use temporarily, please ?

qmg-rbass commented 6 months ago

@santhosh-r-urs I added the following workaround to my test suite (thanks for the hint @rholshausen)

const setBlockingOutput = (blocking : boolean) => {
  if (process.stdout._handle) {
    process.stdout._handle.setBlocking(blocking)
  }
}

beforeAll(() => {
  setBlockingOutput(true)
});

afterAll(() => {
  setBlockingOutput(false)
});

santhosh-r-urs commented 6 months ago

Thanks @qmg-rbass . The workaround worked perfect for my suite too !

YOU54F commented 6 months ago

Fix released in 14.3.7 of pact-js-core

https://github.com/pact-foundation/pact-js-core/releases/tag/v14.3.7

Failing run of repro, pre release Passing run of repro post release

pact-foundation / pact-js