feat: adds a pathway for automatic instrumentation

* Exports an autoinstrumnetation library that can be ran, resulting in logs and traces being
  exported to gcp
* a winston logger is automatically created for users of synthetics, isntrumented or otherwise,
  for use within synthetic code

Author: dkoss2

.github/workflows/ci.yml

@@ -8,7 +8,7 @@ jobs:
     runs-on: ubuntu-latest
     strategy:
       matrix:
-        node: [14, 16, 18, 20]
+        node: [18, 20]
         include:
           # use latest npm by default
           - npm-version: latest

package-lock.json

@@ -15,6 +15,7 @@
     "@types/supertest": "^2.0.12",
     "chai": "^4.3.7",
     "express": "^4.18.2",
+    "sinon": "^16.0.0",
     "supertest": "^6.3.3"
   },
   "scripts": {
@@ -30,8 +31,18 @@
     "posttest": "npm run lint"
   },
   "dependencies": {
+    "@google-cloud/opentelemetry-cloud-trace-exporter": "^2.1.0",
+    "@opentelemetry/api": "^1.6.0",
+    "@opentelemetry/auto-instrumentations-node": "^0.39.2",
+    "@opentelemetry/instrumentation": "^0.43.0",
+    "@opentelemetry/sdk-node": "^0.43.0",
+    "@opentelemetry/sdk-trace-base": "^1.17.0",
+    "@opentelemetry/sdk-trace-node": "^1.17.0",
+    "@types/sinon": "^10.0.16",
     "error-stack-parser": "^2.1.4",
-    "ts-proto": "^1.148.1"
+    "google-auth-library": "^9.0.0",
+    "ts-proto": "^1.148.1",
+    "winston": "^3.10.0"
   },
   "author": "Google Inc.",
   "license": "Apache-2.0"

packages/synthetics-sdk-api/package.json

@@ -0,0 +1,179 @@
+// Copyright 2023 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//      https://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';
+import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node';
+import { registerInstrumentations } from '@opentelemetry/instrumentation';
+import {
+  BatchSpanProcessor,
+  AlwaysOnSampler,
+} from '@opentelemetry/sdk-trace-base';
+import { Span, TraceFlags } from '@opentelemetry/api';
+import { GoogleAuth, GoogleAuthOptions } from 'google-auth-library';
+import { Logger } from 'winston';
+import { TraceExporter } from '@google-cloud/opentelemetry-cloud-trace-exporter';
+
+const LOGGING_TRACE_KEY = 'logging.googleapis.com/trace';
+const LOGGING_SPAN_KEY = 'logging.googleapis.com/spanId';
+const LOGGING_SAMPLED_KEY = 'logging.googleapis.com/trace_sampled';
+const LOGGING_SEVERITY_KEY = 'severity';
+
+const levelToSeverityMap: { [key: string]: string } = {
+  error: 'ERROR',
+  warn: 'WARNING',
+  info: 'INFO',
+  http: 'INFO',
+  verbose: 'DEBUG',
+  debug: 'DEBUG',
+  silly: 'DEBUG',
+};
+
+let singletonAutoInstrumentation: SyntheticsAutoInstrumentation | null;
+
+/**
+ * @public
+ *
+ * This function sets up user authored synthetic code with a baseline open
+ * telemetry setup that will write traces and logs to cloud trace and cloud
+ * logging.
+ *
+ * NOTE: For this module to be used effectively, it needs to be included
+ * and ran before any other code within your synthetic application runs.
+ */
+export const instantiateAutoInstrumentation = (
+  args: { googleAuthOptions?: GoogleAuthOptions } = {}
+) => {
+  singletonAutoInstrumentation = new SyntheticsAutoInstrumentation(args);
+};
+
+/**
+ * @public
+ *
+ * Returns a winston logger that is instrumented to use the console transport.
+ *
+ * If {@link #instantiateAutoInstrumentation} is ran prior to any other code,
+ * and a project id is detected according to the logs will be instrumented
+ * with trace information that is formated in gcp's
+ * {@link https://cloud.google.com/logging/docs/structured-logging|structured logging}
+ * format.
+ */
+export const getInstrumentedLogger = async (): Promise<Logger> => {
+  if (singletonAutoInstrumentation) {
+    return await singletonAutoInstrumentation.getInstrumentedLogger();
+  } else {
+    const winston = require('winston');
+    return winston.createLogger({
+      transports: [new winston.transports.Console()],
+    });
+  }
+};
+
+class SyntheticsAutoInstrumentation {
+  provider: NodeTracerProvider;
+
+  private logger: Logger;
+  private gcpProjectId?: string | null;
+  private authArgs: GoogleAuthOptions;
+
+  constructor(args: { googleAuthOptions?: GoogleAuthOptions } = {}) {
+    this.authArgs = args.googleAuthOptions || {};
+
+    this.provider = new NodeTracerProvider({
+      sampler: new AlwaysOnSampler(),
+    });
+    const exporter = new TraceExporter();
+    this.provider.addSpanProcessor(new BatchSpanProcessor(exporter));
+    this.provider.register();
+
+    // add node auto instrumentation
+    registerInstrumentations({
+      instrumentations: [
+        getNodeAutoInstrumentations({
+          '@opentelemetry/instrumentation-winston': {
+            logHook: (span: Span, record: Record<string, string | boolean>) => {
+              // If the auto instrumentation has detected a project id, convert
+              // otel fields that are automatically added to the record to use
+              // structured logging fields instead.
+              if (this.gcpProjectId) {
+                record[LOGGING_TRACE_KEY] = `projects/${
+                  this.gcpProjectId
+                }/traces/${span.spanContext().traceId}`;
+                record[LOGGING_SPAN_KEY] = span.spanContext().spanId;
+                record[LOGGING_SAMPLED_KEY] =
+                  span.spanContext().traceFlags === TraceFlags.SAMPLED;
+                record[LOGGING_SEVERITY_KEY] =
+                  levelToSeverityMap[String(record.level)] ?? 'DEFAULT';
+                delete record['span_id'];
+                delete record['trace_flags'];
+                delete record['level'];
+                delete record['trace_id'];
+              }
+            },
+          },
+        }),
+      ],
+    });
+
+    // Require dependencies after instrumentation is registered,
+    // otherwise they wont be instrumented.
+    const winston = require('winston');
+    const logger = winston.createLogger({
+      transports: [new winston.transports.Console()],
+    });
+    this.logger = logger;
+  }
+
+  async getInstrumentedLogger(): Promise<Logger> {
+    this.gcpProjectId = await resolveProjectId(
+      this.gcpProjectId,
+      this.authArgs
+    );
+    return this.logger;
+  }
+}
+
+/**
+ * @public
+ *
+ * Resolves and caches the project ID, a field that is required for formatting
+ * structured logs.
+ */
+export const resolveProjectId = async (
+  gcpProjectId?: string | null,
+  googleAuthOptions?: GoogleAuthOptions
+): Promise<string | null> => {
+  // if gcpProjectId has been instantiated, return it. Otherwise attempt to
+  // resolve at most 1 times, assign to null otherwise.
+  if (typeof gcpProjectId === 'string' || gcpProjectId === null) {
+    return gcpProjectId;
+  }
+
+  const auth = new GoogleAuth({
+    credentials: googleAuthOptions?.credentials,
+    keyFile: googleAuthOptions?.keyFile,
+    keyFilename: googleAuthOptions?.keyFilename,
+    projectId: googleAuthOptions?.projectId,
+    scopes: ['https://www.googleapis.com/auth/cloud-platform'],
+  });
+
+  try {
+    return await auth.getProjectId();
+  } catch (e) {
+    console.log(
+      'Unable to resolve gcpProjectId, logs will not be written in GCP Structured Logging format'
+    );
+  }
+
+  return null;
+};

