It's the Circle of (NestJS) Life - NestJS Lifecycle breakdown

First blogpost about stuff I’ve learned since I (Shay Nehmad) started working at Opsin Security!

Check out this post for more details.

NestJS lifecycle issues

Recently at work I filed a new ticket on Linear related to NestJS lifecycle. It was a followup on a ramble on a Slack thread:

When a certain shared module provider started (vagueness on purpose), even though I wanted it to load only once, it was being loaded multiple times. In this case it was annoying because it was the database module - and it ran migrations multiple times each load. Here’s how it looked in the logs (simplified):

> nest start

69061 2/26/2025, 3:21:16 PM     LOG [NestFactory] Starting Nest application... +0ms
...
69061 2/26/2025, 3:21:16 PM     LOG [InstanceLoader] ConfigModule dependencies initialized +1ms
69061 2/26/2025, 3:21:16 PM   DEBUG [DatabaseConnectionProvider] Connecting to DB using pg... +0ms
69061 2/26/2025, 3:21:16 PM   DEBUG [DatabaseConnectionProvider] Connecting to DB using pg... +0ms
69061 2/26/2025, 3:21:16 PM   DEBUG [DatabaseConnectionProvider] Connecting to DB using pg... +0ms
...
69061 2/26/2025, 3:21:17 PM   DEBUG [DatabaseConnectionProvider] Running migrations using dbmate... +0ms
69061 2/26/2025, 3:21:17 PM     LOG [DatabaseConnectionProvider] Migrations ran successfully - {
  output: 'Applying: 20250120134452_REDACRED.sql\n' +
    'Applied: 20250120134452_REDACTED.sql in 9.877167ms\n' +
...
} +0ms
69061 2/26/2025, 3:21:17 PM   DEBUG [DatabaseConnectionProvider] Running migrations using dbmate... +0ms
69061 2/26/2025, 3:21:17 PM     LOG [DatabaseConnectionProvider] Migrations ran successfully - { output: '' } +0ms
...
69061 2/26/2025, 3:21:17 PM   DEBUG [DatabaseConnectionProvider] Running migrations using dbmate... +0ms
69061 2/26/2025, 3:21:17 PM     LOG [DatabaseConnectionProvider] Migrations ran successfully - { output: '' } +0ms
69061 2/26/2025, 3:21:17 PM     LOG [NestApplication] Nest application successfully started +0ms
69061 2/26/2025, 3:21:17 PM     LOG [bootstrap] Listening on http://[::1]:4000 +0ms

It didn’t cause any bugs in prod, but it polluted the logs and made my skin crawl - exactly the sorts of issues that you shouldn’t let fester too long…

Note: we run the migrations using the simple and effective dbmate, which I’ve been using for years now.

RTFM GG EZ

I started looking into the NestJS docs. My module called the migrate function during the onModuleInit lifecycle hook. From the name, it sounded like it was the right place to call it. The docs say:

“onModuleInit(): Called once the host module’s dependencies have been resolved.”

The docs say “once”. The code runs multiple times. What gives?

EDIT a few days after writing this blog post.

THE DOCS ARE RIGHT, BUT ONLY TECHNICALLY RIGHT. Which makes life harder for us mere mortals, especially “English as a second language” types. This sentence, as pointed out to me by Diego González on Rands:

Not trying to be the :actually: guy :smile: but this:

“onModuleInit(): Called once the host module’s dependencies have been resolved.”

simply means:

“onModuleInit(): Called after the host module’s dependencies have been resolved.”

and not:

“onModuleInit(): Called one time [after] the host module’s dependencies have been resolved.”

So I opened a pull request to NestJS to clarify the docs, let’s see what they say.

The quick fix, because I’m at a startup

I wanted to delve into this deeply, but startup life means “find a pragmatic solution and move on”. So, if you have a similar issue, here’s a quick panecea:

@Injectable()
export class ModuleThatShouldOnlyInitOnce
  implements OnModuleInit, OnModuleDestroy {
  private static initialized: boolean = false;
  
  async onModuleInit() {
    if (ModuleThatShouldOnlyInitOnce.initialized) {
      return;
    }
    this.doInitStuff();  // e.g. run migrations
    ModuleThatShouldOnlyInitOnce.initialized = true;
  }
}

You can repeat this trick for the destroy hook if it’s not idempotent as well. If you we’re just looking for how to fix: that’s it!

Figuring out the lifecycle, for real

So, I fixed the issue, and my fix worked. I’ve moved on with my life. But what if the docs are wrong? Or what if I misunderstood them? I’ve been using NestJS for a while now; shouldn’t I contribute to the internet’s collective knowledge of how the framework works a bit more?

I thought about two ways to do this:

1. Read the source code - I could read the NestJS source code, figure out how it works, and write a blog post about it.
2. Write a demo app - I could write a demo app that demonstrates the lifecycle events.

Wading in the source code

I was happy to see this in NestJS’s NestApplication class:

  public async init(): Promise<this> {
    if (this.isInitialized) {
      return this;
    }

The NestJS team and me are on the same page :) So, let’s find the relevant call stack and read it slowly and carefully. Most function calls here are links to the actual source code:

