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

"getport" sometimes throwing an error #827

Open
tarasromil opened this issue Nov 3, 2023 · 41 comments
Open

"getport" sometimes throwing an error #827

tarasromil opened this issue Nov 3, 2023 · 41 comments
Labels
bug keep Keep this issue open (no Stale)

Comments

@tarasromil
Copy link

Versions

  • NodeJS: 16.20.2
  • mongodb-memory-server-*: 9.0.1
  • mongodb(the binary version): 6.0.10
  • mongodb(the js package): 5.9.0
  • system: MacOS 14.1

package: mongo-memory-server

What is the Problem?

When I'm trun to run test using "vitest@0.34.6" in concurrency mode I have an error that port already in use. No always, but pretty often

Starting the MongoMemoryServer Instance failed, enable debug log for more information. Error:
 StdoutInstanceError: Port "15490" already in use

Want to notice that there is no error on v8.16.0

Code Example

globalThis.__MONGO_DB__ = await MongoMemoryServer.create();

Debug Output

stderr | unknown test
Starting the MongoMemoryServer Instance failed, enable debug log for more information. Error:
 StdoutInstanceError: Port "52929" already in use
    at MongoInstance.checkErrorInLine (/.../node_modules/.pnpm/mongodb-memory-server-core@9.0.1/node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:641:9)
    at MongoInstance.stdoutHandler (/.../node_modules/.pnpm/mongodb-memory-server-core@9.0.1/node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:615:10)
    at Socket.emit (node:events:513:28)
    at addChunk (node:internal/streams/readable:315:12)
    at readableAddChunk (node:internal/streams/readable:289:9)
    at Socket.Readable.push (node:internal/streams/readable:228:10)
    at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)

Do you know why it happenes?

Looks like there is a race condition after replacing "get-port" to own implementation

@tarasromil tarasromil added the bug label Nov 3, 2023
@hasezoey
Copy link
Collaborator

hasezoey commented Nov 3, 2023

i dont know how vitest's concurrency works or how / where you create your server.
i also dont know why the new implementation would fail when the old one would not in the same scenario.

port acquisition and keeping is a fickle process, because you cant just "give me a free port and keep it on-hold until used" and also cannot be marked as "used for later", like it is tested that it is free with a small http server, which is closed to free the port so that it can be used by mongod, but in that small time another process may just get that port

@AndreasGalster2
Copy link

AndreasGalster2 commented Nov 7, 2023

I just got here because I have the same issue. Since there's currently no solution, I'm thinking maybe https://www.npmjs.com/package/promise-retry will do the trick to create a server in case the port fails. I haven't tried this yet but that might work at least as a temporary fix.

/edit:

    import promiseRetry from 'promise-retry';

    const promiseRetryOptions = {
      retries: 3,
      factor: 2,
      minTimeout: 50,
      maxTimeout: 10000,
    };

    return promiseRetry((retry, number) => {
      console.log(`Creating MongoClient - Retrying if port is unavailable - Try Number: ${number}`);

      return mongoose.connect(url, { useNewUrlParser: true });
    }, promiseRetryOptions);

I've done a few runs now and it seems I no longer have port issues. No guarantees here but out of 5 runs, they all passed... Before every 2nd run or so failed.

@JacksonUtsch
Copy link

I seem to getting the same port issue sometimes. Oddly enough also on macOS 14.1. but mongodb-memory-server v8.13.0. Will try newer version.

@trevorah
Copy link

trevorah commented Nov 9, 2023

We've had the same issue with v9.0.1 on macos and on GHA linux build machines, where v8.13.0 was fine.

We ended up with this workaround:

import getPort from 'get-port';
import retry from 'async-retry';

const port = await getPort();
const mongo = await retry(
  () =>
    MongoMemoryReplSet.create({
      ...this.testEnvironmentOptions,
      instanceOpts: [{ port }],
      replSet: { count: 2 },
    }),
  {
    retries: 3,
  },
);

@JacksonUtsch
Copy link

Well, it seems I have interesting results. Updating to v9.0.1 seems to made this issue much less frequent.

@hasezoey
Copy link
Collaborator

hasezoey commented Nov 9, 2023

@JacksonUtsch @trevorah, what exact errors are you seeing, are you seeing a Port is already in use(by the mongod log) error or a Max port tries exceeded error?

