Error: The specified procedure could not be found.

[mefellows]

The error "Error: The specified procedure could not be found." is thrown on most Windows builds, resulting in CI failures for Pact JS builds.

Example build

The issue is thrown when loading pact.node, which is a native library produced by https://github.com/pact-foundation/pact-js-core/. The error seems to indicate a symbol in the shared library is not found on the CI runtime, and is therefore unable to execute the library, and subsequent tests.

The behaviour did seem to be non-deterministic, at least historically (update: previous build histories referred to here are now beyond reach of GitHub's memory), however, it does seem to consistently fail when executing the first example (V3 e2e: D:\a\pact-js\pact-js\examples\v3\e2e).

Example build that mostly succeeded with previous examples, and then died during the v3 e2e test: https://github.com/pact-foundation/pact-js/actions/runs/4193805789/jobs/7271156646.

I have been unable to reproduce on my own Windows environment, albeit I wasn't able to get something as close to the CI runner as I'd have liked.

Error

Example log file: 1_build-and-test-windows (14.x).txt

> e2e@1.0.0 test:consumer D:\a\pact-js\pact-js\examples\v3\e2e
> mocha test/consumer.spec.js


Warning: Cannot find any files matching pattern "src/*.spec.ts"
Warning: Cannot find any files matching pattern "src/**/*.spec.ts"

Error: The specified procedure could not be found.
\\?\D:\a\pact-js\pact-js\dist\node_modules\@pact-foundation\pact-core\build\Release\pact.node
    at Object.Module._extensions..node (internal/modules/cjs/loader.js:1173:18)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at Module.require (internal/modules/cjs/loader.js:1003:19)
    at require (internal/modules/cjs/helpers.js:107:18)
    at bindings (D:\a\pact-js\pact-js\dist\node_modules\bindings\bindings.js:112:48)
    at Object.<anonymous> (D:\a\pact-js\pact-js\dist\node_modules\@pact-foundation\pact-core\src\ffi\index.ts:6:21)
    at Module._compile (internal/modules/cjs/loader.js:1114:14)
    at Module._extensions..js (internal/modules/cjs/loader.js:1143:10)
    at Object.require.extensions.<computed> [as .js] (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\ts-node\src\index.ts:1608:43)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at Module.require (internal/modules/cjs/loader.js:1003:19)
    at require (internal/modules/cjs/helpers.js:107:18)
    at Object.<anonymous> (D:\a\pact-js\pact-js\dist\node_modules\@pact-foundation\pact-core\src\verifier\nativeVerifier.ts:3:1)
    at Module._compile (internal/modules/cjs/loader.js:1114:14)
    at Module._extensions..js (internal/modules/cjs/loader.js:1143:10)
    at Object.require.extensions.<computed> [as .js] (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\ts-node\src\index.ts:1608:43)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at Module.require (internal/modules/cjs/loader.js:1003:19)
    at require (internal/modules/cjs/helpers.js:107:18)
    at Object.<anonymous> (D:\a\pact-js\pact-js\dist\node_modules\@pact-foundation\pact-core\src\verifier\index.ts:3:1)
    at Module._compile (internal/modules/cjs/loader.js:1114:14)
    at Module._extensions..js (internal/modules/cjs/loader.js:1143:10)
    at Object.require.extensions.<computed> [as .js] (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\ts-node\src\index.ts:1608:43)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at Module.require (internal/modules/cjs/loader.js:1003:19)
    at require (internal/modules/cjs/helpers.js:107:18)
    at Object.<anonymous> (D:\a\pact-js\pact-js\dist\node_modules\@pact-foundation\pact-core\src\pact.ts:7:1)
    at Module._compile (internal/modules/cjs/loader.js:1114:14)
    at Module._extensions..js (internal/modules/cjs/loader.js:1143:10)
    at Object.require.extensions.<computed> [as .js] (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\ts-node\src\index.ts:1608:43)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at Module.require (internal/modules/cjs/loader.js:1003:19)
    at require (internal/modules/cjs/helpers.js:107:18)
    at Object.<anonymous> (D:\a\pact-js\pact-js\dist\node_modules\@pact-foundation\pact-core\src\index.ts:1:1)
    at Module._compile (internal/modules/cjs/loader.js:1114:14)
    at Module._extensions..js (internal/modules/cjs/loader.js:1143:10)
    at Object.require.extensions.<computed> [as .js] (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\ts-node\src\index.ts:1608:43)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at Module.require (internal/modules/cjs/loader.js:1003:19)
    at require (internal/modules/cjs/helpers.js:107:18)
    at Object.<anonymous> (D:\a\pact-js\pact-js\src\httpPact\index.ts:1:1)
    at Module._compile (internal/modules/cjs/loader.js:1114:14)
    at Module._extensions..js (internal/modules/cjs/loader.js:1143:10)
    at Object.require.extensions.<computed> [as .js] (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\ts-node\src\index.ts:1608:43)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at Module.require (internal/modules/cjs/loader.js:1003:19)
    at require (internal/modules/cjs/helpers.js:107:18)
    at Object.<anonymous> (D:\a\pact-js\pact-js\src\index.ts:25:1)
    at Module._compile (internal/modules/cjs/loader.js:1114:14)
    at Module._extensions..js (internal/modules/cjs/loader.js:1143:10)
    at Object.require.extensions.<computed> [as .js] (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\ts-node\src\index.ts:1608:43)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at Module.require (internal/modules/cjs/loader.js:1003:19)
    at require (internal/modules/cjs/helpers.js:107:18)
    at Object.<anonymous> (D:\a\pact-js\pact-js\examples\v3\e2e\test\consumer.spec.js:10:5)
    at Module._compile (internal/modules/cjs/loader.js:1114:14)
    at Module._extensions..js (internal/modules/cjs/loader.js:1143:10)
    at Object.require.extensions.<computed> [as .js] (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\ts-node\src\index.ts:1608:43)
    at Module.load (internal/modules/cjs/loader.js:979:32)
    at Function.Module._load (internal/modules/cjs/loader.js:819:12)
    at ModuleWrap.<anonymous> (internal/modules/esm/translators.js:203:29)
    at ModuleJob.run (internal/modules/esm/module_job.js:183:25)
    at async Loader.import (internal/modules/esm/loader.js:178:24)
    at async formattedImport (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\mocha\lib\nodejs\esm-utils.js:7:14)
    at async Object.exports.requireOrImport (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\mocha\lib\nodejs\esm-utils.js:38:28)
    at async Object.exports.loadFilesAsync (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\mocha\lib\nodejs\esm-utils.js:91:20)
    at async singleRun (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\mocha\lib\cli\run-helpers.js:125:3)
    at async Object.exports.handler (D:\a\pact-js\pact-js\examples\v3\e2e\node_modules\mocha\lib\cli\run.js:370:5)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! e2e@1.0.0 test:consumer: `mocha test/consumer.spec.js`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the e2e@1.0.0 test:consumer script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     C:\npm\cache\_logs\2023-03-02T07_11_24_404Z-debug.log
npm ERR! Test failed.  See above for more details.
Error: Process completed with exit code 1.

Possible problem candidates

• we use a relative module installation (file:../../../dist) that loads a relative version of Pact JS that was compiled and packaged in the current build (to ensure the examples continue to work with the latest changes). It's plausible there is a conflicting version of pact-core in the relative node_modules folder that is conflicting with the one imported by the imported pact package from the dist folder
• The v3 e2e package has a module that is also used by pact-core which is conflicting.

Research

I have extracted the e2e test into its own repo, and the consumer test runs and passes(the provider test is failing as expected, but is executing just fine).

This lends credence to the possibility of conflicting dependencies.

Other similar issues from the Internet

1. Node Canvas: The specified procedure could not be found Automattic/node-canvas#1219 (comment) / Error: The specified procedure could not be found. With sharp js. Automattic/node-canvas#930

I think this can happen for a few reasons: (a) if you have another module that depends on one of the same dependencies of canvas, like cairo, (b) if you have multiple versions of canvas loaded by the same node.js process, sometimes, (c) if canvas was built with a different version of the dependencies than it's attempting to run with. When Windows searches for a DLL, if it finds one already loaded in memory with the same name, that one will be used even if it's the wrong one.

a) and c) worry me, because this doesn't strike me as a "rare" scenario or edge case.

