Nest.js ECONNREFUSED after an uncaught exception

[abreu-gyant]

Describe the bug

When using APM with Nest.js, after an uncaught exception, all HTTP requests are refused.

To Reproduce

Steps to reproduce the behavior:

1. Bootstrap Nest.js using the CLI
2. Install APM
3. Replace main.ts with the following code:

import * as apm from 'elastic-apm-node';
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';

apm.start({
  serviceName: 'Nest APM Example',
  serverUrl: 'http://localhost:8200/',
});

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  await app.listen(3000);
  setTimeout(() => {
    throw new Error('Some error');
  }, 3000);
}
bootstrap();

5. Start the application npm run start:dev
6. After the 3s make HTTP request to 'http://localhost:3000/'
7. Expect "Error: connect ECONNREFUSED 127.0.0.1:3000"

Expected behavior

The application should never return ECONNREFUSED after an uncaught exception.

Environment (please complete the following information)

• OS: macOS (11.3.1)
• Node.js version:
• APM Server version: 3.21.1
• Agent version: 3.21.1

How are you starting the agent? (please tick one of the boxes)

• Calling agent.start() directly (e.g. require('elastic-apm-node').start(...))
• Requiring elastic-apm-node/start from within the source code
• Starting node with -r elastic-apm-node/start

[trentm]

@abreu-gyant Thank you very much for the repro code! Apologies for the delay in responding.

I am able to reproduce what you are describing. However, I believe the APM agent is operating correctly -- with one caveat that the APM agent default behaviour is a little surprising.

without APM

First, if we remove APM from main.ts:

// import * as apm from 'elastic-apm-node';
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';

// apm.start({
//   serviceName: 'Nest APM Example',
//   serverUrl: 'http://localhost:8200/',
// });

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  await app.listen(3000);
  setTimeout(() => {
    throw new Error('Some error');
  }, 3000);
}
bootstrap();

And run this, we get the same crash:

% npm start

> nesthi1@0.0.1 start /Users/trentm/tmp/nestplay/nesthi1
> nest start

[Nest] 89074  - 2021-11-03, 4:44:49 p.m.     LOG [NestFactory] Starting Nest application...
[Nest] 89074  - 2021-11-03, 4:44:49 p.m.     LOG [InstanceLoader] AppModule dependencies initialized +23ms
[Nest] 89074  - 2021-11-03, 4:44:50 p.m.     LOG [RoutesResolver] AppController {/}: +5ms
[Nest] 89074  - 2021-11-03, 4:44:50 p.m.     LOG [RouterExplorer] Mapped {/, GET} route +2ms
[Nest] 89074  - 2021-11-03, 4:44:50 p.m.     LOG [NestApplication] Nest application successfully started +1ms

/Users/trentm/tmp/nestplay/nesthi1/src/main.ts:16
    throw new Error('Some error');
          ^
Error: Some error
    at Timeout._onTimeout (/Users/trentm/tmp/nestplay/nesthi1/src/main.ts:16:11)
    at listOnTimeout (internal/timers.js:557:17)
    at processTimers (internal/timers.js:500:7)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! nesthi1@0.0.1 start: `nest start`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the nesthi1@0.0.1 start 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!     /Users/trentm/.npm/_logs/2021-11-03T23_44_53_074Z-debug.log

with APM

Again with APM:

import * as apm from 'elastic-apm-node';
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';

apm.start({
  serviceName: 'Nest APM Example',
  serverUrl: 'http://localhost:8200/',
});

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  await app.listen(3000);
  setTimeout(() => {
    throw new Error('Some error');
  }, 3000);
}
bootstrap();

we see almost the same behaviour:

% npm start

> nesthi1@0.0.1 start /Users/trentm/tmp/nestplay/nesthi1
> nest start

[Nest] 89098  - 2021-11-03, 4:45:43 p.m.     LOG [NestFactory] Starting Nest application...
[Nest] 89098  - 2021-11-03, 4:45:43 p.m.     LOG [InstanceLoader] AppModule dependencies initialized +22ms
[Nest] 89098  - 2021-11-03, 4:45:43 p.m.     LOG [RoutesResolver] AppController {/}: +4ms
[Nest] 89098  - 2021-11-03, 4:45:43 p.m.     LOG [RouterExplorer] Mapped {/, GET} route +2ms
[Nest] 89098  - 2021-11-03, 4:45:43 p.m.     LOG [NestApplication] Nest application successfully started +1ms
{"log.level":"info","@timestamp":"2021-11-03T23:45:46.810Z","log":{"logger":"elastic-apm-node"},"ecs":{"version":"1.6.0"},"message":"Sending error to Elastic APM: {\"id\":\"06939884974cdef22605341481590cde\"}"}
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! nesthi1@0.0.1 start: `nest start`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the nesthi1@0.0.1 start 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!     /Users/trentm/.npm/_logs/2021-11-03T23_45_46_880Z-debug.log

1. An error is reported to the APM server.
2. The application crashes on the uncaught exception.

The difference in application behaviour is that the uncaught exception is not printed out before terminating. The logUncaughtExceptions: true config var to the APM agent can be used to turn that on, so that what is happening is less subtle.

For future versions of the APM agent, I think that logUncaughtExceptions: true (I've opened #2412 for that). As well, there is #2367 to consider switching to another mechanism that might allow the APM agent to capture uncaughtExceptions without having this side-effect.

Did you perhaps expect that APM agent should capture uncaught exceptions and prevent the application from crashing? If so, it might be worth us improving the APM agent docs.

[abreu-gyant]

@trentm Thank you so much for your detailed explanation. Now it really makes sense. When using npm run start:dev (in dev mode), nest does not output the stderr, and because uncaught exceptions with APM is not printing by default I assumed that APM was handling the exception and preventing it from crashing. I think it will be nice having some documentation about it. Once again thanks @trentm :)

[trentm]

I've opened #2421 to attempt to somewhat clarify in the docs. This isn't perfect because I'm not sure all users will know to look at the captureExceptions docs.