i also dont know what is so much different from the get-port implementation, does someone maybe have some suggestions? code here

@JacksonUtsch
Copy link

Port "50113" already in use
  at MongoInstance.checkErrorInLine (node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:611:9)
  at MongoInstance.stdoutHandler (node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:585:10)

In the code referenced I think we need a lock of sorts for PORTS_CACHE. If we could await read and writing of that value. Does that sound about right?

@hasezoey
Copy link
Collaborator

hasezoey commented Nov 9, 2023

In the code referenced I think we need a lock of sorts for PORTS_CACHE. If we could await read and writing of that value. Does that sound about right?

do you mean some kind of mutex or do you mean a cache file with lock?

also what is your use-case, replset or just many severs?

@JacksonUtsch
Copy link

A mutex yes. Running many e2e tests from separate files.

@hasezoey
Copy link
Collaborator

hasezoey commented Nov 9, 2023

Running many e2e tests from separate files.

what is your testing environment?

(example jest) the problem with many concurrent tests and each having their own server is that those modules are isolated and cannot speak to each-other without some kind of cache file (so a normal mutex would not work), but i didnt want to increase complexity compared to the old get-port (that is why it is recommended to start a server in globalSetup)

@JacksonUtsch
Copy link

Yes, using jest for testing here.

Hmm, I thought there was only a single instance of PORTS_CACHE defined at the file level and they would all use the same? Ex: A singleton or global variable with locking.

@hasezoey
Copy link
Collaborator

hasezoey commented Nov 9, 2023

Hmm, I thought there was only a single instance of PORTS_CACHE defined at the file level and they would all use the same? Ex: A singleton or global variable with locking.

yes it is a singleton, but the problem is that they are isolated instances, each jest worker can be seen as its own nodejs process, so a singleton is not shared across those processes (at least to my knowledge).
basically meaning that each test file is executed as a "new nodejs process"

@JacksonUtsch
Copy link

Ahh, good to know. Then a temp file might be the way to go.

hasezoey added a commit that referenced this issue Nov 9, 2023
this changes the behavior to use "net.listen(0)" to create a random port

re #827
@hasezoey
Copy link
Collaborator

hasezoey commented Nov 9, 2023

there might be 1 thing that is definitely different from get-port and that is that it relies on net.listen(0) returning a random port, whereas this new implementation is basically predictable. though that should theoretically not have a effect because it is tested to be free (net.listen), but another process may just snatch it in the time between generation and usage.
(i had designed it to be predictable, so that it could be tested and get to know what port might be chosen for a test)

for the next version i have done some slight refactors regarding the port implementation, and i also have cobbled something together to use net.listen(0) (earliest version 9.1.0-beta.3), under the flag EXP_NET0LISTEN (link should be valid in a few minutes)
please try this new option if you run into this often and report your results.

if that does not work, i will try to make a more complex solution similar to locking a binary download place (via our LockFile implementation) to only allow one server to generate a port, use it and then unlock it - which might make tests longer, so it will likely be a non-default option - it will also not prevent other unrelated applications using those ports in the meantime and they will have to have the same lockfile path (download dir?)

@JacksonUtsch
Copy link

@hasezoey This seems to work for me. I've not seen the error show up when using the tag and flag. 😃

@hasezoey
Copy link
Collaborator

because port problems are somewhat sporadic, i have not been able to actually test much about it, but today just run into a case where i consistently got failed tests because of "port already in use" (even after multiple tries), adding EXP_NET0LISTEN actually fixed it, at least for now.

i am thinking about making it the default in some future version (but not 9.1.0 yet) to get some more testing, and push the old behavior behind a flag.

just keep in mind that this will just lessen the port conflicts, but not entirely avoid them.

@JacksonUtsch
Copy link

Great. Agreed it should be default behavior. Good to have a reproducible test with the issue here.

@hasezoey
Copy link
Collaborator

Good to have a reproducible test with the issue here.

I dont quite know what you mean, there still is not reproduce-able case i know of, i just ran into it - if i would reboot it would likely be gone again (or after many retries), port testing is a very fickle process. The best would be if mongod would implement something to generate their own port.

@JacksonUtsch
Copy link

but today just run into a case where i consistently got failed tests because of "port already in use" (even after multiple tries), adding EXP_NET0LISTEN actually fixed it, at least for now.

It only sounded like this was reproducible is all.

