diff --git a/package.json b/package.json index 4af28865..359b499d 100644 --- a/package.json +++ b/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" diff --git a/src/common.ts b/src/common.ts index 47443274..2011ff81 100644 --- a/src/common.ts +++ b/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?: {}; /** diff --git a/system-test/logging-winston.ts b/system-test/logging-winston.ts index 5654636f..6f4f8d72 100644 --- a/system-test/logging-winston.ts +++ b/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((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(); diff --git a/test/common.ts b/test/common.ts index 05973b5b..0e0555d4 100644 --- a/test/common.ts +++ b/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', () => { diff --git a/test/index.ts b/test/index.ts index 5461068f..1748829e 100644 --- a/test/index.ts +++ b/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); }); diff --git a/test/stackdriver-trace-integration.ts b/test/stackdriver-trace-integration.ts index 20d039a2..1f338c0d 100644 --- a/test/stackdriver-trace-integration.ts +++ b/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(); }); });