NestJS app initialization issue

[szabolcs-szilagyi]

When you have multiple parallel requests to the API, when the page first loads, then you will end up with multiple INestApplication instances. The async-await usage in the backend/main.ts doesn't guarantee that there will be a single instance of app.

Create a dirty test change in a fork. When running it and loading the page there will be multiple "App not initialized yet!" lines in the console.

Would suggest to change from async-await to just dealing with Promise instead. So that part could look like:

export module Backend {

  let app: Promise<INestApplication>;

  export function getApp() {
    if (app) return app;

    app = NestFactory.create(
      AppModule,
      { bodyParser: false }
    )
      .then((appInstance) => {
        appInstance.setGlobalPrefix("api");
        return appInstance.init().then(() => appInstance);
      });

    return app;
  }

  export async function getListener() {
    const app = await getApp();
    const server: http.Server = app.getHttpServer();
    const [listener] = server.listeners("request") as NextApiHandler[];
    return listener;
  }
}

[szabolcs-szilagyi]

Hmm further looking at it this may not solve it :thinking:

Looking at this issue as I also got a problem with database connection, it keeps wanting to create new database connection, when there is one already with the same name.

[Nest] 2273044   - 17/04/2021, 21:14:10   [TypeOrmModule] Unable to connect to the database. Retrying (3)... +1212ms
AlreadyHasActiveConnectionError: Cannot create a new connection named "default", because connection with such name already exist and it now has an active connection session.

[Skn0tt]

let app: INestApplication;
let appPromise: Promise<void>;

export async function getApp() {
  if (app) {
    return app;
  }

  if (!appPromise) {
    appPromise = new Promise(async (resolve) => {
      const appInCreation = await NestFactory.create(AppModule, {
        bodyParser: false,
      });
      appInCreation.setGlobalPrefix("api");

      await appInCreation.init();
      app = appInCreation;
      resolve();
    });
  }

  await appPromise;
  return app;
}

This fixed it for me, can you confirm?

[szabolcs-szilagyi]

hello @Skn0tt,

Yes it seems to solve it.

[szabolcs-szilagyi]

pardon, small correction: on the test case noted here. It works, but on my other project even with this I get the multiple initialization.

Log from there:

$ npm run dev-experiment

> myna@0.1.0 dev-experiment /home/user/Projects/Personal/nestjs-nextjs-project
> DEV_PORT=3000 API_PATH='api/legacy' next dev