@hasezoey
Copy link
Collaborator

It only sounded like this was reproducible is all.

it sounded like it, but it was just sporadic as said in the earlier comment, i dont have a reproduce-able case for this, i dont even know if there is one - the best i have to test "port already in use" falky-ness is just re-running the MMS tests over and over

@andr9528
Copy link

andr9528 commented Nov 16, 2023

At Tv2 Danmark one of our repositories uses version 9.0.0 for tests. We have found the same bug as desribed here - but only on unix environments. Two of the developers are using Mac, which has the error along with during GitHub action, however the two other developers (me included) using windowns have not been able to reproduce the error. It appears to happen quite often on GitHub actions and for the Mac users, so it would appear to be reproducable in the right environment.

Going to test now if the v9.1.0-beta.5 fixes it for us.

At the very least i hope it helps to know that it is very likely a unix related issue.

@andr9528
Copy link

andr9528 commented Nov 16, 2023

At the 4th run of our GitHub check action that runs our test using this, the usual tests failed again with the same error.

 Port "27245" already in use
      at MongoInstance.checkErrorInLine (node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:643:9)
      at MongoInstance.stdoutHandler (node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:617:10)

Unsure if perhabs we are missing an option for the create method, for changes introduced to have an effect.

export class MongoTestDatabase {
  private mongoServer: MongoMemoryServer
  private client: MongoClient

  ...

  public async setupDatabase(): Promise<void> {
    this.mongoServer = await MongoMemoryServer.create()
    this.client = await MongoClient.connect(this.mongoServer.getUri())
  }

  public async teardownDatabase(): Promise<void> {
    if (this.client) {
      await this.client.close()
    }
    if (this.mongoServer) {
      await this.mongoServer.stop()
    }
  }
  ...
}

setupDatabase is called from beforeEach, and teardownDatabase is called from afterEach in each of our test files that use this class.

@hasezoey
Copy link
Collaborator

@andr9528 i dont see a problem with the code provided

Going to test now if the v9.1.0-beta.5 fixes it for us.
At the 4th run of our GitHub check action that runs our test using this, the usual tests failed again with the same error.

are those runs using the experimental option?

@andr9528
Copy link

@hasezoey The 4 runs i did, where the last threw the error again, was with version 9.1.0-beta.5.

Is there anything special that needs to be configued to use the experimental option?

{ // package.json
  ...
  "devDependencies": { 
    ...
    "mongodb-memory-server": "9.1.0-beta.5",
  },
  "dependencies": { 
    ...
    "mongodb": "^6.1.0",
  }
}

@hasezoey
Copy link
Collaborator

Is there anything special that needs to be configued to use the experimental option?

yes config option EXP_NET0LISTEN aside from that option, the current beta only had some small changes regarding port generation; either set via environment variables or via the package.json

@andr9528
Copy link

I am sorry that i overlooked that section. As mentioned in the section linked to, it

will not eliminate them

Immediatly after adding the missing config section to the package.json, it threw the same error twice, followed by 4 good runs, then failing again. Thus it doesn't seem to have made much of a change, if any.

The cutout of our package.json looks like this now.

{ // package.json
  ...
  "config": {
    "mongodbMemoryServer": {
      "expNet0Listen": true
    }
  },
  "devDependencies": { 
    ...
    "mongodb-memory-server": "9.1.0-beta.5",
  },
  "dependencies": { 
    ...
    "mongodb": "^6.1.0",
  }
}

As i mentioned earlier it might be related to something unix based. We are yet to see it on any of our Windows PC, while seeing it commonly on unix based enviroment. Has been seen on both MacOS and Linux, in the form of Github Actions.

@hasezoey
Copy link
Collaborator

As i mentioned earlier it might be related to something unix based

it should theoretically happen on all systems, because at the time the port is generated, another process could come in and use it before actually being used by the mongod server (in the downtime in-between), net.listen(0) should reduce the frequency, because it is actually generating a random port, instead of a predictable port like the non-experimental implementation.

to confirm, is that the only package.json or are there more? could you maybe try via a environment variable too? (i did not add a log to indicate whether the experiment is active or not, but maybe i should)

@hasezoey
Copy link
Collaborator

version 9.1.0 has now been released with the EXP_NET0LISTEN option, and also added a long to know whether it is enabled or not (requires Debug Logs to be active), search for EXP_NET0LISTEN and it should either log true or false after it

