Adds structured logging API.

CHANGELOG.md

@@ -0,0 +1,18 @@
+- Adds `functions.logger` SDK to enable structured logging in the Node.js 10 runtime. For example:
+
+  ```js
+  const functions = require('firebase-functions');
+
+  functions.logger.debug('example log with structured data', {
+    uid: user.uid,
+    authorized: true,
+  });
+  ```
+
+  The logger can also override default behavior of `console.*` methods through a special require:
+
+  ```js
+  require('firebase-functions/logger/compat');
+  ```
+
+  In older runtimes, logger prints to the console, and no structured data is saved.

spec/logger.spec.ts

@@ -0,0 +1,105 @@
+import { expect } from 'chai';
+import * as sinon from 'sinon';
+import * as logger from '../src/logger';
+
+const SUPPORTS_STRUCTURED_LOGS =
+  parseInt(process.versions?.node?.split('.')?.[0] || '8', 10) >= 10;
+
+describe(`logger (${
+  SUPPORTS_STRUCTURED_LOGS ? 'structured' : 'unstructured'
+})`, () => {
+  let sandbox: sinon.SinonSandbox;
+  let stdoutStub: sinon.SinonStub;
+  let stderrStub: sinon.SinonStub;
+
+  beforeEach(() => {
+    sandbox = sinon.createSandbox();
+    stdoutStub = sandbox.stub(process.stdout, 'write');
+    stderrStub = sandbox.stub(process.stderr, 'write');
+  });
+
+  function expectOutput(stdStub: sinon.SinonStub, entry: any) {
+    if (SUPPORTS_STRUCTURED_LOGS) {
+      return expect(
+        JSON.parse((stdStub.getCalls()[0].args[0] as string).trim())
+      ).to.deep.eq(entry);
+    } else {
+      // legacy logging is not structured, but do a sanity check
+      return expect(stdStub.getCalls()[0].args[0]).to.include(entry.message);
+    }
+  }
+
+  function expectStdout(entry: any) {
+    return expectOutput(stdoutStub, entry);
+  }
+
+  function expectStderr(entry: any) {
+    return expectOutput(stderrStub, entry);
+  }
+
+  describe('logging methods', () => {
+    let writeStub: sinon.SinonStub;
+    beforeEach(() => {
+      writeStub = sinon.stub(logger, 'write');
+    });
+
+    afterEach(() => {
+      writeStub.restore();
+    });
+
+    it('should coalesce arguments into the message', () => {
+      logger.log('hello', { middle: 'obj' }, 'end message');
+      expectStdout({
+        severity: 'INFO',
+        message: "hello { middle: 'obj' } end message",
+      });
+      sandbox.restore(); // to avoid swallowing test runner output
+    });
+
+    it('should merge structured data from the last argument', () => {
+      logger.log('hello', 'world', { additional: 'context' });
+      expectStdout({
+        severity: 'INFO',
+        message: 'hello world',
+        additional: 'context',
+      });
+      sandbox.restore(); // to avoid swallowing test runner output
+    });
+  });
+
+  describe('write', () => {
+    describe('structured logging', () => {
+      describe('write', () => {
+        for (const severity of ['DEBUG', 'INFO', 'NOTICE']) {
+          it(`should output ${severity} severity to stdout`, () => {
+            let entry: logger.LogEntry = {
+              severity: severity as logger.LogSeverity,
+              message: 'test',
+            };
+            logger.write(entry);
+            expectStdout(entry);
+            sandbox.restore(); // to avoid swallowing test runner output
+          });
+        }
+
+        for (const severity of [
+          'WARNING',
+          'ERROR',
+          'CRITICAL',
+          'ALERT',
+          'EMERGENCY',
+        ]) {
+          it(`should output ${severity} severity to stderr`, () => {
+            let entry: logger.LogEntry = {
+              severity: severity as logger.LogSeverity,
+              message: 'test',
+            };
+            logger.write(entry);
+            expectStderr(entry);
+            sandbox.restore(); // to avoid swallowing test runner output
+          });
+        }
+      });
+    });
+  });
+});

src/index.ts

@@ -33,6 +33,7 @@ import * as storage from './providers/storage';
 import * as testLab from './providers/testLab';
 
 import * as apps from './apps';
+import * as logger from './logger';
 import { handler } from './handler-builder';
 import { setup } from './setup';
 
@@ -51,6 +52,7 @@ export {
   remoteConfig,
   storage,
   testLab,
+  logger,
 };
 
 // Exported root types:

src/logger.ts