2. Electron: https://www.electronjs.org/docs/latest/tutorial/using-native-node-modules#troubleshooting

Debugging suggestions

• https://ofekshilon.com/2013/06/22/entry-point-not-found-and-other-dll-loading-problems/
• https://nodejs.org/api/addons.html#loading-addons-using-require
• https://learn.microsoft.com/en-us/windows-hardware/drivers/debugger/show-loader-snaps?redirectedfrom=MSDN, https://learn.microsoft.com/en-us/windows-hardware/drivers/debugger/gflags, https://learn.microsoft.com/en-us/windows-hardware/drivers/debugger/debugger-download-tools and https://learn.microsoft.com/en-us/windows-hardware/drivers/debugger/gflags-commands?source=recommendations

[github-actions]

👋 Hi! The 'smartbear-supported' label has just been added to this issue, which will create an internal tracking ticket in PactFlow's Jira (PACT-791). 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.

[TimothyJones]

if you have another module that depends on one of the same dependencies of canvas, like cairo,
...
c) if canvas was built with a different version of the dependencies than it's attempting to run with. When Windows searches for a DLL, if it finds one already loaded in memory with the same name, that one will be used even if it's the wrong one.

I reckon this is the problem. Npm can handle duplicate dependencies with different versions, but I doubt the DLL loader can.