ready - started server on 0.0.0.0:3000, url: http://localhost:3000
warn  - React 17.0.1 or newer will be required to leverage all of the upcoming features in Next.js 11. Read more: https://err.sh/next.js/react-version
info  - Using external babel configuration from /home/user/Projects/Personal/nestjs-nextjs-project/.babelrc
event - compiled successfully
event - build page: /[idname]
wait  - compiling...
event - compiled successfully
event - build page: /api/[...catchAll]
wait  - compiling...
event - compiled successfully
################ App not initialized yet! ###########
[Nest] 2562650   - 19/04/2021, 19:11:42   [NestFactory] Starting Nest application...
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TypeOrmModule dependencies initialized +68ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] AppModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TypeOrmCoreModule dependencies initialized +39ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TypeOrmModule dependencies initialized +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TypeOrmModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TypeOrmModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TypeOrmModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TypeOrmModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TypeOrmModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] UserModule dependencies initialized +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] NewsletterModule dependencies initialized +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] AddressModule dependencies initialized +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] TokenModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] ProductModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [InstanceLoader] CartModule dependencies initialized +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RoutesResolver] AppController {/api}: +5ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/legacy, GET} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RoutesResolver] AddressController {/api/address}: +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/address/shipping-info, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/address/address-data, GET} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/address/address-data, POST} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RoutesResolver] TokenController {/api/token}: +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/token/mail-login, POST} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/token/login, POST} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/token/ping, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/token/am-i-logged-in, GET} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/token/get-user-data, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/token/update-user-data, POST} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/token/get-email, GET} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/token/session, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RoutesResolver] CartController {/api/cart}: +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/cart, POST} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/cart/:id, DELETE} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/cart/products-in-cart, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/cart/products-paid, POST} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/cart/availability, GET} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/cart/more-accurate-availability, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/cart/total, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RoutesResolver] NewsletterController {/api/newsletter}: +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/newsletter/subscribe, POST} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/newsletter/confirm, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/newsletter/unsubscribe, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RoutesResolver] ProductController {/api/product}: +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/product, GET} route +1ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [RouterExplorer] Mapped {/api/product/:id, GET} route +0ms
[Nest] 2562650   - 19/04/2021, 19:11:42   [NestApplication] Nest application successfully started +2ms
event - build page: /shop-collections
wait  - compiling...
event - compiled successfully
################ App not initialized yet! ###########
[Nest] 2562650   - 19/04/2021, 19:12:02   [NestFactory] Starting Nest application... +20401ms
[Nest] 2562650   - 19/04/2021, 19:12:02   [TypeOrmModule] Unable to connect to the database. Retrying (1)... +28ms
AlreadyHasActiveConnectionError: Cannot create a new connection named "default", because connection with such name already exist and it now has an active connection session.
    at new AlreadyHasActiveConnectionError (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/error/AlreadyHasActiveConnectionError.js:10:28)
    at ConnectionManager.create (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/connection/ConnectionManager.js:51:23)
    at Object.<anonymous> (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/index.js:195:66)
    at step (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/node_modules/tslib/tslib.js:141:27)
    at Object.next (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/node_modules/tslib/tslib.js:122:57)
    at /home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/node_modules/tslib/tslib.js:115:75
    at new Promise (<anonymous>)
    at Object.__awaiter (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/node_modules/tslib/tslib.js:111:16)
    at Object.createConnection (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/index.js:180:20)
    at /home/user/Projects/Personal/nestjs-nextjs-project/node_modules/@nestjs/typeorm/dist/typeorm-core.module.js:171:34
    at Observable._subscribe (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/rxjs/internal/observable/defer.js:10:21)
    at Observable._trySubscribe (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/rxjs/internal/Observable.js:44:25)
    at Observable.subscribe (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/rxjs/internal/Observable.js:30:22)
    at RetryWhenOperator.call (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/rxjs/internal/operators/retryWhen.js:28:23)
    at Observable.subscribe (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/rxjs/internal/Observable.js:25:31)
    at /home/user/Projects/Personal/nestjs-nextjs-project/node_modules/rxjs/internal/Observable.js:99:19
[Nest] 2562650   - 19/04/2021, 19:12:02   [InstanceLoader] TypeOrmModule dependencies initialized +2ms
[Nest] 2562650   - 19/04/2021, 19:12:02   [InstanceLoader] AppModule dependencies initialized +0ms
################ App not initialized yet! ###########
################ App not initialized yet! ###########
################ App not initialized yet! ###########
[Nest] 2562650   - 19/04/2021, 19:12:05   [TypeOrmModule] Unable to connect to the database. Retrying (2)... +2999ms
AlreadyHasActiveConnectionError: Cannot create a new connection named "default", because connection with such name already exist and it now has an active connection session.
    at new AlreadyHasActiveConnectionError (/home/user/Projects/Personal/nestjs-nextjs-project/node_modules/typeorm/error/AlreadyHasActiveConnectionError.js:10:28)

[szabolcs-szilagyi]

From the above just ignore the TypeORM issue - needed to add the keepConnectionAlive: true option for it. But the reinitialization of the NestJS app is still happening. It also happens when I navigate from one page to another:

