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

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

Closed
5 tasks done
qmg-rbass opened this issue May 8, 2024 · 8 comments · Fixed by pact-foundation/pact-js-core#510
Labels
bug Indicates an unexpected problem or unintended behavior good first issue Indicates a good issue for first-time contributors help wanted Indicates that a maintainer wants help on an issue or pull request triage This issue is yet to be triaged by a maintainer upstream Indicates that an issue relates to an upstream problem (such as in pact-reference)

Comments

@qmg-rbass
Copy link

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:

  • I have upgraded to the latest
  • I have the read the FAQs in the Readme
  • I have triple checked, that there are no unhandled promises in my code and have read the section on intermittent test failures
  • I have set my log level to debug and attached a log file showing the complete request/response cycle
  • 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): [email protected]: 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): [email protected]: 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): [email protected]: response from verifier: null, 1
[15:34:07.729] ERROR (40817): [email protected]: Verification unsuccessful
@qmg-rbass qmg-rbass added bug Indicates an unexpected problem or unintended behavior triage This issue is yet to be triaged by a maintainer labels May 8, 2024
@mefellows mefellows added the upstream Indicates that an issue relates to an upstream problem (such as in pact-reference) label May 9, 2024
@mefellows
Copy link
Member

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.

@mefellows mefellows transferred this issue from pact-foundation/pact-js May 9, 2024
@rholshausen rholshausen added the smartbear-supported SmartBear engineering team will support this issue. See https://docs.pact.io/help/smartbear label May 12, 2024
Copy link

🤖 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
Copy link

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.

@rholshausen rholshausen transferred this issue from pact-foundation/pact-reference May 13, 2024
@mefellows
Copy link
Member

Nice find - thanks Ron!

@mefellows mefellows added help wanted Indicates that a maintainer wants help on an issue or pull request good first issue Indicates a good issue for first-time contributors and removed smartbear-supported SmartBear engineering team will support this issue. See https://docs.pact.io/help/smartbear labels May 16, 2024
@santhosh-r-urs
Copy link

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
Copy link
Author

@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
Copy link

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

YOU54F added a commit to YOU54F/pact-js-core that referenced this issue May 28, 2024
fixes pact-foundation/pact-js#1216

Large number of pact verifications fail when run in parallel
mefellows pushed a commit to pact-foundation/pact-js-core that referenced this issue May 29, 2024
fixes pact-foundation/pact-js#1216

Large number of pact verifications fail when run in parallel
@YOU54F
Copy link
Member

YOU54F commented May 29, 2024

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 good first issue Indicates a good issue for first-time contributors help wanted Indicates that a maintainer wants help on an issue or pull request triage This issue is yet to be triaged by a maintainer upstream Indicates that an issue relates to an upstream problem (such as in pact-reference)
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants