Skip to content

Commit bb92d38

Browse files
mbleighmbleigh
authored
Adds structured logging API. (#665)
1 parent bb6f038 commit bb92d38

File tree

6 files changed

+269
-1
lines changed

6 files changed

+269
-1
lines changed

‎CHANGELOG.md

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,18 @@
1+
- Adds `functions.logger` SDK to enable structured logging in the Node.js 10 runtime. For example:
2+
3+
```js
4+
const functions = require('firebase-functions');
5+
6+
functions.logger.debug('example log with structured data', {
7+
uid: user.uid,
8+
authorized: true,
9+
});
10+
```
11+
12+
The logger can also override default behavior of `console.*` methods through a special require:
13+
14+
```js
15+
require('firebase-functions/logger/compat');
16+
```
17+
18+
In older runtimes, logger prints to the console, and no structured data is saved.

‎spec/logger.spec.ts

Lines changed: 105 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,105 @@
1+
import { expect } from 'chai';
2+
import * as sinon from 'sinon';
3+
import * as logger from '../src/logger';
4+
5+
const SUPPORTS_STRUCTURED_LOGS =
6+
parseInt(process.versions?.node?.split('.')?.[0] || '8', 10) >= 10;
7+
8+
describe(`logger (${
9+
SUPPORTS_STRUCTURED_LOGS ? 'structured' : 'unstructured'
10+
})`, () => {
11+
let sandbox: sinon.SinonSandbox;
12+
let stdoutStub: sinon.SinonStub;
13+
let stderrStub: sinon.SinonStub;
14+
15+
beforeEach(() => {
16+
sandbox = sinon.createSandbox();
17+
stdoutStub = sandbox.stub(process.stdout, 'write');
18+
stderrStub = sandbox.stub(process.stderr, 'write');
19+
});
20+
21+
function expectOutput(stdStub: sinon.SinonStub, entry: any) {
22+
if (SUPPORTS_STRUCTURED_LOGS) {
23+
return expect(
24+
JSON.parse((stdStub.getCalls()[0].args[0] as string).trim())
25+
).to.deep.eq(entry);
26+
} else {
27+
// legacy logging is not structured, but do a sanity check
28+
return expect(stdStub.getCalls()[0].args[0]).to.include(entry.message);
29+
}
30+
}
31+
32+
function expectStdout(entry: any) {
33+
return expectOutput(stdoutStub, entry);
34+
}
35+
36+
function expectStderr(entry: any) {
37+
return expectOutput(stderrStub, entry);
38+
}
39+
40+
describe('logging methods', () => {
41+
let writeStub: sinon.SinonStub;
42+
beforeEach(() => {
43+
writeStub = sinon.stub(logger, 'write');
44+
});
45+
46+
afterEach(() => {
47+
writeStub.restore();
48+
});
49+
50+
it('should coalesce arguments into the message', () => {
51+
logger.log('hello', { middle: 'obj' }, 'end message');
52+
expectStdout({
53+
severity: 'INFO',
54+
message: "hello { middle: 'obj' } end message",
55+
});
56+
sandbox.restore(); // to avoid swallowing test runner output
57+
});
58+
59+
it('should merge structured data from the last argument', () => {
60+
logger.log('hello', 'world', { additional: 'context' });
61+
expectStdout({
62+
severity: 'INFO',
63+
message: 'hello world',
64+
additional: 'context',
65+
});
66+
sandbox.restore(); // to avoid swallowing test runner output
67+
});
68+
});
69+
70+
describe('write', () => {
71+
describe('structured logging', () => {
72+
describe('write', () => {
73+
for (const severity of ['DEBUG', 'INFO', 'NOTICE']) {
74+
it(`should output ${severity} severity to stdout`, () => {
75+
let entry: logger.LogEntry = {
76+
severity: severity as logger.LogSeverity,
77+
message: 'test',
78+
};
79+
logger.write(entry);
80+
expectStdout(entry);
81+
sandbox.restore(); // to avoid swallowing test runner output
82+
});
83+
}
84+
85+
for (const severity of [
86+
'WARNING',
87+
'ERROR',
88+
'CRITICAL',
89+
'ALERT',
90+
'EMERGENCY',
91+
]) {
92+
it(`should output ${severity} severity to stderr`, () => {
93+
let entry: logger.LogEntry = {
94+
severity: severity as logger.LogSeverity,
95+
message: 'test',
96+
};
97+
logger.write(entry);
98+
expectStderr(entry);
99+
sandbox.restore(); // to avoid swallowing test runner output
100+
});
101+
}
102+
});
103+
});
104+
});
105+
});

‎src/index.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@ import * as storage from './providers/storage';
3333
import * as testLab from './providers/testLab';
3434

3535
import * as apps from './apps';
36+
import * as logger from './logger';
3637
import { handler } from './handler-builder';
3738
import { setup } from './setup';
3839

@@ -51,6 +52,7 @@ export {
5152
remoteConfig,
5253
storage,
5354
testLab,
55+
logger,
5456
};
5557

5658
// Exported root types:

‎src/logger.ts

Lines changed: 135 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,135 @@
1+
import { format } from 'util';
2+
3+
// safely preserve unpatched console.* methods in case of compat require
4+
const unpatchedConsole = {
5+
debug: console.debug,
6+
info: console.info,
7+
log: console.log,
8+
warn: console.warn,
9+
error: console.error,
10+
};
11+
12+
// Determine if structured logs are supported (node >= 10). If something goes wrong,
13+
// assume no since unstructured is safer.
14+
const SUPPORTS_STRUCTURED_LOGS =
15+
parseInt(process.versions?.node?.split('.')?.[0] || '8', 10) >= 10;
16+
17+
// Map LogSeverity types to their equivalent `console.*` method.
18+
const CONSOLE_SEVERITY: {
19+
[severity: string]: 'debug' | 'info' | 'warn' | 'error';
20+
} = {
21+
DEBUG: 'debug',
22+
INFO: 'info',
23+
NOTICE: 'info',
24+
WARNING: 'warn',
25+
ERROR: 'error',
26+
CRITICAL: 'error',
27+
ALERT: 'error',
28+
EMERGENCY: 'error',
29+
};
30+
31+
/**
32+
* `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.
33+
*/
34+
export type LogSeverity =
35+
| 'DEBUG'
36+
| 'INFO'
37+
| 'NOTICE'
38+
| 'WARNING'
39+
| 'ERROR'
40+
| 'CRITICAL'
41+
| 'ALERT'
42+
| 'EMERGENCY';
43+
44+
/**
45+
* `LogEntry` represents a structured Cloud Logging entry. All keys aside from `severity` and `message` are
46+
* included in the `jsonPayload` of the logged entry.
47+
*/
48+
export interface LogEntry {
49+
severity: LogSeverity;
50+
message?: string;
51+
[key: string]: any;
52+
}
53+
54+
/**
55+
* Writes a `LogEntry` to `stdout`/`stderr` (depending on severity).
56+
* @param entry The LogEntry including severity, message, and any additional structured metadata.
57+
*/
58+
export function write(entry: LogEntry) {
59+
if (SUPPORTS_STRUCTURED_LOGS) {
60+
unpatchedConsole[CONSOLE_SEVERITY[entry.severity]](JSON.stringify(entry));
61+
return;
62+
}
63+
64+
let message = entry.message || '';
65+
const jsonPayload: { [key: string]: any } = {};
66+
let jsonKeyCount = 0;
67+
for (const k in entry) {
68+
if (!['severity', 'message'].includes(k)) {
69+
jsonKeyCount++;
70+
jsonPayload[k] = entry[k];
71+
}
72+
}
73+
if (jsonKeyCount > 0) {
74+
message = `${message} ${JSON.stringify(jsonPayload, null, 2)}`;
75+
}
76+
unpatchedConsole[CONSOLE_SEVERITY[entry.severity]](message);
77+
}
78+
79+
/**
80+
* Writes a `DEBUG` severity log. If the last argument provided is a plain object,
81+
* it will be added to the `jsonPayload` in the Cloud Logging entry.
82+
* @param args Arguments, concatenated into the log message with space separators.
83+
*/
84+
export function debug(...args: any[]) {
85+
write(entryFromArgs('DEBUG', args));
86+
}
87+
88+
/**
89+
* Writes an `INFO` severity log. If the last argument provided is a plain object,
90+
* it will be added to the `jsonPayload` in the Cloud Logging entry.
91+
* @param args Arguments, concatenated into the log message with space separators.
92+
*/
93+
export function log(...args: any[]) {
94+
write(entryFromArgs('INFO', args));
95+
}
96+
97+
/**
98+
* Writes an `INFO` severity log. If the last argument provided is a plain object,
99+
* it will be added to the `jsonPayload` in the Cloud Logging entry.
100+
* @param args Arguments, concatenated into the log message with space separators.
101+
*/
102+
export function info(...args: any[]) {
103+
write(entryFromArgs('INFO', args));
104+
}
105+
106+
/**
107+
* Writes a `WARNING` severity log. If the last argument provided is a plain object,
108+
* it will be added to the `jsonPayload` in the Cloud Logging entry.
109+
* @param args Arguments, concatenated into the log message with space separators.
110+
*/
111+
export function warn(...args: any[]) {
112+
write(entryFromArgs('WARNING', args));
113+
}
114+
115+
/**
116+
* Writes an `ERROR` severity log. If the last argument provided is a plain object,
117+
* it will be added to the `jsonPayload` in the Cloud Logging entry.
118+
* @param args Arguments, concatenated into the log message with space separators.
119+
*/
120+
export function error(...args: any[]) {
121+
write(entryFromArgs('ERROR', args));
122+
}
123+
124+
function entryFromArgs(severity: LogSeverity, args: any[]): LogEntry {
125+
let entry = {};
126+
const lastArg = args[args.length - 1];
127+
if (typeof lastArg == 'object' && lastArg.constructor == Object) {
128+
entry = args.pop();
129+
}
130+
return Object.assign({}, entry, {
131+
severity,
132+
// mimic `console.*` behavior, see https://nodejs.org/api/console.html#console_console_log_data_args
133+
message: format.apply(null, args),
134+
});
135+
}

‎src/logger/compat.ts

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,8 @@
1+
import { debug, info, warn, error } from '../logger';
2+
3+
// IMPORTANT -- "../logger" must be imported before monkeypatching!
4+
console.debug = debug;
5+
console.info = info;
6+
console.log = info;
7+
console.warn = warn;
8+
console.error = error;

‎tsconfig.release.json

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -10,5 +10,5 @@
1010
"target": "es2017",
1111
"typeRoots": ["./node_modules/@types"]
1212
},
13-
"files": ["./src/index.ts"]
13+
"files": ["./src/index.ts", "./src/logger.ts", "./src/logger/compat.ts"]
1414
}

0 commit comments

Comments
 (0)