feat: Add support for library instrumentation (#713)

* feat: Add support for library instrumentation

* Add library version support and update basic package

* Update after main merge

* feat: Add support for library instrumentation

package.json

@@ -50,7 +50,7 @@
     "precompile": "gts clean"
   },
   "dependencies": {
-    "@google-cloud/logging": "^10.0.0",
+    "@google-cloud/logging": "^10.0.1",
     "google-auth-library": "^8.0.2",
     "lodash.mapvalues": "^4.6.0",
     "winston-transport": "^4.3.0"

src/common.ts

@@ -21,10 +21,15 @@ import {
   Log,
   LogSync,
 } from '@google-cloud/logging';
+import {
+  setInstrumentationStatus,
+  createDiagnosticEntry,
+} from '@google-cloud/logging/build/src/utils/instrumentation';
 import {LogSeverityFunctions} from '@google-cloud/logging/build/src/utils/log-common';
 import mapValues = require('lodash.mapvalues');
 import {Options} from '.';
 import {Entry, LogEntry} from '@google-cloud/logging/build/src/entry';
+import path = require('path');
 
 type Callback = (err: Error | null, apiResponse?: {}) => void;
 export type MonitoredResource = protos.google.api.MonitoredResource;
@@ -83,6 +88,9 @@ export const LOGGING_SPAN_KEY = 'logging.googleapis.com/spanId';
  */
 export const LOGGING_SAMPLED_KEY = 'logging.googleapis.com/trace_sampled';
 
+// The variable to hold cached library version
+let libraryVersion: string;
+
 /*!
  * Gets the current fully qualified trace ID when available from the
  * @google-cloud/trace-agent library in the LogEntry.trace field format of:
@@ -164,6 +172,18 @@ export class LoggingCommon {
     callback: Callback
   ) {
     metadata = metadata || ({} as MetadataArg);
+    // First create instrumentation record if it is never written before
+    let instrumentationEntry: Entry | undefined;
+    if (!setInstrumentationStatus(true)) {
+      instrumentationEntry = createDiagnosticEntry(
+        'nodejs-winston',
+        getNodejsLibraryVersion()
+      );
+      // Update instrumentation record resource, logName and timestamp
+      instrumentationEntry.metadata.resource = this.resource;
+      instrumentationEntry.metadata.logName = metadata.logName;
+      instrumentationEntry.metadata.timestamp = metadata.timestamp;
+    }
     message = message || '';
     const hasMetadata = Object.keys(metadata).length;
 
@@ -265,7 +285,22 @@ export class LoggingCommon {
       delete data.metadata!.logName;
     }
 
-    const entry = this.entry(entryMetadata, data);
+    const entries: Entry[] = [];
+    entries.push(this.entry(entryMetadata, data));
+    // Check if instrumentation entry needs to be added as well
+    if (instrumentationEntry) {
+      // Make sure instrumentation entry is updated by underlying logger
+      instrumentationEntry = this.entry(
+        instrumentationEntry.metadata,
+        instrumentationEntry.data
+      );
+      if (levelCode !== NPM_LEVEL_NAME_TO_CODE.info) {
+        // We using info level for diagnostic records
+        this.cloudLog[
+          CLOUD_LOGGING_LEVEL_CODE_TO_NAME[NPM_LEVEL_NAME_TO_CODE.info]
+        ]([instrumentationEntry], this.defaultCallback);
+      } else entries.push(instrumentationEntry);
+    }
     // Make sure that both callbacks are called in case if provided
     const newCallback: Callback = (err: Error | null, apiResponse?: {}) => {
       if (callback) {
@@ -275,7 +310,7 @@ export class LoggingCommon {
         this.defaultCallback(err, apiResponse);
       }
     };
-    this.cloudLog[cloudLevel](entry, newCallback);
+    this.cloudLog[cloudLevel](entries, newCallback);
     // The LogSync class does not supports callback. However Writable class always
     // provides onwrite() callback which needs to be called after each log is written,
     // so the stream would remove writing state. Since this.defaultCallback can also be set, we
@@ -293,6 +328,18 @@ export class LoggingCommon {
   }
 }
 
+export function getNodejsLibraryVersion() {
+  if (libraryVersion) {
+    return libraryVersion;
+  }
+  libraryVersion = require(path.resolve(
+    __dirname,
+    '../../',
+    'package.json'
+  )).version;
+  return libraryVersion;
+}
+
 type MetadataArg = {
   stack?: {};
   /**

system-test/logging-winston.ts

@@ -21,6 +21,7 @@ import {ErrorsApiTransport} from './errors-transport';
 import * as proxyquire from 'proxyquire';
 import * as winston from 'winston';
 import {Logging, Entry} from '@google-cloud/logging';
+import * as instrumentation from '@google-cloud/logging/build/src/utils/instrumentation';
 
 const logging = new Logging();
 
@@ -166,15 +167,31 @@ describe('LoggingWinston', function () {
       // will not return additional diagnostic record which is always written with INFO severity
       logger.error(MESSAGE);
 
-      const [entry] = await pollLogs(
+      const entries = await pollLogs(
         LOG_NAME,
         start,
-        1,
-        WRITE_CONSISTENCY_DELAY_MS,
-        'severity:"ERROR"'
+        2,
+        WRITE_CONSISTENCY_DELAY_MS
       );
-      const data = entry.data as {message: string};
-      assert.strictEqual(data.message, `   ${MESSAGE}`);
+      entries.forEach(entry => {
+        assert.ok(entry.data);
+        if (
+          Object.prototype.hasOwnProperty.call(
+            entry.data,
+            instrumentation.DIAGNOSTIC_INFO_KEY
+          )
+        ) {
+          const info =
+            entry.data[instrumentation.DIAGNOSTIC_INFO_KEY][
+              instrumentation.INSTRUMENTATION_SOURCE_KEY
+            ];
+          assert.equal(info[0].name, 'nodejs');
+          assert.equal(info[1].name, 'nodejs-winston');
+        } else {
+          const data = entry.data as {message: string};
+          assert.strictEqual(data.message, `   ${MESSAGE}`);
+        }
+      });
     });
   });
 
@@ -224,8 +241,7 @@ function pollLogs(
   logName: string,
   logTime: number,
   size: number,
-  timeout: number,
-  filter?: string
+  timeout: number
 ) {
   const p = new Promise<Entry[]>((resolve, reject) => {
     const end = Date.now() + timeout;
@@ -236,7 +252,6 @@ function pollLogs(
         logging.log(logName).getEntries(
           {
             pageSize: size,
-            filter: filter,
           },
           (err, entries) => {
             if (!entries || entries.length < size) return loop();

test/common.ts

@@ -18,6 +18,7 @@ import * as nodeutil from 'util';
 import * as proxyquire from 'proxyquire';
 import {Options} from '../src';
 import {Entry, Logging, LogSync, Log} from '@google-cloud/logging';
+import * as instrumentation from '@google-cloud/logging/build/src/utils/instrumentation';
 import {LoggingCommon} from '../src/common';
 
 declare const global: {[index: string]: {} | null};
@@ -72,6 +73,7 @@ describe('logging-common', () => {
     logName: 'log-name',
     levels: {
       one: 1,
+      six: 6,
     },
     resource: {},
     serviceContext: {
@@ -191,6 +193,7 @@ describe('logging-common', () => {
 
   describe('log', () => {
     const LEVEL = Object.keys(OPTIONS.levels as {[name: string]: number})[0];
+    const INFO = Object.keys(OPTIONS.levels as {[name: string]: number})[1];
     const STACKDRIVER_LEVEL = 'alert'; // (code 1)
     const MESSAGE = 'message';
     const METADATA = {
@@ -497,15 +500,61 @@ describe('logging-common', () => {
       };
 
       loggingCommon.cloudLog[STACKDRIVER_LEVEL] = (
-        entry_: Entry,
+        entry_: Entry[],
         callback: () => void
       ) => {
-        assert.strictEqual(entry_, entry);
+        assert.deepEqual(entry_[0], entry);
         callback(); // done()
       };
 
       loggingCommon.log(LEVEL, MESSAGE, METADATA, done);
     });
+
+    it('should add instrumentation log entry', done => {
+      loggingCommon.cloudLog.entry = (entryMetadata: {}, data: {}) => {
+        return new Entry(entryMetadata, data);
+      };
+      loggingCommon.cloudLog['info'] = (
+        entry_: Entry[],
+        callback: () => void
+      ) => {
+        assert.equal(entry_.length, 2);
+        assert.equal(
+          entry_[1].data[instrumentation.DIAGNOSTIC_INFO_KEY][
+            instrumentation.INSTRUMENTATION_SOURCE_KEY
+          ][0].name,
+          'nodejs-winston'
+        );
+        callback(); // done()
+      };
+      instrumentation.setInstrumentationStatus(false);
+      loggingCommon.log(INFO, MESSAGE, METADATA, done);
+    });
+
+    it('should add instrumentation log entry with info log level', done => {
+      loggingCommon.cloudLog.entry = (entryMetadata: {}, data: {}) => {
+        return new Entry(entryMetadata, data);
+      };
+      loggingCommon.cloudLog['info'] = (entry_: Entry[]) => {
+        assert.equal(entry_.length, 1);
+        assert.equal(
+          entry_[0].data[instrumentation.DIAGNOSTIC_INFO_KEY][
+            instrumentation.INSTRUMENTATION_SOURCE_KEY
+          ][0].name,
+          'nodejs-winston'
+        );
+      };
+      loggingCommon.cloudLog[STACKDRIVER_LEVEL] = (entry_: Entry[]) => {
+        assert.equal(entry_.length, 1);
+        assert.deepStrictEqual(entry_[0].data, {
+          message: MESSAGE,
+          metadata: METADATA,
+        });
+      };
+      instrumentation.setInstrumentationStatus(false);
+      loggingCommon.log(LEVEL, MESSAGE, METADATA);
+      done();
+    });
   });
 
   describe('label and labels', () => {

test/index.ts

@@ -76,6 +76,7 @@ describe('logging-winston', () => {
 
   beforeEach(() => {
     fakeLoggingOptions_ = null;
+    //eslint-disable-next-line @typescript-eslint/no-unused-vars
     loggingWinston = new loggingWinstonLib.LoggingWinston(OPTIONS);
   });
 

test/stackdriver-trace-integration.ts

@@ -98,8 +98,8 @@ describe('Stackdriver Trace Log Correlation', () => {
     logger.log({level: 'info', message: 'hello'});
     setCurrentContextId('3');
     setImmediate(() => {
-      assert.strictEqual(seenContextIds.length, 2);
-      assert.deepStrictEqual(seenContextIds, ['1', '2']);
+      assert.strictEqual(seenContextIds.length, 3);
+      assert.deepStrictEqual(seenContextIds, ['1', '', '2']);
       done();
     });
   });