From 34f56e0e28a0873b69a499c9e91798b19fea8e96 Mon Sep 17 00:00:00 2001 From: Amir Blum Date: Thu, 2 May 2024 09:10:48 +0300 Subject: [PATCH] fix: remove unuseful patch message from instrumentations (#2161) * chore(mongoose): remove diag prints in patch * chore(tedious): remove diag prints in patch * chore(dns): remove diag prints in patch * chore(fastify): remove diag prints in patch * chore(hapi): remove diag prints in patch * chore(knex): remove diag prints in patch * chore(mysql): remove diag prints in patch * chore(pg): remove diag prints in patch * chore(redis): remove diag prints in patch * docs: document when to use diag for patch * chore: lint markdown * fix: unused import * chore: remove unused import * Update GUIDELINES.md Co-authored-by: Jamie Danielson * Update GUIDELINES.md Co-authored-by: Jamie Danielson * Update GUIDELINES.md Co-authored-by: Jamie Danielson * Update GUIDELINES.md Co-authored-by: Jamie Danielson * Update GUIDELINES.md Co-authored-by: Jamie Danielson * Update GUIDELINES.md Co-authored-by: Trent Mick * fix: name of diag in CHANGELOG --------- Co-authored-by: Jamie Danielson Co-authored-by: Trent Mick --- GUIDELINES.md | 33 +++++++++++++++++++ .../instrumentation-mongoose/src/mongoose.ts | 5 --- .../src/instrumentation.ts | 3 -- .../src/instrumentation.ts | 1 - .../src/instrumentation.ts | 1 - .../src/instrumentation.ts | 3 -- .../src/instrumentation.ts | 5 +-- .../src/instrumentation.ts | 13 -------- .../src/instrumentation.ts | 3 -- .../src/instrumentation.ts | 4 --- 10 files changed, 34 insertions(+), 37 deletions(-) diff --git a/GUIDELINES.md b/GUIDELINES.md index b67f294370..04bc219b14 100644 --- a/GUIDELINES.md +++ b/GUIDELINES.md @@ -164,3 +164,36 @@ To support this use case, you can choose one of the following options: }; ... ``` + +## Diag Logging + +The OpenTelemetry diagnostic logging channel can be used to troubleshoot issues with instrumentation packages. + +### Patching Messages + +When OpenTelemetry is installed in a user application, and expected spans are missing from generated traces, it is often useful to differentiate between the following scenarios: + +- The instrumentation is not auto loaded - due to issue with the require/import interception, an unsupported version of the instrumented package, or some other issue. This knowledge can pin-point the issue to the instrumentation package. +- The instrumentation patch was applied but expected spans are missing -- this can suggest an issue with instrumented package logic, configuration, limits, otel sdk, or other issues. + +It can also be useful to know when the instrumentation is loaded and patched, to understand the order of operations in the application. + +Instrumentation packages should use the `@opentelemetry/instrumentation` package `InstrumentationBase` class to register patches and unpatch callbacks for specific require/import of the instrumented package, it's dependency or an internal module file. When this mechanism is used, the base class will automatically emit a debug message on instrumentation diag component logger, looking like this: + +```shell +@opentelemetry/instrumentation-foo Applying instrumentation patch for module on require hook { + module: 'foo', + version: '1.2.3', + baseDir: '/node_modules/foo' +} +``` + +Instrumentation should not add additional debug messages for triggering the patching and unpatching callbacks, as the base class will handle this. + +Instrumentation may add additional patch/unpatch messages for specific functions if it is expected to help in troubleshooting issues with the instrumentation. Few examples: + +- If the patch logic is conditional, and user can benefit from ensuring the condition is met and the patch happened. `koa` patching logic examine an object and branch between patching it as router vs middleware, which is applied at runtime. `aws-lambda` will abort patching if the environment is not configured properly. +- When the patch is not applied directly on a `moduleExports` object in the `InstrumentationBase` callbacks, but rather from an event in the package, like creating new client instance, registering a listener, etc. `fastify` instrumentation applies a patch when a hook is added to the fastify app instance, which is patched from `moduleExports`. +- In situations where the patch logic is not trivial and it helps to specify patch events in the right context and nuances. `aws-lambda` logs additional properties extracted from the lambda framework and exposes them for troubleshooting. + +The cases above are not covered by the base class and offer additional context to the user troubleshooting an issue with the instrumentation. diff --git a/plugins/node/instrumentation-mongoose/src/mongoose.ts b/plugins/node/instrumentation-mongoose/src/mongoose.ts index 33aa3bf380..ff76b33735 100644 --- a/plugins/node/instrumentation-mongoose/src/mongoose.ts +++ b/plugins/node/instrumentation-mongoose/src/mongoose.ts @@ -137,7 +137,6 @@ export class MongooseInstrumentation extends InstrumentationBase { private patchAggregateExec(moduleVersion: string | undefined) { const self = this; - this._diag.debug('patched mongoose Aggregate exec function'); return (originalAggregate: Function) => { return function exec(this: any, callback?: Function) { if ( @@ -179,7 +178,6 @@ export class MongooseInstrumentation extends InstrumentationBase { private patchQueryExec(moduleVersion: string | undefined) { const self = this; - this._diag.debug('patched mongoose Query exec function'); return (originalExec: Function) => { return function exec(this: any, callback?: Function) { if ( @@ -222,7 +220,6 @@ export class MongooseInstrumentation extends InstrumentationBase { private patchOnModelMethods(op: string, moduleVersion: string | undefined) { const self = this; - this._diag.debug(`patching mongoose Model '${op}' operation`); return (originalOnModelFunction: Function) => { return function method(this: any, options?: any, callback?: Function) { if ( @@ -271,7 +268,6 @@ export class MongooseInstrumentation extends InstrumentationBase { // the aggregate of Model, and set the context on the Aggregate object private patchModelAggregate() { const self = this; - this._diag.debug('patched mongoose model aggregate function'); return (original: Function) => { return function captureSpanContext(this: any) { const currentSpan = trace.getSpan(context.active()); @@ -286,7 +282,6 @@ export class MongooseInstrumentation extends InstrumentationBase { private patchAndCaptureSpanContext(funcName: string) { const self = this; - this._diag.debug(`patching mongoose query ${funcName} function`); return (original: Function) => { return function captureSpanContext(this: any) { this[_STORED_PARENT_SPAN] = trace.getSpan(context.active()); diff --git a/plugins/node/instrumentation-tedious/src/instrumentation.ts b/plugins/node/instrumentation-tedious/src/instrumentation.ts index ba63ce1eae..78b11de517 100644 --- a/plugins/node/instrumentation-tedious/src/instrumentation.ts +++ b/plugins/node/instrumentation-tedious/src/instrumentation.ts @@ -129,9 +129,6 @@ export class TediousInstrumentation extends InstrumentationBase { private _patchQuery(operation: string) { return (originalMethod: UnknownFunction): UnknownFunction => { const thisPlugin = this; - this._diag.debug( - `TediousInstrumentation: patched Connection.prototype.${operation}` - ); function patchedMethod(this: ApproxConnection, request: ApproxRequest) { if (!(request instanceof EventEmitter)) { diff --git a/plugins/node/opentelemetry-instrumentation-dns/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-dns/src/instrumentation.ts index f408f7f17b..0be1211a60 100644 --- a/plugins/node/opentelemetry-instrumentation-dns/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-dns/src/instrumentation.ts @@ -105,7 +105,6 @@ export class DnsInstrumentation extends InstrumentationBase { private _getPatchLookupFunction( original: (hostname: string, ...args: unknown[]) => void ) { - diag.debug('patch lookup function'); const plugin = this; return function patchedLookup( this: {}, diff --git a/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts index 914b608fd8..208a2e09a5 100644 --- a/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-fastify/src/instrumentation.ts @@ -194,7 +194,6 @@ export class FastifyInstrumentation extends InstrumentationBase { fastify: () => FastifyInstance; }): () => FastifyInstance { const instrumentation = this; - this._diag.debug('Patching fastify constructor function'); function fastify(this: FastifyInstance, ...args: any) { const app: FastifyInstance = moduleExports.fastify.apply(this, args); diff --git a/plugins/node/opentelemetry-instrumentation-hapi/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-hapi/src/instrumentation.ts index af550b137c..ac930ffa68 100644 --- a/plugins/node/opentelemetry-instrumentation-hapi/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-hapi/src/instrumentation.ts @@ -135,7 +135,6 @@ export class HapiInstrumentation extends InstrumentationBase { original: RegisterFunction ): RegisterFunction { const instrumentation: HapiInstrumentation = this; - api.diag.debug('Patching Hapi.Server register function'); return function register( this: Hapi.Server, pluginInput: HapiPluginInput, @@ -169,7 +168,6 @@ export class HapiInstrumentation extends InstrumentationBase { pluginName?: string ) { const instrumentation: HapiInstrumentation = this; - api.diag.debug('Patching Hapi.Server ext function'); return function ext( this: ThisParameterType, @@ -231,7 +229,6 @@ export class HapiInstrumentation extends InstrumentationBase { pluginName?: string ) { const instrumentation: HapiInstrumentation = this; - api.diag.debug('Patching Hapi.Server route function'); return function route( this: Hapi.Server, route: HapiServerRouteInput diff --git a/plugins/node/opentelemetry-instrumentation-knex/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-knex/src/instrumentation.ts index 40577aa886..762b9d1455 100644 --- a/plugins/node/opentelemetry-instrumentation-knex/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-knex/src/instrumentation.ts @@ -109,10 +109,7 @@ export class KnexInstrumentation extends InstrumentationBase { ); return Client; }, - (Client: any, moduleVersion) => { - api.diag.debug( - `Removing ${basePath}/client.js patch for ${constants.MODULE_NAME}@${moduleVersion}` - ); + (Client: any) => { this._unwrap(Client.prototype, 'queryBuilder'); this._unwrap(Client.prototype, 'schemaBuilder'); this._unwrap(Client.prototype, 'raw'); diff --git a/plugins/node/opentelemetry-instrumentation-mysql/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-mysql/src/instrumentation.ts index f4de0bc36a..cf43c406e6 100644 --- a/plugins/node/opentelemetry-instrumentation-mysql/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-mysql/src/instrumentation.ts @@ -17,7 +17,6 @@ import { context, Context, - diag, trace, Span, SpanKind, @@ -84,7 +83,6 @@ export class MySQLInstrumentation extends InstrumentationBase { 'mysql', ['2.*'], (moduleExports: typeof mysqlTypes) => { - diag.debug('Patching mysql.createConnection'); if (isWrapped(moduleExports.createConnection)) { this._unwrap(moduleExports, 'createConnection'); } @@ -94,7 +92,6 @@ export class MySQLInstrumentation extends InstrumentationBase { this._patchCreateConnection() as any ); - diag.debug('Patching mysql.createPool'); if (isWrapped(moduleExports.createPool)) { this._unwrap(moduleExports, 'createPool'); } @@ -104,7 +101,6 @@ export class MySQLInstrumentation extends InstrumentationBase { this._patchCreatePool() as any ); - diag.debug('Patching mysql.createPoolCluster'); if (isWrapped(moduleExports.createPoolCluster)) { this._unwrap(moduleExports, 'createPoolCluster'); } @@ -130,7 +126,6 @@ export class MySQLInstrumentation extends InstrumentationBase { private _patchCreateConnection() { return (originalCreateConnection: Function) => { const thisPlugin = this; - diag.debug('MySQLInstrumentation#patch: patched mysql createConnection'); return function createConnection( _connectionUri: string | mysqlTypes.ConnectionConfig @@ -153,7 +148,6 @@ export class MySQLInstrumentation extends InstrumentationBase { private _patchCreatePool() { return (originalCreatePool: Function) => { const thisPlugin = this; - diag.debug('MySQLInstrumentation#patch: patched mysql createPool'); return function createPool(_config: string | mysqlTypes.PoolConfig) { const pool = originalCreatePool(...arguments); @@ -173,7 +167,6 @@ export class MySQLInstrumentation extends InstrumentationBase { private _patchPoolEnd(pool: any) { return (originalPoolEnd: Function) => { const thisPlugin = this; - diag.debug('MySQLInstrumentation#patch: patched mysql pool end'); return function end(callback?: unknown) { const nAll = (pool as any)._allConnections.length; const nFree = (pool as any)._freeConnections.length; @@ -196,7 +189,6 @@ export class MySQLInstrumentation extends InstrumentationBase { private _patchCreatePoolCluster() { return (originalCreatePoolCluster: Function) => { const thisPlugin = this; - diag.debug('MySQLInstrumentation#patch: patched mysql createPoolCluster'); return function createPool(_config: string | mysqlTypes.PoolConfig) { const cluster = originalCreatePoolCluster(...arguments); @@ -215,7 +207,6 @@ export class MySQLInstrumentation extends InstrumentationBase { private _patchAdd(cluster: mysqlTypes.PoolCluster) { return (originalAdd: Function) => { const thisPlugin = this; - diag.debug('MySQLInstrumentation#patch: patched mysql pool cluster add'); return function add(id: string, config: unknown) { // Unwrap if unpatch has been called if (!thisPlugin['_enabled']) { @@ -241,9 +232,6 @@ export class MySQLInstrumentation extends InstrumentationBase { private _patchGetConnection(pool: mysqlTypes.Pool | mysqlTypes.PoolCluster) { return (originalGetConnection: Function) => { const thisPlugin = this; - diag.debug( - 'MySQLInstrumentation#patch: patched mysql pool getConnection' - ); return function getConnection( arg1?: unknown, @@ -308,7 +296,6 @@ export class MySQLInstrumentation extends InstrumentationBase { private _patchQuery(connection: mysqlTypes.Connection | mysqlTypes.Pool) { return (originalQuery: Function): mysqlTypes.QueryFunction => { const thisPlugin = this; - diag.debug('MySQLInstrumentation: patched mysql query'); return function query( query: string | mysqlTypes.Query | mysqlTypes.QueryOptions, diff --git a/plugins/node/opentelemetry-instrumentation-mysql2/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-mysql2/src/instrumentation.ts index 18cb1681e0..ade7fd117f 100644 --- a/plugins/node/opentelemetry-instrumentation-mysql2/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-mysql2/src/instrumentation.ts @@ -56,7 +56,6 @@ export class MySQL2Instrumentation extends InstrumentationBase { (moduleExports: any) => { const ConnectionPrototype: mysqlTypes.Connection = moduleExports.Connection.prototype; - api.diag.debug('Patching Connection.prototype.query'); if (isWrapped(ConnectionPrototype.query)) { this._unwrap(ConnectionPrototype, 'query'); } @@ -91,8 +90,6 @@ export class MySQL2Instrumentation extends InstrumentationBase { private _patchQuery(format: formatType, isPrepared: boolean) { return (originalQuery: Function): Function => { const thisPlugin = this; - api.diag.debug('MySQL2Instrumentation: patched mysql query/execute'); - return function query( this: mysqlTypes.Connection, query: string | mysqlTypes.Query | mysqlTypes.QueryOptions, diff --git a/plugins/node/opentelemetry-instrumentation-redis/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-redis/src/instrumentation.ts index 85bb908c07..8d6f2ba88d 100644 --- a/plugins/node/opentelemetry-instrumentation-redis/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-redis/src/instrumentation.ts @@ -14,7 +14,6 @@ * limitations under the License. */ -import { diag } from '@opentelemetry/api'; import { isWrapped, InstrumentationBase, @@ -51,7 +50,6 @@ export class RedisInstrumentation extends InstrumentationBase { 'redis', ['^2.6.0', '^3.0.0'], moduleExports => { - diag.debug('Patching redis.RedisClient.internal_send_command'); if ( isWrapped( moduleExports.RedisClient.prototype['internal_send_command'] @@ -68,7 +66,6 @@ export class RedisInstrumentation extends InstrumentationBase { this._getPatchInternalSendCommand() ); - diag.debug('patching redis.RedisClient.create_stream'); if (isWrapped(moduleExports.RedisClient.prototype['create_stream'])) { this._unwrap(moduleExports.RedisClient.prototype, 'create_stream'); } @@ -78,7 +75,6 @@ export class RedisInstrumentation extends InstrumentationBase { this._getPatchCreateStream() ); - diag.debug('patching redis.createClient'); if (isWrapped(moduleExports.createClient)) { this._unwrap(moduleExports, 'createClient'); }