1. The app initialized in NestApplication.init(), which calls:
2. await this.callInitHook();, which calls:
3. getModulesToTriggerHooksOn(): Module[] { - this returns a list of modules that should be initialized, sorted by their distance, to create a topological sort (according to the unit test). This list is NOT deduped (at least anywhere I can see).
4. Then, for each module in the array, callInitHook() calls the callModuleInitHook method. Which you’d think just calls the onModuleInit method. But it does a lot more! It looks like this, and let’s break it down:

export async function callModuleInitHook(module: Module): Promise<void> {
  const providers = module.getNonAliasProviders();
  // Module (class) instance is the first element of the providers array
  // Lifecycle hook has to be called once all classes are properly initialized
  const [_, moduleClassHost] = providers.shift()!;
  const instances = [
    ...module.controllers,
    ...providers,
    ...module.injectables,
    ...module.middlewares,
  ];

  const nonTransientInstances = getNonTransientInstances(instances);
  await Promise.all(callOperator(nonTransientInstances));

  const transientInstances = getTransientInstances(instances);
  await Promise.all(callOperator(transientInstances));

  // Call the instance itself
  const moduleClassInstance = moduleClassHost.instance;
  if (
    moduleClassInstance &&
    hasOnModuleInitHook(moduleClassInstance) &&
    moduleClassHost.isDependencyTreeStatic()
  ) {
    await moduleClassInstance.onModuleInit();
  }

So, what does callModuleInitHook do:

5. Gets all the module’s instances of providers, controllers, injectables, and middlewares
6. Separates the transiant and non-transiant providers

Hold up; WTF are [non-]transiant providers? I had to look this up, and getTransientInstances filters and returns providers that construct a new instance for every injection (useful for stateless helpers), while getNonTransientInstances returns providers that are not transient (typically singleton or request-scoped). Importantly: By default, providers in NestJS are singletons within the scope of the application or module. This means a single instance is created and shared across the app.

Back to the code…

7. It calls callOperator, which filters non-nil instances and modules that don’t have an onModuleInit method, and then calls the onModuleInit method on each of them.
8. Finally, it calls the onModuleInit() method on the module class itself.

After reading all this code, I feel confident that there isn’t a straightforward mechanism I can see to promise that a module’s onModuleInit method will only be called once.

There might be one. I wasn’t able to find it after this pretty thorough investigation, and the blackbox behavior of my bug from before seems to confirm my investigation. But I may have missed something.

The fact is if I couldn’t figure it out yet after reading the docs and the code, even if there is a “correct” way to do it, it’s not obvious enough.

The only thing worth mentioning is that the callOperator function filters non-nil instances. But is that enough? not really, since they all run in parallel (using await Promise.all(callOperator(nonTransientInstances))), so if the it might be that multiple instances are initialized in parallel.

The code is complex enough that I don’t think static analysis will help me understand it better. To the blackbox-mobile!

Writing a demo app

For each one of the modules, I added prints in the onModuleInit hook, like so:

@Module({})
export class FeatureModuleAModule implements OnModuleInit {
  onModuleInit() {
    console.log('FeatureModuleA initialized');
  }
}

Before adding any dependencies, we’re getting:

FeatureModuleA initialized
FeatureModuleB initialized
SharedModuleA initialized
SharedModuleB initialized

And I added the dependencies like so:

1. FeatureModuleA depends on SharedModuleA
2. FeatureModuleB depends on FeatureModuleA and SharedModuleB

graph TD;
    FA[FeatureModuleA] -->|depends on| SA[SharedModuleA];
    FB[FeatureModuleB] -->|depends on| FA;
    FB -->|depends on| SB[SharedModuleB];

Now we’re getting:

FeatureModuleA initialized
SharedModuleA initialized
SharedModuleB initialized
FeatureModuleB initialized

Now let’s make SharedModuleB depend on FeatureModuleA:

graph TD;
    FA[FeatureModuleA] -->|depends on| SA[SharedModuleA];
    FB[FeatureModuleB] -->|depends on| FA;
    FB -->|depends on| SB[SharedModuleB];
    SB -->|depends on| FA;

And now, we’re getting:

SharedModuleA initialized
FeatureModuleA initialized
SharedModuleB initialized
FeatureModuleB initialized

So, a different order (topological sort) of the same modules. But no duplicates. That means that the problem is with providers that implement OnModuleInit and not modules on their own. Let’s try to add a shared provider:

And I’ve the shared provider provided from SharedModuleB.

graph TD;
    FA[FeatureModuleA] -->|depends on| SA[SharedModuleA];
    FB[FeatureModuleB] -->|depends on| FA;
    FB -->|depends on| SB[SharedModuleB];
    SB -->|depends on| FA;
    SB ==>|provides| SP[SharedProvider];

Finally, now we get a reproduction!

SharedModuleA initialized
FeatureModuleA initialized
SharedProvider initialized  <-- from SharedModuleB
SharedModuleB initialized
FeatureModuleB initialized
SharedProvider initialized  <-- from FeatureModuleB

So, the documentation is inaccurate when it comes to PROVIDERS that implement OnModuleInit. The onModuleInit method is called for each provider that implements the OnModuleInit interface, and not just once per module. This is the root cause of the issue I was having. The fix I implemented in the quick fix section is the correct fix, and it works for both modules and providers.

Conclusion

1. Read docs slowly. Slow is smooth, smooth is fast
2. Don’t trust the docs
3. Don’t trust the code
4. Don’t trust anyone
5. Simple fix is normally the best fix