Very slow cleanup with PactV3, something happening on the ffi side

algardas-sca commented 1 year ago

Software versions

OS: Ubuntu 22.04
Consumer Pact library: pact-js 10.4.0
Provider Pact library: {"pactRust": Object {"ffi": String("0.3.15")}}
Node Version: 18.12.1

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

Expected behaviour

Cleanup after a few new PactV3(...) calls is fast.

Actual behaviour

Cleanup is very slow.

Steps to reproduce

const { PactV3 } = require("@pact-foundation/pact")

const providers = []
for (let i = 0, len = 20; i < len; i++) {
  const provider = new PactV3({
    consumer: 'MyConsumer',
    provider: 'MyProvider',
    logLevel: 'debug',
  })
  providers.push(provider)
}

console.log(Date.now(), 'DONE')

process.on('exit', function() {
  console.log(Date.now(), "EXIT")
})

>>node test-pact.js; date +%s
1670594674361 DONE
(node:18241) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 exit listeners added to [process]. Use emitter.setMaxListeners() to increase limit
(Use `node --trace-warnings ...` to show where the warning was created)
1670594675207 EXIT
1670594682

7s doing cleanup?

Of course this is a contrived example because the provider is not used, but I see the same when running a full test.

mefellows commented 1 year ago

Interesting. I ran that on my machine and it took 240ms, but I have heard anecdotally that others are having the same issue.

We run the builds on Ubuntu, Windows and Mac and don't see this issue (albeit I am seeing a strange issue on Windows builds at the moment).

The event emitter warning is also interesting, perhaps it's related.

We're going to need to find a way to reliably reproduce this (if possible), otherwise it's going to be hard to pin down.

Could you please try running your command with loglevel set to trace and also the env var RUST_BACKTRACE=1?

algardas-sca commented 1 year ago

For me it reproduces using github workflow running on ubuntu-22.04.

Attaching logs from the github action run and the github workflow file: logs.txt test-workflow.yml.txt

package.json:

    "dependencies": {},
    "devDependencies": {
        "@pact-foundation/pact": "^10.1.4"
    },

lhokktyn commented 1 year ago

Hi Pact team 👋 I'm experiencing the same here whilst evaluating Pact. The likelihood increases - and the duration of the hangs are longer - with every executeTest() we add to the suite. Often it doesn't exit at all.

My environment:

OS: MacOS Monterey (12.6.1)
node: 18.13.0
pact-js: "10.4.1"
pactRust.ffi: "0.3.19"

Taking @algardas-sca test script above, I've noticed that attempting to add anything further to the async stack doesn't ever get executed, eg:

import { kill } from 'node:process'
import { PactV3 } from "@pact-foundation/pact"

const providers = []
for (let i = 0, len = 20; i < len; i++) {
  const provider = new PactV3({
    consumer: 'MyConsumer',
    provider: 'MyProvider',
  })
  providers.push(provider)
}

console.log(Date.now(), 'DONE')

process.on('exit', function() {
  console.log(Date.now(), "EXIT")
  setTimeout(() => kill(process.pid, 'SIGHUP'), 1000); // never manages to execute
})

Removing that setTimeout(), the process is killed immediately:

process.on('exit', function() {
  console.log(Date.now(), "EXIT")
  kill(process.pid, 'SIGHUP')
})

Which suggests node's callback stack is under heavy load, and aligns with the appearance of those MaxListenersExceededWarning warnings.

Setting len = 6 avoids that leak warning altogether;

Setting len = 7 gives:

(node:13359) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 exit listeners added to [process]. Use emitter.setMaxListeners() to increase limit
    at _addListener (node:events:587:17)
    at process.addListener (node:events:605:10)
    at file:///test-pact.js:16:9
    at ModuleJob.run (node:internal/modules/esm/module_job:194:25)

Setting len = 8 gives:

(node:13862) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 exit listeners added to [process]. Use emitter.setMaxListeners() to increase limit
    at _addListener (node:events:587:17)
    at process.addListener (node:events:605:10)
    at buildStream (/node_modules/pino/lib/transport.js:32:11)
    at transport (/node_modules/pino/lib/transport.js:110:10)
    at normalizeArgs (/node_modules/pino/lib/tools.js:297:16)
    at pino (/node_modules/pino/pino.js:86:28)
    at createLogger (/node_modules/@pact-foundation/pact-core/src/logger/pino.js:5:49)
    at setLogLevel (/node_modules/@pact-foundation/pact-core/src/logger/index.js:13:38)
    at makeConsumerPact (/node_modules/@pact-foundation/pact-core/src/consumer/index.js:25:34)

(which echos the issue reported in https://github.com/pact-foundation/pact-js/issues/1033)

On my particular environment, I can reliably setup ~16 provider instances in the above script before shutdowns start getting a bit more flaky (process hanging entirely).

mefellows commented 1 year ago

Thanks for the additional info. All signs point to pino (or how we use pino) at this stage, so I think that's worth diving into.

As has been stated in the referenced issue, I'm not convinced we even need a 3rd party logger here given what is needed by Pact. If somebody has time to look into this I'd love a PR, otherwise it will go on a relatively high priority stack of bug fixes to get done in due course.

mefellows commented 1 year ago

For now, marking this as a duplicate of #1033, and will review as part of that.

pact-foundation / pact-js