@AndreasGalster2
Copy link

AndreasGalster2 commented Nov 17, 2023

version 9.1.0 has now been released with the EXP_NET0LISTEN option, and also added a long to know whether it is enabled or not (requires Debug Logs to be active), search for EXP_NET0LISTEN and it should either log true or false after it

I'm trying to verify. Just upgraded to 9.1.0 but not getting the config to work I think. When my port fails it actually tells me to enable debug. I enabled debug but getting no log... Are the config values different for local vs global in-memory-package? I'm using the global package. In my package.json

  "config": {
    "mongodbMemoryServer": {
      "expNet0Listen": true,
      "debug": "1"
    }
  }

/Edit: Yes, just enabled logs via ENV var... not sure why package.json doesn't work for me. Will report my findings in the next days whether I still get port issues.

Actually, sorry can you please let me know what's the right env variables?

MONGOMS_DEBUG=1
MONGOMS_EXP_NET0LISTEN=true

True or 1?

/edit:

2023-11-17T08:26:16.867Z MongoMS:GetPort EXP_NET0LISTEN true

I assume this means EXP_NET-LISTEN is running... Still getting port errors.

 FAIL  src/__tests__/product_inventory.test.js > Integration Test: Validating Reviews
Error: Port "24547" already in use
 ❯ MongoInstance.checkErrorInLine node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:643:9
 ❯ MongoInstance.stdoutHandler node_modules/mongodb-memory-server-core/src/util/MongoInstance.ts:617:10
 ❯ Socket.emit node:events:517:28

@hasezoey
Copy link
Collaborator

/Edit: Yes, just enabled logs via ENV var... not sure why package.json doesn't work for me.

what is you structure and package manager? because MMS's package.json finding works by working each directory upwards, checking if there is package.json with a config.mongodbMemoryServer key, if not repeat until at root; starting from the processes cwd

True or 1?

either

return ['1', 'on', 'yes', 'true'].indexOf(env.toLowerCase()) !== -1;

I assume this means EXP_NET-LISTEN is running... Still getting port errors.

yes that means it is enabled


if this is true, i will likely need to work on a inter-process exclusive locking for ports, also running as a experiment
to gather some feedback. i am thinking of putting that lockfile in the temporary directory (maybe in a subdirectory), any other place suggestions or is that fine? (will likely make it configureable; dbpath is not possible because that is different for each instance)


PS: for anyone just wanting to check if the experiment is running, without other debug logs can also use DEBUG=MongoMS:GetPort (instead of MONGOMS_DEBUG=true)

@AndreasGalster2
Copy link

{
  "engines": {
    "node": ">=18.0"
  },
  "config": {
    "mongodbMemoryServer": {
      "expNet0Listen": true,
      "debug": "1"
    }
  },
  "devDependencies": {
    "mongodb-memory-server": "^9.1.0",
    "mongodb-memory-server-global": "^9.1.0",
  }
}

This is my package.json

@dimaip
Copy link

dimaip commented Nov 24, 2023

In our case, the problem comes from mocked dates in Jest.

We have this in the Jest setup file:

const jestDateMock = require('jest-date-mock');
jestDateMock.advanceTo(new Date('2020-07-01T00:00:00Z'));

Since mongodb-memory-server-core uses Date.now() as a source of randomness, firstPort now always resolves with the same port number, and we always get Port "22815" already in use.

https://github.com/nodkz/mongodb-memory-server/blob/master/packages/mongodb-memory-server-core/src/util/getport/index.ts#L52

Possible solutions:

  • stop relying on Date.now for randomness and instead do smth like Math.random?
  • if you are keen on using timestamps, maybe use process.hrtime.bigint() instead, as mocking Date in Jest should be very common?

Workaround

For now this workaround helped us fix the issue:

jestDateMock.clear();
await replSet.start();
jestDateMock.advanceTo(new Date('2020-07-01T00:00:00Z'));

@hasezoey
Copy link
Collaborator

In our case, the problem comes from mocked dates in Jest.

for now maybe try using the EXP_NET0LISTEN option

@dimaip
Copy link

dimaip commented Nov 24, 2023

for now maybe try using the EXP_NET0LISTEN option

