From ea0362d4140b75ce60d72f76e75a8924af52186e Mon Sep 17 00:00:00 2001 From: Jackson Weber Date: Tue, 4 Aug 2026 15:01:21 -0700 Subject: [PATCH 1/7] fix(logs,metrics): stop duplicating log records and fix zeroed performance counters MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three defects surfaced by an end-to-end run that captured the Breeze envelopes actually transmitted to Application Insights. 1. Every bunyan and winston record was transmitted twice. `LogHandler` constructed its own `BunyanInstrumentation` / `WinstonInstrumentation`. `InstrumentationBase` auto-enables an instrumentation whose config has `enabled: true`, so that second copy patched `bunyan` and appended a second `OpenTelemetryBunyanStream` to every logger — even though `LogHandler.getInstrumentations()` was never passed to the `NodeSDK`. The trace instrumentations were unaffected because they unwrap before wrapping; the bunyan instrumentation does not. `createInstrumentations` is now the single owner of all instrumentations, and the dead `getInstrumentations()` accessor is gone. 2. `\Process(??APP_WIN32_PROC??)\% Processor Time Normalized` was always 0. `getNormalizedProcessTime` and `getProcessTime` shared `lastAppCpuUsage`, `lastHrtime` and `lastCpusProcess`, so whichever observable callback ran second measured a near-zero delta. The normalized gauge now keeps its own last-sample state. 3. The first export of `Requests/Sec` and the exception rate was always ~0. `lastRequestRate` was re-initialized to `time: 0` after the constructor had already seeded it with `Date.now()`, so the first collection interval spanned decades. Dropped the re-initialization and seeded `lastExceptionRate` the same way. The logHandler tests that only asserted on the removed accessor now cover `createInstrumentations`, plus a regression test asserting exactly one bunyan instrumentation is created. Verified end to end against a live Application Insights resource: before the fix Kusto reported 2 rows per bunyan message, after the fix 1. The normalized CPU counter went from 0.0000 to 0.13-0.27 and `Requests/Sec` reports ~1.9 on the first export instead of 0. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- CHANGELOG.md | 5 ++ src/azureMonitor/logs/handler.ts | 42 +++----------- .../metrics/performanceCounters.ts | 40 +++++++++---- test/internal/unit/logs/logHandler.test.ts | 57 +++++++++++++------ 4 files changed, 81 insertions(+), 63 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 437a092..20c9086 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,11 @@ ## [Unreleased] +### Bugs Fixed +- Stop emitting every `bunyan` and `winston` log record twice. `LogHandler` constructed a second `BunyanInstrumentation` / `WinstonInstrumentation`; `InstrumentationBase` auto-enables an instrumentation whose config has `enabled: true`, so that second copy patched the logging module and appended a second `OpenTelemetryBunyanStream` to every logger — even though `LogHandler.getInstrumentations()` was never registered with the `NodeSDK`. `createInstrumentations` is now the single owner of all instrumentations. +- Report a real value for the `\Process(??APP_WIN32_PROC??)\% Processor Time Normalized` performance counter. It shared `lastAppCpuUsage` / `lastHrtime` / `lastCpusProcess` with the standard process time counter, so whichever observable callback ran second measured a near-zero delta and always reported `0`. +- Report a real value on the first export of the `\ASP.NET Applications(??APP_W3SVC_PROC??)\Requests/Sec` and `\.NET CLR Exceptions(??APP_CLR_PROC??)\# of Exceps Thrown / sec` performance counters. `lastRequestRate` was re-initialized to `time: 0` after the constructor had already seeded it with the current time, making the first collection interval span decades and driving the computed rate to ~0. + ## [1.3.0] - 2026-08-03 ### Features Added diff --git a/src/azureMonitor/logs/handler.ts b/src/azureMonitor/logs/handler.ts index 85732be..0597df6 100644 --- a/src/azureMonitor/logs/handler.ts +++ b/src/azureMonitor/logs/handler.ts @@ -2,15 +2,11 @@ // Licensed under the MIT License. import { AzureMonitorLogExporter } from "@azure/monitor-opentelemetry-exporter"; -import type { Instrumentation } from "@opentelemetry/instrumentation"; -import { BunyanInstrumentation } from "@opentelemetry/instrumentation-bunyan"; -import { WinstonInstrumentation } from "@opentelemetry/instrumentation-winston"; import type { BatchLogRecordProcessor } from "@opentelemetry/sdk-logs"; import type { InternalConfig } from "../../shared/config.js"; import type { MetricHandler } from "../metrics/handler.js"; import { AzureLogRecordProcessor } from "./logRecordProcessor.js"; import { AzureBatchLogRecordProcessor } from "./batchLogRecordProcessor.js"; -import { logLevelToSeverityNumber } from "../utils/logUtils.js"; /** * Azure Monitor OpenTelemetry Log Handler @@ -21,10 +17,16 @@ export class LogHandler { private _azureBatchLogRecordProcessor: AzureBatchLogRecordProcessor; private _metricHandler: MetricHandler; private _config: InternalConfig; - private _instrumentations: Instrumentation[]; /** * Initializes a new instance of the LogHandler class. + * + * Log instrumentations (bunyan, winston, console) are not created here — they + * are created once by `createInstrumentations` and registered with the + * NodeSDK. Creating them here as well would enable a second copy of each + * instrumentation, which appends a second OpenTelemetry stream to every + * logger and duplicates each log record. + * * @param config - Microsoft OpenTelemetry configuration. * @param metricHandler - MetricHandler. */ @@ -36,8 +38,6 @@ export class LogHandler { enableTraceBasedSamplingForLogs: this._config.enableTraceBasedSamplingForLogs, }); this._azureLogRecordProcessor = new AzureLogRecordProcessor(this._metricHandler); - this._instrumentations = []; - this._initializeInstrumentations(); } public getAzureLogRecordProcessor(): AzureLogRecordProcessor { @@ -47,32 +47,4 @@ export class LogHandler { public getBatchLogRecordProcessor(): BatchLogRecordProcessor { return this._azureBatchLogRecordProcessor; } - - public getInstrumentations(): Instrumentation[] { - return this._instrumentations; - } - - /** - * Start auto collection of telemetry - */ - private _initializeInstrumentations(): void { - const logLevelEnv = process.env.APPLICATIONINSIGHTS_INSTRUMENTATION_LOGGING_LEVEL; - - if (this._config.instrumentationOptions.bunyan?.enabled) { - this._instrumentations.push( - new BunyanInstrumentation({ - ...this._config.instrumentationOptions.bunyan, - logSeverity: logLevelEnv ? logLevelToSeverityNumber(logLevelEnv) : undefined, - }), - ); - } - if (this._config.instrumentationOptions.winston?.enabled) { - this._instrumentations.push( - new WinstonInstrumentation({ - ...this._config.instrumentationOptions.winston, - logSeverity: logLevelEnv ? logLevelToSeverityNumber(logLevelEnv) : undefined, - }), - ); - } - } } diff --git a/src/azureMonitor/metrics/performanceCounters.ts b/src/azureMonitor/metrics/performanceCounters.ts index 81c9a55..b59f2ae 100644 --- a/src/azureMonitor/metrics/performanceCounters.ts +++ b/src/azureMonitor/metrics/performanceCounters.ts @@ -66,6 +66,16 @@ export class PerformanceCounterMetrics { speed: number; times: { user: number; nice: number; sys: number; idle: number; irq: number }; }[]; + // The normalized process time gauge keeps its own last-sample state. Sharing + // it with the standard process time gauge means whichever callback runs + // second measures a ~zero delta and always reports 0. + private lastAppCpuUsageNormalized: { user: number; system: number }; + private lastHrtimeNormalized: number[]; + private lastCpusProcessNormalized: { + model: string; + speed: number; + times: { user: number; nice: number; sys: number; idle: number; irq: number }; + }[]; private totalExceptionCount: number = 0; /** @@ -79,12 +89,16 @@ export class PerformanceCounterMetrics { this.lastCpusProcess = os.cpus(); this.lastAppCpuUsage = process.cpuUsage(); this.lastHrtime = process.hrtime(); + this.lastCpusProcessNormalized = os.cpus(); + this.lastAppCpuUsageNormalized = process.cpuUsage(); + this.lastHrtimeNormalized = process.hrtime(); this.lastRequestRate = { count: this.totalCount, time: +new Date(), executionInterval: this.intervalExecutionTime, }; + this.lastExceptionRate = { count: this.totalExceptionCount, time: +new Date() }; this.azureExporter = new AzureMonitorMetricExporter( this.internalConfig.azureMonitorExporterOptions, @@ -100,8 +114,6 @@ export class PerformanceCounterMetrics { this.meterProvider = new MeterProvider(meterProviderConfig); this.meter = this.meterProvider.getMeter("AzureMonitorPerformanceCountersMeter"); - this.lastRequestRate = { count: 0, time: 0, executionInterval: 0 }; - // Create Instruments this.requestDurationHistogram = this.meter.createHistogram( PerformanceCounterMetricNames.REQUEST_DURATION, @@ -314,8 +326,8 @@ export class PerformanceCounterMetrics { if ( cpus && cpus.length && - this.lastCpusProcess && - cpus.length === this.lastCpusProcess.length + this.lastCpusProcessNormalized && + cpus.length === this.lastCpusProcessNormalized.length ) { // Calculate % of total cpu time (user + system) this App Process used (Only supported by node v6.1.0+) let appCpuPercent: number | undefined = undefined; @@ -323,26 +335,30 @@ export class PerformanceCounterMetrics { const hrtime = process.hrtime(); const totalApp = appCpuUsage.user - - this.lastAppCpuUsage.user + - (appCpuUsage.system - this.lastAppCpuUsage.system) || 0; + this.lastAppCpuUsageNormalized.user + + (appCpuUsage.system - this.lastAppCpuUsageNormalized.system) || 0; - if (typeof this.lastHrtime !== "undefined" && this.lastHrtime.length === 2) { + if ( + typeof this.lastHrtimeNormalized !== "undefined" && + this.lastHrtimeNormalized.length === 2 + ) { const elapsedTime = - (hrtime[0] - this.lastHrtime[0]) * 1e6 + (hrtime[1] - this.lastHrtime[1]) / 1e3 || 0; // convert to microseconds + (hrtime[0] - this.lastHrtimeNormalized[0]) * 1e6 + + (hrtime[1] - this.lastHrtimeNormalized[1]) / 1e3 || 0; // convert to microseconds appCpuPercent = (100 * totalApp) / (elapsedTime * cpus.length); } // Set previous - this.lastAppCpuUsage = appCpuUsage; - this.lastHrtime = hrtime; - const cpuTotals = this.getTotalCombinedCpu(cpus, this.lastCpusProcess); + this.lastAppCpuUsageNormalized = appCpuUsage; + this.lastHrtimeNormalized = hrtime; + const cpuTotals = this.getTotalCombinedCpu(cpus, this.lastCpusProcessNormalized); const value = appCpuPercent !== undefined ? appCpuPercent : (cpuTotals.totalUser / cpuTotals.combinedTotal) * 100; observableResult.observe(value); } - this.lastCpusProcess = cpus; + this.lastCpusProcessNormalized = cpus; } private getProcessTime(observableResult: ObservableResult): void { diff --git a/test/internal/unit/logs/logHandler.test.ts b/test/internal/unit/logs/logHandler.test.ts index a0b906f..da04eec 100644 --- a/test/internal/unit/logs/logHandler.test.ts +++ b/test/internal/unit/logs/logHandler.test.ts @@ -8,6 +8,7 @@ import { ExportResultCode } from "@opentelemetry/core"; import { LoggerProvider } from "@opentelemetry/sdk-logs"; import { LogHandler } from "../../../../src/azureMonitor/logs/index.js"; import { MetricHandler } from "../../../../src/azureMonitor/metrics/index.js"; +import { createInstrumentations } from "../../../../src/distro/instrumentations.js"; import { InternalConfig } from "../../../../src/shared/index.js"; import { NodeTracerProvider } from "@opentelemetry/sdk-trace-node"; import { SemanticAttributes } from "@opentelemetry/semantic-conventions"; @@ -165,15 +166,34 @@ describe("LogHandler", () => { config.instrumentationOptions.bunyan = { enabled: true, }; - const logHandler = new LogHandler(config, metricHandler); - assert.isTrue(logHandler.getInstrumentations().length > 0, "Log instrumentations not added"); - assert.strictEqual( - logHandler.getInstrumentations()[0].instrumentationName, - "@opentelemetry/instrumentation-bunyan", + const instrumentations = createInstrumentations(config); + assert.isDefined( + instrumentations.find( + (instrumentation) => + instrumentation.instrumentationName === "@opentelemetry/instrumentation-bunyan", + ), "Bunyan instrumentation not added", ); }); + it("should not create a second copy of the bunyan instrumentation", () => { + const config = new InternalConfig(); + config.azureMonitorExporterOptions.connectionString = + "InstrumentationKey=1aa11111-bbbb-1ccc-8ddd-eeeeffff3333"; + config.instrumentationOptions.bunyan = { + enabled: true, + }; + // A second enabled BunyanInstrumentation appends another OpenTelemetry + // stream to every logger, which duplicates every log record. + const instrumentations = createInstrumentations(config); + const bunyanInstrumentations = instrumentations.filter( + (instrumentation) => + instrumentation.instrumentationName === "@opentelemetry/instrumentation-bunyan", + ); + assert.strictEqual(bunyanInstrumentations.length, 1); + assert.isUndefined((new LogHandler(config, metricHandler) as any).getInstrumentations); + }); + it("should add winston instrumentation", () => { const config = new InternalConfig(); config.azureMonitorExporterOptions.connectionString = @@ -181,11 +201,12 @@ describe("LogHandler", () => { config.instrumentationOptions.winston = { enabled: true, }; - const logHandler = new LogHandler(config, metricHandler); - assert.isTrue(logHandler.getInstrumentations().length > 0, "Log instrumentations not added"); - assert.strictEqual( - logHandler.getInstrumentations()[0].instrumentationName, - "@opentelemetry/instrumentation-winston", + const instrumentations = createInstrumentations(config); + assert.isDefined( + instrumentations.find( + (instrumentation) => + instrumentation.instrumentationName === "@opentelemetry/instrumentation-winston", + ), "Winston instrumentation not added", ); }); @@ -198,10 +219,12 @@ describe("LogHandler", () => { config.instrumentationOptions.bunyan = { enabled: true, }; - const logHandler = new LogHandler(config, metricHandler); + const bunyanInstrumentation = createInstrumentations(config).find( + (instrumentation) => + instrumentation.instrumentationName === "@opentelemetry/instrumentation-bunyan", + ); assert.strictEqual( - (logHandler.getInstrumentations()[0].getConfig() as BunyanInstrumentationConfig) - .logSeverity, + (bunyanInstrumentation!.getConfig() as BunyanInstrumentationConfig).logSeverity, SeverityNumber.DEBUG, ); }); @@ -214,10 +237,12 @@ describe("LogHandler", () => { config.instrumentationOptions.winston = { enabled: true, }; - const logHandler = new LogHandler(config, metricHandler); + const winstonInstrumentation = createInstrumentations(config).find( + (instrumentation) => + instrumentation.instrumentationName === "@opentelemetry/instrumentation-winston", + ); assert.strictEqual( - (logHandler.getInstrumentations()[0].getConfig() as WinstonInstrumentationConfig) - .logSeverity, + (winstonInstrumentation!.getConfig() as WinstonInstrumentationConfig).logSeverity, SeverityNumber.ERROR, ); }); From 5a4d62fa2eb9618fd8096a1cea19ebfac5f55c7e Mon Sep 17 00:00:00 2001 From: Jackson Weber Date: Tue, 4 Aug 2026 15:04:31 -0700 Subject: [PATCH 2/7] docs(changelog): link the fixes to PR #212 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- CHANGELOG.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 20c9086..67eb61e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,9 +3,9 @@ ## [Unreleased] ### Bugs Fixed -- Stop emitting every `bunyan` and `winston` log record twice. `LogHandler` constructed a second `BunyanInstrumentation` / `WinstonInstrumentation`; `InstrumentationBase` auto-enables an instrumentation whose config has `enabled: true`, so that second copy patched the logging module and appended a second `OpenTelemetryBunyanStream` to every logger — even though `LogHandler.getInstrumentations()` was never registered with the `NodeSDK`. `createInstrumentations` is now the single owner of all instrumentations. -- Report a real value for the `\Process(??APP_WIN32_PROC??)\% Processor Time Normalized` performance counter. It shared `lastAppCpuUsage` / `lastHrtime` / `lastCpusProcess` with the standard process time counter, so whichever observable callback ran second measured a near-zero delta and always reported `0`. -- Report a real value on the first export of the `\ASP.NET Applications(??APP_W3SVC_PROC??)\Requests/Sec` and `\.NET CLR Exceptions(??APP_CLR_PROC??)\# of Exceps Thrown / sec` performance counters. `lastRequestRate` was re-initialized to `time: 0` after the constructor had already seeded it with the current time, making the first collection interval span decades and driving the computed rate to ~0. +- Stop emitting every `bunyan` and `winston` log record twice. `LogHandler` constructed a second `BunyanInstrumentation` / `WinstonInstrumentation`; `InstrumentationBase` auto-enables an instrumentation whose config has `enabled: true`, so that second copy patched the logging module and appended a second `OpenTelemetryBunyanStream` to every logger — even though `LogHandler.getInstrumentations()` was never registered with the `NodeSDK`. `createInstrumentations` is now the single owner of all instrumentations. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) +- Report a real value for the `\Process(??APP_WIN32_PROC??)\% Processor Time Normalized` performance counter. It shared `lastAppCpuUsage` / `lastHrtime` / `lastCpusProcess` with the standard process time counter, so whichever observable callback ran second measured a near-zero delta and always reported `0`. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) +- Report a real value on the first export of the `\ASP.NET Applications(??APP_W3SVC_PROC??)\Requests/Sec` and `\.NET CLR Exceptions(??APP_CLR_PROC??)\# of Exceps Thrown / sec` performance counters. `lastRequestRate` was re-initialized to `time: 0` after the constructor had already seeded it with the current time, making the first collection interval span decades and driving the computed rate to ~0. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) ## [1.3.0] - 2026-08-03 From 3d9a979cca77e20222887ac83e019c700d8f4110 Mon Sep 17 00:00:00 2001 From: Jackson Weber Date: Tue, 4 Aug 2026 15:49:09 -0700 Subject: [PATCH 3/7] fix(traces): stop creating a second copy of the trace instrumentations MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Follow-up to the LogHandler fix in this branch, from a review pass that caught two problems with the original change. 1. `TraceHandler` had the same dead-code pattern as `LogHandler`: it built its own HttpInstrumentation / AzureSdk / MongoDB / MySQL / Pg / Redis instances that were never passed to the NodeSDK. This is worse than it looks. `instrumentation-http` guards against double-patching with a per-instance `_httpPatched` flag rather than unwrapping, so with two instances the unregistered one ends up owning the patch — and because `registerInstrumentations` never wired it up, it keeps the no-op meter it was constructed with. Measured with two instances, one registered with a real MeterProvider: one instance -> http.server.request.duration, http.client.request.duration two instances -> no HTTP metrics at all Spans were unaffected, which is why this went unnoticed. Confirmed end to end: `http.server.request.duration` and `http.client.request.duration` now appear in the transmitted telemetry and were completely absent before. It also double-wrapped `ignoreOutgoingRequestHook`: `createInstrumentations` and `TraceHandler` both wrapped the hook on the same shared `instrumentationOptions.http` object, so the Azure Monitor exclusion check ran twice per outgoing request. With this removed, `createInstrumentations` really is the single owner of all instrumentations, as the changelog claims. 2. Corrected the winston claim. Winston was not duplicated: unlike bunyan, its instrumentation unwraps an existing patch before wrapping (instrumentation-winston `instrumentation.js` lines 21-30 and 40-45), so a second instance replaces the first rather than stacking transports. Only bunyan stacks, because `_addStream` appends unconditionally. Updated the changelog and the handler comment accordingly. The handler guard tests now assert that neither handler holds an instrumentation under any property name, rather than asserting a specific method was deleted. Both fail against the pre-fix source. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- CHANGELOG.md | 4 +- src/azureMonitor/logs/handler.ts | 11 +-- src/azureMonitor/traces/handler.ts | 88 ++----------------- test/internal/unit/logs/logHandler.test.ts | 32 +++++-- .../internal/unit/traces/traceHandler.test.ts | 28 ++++-- 5 files changed, 65 insertions(+), 98 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 67eb61e..2c6f433 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,7 +3,9 @@ ## [Unreleased] ### Bugs Fixed -- Stop emitting every `bunyan` and `winston` log record twice. `LogHandler` constructed a second `BunyanInstrumentation` / `WinstonInstrumentation`; `InstrumentationBase` auto-enables an instrumentation whose config has `enabled: true`, so that second copy patched the logging module and appended a second `OpenTelemetryBunyanStream` to every logger — even though `LogHandler.getInstrumentations()` was never registered with the `NodeSDK`. `createInstrumentations` is now the single owner of all instrumentations. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) +- Stop emitting every `bunyan` log record twice. `LogHandler` constructed a second `BunyanInstrumentation`; `InstrumentationBase` auto-enables an instrumentation whose config has `enabled: true`, so that second copy patched `bunyan` and appended a second `OpenTelemetryBunyanStream` to every logger — even though `LogHandler.getInstrumentations()` was never registered with the `NodeSDK`. Unlike the other instrumentations, the bunyan instrumentation never unwraps a previous patch, so the streams stacked. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) +- Restore the `@opentelemetry/instrumentation-http` duration metrics (`http.server.request.duration`, `http.client.request.duration`). `TraceHandler` created a second, enabled copy of each trace instrumentation that the `NodeSDK` never wired up, so it kept the no-op meter it was constructed with. With two `HttpInstrumentation` instances patching `http`, no HTTP metrics were recorded at all. `createInstrumentations` is now the single owner of all instrumentations. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) +- Apply the Azure Monitor `ignoreOutgoingRequestHook` filter once instead of twice. `createInstrumentations` and `TraceHandler` both wrapped the hook on the same shared `instrumentationOptions.http` object. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) - Report a real value for the `\Process(??APP_WIN32_PROC??)\% Processor Time Normalized` performance counter. It shared `lastAppCpuUsage` / `lastHrtime` / `lastCpusProcess` with the standard process time counter, so whichever observable callback ran second measured a near-zero delta and always reported `0`. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) - Report a real value on the first export of the `\ASP.NET Applications(??APP_W3SVC_PROC??)\Requests/Sec` and `\.NET CLR Exceptions(??APP_CLR_PROC??)\# of Exceps Thrown / sec` performance counters. `lastRequestRate` was re-initialized to `time: 0` after the constructor had already seeded it with the current time, making the first collection interval span decades and driving the computed rate to ~0. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) diff --git a/src/azureMonitor/logs/handler.ts b/src/azureMonitor/logs/handler.ts index 0597df6..884399f 100644 --- a/src/azureMonitor/logs/handler.ts +++ b/src/azureMonitor/logs/handler.ts @@ -21,11 +21,12 @@ export class LogHandler { /** * Initializes a new instance of the LogHandler class. * - * Log instrumentations (bunyan, winston, console) are not created here — they - * are created once by `createInstrumentations` and registered with the - * NodeSDK. Creating them here as well would enable a second copy of each - * instrumentation, which appends a second OpenTelemetry stream to every - * logger and duplicates each log record. + * Log instrumentations are not created here — they are created once by + * `createInstrumentations` and registered with the NodeSDK. Creating them + * here as well left a second, enabled copy of each instrumentation that the + * SDK never wired up. For bunyan that is actively harmful: its instrumentation + * appends an `OpenTelemetryBunyanStream` every time it is enabled and never + * unwraps a previous patch, so every record was emitted twice. * * @param config - Microsoft OpenTelemetry configuration. * @param metricHandler - MetricHandler. diff --git a/src/azureMonitor/traces/handler.ts b/src/azureMonitor/traces/handler.ts index 8128341..1fcc91b 100644 --- a/src/azureMonitor/traces/handler.ts +++ b/src/azureMonitor/traces/handler.ts @@ -1,26 +1,13 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. -import type { RequestOptions } from "node:http"; -import { createAzureSdkInstrumentation } from "@azure/opentelemetry-instrumentation-azure-sdk"; import { AzureMonitorTraceExporter } from "@azure/monitor-opentelemetry-exporter"; import type { BufferConfig } from "@opentelemetry/sdk-trace-base"; import { BatchSpanProcessor } from "@opentelemetry/sdk-trace-base"; -import type { - HttpInstrumentationConfig, - IgnoreOutgoingRequestFunction, -} from "@opentelemetry/instrumentation-http"; -import { HttpInstrumentation } from "@opentelemetry/instrumentation-http"; -import { MongoDBInstrumentation } from "@opentelemetry/instrumentation-mongodb"; -import { MySQLInstrumentation } from "@opentelemetry/instrumentation-mysql"; -import { PgInstrumentation } from "@opentelemetry/instrumentation-pg"; -import { RedisInstrumentation } from "@opentelemetry/instrumentation-redis"; import type { InternalConfig } from "../../shared/config.js"; import type { MetricHandler } from "../metrics/handler.js"; -import { ignoreOutgoingRequestHook } from "../utils/common.js"; import { AzureMonitorSpanProcessor } from "./spanProcessor.js"; -import type { Instrumentation } from "@opentelemetry/instrumentation"; /** * Azure Monitor OpenTelemetry Trace Handler @@ -29,19 +16,24 @@ export class TraceHandler { private _batchSpanProcessor: BatchSpanProcessor; private _azureSpanProcessor: AzureMonitorSpanProcessor; private _azureExporter: AzureMonitorTraceExporter; - private _instrumentations: Instrumentation[]; private _config: InternalConfig; private _metricHandler: MetricHandler; /** * Initializes a new instance of the TraceHandler class. - * @param _config - Configuration. - * @param _metricHandler - MetricHandler. + * + * Trace instrumentations are not created here — they are created once by + * `createInstrumentations` and registered with the NodeSDK. Creating them + * here as well left a second, enabled copy of each instrumentation that the + * SDK never wired up, so it kept a no-op meter and silently suppressed the + * HTTP instrumentation's duration metrics. + * + * @param config - Configuration. + * @param metricHandler - MetricHandler. */ constructor(config: InternalConfig, metricHandler: MetricHandler) { this._config = config; this._metricHandler = metricHandler; - this._instrumentations = []; this._azureExporter = new AzureMonitorTraceExporter(this._config.azureMonitorExporterOptions); const bufferConfig: BufferConfig = { maxExportBatchSize: 512, @@ -51,7 +43,6 @@ export class TraceHandler { }; this._batchSpanProcessor = new BatchSpanProcessor(this._azureExporter, bufferConfig); this._azureSpanProcessor = new AzureMonitorSpanProcessor(this._metricHandler); - this._initializeInstrumentations(); } public getBatchSpanProcessor(): BatchSpanProcessor { @@ -62,10 +53,6 @@ export class TraceHandler { return this._azureSpanProcessor; } - public getInstrumentations(): Instrumentation[] { - return this._instrumentations; - } - /** * Shutdown handler */ @@ -74,61 +61,4 @@ export class TraceHandler { await this._azureSpanProcessor.shutdown(); await this._azureExporter.shutdown(); } - - /** - * Start auto collection of telemetry - */ - private _initializeInstrumentations(): void { - if (this._config.instrumentationOptions.http?.enabled) { - const httpinstrumentationOptions = this._config.instrumentationOptions - .http as HttpInstrumentationConfig; - const providedIgnoreOutgoingRequestHook = - httpinstrumentationOptions.ignoreOutgoingRequestHook; - const mergedIgnoreOutgoingRequestHook: IgnoreOutgoingRequestFunction = ( - request: RequestOptions, - ) => { - const result = ignoreOutgoingRequestHook(request); - if (!result) { - // Not internal call - if (providedIgnoreOutgoingRequestHook) { - // Provided hook in config - return providedIgnoreOutgoingRequestHook(request); - } - } - return result; - }; - httpinstrumentationOptions.ignoreOutgoingRequestHook = mergedIgnoreOutgoingRequestHook; - this._instrumentations.push( - new HttpInstrumentation(this._config.instrumentationOptions.http), - ); - } - if (this._config.instrumentationOptions.azureSdk?.enabled) { - this._instrumentations.push( - createAzureSdkInstrumentation(this._config.instrumentationOptions.azureSdk), - ); - } - if (this._config.instrumentationOptions.mongoDb?.enabled) { - this._instrumentations.push( - new MongoDBInstrumentation(this._config.instrumentationOptions.mongoDb), - ); - } - if (this._config.instrumentationOptions.mySql?.enabled) { - this._instrumentations.push( - new MySQLInstrumentation(this._config.instrumentationOptions.mySql), - ); - } - if (this._config.instrumentationOptions.postgreSql?.enabled) { - this._instrumentations.push( - new PgInstrumentation(this._config.instrumentationOptions.postgreSql), - ); - } - if ( - this._config.instrumentationOptions.redis?.enabled || - this._config.instrumentationOptions.redis4?.enabled - ) { - this._instrumentations.push( - new RedisInstrumentation(this._config.instrumentationOptions.redis), - ); - } - } } diff --git a/test/internal/unit/logs/logHandler.test.ts b/test/internal/unit/logs/logHandler.test.ts index da04eec..4080309 100644 --- a/test/internal/unit/logs/logHandler.test.ts +++ b/test/internal/unit/logs/logHandler.test.ts @@ -183,15 +183,33 @@ describe("LogHandler", () => { config.instrumentationOptions.bunyan = { enabled: true, }; + config.instrumentationOptions.winston = { + enabled: true, + }; + config.instrumentationOptions.console = { + enabled: true, + }; // A second enabled BunyanInstrumentation appends another OpenTelemetry - // stream to every logger, which duplicates every log record. - const instrumentations = createInstrumentations(config); - const bunyanInstrumentations = instrumentations.filter( - (instrumentation) => - instrumentation.instrumentationName === "@opentelemetry/instrumentation-bunyan", + // stream to every logger, which duplicates every log record. Every + // instrumentation must therefore be created exactly once. + const names = createInstrumentations(config).map( + (instrumentation) => instrumentation.instrumentationName, ); - assert.strictEqual(bunyanInstrumentations.length, 1); - assert.isUndefined((new LogHandler(config, metricHandler) as any).getInstrumentations); + assert.deepStrictEqual( + names.filter((name, index) => names.indexOf(name) !== index), + [], + "createInstrumentations returned duplicate instrumentations", + ); + + // The handler must not hold instrumentations of its own, under any + // property name — anything it constructs is enabled but never registered. + const logHandler = new LogHandler(config, metricHandler); + const held = Object.values(logHandler as unknown as Record) + .flatMap((value) => (Array.isArray(value) ? value : [value])) + .filter( + (value) => typeof value === "object" && value !== null && "instrumentationName" in value, + ); + assert.deepStrictEqual(held, [], "LogHandler must not create instrumentations"); }); it("should add winston instrumentation", () => { diff --git a/test/internal/unit/traces/traceHandler.test.ts b/test/internal/unit/traces/traceHandler.test.ts index bc26f86..71b06b2 100644 --- a/test/internal/unit/traces/traceHandler.test.ts +++ b/test/internal/unit/traces/traceHandler.test.ts @@ -5,7 +5,7 @@ import { TraceHandler } from "../../../../src/azureMonitor/traces/index.js"; import { MetricHandler } from "../../../../src/azureMonitor/metrics/index.js"; import { InternalConfig } from "../../../../src/shared/index.js"; import { ApplicationInsightsSampler } from "../../../../src/azureMonitor/traces/sampler.js"; -import { createSampler } from "../../../../src/distro/instrumentations.js"; +import { createSampler, createInstrumentations } from "../../../../src/distro/instrumentations.js"; import { HttpInstrumentation, type HttpInstrumentationConfig, @@ -171,10 +171,13 @@ describe("Library/TraceHandler", () => { _config.instrumentationOptions.http = httpConfig; metricHandler = new MetricHandler(_config); handler = new TraceHandler(_config, metricHandler); - handler.getInstrumentations().forEach((instrumentation) => { - instrumentation.enable(); - activeInstrumentations.push(instrumentation); - }); + // Instrumentations are owned by createInstrumentations, not the handler. + createInstrumentations(_config, { filterAzureMonitorRequests: true }).forEach( + (instrumentation) => { + instrumentation.enable(); + activeInstrumentations.push(instrumentation); + }, + ); // Because the instrumentation is registered globally, its config is not updated // when the handler is created. We need to mock the getConfig method to return @@ -354,9 +357,22 @@ describe("Library/TraceHandler", () => { }; metricHandler = new MetricHandler(_config); handler = new TraceHandler(_config, metricHandler); - const instrumentations = handler.getInstrumentations(); + const instrumentations = createInstrumentations(_config); expect(instrumentations).toHaveLength(0); expect(instrumentations[0]).not.toBeInstanceOf(HttpInstrumentation); }); + + it("the trace handler does not create instrumentations", () => { + // A second, enabled copy of an instrumentation that the SDK never wires + // up keeps a no-op meter and suppresses the HTTP duration metrics. + metricHandler = new MetricHandler(_config); + handler = new TraceHandler(_config, metricHandler); + const held = Object.values(handler as unknown as Record) + .flatMap((value) => (Array.isArray(value) ? value : [value])) + .filter( + (value) => typeof value === "object" && value !== null && "instrumentationName" in value, + ); + expect(held).toEqual([]); + }); }); }); From d5ff88eb7b5463915faf1b3354f05e2a1cdc1ada Mon Sep 17 00:00:00 2001 From: Jackson Weber Date: Tue, 4 Aug 2026 16:18:37 -0700 Subject: [PATCH 4/7] docs: correct the normalized CPU counter description A controlled A/B run against unmodified main showed the broken counter is not reliably 0: the first export read 28.2576 while the standard process CPU counter read 3.4623 on a 12-core machine, where the correct value is 3.4623/12 = 0.2885. Sharing the last-sample state means the second callback measures a ~zero-length window, so the quotient is garbage in either direction, not consistently zero. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- CHANGELOG.md | 2 +- src/azureMonitor/metrics/performanceCounters.ts | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2c6f433..3bb8bb5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,7 +6,7 @@ - Stop emitting every `bunyan` log record twice. `LogHandler` constructed a second `BunyanInstrumentation`; `InstrumentationBase` auto-enables an instrumentation whose config has `enabled: true`, so that second copy patched `bunyan` and appended a second `OpenTelemetryBunyanStream` to every logger — even though `LogHandler.getInstrumentations()` was never registered with the `NodeSDK`. Unlike the other instrumentations, the bunyan instrumentation never unwraps a previous patch, so the streams stacked. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) - Restore the `@opentelemetry/instrumentation-http` duration metrics (`http.server.request.duration`, `http.client.request.duration`). `TraceHandler` created a second, enabled copy of each trace instrumentation that the `NodeSDK` never wired up, so it kept the no-op meter it was constructed with. With two `HttpInstrumentation` instances patching `http`, no HTTP metrics were recorded at all. `createInstrumentations` is now the single owner of all instrumentations. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) - Apply the Azure Monitor `ignoreOutgoingRequestHook` filter once instead of twice. `createInstrumentations` and `TraceHandler` both wrapped the hook on the same shared `instrumentationOptions.http` object. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) -- Report a real value for the `\Process(??APP_WIN32_PROC??)\% Processor Time Normalized` performance counter. It shared `lastAppCpuUsage` / `lastHrtime` / `lastCpusProcess` with the standard process time counter, so whichever observable callback ran second measured a near-zero delta and always reported `0`. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) +- Report a correct value for the `\Process(??APP_WIN32_PROC??)\% Processor Time Normalized` performance counter. It shared `lastAppCpuUsage` / `lastHrtime` / `lastCpusProcess` with the standard process time counter, so whichever observable callback ran second measured a ~zero-length window. The resulting value was garbage — usually `0`, but sometimes wildly inflated (observed `28.2576` on a 12-core machine where the standard counter read `3.4623`, i.e. the correct answer was `0.2885`). The counter is by definition the standard value divided by the CPU count. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) - Report a real value on the first export of the `\ASP.NET Applications(??APP_W3SVC_PROC??)\Requests/Sec` and `\.NET CLR Exceptions(??APP_CLR_PROC??)\# of Exceps Thrown / sec` performance counters. `lastRequestRate` was re-initialized to `time: 0` after the constructor had already seeded it with the current time, making the first collection interval span decades and driving the computed rate to ~0. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) ## [1.3.0] - 2026-08-03 diff --git a/src/azureMonitor/metrics/performanceCounters.ts b/src/azureMonitor/metrics/performanceCounters.ts index b59f2ae..fceb89e 100644 --- a/src/azureMonitor/metrics/performanceCounters.ts +++ b/src/azureMonitor/metrics/performanceCounters.ts @@ -68,7 +68,8 @@ export class PerformanceCounterMetrics { }[]; // The normalized process time gauge keeps its own last-sample state. Sharing // it with the standard process time gauge means whichever callback runs - // second measures a ~zero delta and always reports 0. + // second measures a ~zero-length window, which yields garbage: usually 0, but + // sometimes a wildly inflated value (observed 28.26% against a true 0.29%). private lastAppCpuUsageNormalized: { user: number; system: number }; private lastHrtimeNormalized: number[]; private lastCpusProcessNormalized: { From 9343b43c7d55b8641768901c4c97f1b59e3737b6 Mon Sep 17 00:00:00 2001 From: Jackson Weber Date: Tue, 4 Aug 2026 17:36:36 -0700 Subject: [PATCH 5/7] test(traces): prove the outgoing request filter still applies exactly once Addresses review feedback: with _initializeInstrumentations removed there was no longer anything in this file showing the hook is applied once. The merge lives in createInstrumentations with identical semantics; this adds a self-calibrating regression test that counts how many times the filter inspects the request and compares against a createInstrumentations-only baseline. Against the pre-fix source it fails with 'expected 6 to be 3'. Also shortened the comments added by this branch. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- src/azureMonitor/logs/handler.ts | 10 ++-- .../metrics/performanceCounters.ts | 7 +-- src/azureMonitor/traces/handler.ts | 8 +-- test/internal/unit/logs/logHandler.test.ts | 6 +- .../internal/unit/traces/traceHandler.test.ts | 60 ++++++++++++++++++- 5 files changed, 70 insertions(+), 21 deletions(-) diff --git a/src/azureMonitor/logs/handler.ts b/src/azureMonitor/logs/handler.ts index 884399f..d93b8aa 100644 --- a/src/azureMonitor/logs/handler.ts +++ b/src/azureMonitor/logs/handler.ts @@ -21,12 +21,10 @@ export class LogHandler { /** * Initializes a new instance of the LogHandler class. * - * Log instrumentations are not created here — they are created once by - * `createInstrumentations` and registered with the NodeSDK. Creating them - * here as well left a second, enabled copy of each instrumentation that the - * SDK never wired up. For bunyan that is actively harmful: its instrumentation - * appends an `OpenTelemetryBunyanStream` every time it is enabled and never - * unwraps a previous patch, so every record was emitted twice. + * Instrumentations are owned by `createInstrumentations`. Creating them here + * too left an enabled copy the SDK never registered, and bunyan's + * instrumentation appends a stream per enable without unwrapping — so every + * record was emitted twice. * * @param config - Microsoft OpenTelemetry configuration. * @param metricHandler - MetricHandler. diff --git a/src/azureMonitor/metrics/performanceCounters.ts b/src/azureMonitor/metrics/performanceCounters.ts index fceb89e..f6f3343 100644 --- a/src/azureMonitor/metrics/performanceCounters.ts +++ b/src/azureMonitor/metrics/performanceCounters.ts @@ -66,10 +66,9 @@ export class PerformanceCounterMetrics { speed: number; times: { user: number; nice: number; sys: number; idle: number; irq: number }; }[]; - // The normalized process time gauge keeps its own last-sample state. Sharing - // it with the standard process time gauge means whichever callback runs - // second measures a ~zero-length window, which yields garbage: usually 0, but - // sometimes a wildly inflated value (observed 28.26% against a true 0.29%). + // Kept separate from the standard process time gauge: sharing this state + // makes whichever callback runs second measure a ~zero-length window, and the + // resulting quotient is garbage (observed 28.26% against a true 0.29%). private lastAppCpuUsageNormalized: { user: number; system: number }; private lastHrtimeNormalized: number[]; private lastCpusProcessNormalized: { diff --git a/src/azureMonitor/traces/handler.ts b/src/azureMonitor/traces/handler.ts index 1fcc91b..d5bea1a 100644 --- a/src/azureMonitor/traces/handler.ts +++ b/src/azureMonitor/traces/handler.ts @@ -22,11 +22,9 @@ export class TraceHandler { /** * Initializes a new instance of the TraceHandler class. * - * Trace instrumentations are not created here — they are created once by - * `createInstrumentations` and registered with the NodeSDK. Creating them - * here as well left a second, enabled copy of each instrumentation that the - * SDK never wired up, so it kept a no-op meter and silently suppressed the - * HTTP instrumentation's duration metrics. + * Instrumentations are owned by `createInstrumentations`. Creating them here + * too left an enabled copy the SDK never registered, which kept a no-op meter + * and suppressed the HTTP duration metrics. * * @param config - Configuration. * @param metricHandler - MetricHandler. diff --git a/test/internal/unit/logs/logHandler.test.ts b/test/internal/unit/logs/logHandler.test.ts index 4080309..1f2db4b 100644 --- a/test/internal/unit/logs/logHandler.test.ts +++ b/test/internal/unit/logs/logHandler.test.ts @@ -190,8 +190,7 @@ describe("LogHandler", () => { enabled: true, }; // A second enabled BunyanInstrumentation appends another OpenTelemetry - // stream to every logger, which duplicates every log record. Every - // instrumentation must therefore be created exactly once. + // stream to every logger, duplicating every record. const names = createInstrumentations(config).map( (instrumentation) => instrumentation.instrumentationName, ); @@ -201,8 +200,7 @@ describe("LogHandler", () => { "createInstrumentations returned duplicate instrumentations", ); - // The handler must not hold instrumentations of its own, under any - // property name — anything it constructs is enabled but never registered. + // The handler must not hold instrumentations under any property name. const logHandler = new LogHandler(config, metricHandler); const held = Object.values(logHandler as unknown as Record) .flatMap((value) => (Array.isArray(value) ? value : [value])) diff --git a/test/internal/unit/traces/traceHandler.test.ts b/test/internal/unit/traces/traceHandler.test.ts index 71b06b2..daf5b3c 100644 --- a/test/internal/unit/traces/traceHandler.test.ts +++ b/test/internal/unit/traces/traceHandler.test.ts @@ -363,8 +363,8 @@ describe("Library/TraceHandler", () => { }); it("the trace handler does not create instrumentations", () => { - // A second, enabled copy of an instrumentation that the SDK never wires - // up keeps a no-op meter and suppresses the HTTP duration metrics. + // An enabled copy the SDK never registers keeps a no-op meter and + // suppresses the HTTP duration metrics. metricHandler = new MetricHandler(_config); handler = new TraceHandler(_config, metricHandler); const held = Object.values(handler as unknown as Record) @@ -374,5 +374,61 @@ describe("Library/TraceHandler", () => { ); expect(held).toEqual([]); }); + + it("applies the Azure Monitor outgoing request filter exactly once", () => { + // Counts how many times the filter inspected the request, so a second + // wrapping layer is detectable rather than silently equivalent. + const countingRequest = () => { + let reads = 0; + const request = {} as Http.RequestOptions; + Object.defineProperty(request, "headers", { + get() { + reads++; + return { "user-agent": "curl/8.0" }; + }, + }); + return { request, reads: () => reads }; + }; + + const buildHook = ( + withHandler: boolean, + userHook: HttpInstrumentationConfig["ignoreOutgoingRequestHook"], + ) => { + const config = new InternalConfig(); + config.azureMonitorExporterOptions.connectionString = + "InstrumentationKey=1aa11111-bbbb-1ccc-8ddd-eeeeffff3333"; + config.instrumentationOptions.http = { + enabled: true, + ignoreOutgoingRequestHook: userHook, + } as HttpInstrumentationConfig; + createInstrumentations(config, { filterAzureMonitorRequests: true }); + if (withHandler) { + // The handler used to wrap the hook a second time on this same object. + new TraceHandler(config, new MetricHandler(config)); + } + return (config.instrumentationOptions.http as HttpInstrumentationConfig) + .ignoreOutgoingRequestHook!; + }; + + const baselineHook = buildHook(false, () => false); + const baseline = countingRequest(); + baselineHook(baseline.request); + + const userHook = vi.fn().mockReturnValue(false); + const hook = buildHook(true, userHook); + + // Exporter traffic is dropped without consulting the caller's hook. + expect( + hook({ headers: { "user-agent": "azsdk-js-monitor-opentelemetry-exporter/1.0" } }), + ).toBe(true); + expect(userHook).not.toHaveBeenCalled(); + + // Everything else defers to the caller's hook, and the Azure Monitor + // check runs the same number of times as with no handler at all. + const actual = countingRequest(); + expect(hook(actual.request)).toBe(false); + expect(userHook).toHaveBeenCalledTimes(1); + expect(actual.reads()).toBe(baseline.reads()); + }); }); }); From a932e4b613dc875f0f6cbb08564a32d95deae89b Mon Sep 17 00:00:00 2001 From: Jackson Weber Date: Tue, 4 Aug 2026 17:44:34 -0700 Subject: [PATCH 6/7] refactor: drop comments narrating previous behavior The rationale for these changes belongs in the commit history, PR and changelog, not in the source files. Remaining comments state current invariants only. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- src/azureMonitor/logs/handler.ts | 6 ------ src/azureMonitor/metrics/performanceCounters.ts | 6 +++--- src/azureMonitor/traces/handler.ts | 5 ----- test/internal/unit/traces/traceHandler.test.ts | 5 ++--- 4 files changed, 5 insertions(+), 17 deletions(-) diff --git a/src/azureMonitor/logs/handler.ts b/src/azureMonitor/logs/handler.ts index d93b8aa..c1d4818 100644 --- a/src/azureMonitor/logs/handler.ts +++ b/src/azureMonitor/logs/handler.ts @@ -20,12 +20,6 @@ export class LogHandler { /** * Initializes a new instance of the LogHandler class. - * - * Instrumentations are owned by `createInstrumentations`. Creating them here - * too left an enabled copy the SDK never registered, and bunyan's - * instrumentation appends a stream per enable without unwrapping — so every - * record was emitted twice. - * * @param config - Microsoft OpenTelemetry configuration. * @param metricHandler - MetricHandler. */ diff --git a/src/azureMonitor/metrics/performanceCounters.ts b/src/azureMonitor/metrics/performanceCounters.ts index f6f3343..6aa431f 100644 --- a/src/azureMonitor/metrics/performanceCounters.ts +++ b/src/azureMonitor/metrics/performanceCounters.ts @@ -66,9 +66,9 @@ export class PerformanceCounterMetrics { speed: number; times: { user: number; nice: number; sys: number; idle: number; irq: number }; }[]; - // Kept separate from the standard process time gauge: sharing this state - // makes whichever callback runs second measure a ~zero-length window, and the - // resulting quotient is garbage (observed 28.26% against a true 0.29%). + // Must not share state with the standard process time gauge: both callbacks + // run in the same collection cycle, so the second one would measure a + // ~zero-length window. private lastAppCpuUsageNormalized: { user: number; system: number }; private lastHrtimeNormalized: number[]; private lastCpusProcessNormalized: { diff --git a/src/azureMonitor/traces/handler.ts b/src/azureMonitor/traces/handler.ts index d5bea1a..21334ba 100644 --- a/src/azureMonitor/traces/handler.ts +++ b/src/azureMonitor/traces/handler.ts @@ -21,11 +21,6 @@ export class TraceHandler { /** * Initializes a new instance of the TraceHandler class. - * - * Instrumentations are owned by `createInstrumentations`. Creating them here - * too left an enabled copy the SDK never registered, which kept a no-op meter - * and suppressed the HTTP duration metrics. - * * @param config - Configuration. * @param metricHandler - MetricHandler. */ diff --git a/test/internal/unit/traces/traceHandler.test.ts b/test/internal/unit/traces/traceHandler.test.ts index daf5b3c..add7cf2 100644 --- a/test/internal/unit/traces/traceHandler.test.ts +++ b/test/internal/unit/traces/traceHandler.test.ts @@ -363,8 +363,8 @@ describe("Library/TraceHandler", () => { }); it("the trace handler does not create instrumentations", () => { - // An enabled copy the SDK never registers keeps a no-op meter and - // suppresses the HTTP duration metrics. + // An enabled instrumentation the SDK never registers keeps a no-op meter + // and suppresses the HTTP duration metrics. metricHandler = new MetricHandler(_config); handler = new TraceHandler(_config, metricHandler); const held = Object.values(handler as unknown as Record) @@ -403,7 +403,6 @@ describe("Library/TraceHandler", () => { } as HttpInstrumentationConfig; createInstrumentations(config, { filterAzureMonitorRequests: true }); if (withHandler) { - // The handler used to wrap the hook a second time on this same object. new TraceHandler(config, new MetricHandler(config)); } return (config.instrumentationOptions.http as HttpInstrumentationConfig) From 583fc58f657ee255ce740fcee7d3e12e1abaaa4a Mon Sep 17 00:00:00 2001 From: Jackson Weber Date: Wed, 5 Aug 2026 11:46:31 -0700 Subject: [PATCH 7/7] test(metrics): cover first-interval counter regressions Add deterministic coverage for request/exception rate initialization and independent normalized CPU sampling. Reduce the changelog and comments to their minimum. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- CHANGELOG.md | 6 +--- .../metrics/performanceCounters.ts | 6 ++-- test/internal/unit/logs/logHandler.test.ts | 3 -- .../unit/metrics/performanceMetrics.test.ts | 32 ++++++++++++++++++- .../internal/unit/traces/traceHandler.test.ts | 11 ++----- 5 files changed, 36 insertions(+), 22 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3bb8bb5..938a017 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,11 +3,7 @@ ## [Unreleased] ### Bugs Fixed -- Stop emitting every `bunyan` log record twice. `LogHandler` constructed a second `BunyanInstrumentation`; `InstrumentationBase` auto-enables an instrumentation whose config has `enabled: true`, so that second copy patched `bunyan` and appended a second `OpenTelemetryBunyanStream` to every logger — even though `LogHandler.getInstrumentations()` was never registered with the `NodeSDK`. Unlike the other instrumentations, the bunyan instrumentation never unwraps a previous patch, so the streams stacked. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) -- Restore the `@opentelemetry/instrumentation-http` duration metrics (`http.server.request.duration`, `http.client.request.duration`). `TraceHandler` created a second, enabled copy of each trace instrumentation that the `NodeSDK` never wired up, so it kept the no-op meter it was constructed with. With two `HttpInstrumentation` instances patching `http`, no HTTP metrics were recorded at all. `createInstrumentations` is now the single owner of all instrumentations. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) -- Apply the Azure Monitor `ignoreOutgoingRequestHook` filter once instead of twice. `createInstrumentations` and `TraceHandler` both wrapped the hook on the same shared `instrumentationOptions.http` object. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) -- Report a correct value for the `\Process(??APP_WIN32_PROC??)\% Processor Time Normalized` performance counter. It shared `lastAppCpuUsage` / `lastHrtime` / `lastCpusProcess` with the standard process time counter, so whichever observable callback ran second measured a ~zero-length window. The resulting value was garbage — usually `0`, but sometimes wildly inflated (observed `28.2576` on a 12-core machine where the standard counter read `3.4623`, i.e. the correct answer was `0.2885`). The counter is by definition the standard value divided by the CPU count. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) -- Report a real value on the first export of the `\ASP.NET Applications(??APP_W3SVC_PROC??)\Requests/Sec` and `\.NET CLR Exceptions(??APP_CLR_PROC??)\# of Exceps Thrown / sec` performance counters. `lastRequestRate` was re-initialized to `time: 0` after the constructor had already seeded it with the current time, making the first collection interval span decades and driving the computed rate to ~0. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) +- Fix duplicate Bunyan logs, missing HTTP duration metrics, duplicate request filtering, and incorrect performance-counter values. [#212](https://github.com/microsoft/opentelemetry-distro-javascript/pull/212) ## [1.3.0] - 2026-08-03 diff --git a/src/azureMonitor/metrics/performanceCounters.ts b/src/azureMonitor/metrics/performanceCounters.ts index 6aa431f..1e77c5d 100644 --- a/src/azureMonitor/metrics/performanceCounters.ts +++ b/src/azureMonitor/metrics/performanceCounters.ts @@ -50,7 +50,7 @@ export class PerformanceCounterMetrics { private processTimeGaugeCallback: ObservableCallback; private exceptionCountGauge: ObservableGauge; private exceptionCountGaugeCallback: ObservableCallback; - private lastExceptionRate: { count: number; time: number } = { count: 0, time: 0 }; + private lastExceptionRate: { count: number; time: number }; private totalCount: number = 0; private intervalExecutionTime = 0; private lastRequestRate: { count: number; time: number; executionInterval: number }; @@ -66,9 +66,7 @@ export class PerformanceCounterMetrics { speed: number; times: { user: number; nice: number; sys: number; idle: number; irq: number }; }[]; - // Must not share state with the standard process time gauge: both callbacks - // run in the same collection cycle, so the second one would measure a - // ~zero-length window. + // Both process CPU callbacks need independent sampling state. private lastAppCpuUsageNormalized: { user: number; system: number }; private lastHrtimeNormalized: number[]; private lastCpusProcessNormalized: { diff --git a/test/internal/unit/logs/logHandler.test.ts b/test/internal/unit/logs/logHandler.test.ts index 1f2db4b..f613366 100644 --- a/test/internal/unit/logs/logHandler.test.ts +++ b/test/internal/unit/logs/logHandler.test.ts @@ -189,8 +189,6 @@ describe("LogHandler", () => { config.instrumentationOptions.console = { enabled: true, }; - // A second enabled BunyanInstrumentation appends another OpenTelemetry - // stream to every logger, duplicating every record. const names = createInstrumentations(config).map( (instrumentation) => instrumentation.instrumentationName, ); @@ -200,7 +198,6 @@ describe("LogHandler", () => { "createInstrumentations returned duplicate instrumentations", ); - // The handler must not hold instrumentations under any property name. const logHandler = new LogHandler(config, metricHandler); const held = Object.values(logHandler as unknown as Record) .flatMap((value) => (Array.isArray(value) ? value : [value])) diff --git a/test/internal/unit/metrics/performanceMetrics.test.ts b/test/internal/unit/metrics/performanceMetrics.test.ts index 2abf880..35733fb 100644 --- a/test/internal/unit/metrics/performanceMetrics.test.ts +++ b/test/internal/unit/metrics/performanceMetrics.test.ts @@ -3,6 +3,7 @@ import type { MockInstance } from "vitest"; import { afterEach, assert, beforeAll, afterAll, describe, it, vi } from "vitest"; import { SpanKind } from "@opentelemetry/api"; +import os from "node:os"; import { ExportResultCode } from "@opentelemetry/core"; import { PerformanceCounterMetrics } from "../../../../src/azureMonitor/metrics/performanceCounters.js"; import { @@ -50,6 +51,7 @@ describe("PerformanceCounterMetricsHandler", () => { const serverSpan: any = { kind: SpanKind.SERVER, duration: [654, 321000000], + events: [{ name: "exception" }], attributes: { "http.status_code": 200, }, @@ -58,6 +60,9 @@ describe("PerformanceCounterMetricsHandler", () => { describe("#Metrics", () => { it("should observe instruments during collection", async () => { + assert.closeTo(autoCollect["lastRequestRate"].time, Date.now(), 5000); + assert.closeTo(autoCollect["lastExceptionRate"].time, Date.now(), 5000); + for (let i = 0; i < 10; i++) { autoCollect.recordSpan(serverSpan); } @@ -94,7 +99,7 @@ describe("PerformanceCounterMetricsHandler", () => { ); assert.deepStrictEqual(metrics[1].descriptor.name, "Request_Rate"); - assert.isTrue((metrics[1].dataPoints[0].value as number) > 0, "Wrong request rate value"); + assert.isTrue((metrics[1].dataPoints[0].value as number) > 1, "Wrong request rate value"); assert.deepStrictEqual(metrics[2].descriptor.name, "Private_Bytes"); assert.isTrue((metrics[2].dataPoints[0].value as number) > 0, "Wrong private bytes value"); assert.deepStrictEqual(metrics[3].descriptor.name, "Available_Bytes"); @@ -119,6 +124,31 @@ describe("PerformanceCounterMetricsHandler", () => { ); assert.isFalse(Number.isNaN(metrics[6].dataPoints[0].value), "Value should not be NaN"); assert.deepStrictEqual(metrics[7].descriptor.name, "Exception_Rate"); + assert.isTrue((metrics[7].dataPoints[0].value as number) > 1, "Wrong exception rate value"); + }); + + it("uses independent state for standard and normalized process CPU", () => { + const cpus = os.cpus(); + autoCollect["lastCpusProcess"] = cpus; + autoCollect["lastCpusProcessNormalized"] = cpus; + autoCollect["lastAppCpuUsage"] = { user: 0, system: 0 }; + autoCollect["lastAppCpuUsageNormalized"] = { user: 0, system: 0 }; + autoCollect["lastHrtime"] = [0, 0]; + autoCollect["lastHrtimeNormalized"] = [0, 0]; + + vi.spyOn(process, "cpuUsage").mockReturnValue({ user: 120000, system: 0 }); + vi.spyOn(process, "hrtime").mockReturnValue([1, 0]); + + const standard: number[] = []; + const normalized: number[] = []; + autoCollect["getProcessTime"]({ observe: (value: number) => standard.push(value) }); + autoCollect["getNormalizedProcessTime"]({ + observe: (value: number) => normalized.push(value), + }); + + assert.strictEqual(standard.length, 1); + assert.strictEqual(normalized.length, 1); + assert.closeTo(normalized[0], standard[0] / cpus.length, 0.0001); }); }); }); diff --git a/test/internal/unit/traces/traceHandler.test.ts b/test/internal/unit/traces/traceHandler.test.ts index add7cf2..eea5951 100644 --- a/test/internal/unit/traces/traceHandler.test.ts +++ b/test/internal/unit/traces/traceHandler.test.ts @@ -171,7 +171,6 @@ describe("Library/TraceHandler", () => { _config.instrumentationOptions.http = httpConfig; metricHandler = new MetricHandler(_config); handler = new TraceHandler(_config, metricHandler); - // Instrumentations are owned by createInstrumentations, not the handler. createInstrumentations(_config, { filterAzureMonitorRequests: true }).forEach( (instrumentation) => { instrumentation.enable(); @@ -363,8 +362,6 @@ describe("Library/TraceHandler", () => { }); it("the trace handler does not create instrumentations", () => { - // An enabled instrumentation the SDK never registers keeps a no-op meter - // and suppresses the HTTP duration metrics. metricHandler = new MetricHandler(_config); handler = new TraceHandler(_config, metricHandler); const held = Object.values(handler as unknown as Record) @@ -376,8 +373,6 @@ describe("Library/TraceHandler", () => { }); it("applies the Azure Monitor outgoing request filter exactly once", () => { - // Counts how many times the filter inspected the request, so a second - // wrapping layer is detectable rather than silently equivalent. const countingRequest = () => { let reads = 0; const request = {} as Http.RequestOptions; @@ -403,7 +398,8 @@ describe("Library/TraceHandler", () => { } as HttpInstrumentationConfig; createInstrumentations(config, { filterAzureMonitorRequests: true }); if (withHandler) { - new TraceHandler(config, new MetricHandler(config)); + metricHandler = new MetricHandler(config); + handler = new TraceHandler(config, metricHandler); } return (config.instrumentationOptions.http as HttpInstrumentationConfig) .ignoreOutgoingRequestHook!; @@ -416,14 +412,11 @@ describe("Library/TraceHandler", () => { const userHook = vi.fn().mockReturnValue(false); const hook = buildHook(true, userHook); - // Exporter traffic is dropped without consulting the caller's hook. expect( hook({ headers: { "user-agent": "azsdk-js-monitor-opentelemetry-exporter/1.0" } }), ).toBe(true); expect(userHook).not.toHaveBeenCalled(); - // Everything else defers to the caller's hook, and the Azure Monitor - // check runs the same number of times as with no handler at all. const actual = countingRequest(); expect(hook(actual.request)).toBe(false); expect(userHook).toHaveBeenCalledTimes(1);