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 <[email protected]>

* Update GUIDELINES.md

Co-authored-by: Jamie Danielson <[email protected]>

* Update GUIDELINES.md

Co-authored-by: Jamie Danielson <[email protected]>

* Update GUIDELINES.md

Co-authored-by: Jamie Danielson <[email protected]>

* Update GUIDELINES.md

Co-authored-by: Jamie Danielson <[email protected]>

* Update GUIDELINES.md

Co-authored-by: Trent Mick <[email protected]>

* fix: name of diag in CHANGELOG

---------

Co-authored-by: Jamie Danielson <[email protected]>
Co-authored-by: Trent Mick <[email protected]>

Author: 3 people

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: '<your directory>/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.

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());

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)) {

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: {},

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);

plugins/node/opentelemetry-instrumentation-hapi/src/instrumentation.ts

@@ -135,7 +135,6 @@ export class HapiInstrumentation extends InstrumentationBase {
     original: RegisterFunction<T>
   ): RegisterFunction<T> {
     const instrumentation: HapiInstrumentation = this;
-    api.diag.debug('Patching Hapi.Server register function');
     return function register(
       this: Hapi.Server,
       pluginInput: HapiPluginInput<T>,
@@ -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<typeof original>,
@@ -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

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');

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,

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,

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');
           }