@@ -0,0 +1,135 @@
+import { format } from 'util';
+
+// safely preserve unpatched console.* methods in case of compat require
+const unpatchedConsole = {
+  debug: console.debug,
+  info: console.info,
+  log: console.log,
+  warn: console.warn,
+  error: console.error,
+};
+
+// Determine if structured logs are supported (node >= 10). If something goes wrong,
+// assume no since unstructured is safer.
+const SUPPORTS_STRUCTURED_LOGS =
+  parseInt(process.versions?.node?.split('.')?.[0] || '8', 10) >= 10;
+
+// Map LogSeverity types to their equivalent `console.*` method.
+const CONSOLE_SEVERITY: {
+  [severity: string]: 'debug' | 'info' | 'warn' | 'error';
+} = {
+  DEBUG: 'debug',
+  INFO: 'info',
+  NOTICE: 'info',
+  WARNING: 'warn',
+  ERROR: 'error',
+  CRITICAL: 'error',
+  ALERT: 'error',
+  EMERGENCY: 'error',
+};
+
+/**
+ * `LogSeverity` indicates the detailed severity of the log entry. See [LogSeverity](https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#logseverity) for more.
+ */
+export type LogSeverity =
+  | 'DEBUG'
+  | 'INFO'
+  | 'NOTICE'
+  | 'WARNING'
+  | 'ERROR'
+  | 'CRITICAL'
+  | 'ALERT'
+  | 'EMERGENCY';
+
+/**
+ * `LogEntry` represents a structured Cloud Logging entry. All keys aside from `severity` and `message` are
+ * included in the `jsonPayload` of the logged entry.
+ */
+export interface LogEntry {
+  severity: LogSeverity;
+  message?: string;
+  [key: string]: any;
+}
+
+/**
+ * Writes a `LogEntry` to `stdout`/`stderr` (depending on severity).
+ * @param entry The LogEntry including severity, message, and any additional structured metadata.
+ */
+export function write(entry: LogEntry) {
+  if (SUPPORTS_STRUCTURED_LOGS) {
+    unpatchedConsole[CONSOLE_SEVERITY[entry.severity]](JSON.stringify(entry));
+    return;
+  }
+
+  let message = entry.message || '';
+  const jsonPayload: { [key: string]: any } = {};
+  let jsonKeyCount = 0;
+  for (const k in entry) {
+    if (!['severity', 'message'].includes(k)) {
+      jsonKeyCount++;
+      jsonPayload[k] = entry[k];
+    }
+  }
+  if (jsonKeyCount > 0) {
+    message = `${message} ${JSON.stringify(jsonPayload, null, 2)}`;
+  }
+  unpatchedConsole[CONSOLE_SEVERITY[entry.severity]](message);
+}
+
+/**
+ * Writes a `DEBUG` severity log. If the last argument provided is a plain object,
+ * it will be added to the `jsonPayload` in the Cloud Logging entry.
+ * @param args Arguments, concatenated into the log message with space separators.
+ */
+export function debug(...args: any[]) {
+  write(entryFromArgs('DEBUG', args));
+}
+
+/**
+ * Writes an `INFO` severity log. If the last argument provided is a plain object,
+ * it will be added to the `jsonPayload` in the Cloud Logging entry.
+ * @param args Arguments, concatenated into the log message with space separators.
+ */
+export function log(...args: any[]) {
+  write(entryFromArgs('INFO', args));
+}
+
+/**
+ * Writes an `INFO` severity log. If the last argument provided is a plain object,
+ * it will be added to the `jsonPayload` in the Cloud Logging entry.
+ * @param args Arguments, concatenated into the log message with space separators.
+ */
+export function info(...args: any[]) {
+  write(entryFromArgs('INFO', args));
+}
+
+/**
+ * Writes a `WARNING` severity log. If the last argument provided is a plain object,
+ * it will be added to the `jsonPayload` in the Cloud Logging entry.
+ * @param args Arguments, concatenated into the log message with space separators.
+ */
+export function warn(...args: any[]) {
+  write(entryFromArgs('WARNING', args));
+}
+
+/**
+ * Writes an `ERROR` severity log. If the last argument provided is a plain object,
+ * it will be added to the `jsonPayload` in the Cloud Logging entry.
+ * @param args Arguments, concatenated into the log message with space separators.
+ */
+export function error(...args: any[]) {
+  write(entryFromArgs('ERROR', args));
+}
+
+function entryFromArgs(severity: LogSeverity, args: any[]): LogEntry {
+  let entry = {};
+  const lastArg = args[args.length - 1];
+  if (typeof lastArg == 'object' && lastArg.constructor == Object) {
+    entry = args.pop();
+  }
+  return Object.assign({}, entry, {
+    severity,
+    // mimic `console.*` behavior, see https://nodejs.org/api/console.html#console_console_log_data_args
+    message: format.apply(null, args),
+  });
+}

src/logger/compat.ts

@@ -0,0 +1,8 @@
+import { debug, info, warn, error } from '../logger';
+
+// IMPORTANT -- "../logger" must be imported before monkeypatching!
+console.debug = debug;
+console.info = info;
+console.log = info;
+console.warn = warn;
+console.error = error;

tsconfig.release.json

@@ -10,5 +10,5 @@
     "target": "es2017",
     "typeRoots": ["./node_modules/@types"]
   },
-  "files": ["./src/index.ts"]
+  "files": ["./src/index.ts", "./src/logger.ts", "./src/logger/compat.ts"]
 }