I don't know much about windows. Would naming the DLL differently in each version help?

This is a good argument generally for the Pact-CLI being separated, because that's the only reason you'd need multiple pact-core versions. I took a stab at this here, https://github.com/TimothyJones/pact-cli but the windows build is failing (unrelated to this issue) and I haven't looked in to it.

[mefellows]

I reckon this is the problem. Npm can handle duplicate dependencies with different versions, but I doubt the DLL loader can.

Yep, it's definitely my current suspicion, because the e2e suite runs just fine on another agent without all of the extra build complexity we do here.

I don't know much about windows. Would naming the DLL differently in each version help?

It might, it would need some investigation. I don't think it would be too hard to version each pact.node lib though if it is the cause. I'd like to get to the bottom of it though if possible, so we know exactly what we're dealing with.

I'd love to be able to get a trace like Automattic/node-canvas#930 (comment), so my next step is to work out how to set that registry value on the CI agent.

This is a good argument generally for the Pact-CLI being separated, because that's the only reason you'd need multiple pact-core versions. I took a stab at this here, https://github.com/TimothyJones/pact-cli but the windows build is failing (unrelated to this issue) and I haven't looked in to it.

Yes, and if it is the problem it also would solve the related issue around OS/arch support here (pact-foundation/pact-js-core#416). Thanks for doing that, I think it should be done regardless of this specific issue.

I think we would have to:

1. Release the CLI package as @pact-foundation/pact-cli
2. Remove it from @pact-foundation/pact-core and bump a major version
3. Add it as a dependency to @pact-foundation/pact

I think this would have the effect of keeping (1) backwards compatible, and then in the next major version of Pact we remove the dependency and let the user choose if they want that behaviour or not.

[TimothyJones]

Remove it from @pact-foundation/pact-core and bump a major version
Add it as a dependency to @pact-foundation/pact

I can make PRs for both of these things this week.

Release the CLI package as @pact-foundation/pact-cli

I can also do this, but I don't have access to @pact-foundation any more, of course.

[mefellows]

Oh, that would be amazing - thanks!

I was half putting that list up as "this is what we need to do" but also looking for anyone to poke holes in that approach.

[mefellows]

We believe this problem stemmed from two versions of pact-core living together. From Tim in a slack chat:

I assume because of the DLL loading issue you mentioned.
However, this isn’t a real world problem, because the only reason the examples needed two versions is because the bin stubs aren’t exposed from the transitive dependency when you’re loading a local folder as a package - this is because the install isn’t run (as per the npm documentation).

Tim has kindly donated https://github.com/pact-foundation/pact-js-cli to the foundation, which we can then use to do (1).