diff --git a/CHANGELOG.md b/CHANGELOG.md index e69de29bb..f85fd69b3 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/spec/logger.spec.ts b/spec/logger.spec.ts new file mode 100644 index 000000000..517f50f1d --- /dev/null +++ b/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 + }); + } + }); + }); + }); +}); diff --git a/src/index.ts b/src/index.ts index d4951c512..dcca98172 100644 --- a/src/index.ts +++ b/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: diff --git a/src/logger.ts b/src/logger.ts new file mode 100644 index 000000000..7d4c91cbf --- /dev/null +++ b/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), + }); +} diff --git a/src/logger/compat.ts b/src/logger/compat.ts new file mode 100644 index 000000000..6f6eda03f --- /dev/null +++ b/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; diff --git a/tsconfig.release.json b/tsconfig.release.json index e93d5d4b6..a226eb290 100644 --- a/tsconfig.release.json +++ b/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"] }