Thanks for the suggestion, but that's what we were already using. Since it always starts with the same port, on the first try it would try to use that port and fail (see https://github.com/nodkz/mongodb-memory-server/blob/master/packages/mongodb-memory-server-core/src/util/getport/index.ts#L73C7-L73C46)

@hasezoey
Copy link
Collaborator

hasezoey commented Nov 24, 2023

Since it always starts with the same port, on the first try it would try to use that port and fail

what exactly do you mean with "fail", as in "failed with error" or "failed and tried another port"?

PS: forgot Date.now was used to get a initial port

as a workaround you could likely use port: 0 explicitly in the server config and EXP_NET0LISTEN. i will try to think of a way to maybe improve getting a starting port if not not provided (like with EXP_NET0LISTEN to directly use 0?)

This comment was marked as outdated.

@github-actions github-actions bot added the stale This Issue is outdated and will likely be closed if no further comments are given label Dec 25, 2023
@hasezoey hasezoey added keep Keep this issue open (no Stale) and removed stale This Issue is outdated and will likely be closed if no further comments are given labels Dec 25, 2023
noseworthy added a commit to noseworthy/mongodb-memory-server that referenced this issue Jan 11, 2024
The current implementation of `getPort()` relies on using `Date.now()`
to get the first port to try to launch mongo on, even when the
`EXP_NET0LISTEN` flag is set. This causes a couple issues:
- If the `Date` module is mocked, it can result in `getFreePort()`
  returning the same first port every time.
- If multiple mongos are being started at once in parallel, it's
  possible for the same first port to be picked leading to port
  conflicts
  In order to better randomize the initial port selection so that port
  conflicts can be avoided, instead of using `Date.now()` for an initial
  seed, use `crypto.randomInt()` which should provide more randomness and
  hopefully avoid some of these race conditions.

Fixes nodkz#827
noseworthy added a commit to noseworthy/mongodb-memory-server that referenced this issue Jan 11, 2024
The current implementation of `getPort()` relies on using `Date.now()`
to get the first port to try to launch mongo on, even when the
`EXP_NET0LISTEN` flag is set. This causes a couple issues:
- If the `Date` module is mocked, it can result in `getFreePort()`
  returning the same first port every time.
- If multiple mongos are being started at once in parallel, it's
  possible for the same first port to be picked leading to port
  conflicts
In order to better randomize the initial port selection so that port
conflicts can be avoided, instead of using `Date.now()` for an initial
seed, use `crypto.randomInt()` which should provide more randomness and
hopefully avoid some of these race conditions.

Fixes nodkz#827
hasezoey added a commit that referenced this issue Jan 13, 2024
* fix(getport): Randomize first port using crypto

The current implementation of `getPort()` relies on using `Date.now()`
to get the first port to try to launch mongo on, even when the
`EXP_NET0LISTEN` flag is set. This causes a couple issues:
- If the `Date` module is mocked, it can result in `getFreePort()`
  returning the same first port every time.
- If multiple mongos are being started at once in parallel, it's
  possible for the same first port to be picked leading to port
  conflicts
In order to better randomize the initial port selection so that port
conflicts can be avoided, instead of using `Date.now()` for an initial
seed, use `crypto.randomInt()` which should provide more randomness and
hopefully avoid some of these race conditions.

re #827

* fix(getport): change crypto.randomInt "max" to be inclusive

---------

Co-authored-by: hasezoey <hasezoey@gmail.com>
@hasezoey
Copy link
Collaborator

version 9.1.5 has been released with #844, which at least fixes the use of Date.now() as a starting port (and instead uses crypto.randomInt)

@zvickery
Copy link

Setting "expNet0Listen": true seemed to help significantly with "Port already in use" errors I observed in my environment!

@JacksonUtsch
Copy link

Max port tries exceeded occurring sometimes in GitHub workflow now. 🤔

@hasezoey
Copy link
Collaborator

hasezoey commented Apr 6, 2024

@JacksonUtsch if it is in the CI, this likely means a lot of MMS instances have been created and not on the same node process instance, is this the case in your tests?
also did you already try the option EXP_NET0LISTEN and use a higher or equal MMS version as 9.1.5?

@JacksonUtsch
Copy link

JacksonUtsch commented Apr 8, 2024

EXP_NET0LISTEN option enabled on 9.1.0-beta.3, will update version and see if that resolves

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug keep Keep this issue open (no Stale)
Projects
None yet
Development

No branches or pull requests

8 participants