[Nest] 2573948   - 19/04/2021, 20:10:22   [RouterExplorer] Mapped {/api/product, GET} route +1ms
[Nest] 2573948   - 19/04/2021, 20:10:22   [RouterExplorer] Mapped {/api/product/:id, GET} route +0ms
[Nest] 2573948   - 19/04/2021, 20:10:22   [NestApplication] Nest application successfully started +2ms
event - build page: /lookbook
wait  - compiling...
event - compiled successfully
################ App not initialized yet! ###########
[Nest] 2573948   - 19/04/2021, 20:10:33   [NestFactory] Starting Nest application... +11466ms
[Nest] 2573948   - 19/04/2021, 20:10:33   [InstanceLoader] TypeOrmModule dependencies initialized +13ms
[Nest] 2573948   - 19/04/2021, 20:10:33   [InstanceLoader] AppModule dependencies initialized +1ms

it builds the page that I navigate to and then also starts the Nest part again.

[Skn0tt]

Can you confirm this also happens during production? I think that's a development thing, and I haven't yet found out how (or tried) to fix this.

[szabolcs-szilagyi]

Tired it in production mode, it also happens there. With the difference, that it happens multiple times upon first page load, but then it doesn't happen again upon navigating to a different page.

$ DEV_PORT=3000 API_PATH='api/legacy' npm run start

> myna@0.1.0 start /home/user/Projects/Personal/nestjs-nextjs-project
> next start

ready - started server on 0.0.0.0:3000, url: http://localhost:3000
################ App not initialized yet! ###########
[Nest] 2640210   - 20/04/2021, 08:48:41   [NestFactory] Starting Nest application...
[Nest] 2640210   - 20/04/2021, 08:48:41   [InstanceLoader] TypeOrmModule dependencies initialized +33ms
[Nest] 2640210   - 20/04/2021, 08:48:41   [InstanceLoader] AppModule dependencies initialized +0ms
################ App not initialized yet! ###########
################ App not initialized yet! ###########
################ App not initialized yet! ###########
################ App not initialized yet! ###########
################ App not initialized yet! ###########
[Nest] 2640210   - 20/04/2021, 08:48:41   [InstanceLoader] TypeOrmCoreModule dependencies initialized +67ms
[Nest] 2640210   - 20/04/2021, 08:48:41   [InstanceLoader] TypeOrmModule dependencies initialized +1ms
[Nest] 2640210   - 20/04/2021, 08:48:41   [InstanceLoader] TypeOrmModule dependencies initialized +0ms
[Nest] 2640210   - 20/04/2021, 08:48:41   [InstanceLoader] TypeOrmModule dependencies initialized +0ms

[maxell1452]

i try assign app to global for keeping app reference in dev mode (refer). It works for database connection without keepConnectionAlive props in Typeorm options but using app in getStaticPaths and getStaicProps will reinitialize the app in dev mode

main.ts

const registerService = (name: string, initFn) => {
  console.log(global[name]);
  if (process.env.NODE_ENV === 'development') {
    if (!(name in global)) {
      global[name] = initFn();
    }
    return global[name];
  }
  return initFn();
};

export const Backend = registerService('backend', () => {
  const app = registerService('nest', async () => {
    const _app = await NestFactory.create(AppModule, { bodyParser: false });
    _app.setGlobalPrefix('api');

    _app.init();

    return _app;
  });
  const getApp: () => Promise<INestApplication> = async () => {
    return await app;
  };

  const getListener = async () => {
    const app = await getApp();
    const server: http.Server = app.getHttpServer();
    const [listener] = server.listeners('request') as NextApiHandler[];
    return listener;
  };

  return {
    getApp,
    getListener,
  };
});

[logusgraphics]

The only weird behavior I get is that I must instantiate the @Injectable decorated classes manually.

No matter if I register these providers on each module or on the main module, when trying to inject these services in the constructor of a controller they just won't be instantiated automatically.

Modules, controllers, guards, everything else works fine. But injectables are undefined upon injection in the constructor.

So I have to manually create new instances on the constructor. If I create a new app and serve with with nest start it all works as expected. So I assume that the CLI triggers something that the app.listen or app.init methods don't.

[logusgraphics]

Ok, I found the issue turned out to be in my tsconfig.json file:

"emitDecoratorMetadata": true