packages/synthetics-sdk-api/src/auto_instrumentation.ts

@@ -23,20 +23,24 @@ import {
   getRuntimeMetadata,
   instantiateMetadata,
 } from './runtime_metadata_extractor';
+import { Logger } from 'winston';
 
+import { getInstrumentedLogger } from './auto_instrumentation';
 instantiateMetadata();
 
 const asyncFilenamePrefix = 'async ';
-
-// eslint-disable-next-line  @typescript-eslint/no-explicit-any
-const runSynthetic = async (syntheticCode: () => any) => {
+const runSynthetic = async (
+  // eslint-disable-next-line  @typescript-eslint/no-explicit-any
+  syntheticCode: (args: { logger: Logger }) => any
+) => {
+  const logger = await getInstrumentedLogger();
   const startTime = new Date().toISOString();
 
   const syntheticResult = SyntheticResult.create();
   const synthetic_generic_result = GenericResultV1.create();
 
   try {
-    await syntheticCode();
+    await syntheticCode({ logger });
     synthetic_generic_result.ok = true;
   } catch (err: unknown) {
     synthetic_generic_result.ok = false;
@@ -88,8 +92,10 @@ const runSynthetic = async (syntheticCode: () => any) => {
  * @returns ExpressJS compatible middleware that invokes SyntheticsSDK mocha, and
  * returns the results via res.send
  */
-// eslint-disable-next-line  @typescript-eslint/no-explicit-any
-export function runSyntheticHandler(syntheticCode: () => any) {
+export function runSyntheticHandler(
+  // eslint-disable-next-line  @typescript-eslint/no-explicit-any
+  syntheticCode: (args: { logger: Logger }) => any
+) {
   // eslint-disable-next-line  @typescript-eslint/no-explicit-any
   return async (req: Request, res: Response): Promise<any> =>
     res.send(await runSynthetic(syntheticCode));

packages/synthetics-sdk-api/src/handlers.ts

@@ -15,9 +15,14 @@
 /**
  * @public
  */
+
 export * from './generated/proto/synthetic_response';
 export { runSyntheticHandler } from './handlers';
 export {
   getRuntimeMetadata,
   instantiateMetadata,
 } from './runtime_metadata_extractor';
+export {
+  instantiateAutoInstrumentation,
+  getInstrumentedLogger,
+} from './auto_instrumentation';

packages/synthetics-sdk-api/src/index.ts

@@ -12,17 +12,20 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+const { runSyntheticHandler, instantiateAutoInstrumentation } = require('../../src/index');
+instantiateAutoInstrumentation();
 const functions = require('@google-cloud/functions-framework');
-const { runSyntheticHandler } = require('@google-cloud/synthetics-sdk-api');
 import { AssertionError } from 'chai';
 
-functions.http('SyntheticOk', runSyntheticHandler(async () => {
+functions.http('SyntheticOk', runSyntheticHandler(async ({logger}) => {
+  logger.info('This is a log');
   return await true;
 }));
 
-functions.http('SyntheticNotOk', runSyntheticHandler(async () => {
+functions.http('SyntheticNotOk', runSyntheticHandler(async ({logger}) => {
     const e = new AssertionError('Did not assert');
     const splitStack = e.stack?.split('\n', 2) ?? '';
+    logger.error('This is an error log');
     e.stack = [
       splitStack?.[0],
       '    at internalFn (node:internal)',

packages/synthetics-sdk-api/test/example_test_files/integration_server.js

@@ -12,23 +12,63 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-import { SyntheticResult } from '../../src'
+require('../../test/example_test_files/integration_server.js');
+import { SyntheticResult, TestFrameworkResultV1 } from '../../src';
 import { expect } from 'chai';
 import supertest from 'supertest';
 
-require('../../test/example_test_files/integration_server.js');
+import { Writable } from 'stream';
+import * as sinon from 'sinon';
+import winston, { Logger } from 'winston';
+
 const { getTestServer } = require('@google-cloud/functions-framework/testing');
+const { getInstrumentedLogger } = require('../../src/auto_instrumentation');
+
+let logger: Logger;
+let writeSpy: sinon.SinonSpy;
+
+const traceVersion = '00';
+const traceId = '12345678901234567890123456789012';
+const traceParentId = '1234567890123456';
+const traceFlags = '01';
+const traceParentHeader = [traceVersion, traceId, traceParentId, traceFlags].join('-');
 
 describe('CloudFunctionV2 Running Synthetics', async () => {
+  beforeEach(async () => {
+    const stream = new Writable();
+    stream._write = () => {};
+    writeSpy = sinon.spy(stream, '_write');
+
+    sinon.replace(process, 'env', {GCLOUD_PROJECT: 'project-id'});
+
+    logger = await getInstrumentedLogger();
+
+    const streamTransport = new winston.transports.Stream({ stream });
+    logger.add(streamTransport);
+  });
+
+  afterEach(async () => {
+    sinon.restore();
+  });
+
   it('runs a passing synthetic function', async () => {
     const server = getTestServer('SyntheticOk');
-
     const response = await supertest(server)
       .get('/')
       .send()
       .set('Content-Type', 'application/json')
+      .set('traceparent', traceParentHeader)
       .expect(200);
 
+    sinon.assert.calledOnce(writeSpy);
+
+    const record = JSON.parse(writeSpy.firstCall.args[0].toString());
+    expect(record['severity']).to.equal('INFO');
+    expect(record['message']).to.equal('This is a log');
+    expect(record['logging.googleapis.com/spanId']).to.equal('1234567890123456');
+    expect(record['logging.googleapis.com/trace']).to.equal('projects/project-id/traces/12345678901234567890123456789012');
+    expect(record['logging.googleapis.com/trace_sampled']).to.equal(true);
+
     const output: SyntheticResult = response.body as SyntheticResult;
     const start_time = output.start_time;
     const end_time = output.end_time;
@@ -51,8 +91,18 @@ describe('CloudFunctionV2 Running Synthetics', async () => {
       .get('/')
       .send()
       .set('Content-Type', 'application/json')
+      .set('traceparent', traceParentHeader)
       .expect(200);
 
+    sinon.assert.calledOnce(writeSpy);
+
+    const record = JSON.parse(writeSpy.firstCall.args[0].toString());
+    expect(record['message']).to.equal('This is an error log');
+    expect(record['severity']).to.equal('ERROR');
+    expect(record['logging.googleapis.com/spanId']).to.equal('1234567890123456');
+    expect(record['logging.googleapis.com/trace']).to.equal('projects/project-id/traces/12345678901234567890123456789012');
+    expect(record['logging.googleapis.com/trace_sampled']).to.equal(true);
+
     const output: SyntheticResult = response.body as SyntheticResult;
     const start_time = output.start_time;
     const end_time = output.end_time;