feat(instrumentation-runtime-node): emit logs for uncaught exceptions

packages/instrumentation-runtime-node/README.md

@@ -4,7 +4,11 @@
 [![Apache License][license-image]][license-image]
 
 This module provides automatic metric instrumentation that exposes measurements from the [Performance measurement APIs](https://nodejs.org/api/perf_hooks.html) (i.e. `perf_hooks`).
-While currently it is limited to metrics, it may be modified to produce other signals in the future.
+It can also emit OpenTelemetry logs for uncaught exceptions.
+When a configured logger provider exposes `forceFlush()` (for example, the SDK
+`LoggerProvider`), this instrumentation calls it immediately after emitting the
+uncaught-exception log record as a best-effort attempt to reduce log loss on
+process termination.
 
 ## Supported Versions
 
@@ -63,6 +67,8 @@ nodejs_performance_event_loop_utilization 0.010140079547955264
 | name                                        | type  | unit        | default | description                                                                                                                                                                                                                                                                                     |
 |---------------------------------------------|-------|-------------|---------|-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
 | [`monitoringPrecision`](./src/types.ts#L25) | `int` | millisecond | `10`    | The approximate number of milliseconds for which to calculate event loop utilization averages. A larger value will result in more accurate averages at the expense of less granular data. Should be set to below the scrape interval of your metrics collector to avoid duplicated data points. |
+| [`captureUncaughtException`](./src/types.ts#L31) | `bool` | - | `true` | Whether to emit a `LogRecord` for uncaught exceptions (severity `FATAL`). Uses the `uncaughtExceptionMonitor` process event. |
+| [`applyCustomAttributes`](./src/types.ts#L43) | `function` | - | `undefined` | Optional callback to attach custom attributes to emitted exception log records. |
 
 ## Useful links
 

packages/instrumentation-runtime-node/package.json

@@ -40,11 +40,15 @@
     "access": "public"
   },
   "dependencies": {
+    "@opentelemetry/api-logs": "^0.214.0",
+    "@opentelemetry/core": "^2.0.0",
     "@opentelemetry/instrumentation": "^0.214.0"
   },
   "devDependencies": {
     "@opentelemetry/api": "^1.3.0",
-    "@opentelemetry/sdk-metrics": "^2.0.0"
+    "@opentelemetry/sdk-logs": "^0.214.0",
+    "@opentelemetry/sdk-metrics": "^2.0.0",
+    "@opentelemetry/semantic-conventions": "^1.29.0"
   },
   "peerDependencies": {
     "@opentelemetry/api": "^1.3.0"

packages/instrumentation-runtime-node/src/instrumentation.ts

@@ -14,6 +14,13 @@
  * limitations under the License.
  */
 import { InstrumentationBase } from '@opentelemetry/instrumentation';
+import type {
+  AnyValueMap,
+  LogRecord,
+  LoggerProvider,
+} from '@opentelemetry/api-logs';
+import { SeverityNumber } from '@opentelemetry/api-logs';
+import { hrTime } from '@opentelemetry/core';
 
 import { RuntimeNodeInstrumentationConfig } from './types';
 import { MetricCollector } from './types/metricCollector';
@@ -27,10 +34,16 @@ import { PACKAGE_VERSION, PACKAGE_NAME } from './version';
 
 const DEFAULT_CONFIG: RuntimeNodeInstrumentationConfig = {
   monitoringPrecision: 10,
+  captureUncaughtException: true,
 };
 
 export class RuntimeNodeInstrumentation extends InstrumentationBase<RuntimeNodeInstrumentationConfig> {
   private readonly _collectors: MetricCollector[] = [];
+  private _loggerProvider?: LoggerProvider;
+  private _onUncaughtExceptionHandler?: (
+    error: Error,
+    origin: NodeJS.UncaughtExceptionOrigin
+  ) => void;
 
   constructor(config: RuntimeNodeInstrumentationConfig = {}) {
     super(
@@ -49,6 +62,7 @@ export class RuntimeNodeInstrumentation extends InstrumentationBase<RuntimeNodeI
       for (const collector of this._collectors) {
         collector.enable();
       }
+      this._registerExceptionHandlers();
     }
   }
 
@@ -72,12 +86,104 @@ export class RuntimeNodeInstrumentation extends InstrumentationBase<RuntimeNodeI
     for (const collector of this._collectors) {
       collector.enable();
     }
+    this._registerExceptionHandlers();
   }
 
   override disable() {
     super.disable();
     for (const collector of this._collectors) {
       collector.disable();
     }
+    this._unregisterExceptionHandlers();
+  }
+
+  override setLoggerProvider(loggerProvider: LoggerProvider): void {
+    super.setLoggerProvider(loggerProvider);
+    this._loggerProvider = loggerProvider;
+  }
+
+  private _registerExceptionHandlers() {
+    const config = this.getConfig();
+    if (config.captureUncaughtException && !this._onUncaughtExceptionHandler) {
+      this._onUncaughtExceptionHandler =
+        this._handleUncaughtException.bind(this);
+      process.on('uncaughtExceptionMonitor', this._onUncaughtExceptionHandler);
+    }
+  }
+
+  private _unregisterExceptionHandlers() {
+    if (this._onUncaughtExceptionHandler) {
+      process.removeListener(
+        'uncaughtExceptionMonitor',
+        this._onUncaughtExceptionHandler
+      );
+      this._onUncaughtExceptionHandler = undefined;
+    }
+  }
+
+  private _handleUncaughtException(
+    error: Error,
+    _origin: NodeJS.UncaughtExceptionOrigin
+  ) {
+    this._emitExceptionLog(error, SeverityNumber.FATAL, 'uncaughtException');
+  }
+
+  private _emitExceptionLog(
+    error: unknown,
+    severityNumber: SeverityNumber,
+    eventType: 'uncaughtException'
+  ) {
+    if (!this.isEnabled()) {
+      return;
+    }
+
+    const config = this.getConfig();
+    let customAttributes: AnyValueMap = {};
+    if (config.applyCustomAttributes) {
+      try {
+        customAttributes = config.applyCustomAttributes(error, eventType) ?? {};
+      } catch (err) {
+        this._diag.error(
+          'applyCustomAttributes threw while handling an exception',
+          err
+        );
+      }
+    }
+
+    const timestamp = hrTime();
+    const errorLog: LogRecord = {
+      body: 'exception',
+      exception: error,
+      severityNumber,
+      attributes: customAttributes,
+      timestamp,
+      observedTimestamp: timestamp,
+    };
+
+    this.logger.emit(errorLog);
+    this._forceFlushLogs();
+  }
+
+  private _forceFlushLogs() {
+    const loggerProvider = this._loggerProvider as
+      | (LoggerProvider & { forceFlush?: () => Promise<void> })
+      | undefined;
+    if (typeof loggerProvider?.forceFlush !== 'function') {
+      return;
+    }
+
+    try {
+      void loggerProvider.forceFlush().catch(err => {
+        this._diag.error(
+          'loggerProvider.forceFlush failed while handling an exception',
+          err
+        );
+      });
+    } catch (err) {
+      this._diag.error(
+        'loggerProvider.forceFlush threw while handling an exception',
+        err
+      );
+    }
   }
 }

packages/instrumentation-runtime-node/src/types.ts

@@ -13,9 +13,24 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
+import type { Attributes } from '@opentelemetry/api';
 import type { InstrumentationConfig } from '@opentelemetry/instrumentation';
 
 export interface RuntimeNodeInstrumentationConfig
   extends InstrumentationConfig {
   monitoringPrecision?: number;
+  /**
+   * Capture uncaught exceptions via process 'uncaughtExceptionMonitor' event.
+   * Enabled by default.
+   * @experimental
+   */
+  captureUncaughtException?: boolean;
+  /**
+   * Add custom attributes to the emitted exception log records.
+   * @experimental
+   */
+  applyCustomAttributes?: (
+    error: unknown,
+    eventType: 'uncaughtException'
+  ) => Attributes;
 }

packages/instrumentation-runtime-node/test/event_loop_delay.test.ts

@@ -16,7 +16,7 @@
 
 import * as assert from 'assert';
 import { MeterProvider, DataPointType } from '@opentelemetry/sdk-metrics';
-import { RuntimeNodeInstrumentation } from '../src';
+import { RuntimeNodeInstrumentation } from '../src/index';
 import { TestMetricReader } from './testMetricsReader';
 import * as semconv from '../src/semconv';
 
@@ -39,6 +39,7 @@ describe('nodejs.eventloop.delay.*', function () {
       // arrange
       const instrumentation = new RuntimeNodeInstrumentation({
         monitoringPrecision: 10,
+        captureUncaughtException: false,
       });
       instrumentation.setMeterProvider(meterProvider);
 

packages/instrumentation-runtime-node/test/event_loop_time.test.ts

@@ -16,7 +16,7 @@
 
 import * as assert from 'assert';
 import { MeterProvider } from '@opentelemetry/sdk-metrics';
-import { RuntimeNodeInstrumentation } from '../src';
+import { RuntimeNodeInstrumentation } from '../src/index';
 import { TestMetricReader } from './testMetricsReader';
 import { METRIC_NODEJS_EVENTLOOP_TIME } from '../src/semconv';
 
@@ -38,6 +38,7 @@ describe('nodejs.eventloop.time', function () {
     const instrumentation = new RuntimeNodeInstrumentation({
       monitoringPrecision: MEASUREMENT_INTERVAL,
       enabled: false,
+      captureUncaughtException: false,
     });
     instrumentation.setMeterProvider(meterProvider);
 
@@ -55,6 +56,7 @@ describe('nodejs.eventloop.time', function () {
     // arrange
     const instrumentation = new RuntimeNodeInstrumentation({
       monitoringPrecision: MEASUREMENT_INTERVAL,
+      captureUncaughtException: false,
     });
     instrumentation.setMeterProvider(meterProvider);
 

packages/instrumentation-runtime-node/test/event_loop_utilization.test.ts

@@ -16,7 +16,7 @@
 
 import * as assert from 'assert';
 import { MeterProvider } from '@opentelemetry/sdk-metrics';
-import { RuntimeNodeInstrumentation } from '../src';
+import { RuntimeNodeInstrumentation } from '../src/index';
 import { TestMetricReader } from './testMetricsReader';
 import { METRIC_NODEJS_EVENTLOOP_UTILIZATION } from '../src/semconv';
 
@@ -38,6 +38,7 @@ describe('nodejs.eventloop.utilization', function () {
     const instrumentation = new RuntimeNodeInstrumentation({
       monitoringPrecision: MEASUREMENT_INTERVAL,
       enabled: false,
+      captureUncaughtException: false,
     });
     instrumentation.setMeterProvider(meterProvider);
 
@@ -55,6 +56,7 @@ describe('nodejs.eventloop.utilization', function () {
     // arrange
     const instrumentation = new RuntimeNodeInstrumentation({
       monitoringPrecision: MEASUREMENT_INTERVAL,
+      captureUncaughtException: false,
     });
     instrumentation.setMeterProvider(meterProvider);
 
@@ -173,9 +175,17 @@ describe('nodejs.eventloop.utilization', function () {
       'Expected utilization in fourth measurement to be 1'
     );
 
-    // Fifth measurement: Do some NON-blocking work (sanity check, should be low)
-    await new Promise(resolve => setTimeout(resolve, 50));
-    const fifthUtilization = await collectUtilization();
+    // Fifth measurement: Do some non-blocking work and retry a few times to
+    // avoid a timing flake where one collection window can still include the
+    // previous busy period.
+    let fifthUtilization = 1;
+    for (let i = 0; i < 5; i++) {
+      await new Promise(resolve => setTimeout(resolve, 50));
+      fifthUtilization = await collectUtilization();
+      if (fifthUtilization < 1) {
+        break;
+      }
+    }
     assert.ok(
       fifthUtilization < 1,
       `Expected utilization in fifth measurement to be less than 1, but got ${fifthUtilization}`