Skip to content

Commit 5ef89de

Browse files
authored
feat: allow users to turn on logging without the environment variable (#1704)
* feat: allow users to turn on logging without the environment variable * docs: add a README.md for logger * fix: run structured logs through console.log to avoid formatting * fix: swallow more exceptions to avoid interfering with other logging
1 parent fc3eeaa commit 5ef89de

File tree

4 files changed

+148
-17
lines changed

4 files changed

+148
-17
lines changed

logging-utils/README.md

Lines changed: 73 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,73 @@
1+
# Google Logging Tools
2+
3+
## About
4+
This package defines an ad-hoc debug logger utility that can be used as a lightweight alternative to "printf debugging" via `console.log`, and provides more, and more structured information. It is based largely on the ideas of the Node `util.debuglog` function, and the `debug` npm package.
5+
6+
## Contracts
7+
These are logging utilities meant primarily for use as an "adhoc debug logger" inside Google libraries. It's possible to use this outside of that context, but it is currently not supported. (You're on your own.)
8+
9+
Additionally, everything about the debug logging is not intended to be a stable interface - you can't rely on messages to remain the same, or to continue to exist from one version to the next. For now, it is meant to be a tool for local usage by users, to get the equivalent of "printf debugging" output. In the future, it may tie into more things (OpenTelemetry Logging, etc). Structured log output is possible for vacuuming into Cloud Logging.
10+
11+
This npm package itself is intended to follow semver standards for its own interfaces, but no guarantees are made for supported time windows, etc.
12+
13+
## Usage
14+
The user interface for this logging is very similar to Node's built-in logging. The primary unit of logging is called a "system", and some libraries may have sub-units called "subsystems". You separate the system and subsystem with a colon, like "pubsub:leasing" or similar. Wildcards may be used (e.g. "pubsub:*"), and multiple of these system/system:subsystem pairs may be listed out, separated by commas. For generated GAPIC libraries, the "system" will generally be the part of the package name specific to the library (e.g. `@google-cloud/translate` will be `translate`).
15+
16+
The environment variable for activating logging is `GOOGLE_SDK_NODE_LOGGING`. So you could run your application similarly to this:
17+
18+
```
19+
GOOGLE_SDK_NODE_LOGGING=translate node yourApp.js
20+
```
21+
22+
Or even enable everything, though you might end up with a firehose if you have multiple libraries as dependencies:
23+
24+
```
25+
GOOGLE_SDK_NODE_LOGGING=* node yourApp.js
26+
```
27+
28+
## Logging
29+
Logging functions are created by calling the `log()` function. You pass a system or system:subsystem identifier, and a function is returned. This function may be called directly:
30+
31+
```
32+
const logger = log('test');
33+
logger({other:{metadata: 'foo'}}, 'format string %j', {formatted: 'parameter'});
34+
```
35+
36+
You may also call shorthands that set the `severity` metadata field, and use defaults for the metadata object generally:
37+
38+
```
39+
logger.debug('format string %s', 'string');
40+
logger.info('format string %s', 'string');
41+
logger.warn('format string %s', 'string');
42+
logger.error('format string %s', 'string');
43+
```
44+
45+
Finally, the logger function may be used to create a "sub-log", i.e. adding a sub-system to a system:
46+
47+
```
48+
const sublogger = logger.sublog('specific');
49+
logger.info('big one');
50+
sublogger.info('specific!');
51+
```
52+
53+
This will output two logs, filed under `test` and `test:specific`, respectively.
54+
55+
## Backends
56+
Additionally, there is a concept of a logging backend. You can manually set where you want logs to go, by default, and how you want them processed. The `setBackend()` function lets you set a backend manually. `undefined` (reset to defaults) and `null` (disable logging) are also possible options.
57+
58+
The package provides several built-in options:
59+
60+
* `getNodeBackend()` This is the default that comes with setting the environment variable. It detects the possibility of coloration in the terminal and formats outputs using `util.format()`.
61+
* `getDebugBackend(debugpkg)` This interfaces with the `debug` npm package. You'd essentially do something like `setBackend(getDebugBackend(require('debug')))`.
62+
* `getStructuredBackend(upstream?)`. This converts log output into structured log JSON objects, suitable for feeding into Cloud Logging. An optional `upstream` parameter lets you funnel the output through another backend instead of `console.log`.
63+
64+
## Hooking logs
65+
The log objects you receive from calling `log()` can be hooked as event emitters, like so:
66+
67+
```
68+
loggingFunc.on('log', (fields: LogFields, args: unknown[]) => {
69+
// Process logs as you like.
70+
});
71+
```
72+
73+
This will not prevent normal log output, and system/system:subsystem identifiers will be cached to make sure that all logs of the same name will output to the same event handlers.

logging-utils/package.json

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,9 +28,11 @@
2828
"devDependencies": {
2929
"@types/mocha": "^10.0.10",
3030
"@types/node": "^22.9.1",
31+
"@types/sinon": "^17.0.3",
3132
"c8": "^9.0.0",
3233
"gts": "^5.3.1",
3334
"mocha": "^9.0.0",
35+
"sinon": "^19.0.2",
3436
"typescript": "^5.1.6"
3537
},
3638
"engines": {

logging-utils/src/logging-utils.ts

Lines changed: 28 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -137,11 +137,19 @@ export class AdhocDebugLogger extends EventEmitter {
137137
invoke(fields: LogFields, ...args: unknown[]): void {
138138
// Push out any upstream logger first.
139139
if (this.upstream) {
140-
this.upstream(fields, ...args);
140+
try {
141+
this.upstream(fields, ...args);
142+
} catch (e) {
143+
// Swallow exceptions to avoid interfering with other logging.
144+
}
141145
}
142146

143147
// Emit sink events.
144-
this.emit('log', fields, args);
148+
try {
149+
this.emit('log', fields, args);
150+
} catch (e) {
151+
// Swallow exceptions to avoid interfering with other logging.
152+
}
145153
}
146154

147155
invokeSeverity(severity: LogSeverity, ...args: unknown[]): void {
@@ -415,11 +423,11 @@ class StructuredBackend extends DebugLogBackendBase {
415423

416424
constructor(upstream?: DebugLogBackend) {
417425
super();
418-
this.upstream = (upstream as DebugLogBackendBase) ?? new NodeBackend();
426+
this.upstream = (upstream as DebugLogBackendBase) ?? undefined;
419427
}
420428

421429
makeLogger(namespace: string): AdhocDebugLogCallable {
422-
const debugLogger = this.upstream.makeLogger(namespace);
430+
const debugLogger = this.upstream?.makeLogger(namespace);
423431
return (fields: LogFields, ...args: unknown[]) => {
424432
const severity = fields.severity ?? LogSeverity.INFO;
425433
const json = Object.assign(
@@ -429,14 +437,18 @@ class StructuredBackend extends DebugLogBackendBase {
429437
},
430438
fields
431439
);
432-
const jsonString = JSON.stringify(json);
433440

434-
debugLogger(fields, jsonString);
441+
const jsonString = JSON.stringify(json);
442+
if (debugLogger) {
443+
debugLogger(fields, jsonString);
444+
} else {
445+
console.log('%s', jsonString);
446+
}
435447
};
436448
}
437449

438450
setFilters(): void {
439-
this.upstream.setFilters();
451+
this.upstream?.setFilters();
440452
}
441453
}
442454

@@ -485,7 +497,7 @@ let cachedBackend: DebugLogBackend | null | undefined = undefined;
485497
*
486498
* @param backend Results from one of the get*Backend() functions.
487499
*/
488-
export function setBackend(backend: DebugLogBackend | null) {
500+
export function setBackend(backend: DebugLogBackend | null | undefined) {
489501
cachedBackend = backend;
490502
loggerCache.clear();
491503
}
@@ -504,10 +516,14 @@ export function log(
504516
namespace: string,
505517
parent?: AdhocDebugLogFunction
506518
): AdhocDebugLogFunction {
507-
// If the enable flag isn't set, do nothing.
508-
const enablesFlag = process.env[env.nodeEnables];
509-
if (!enablesFlag) {
510-
return placeholder;
519+
// If the enable environment variable isn't set, do nothing. The user
520+
// can still choose to set a backend of their choice using the manual
521+
// `setBackend()`.
522+
if (!cachedBackend) {
523+
const enablesFlag = process.env[env.nodeEnables];
524+
if (!enablesFlag) {
525+
return placeholder;
526+
}
511527
}
512528

513529
// This might happen mostly if the typings are dropped in a user's code,

logging-utils/test/logging-utils.ts

Lines changed: 45 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@
1414

1515
import {describe, it} from 'mocha';
1616
import * as assert from 'assert';
17+
import * as sinon from 'sinon';
1718

1819
import * as al from '../src/logging-utils';
1920

@@ -46,19 +47,18 @@ describe('adhoc-logging', () => {
4647
describe('Disabled', () => {
4748
const system = 'disabled';
4849

49-
beforeEach(() => {
50-
al.setBackend(sink);
51-
sink.reset();
52-
});
53-
5450
it('obeys a lack of global enable', () => {
51+
al.setBackend(undefined);
5552
delete process.env[al.env.nodeEnables];
5653
const logger = al.log(system);
5754
logger({}, 'foo');
5855
assert.deepStrictEqual(sink.logs, []);
5956
});
6057

6158
it('obeys "all" as an alias for "*"', () => {
59+
al.setBackend(sink);
60+
sink.reset();
61+
6262
process.env[al.env.nodeEnables] = 'all';
6363
const logger = al.log(system);
6464
logger({}, 'foo');
@@ -72,6 +72,30 @@ describe('adhoc-logging', () => {
7272
});
7373
});
7474

75+
describe('Manually enabled', () => {
76+
let logger: al.AdhocDebugLogFunction;
77+
const system = 'basic';
78+
79+
beforeEach(() => {
80+
al.setBackend(sink);
81+
sink.reset();
82+
83+
delete process.env[al.env.nodeEnables];
84+
logger = al.log(system);
85+
});
86+
87+
it('logs in spite of no environment variable', () => {
88+
logger({}, 'test log', 5, {other: 'foo'});
89+
assert.deepStrictEqual(sink.logs, [
90+
{
91+
namespace: system,
92+
fields: {},
93+
args: ['test log', 5, {other: 'foo'}],
94+
},
95+
]);
96+
});
97+
});
98+
7599
describe('Basic enabled', () => {
76100
let logger: al.AdhocDebugLogFunction;
77101
const system = 'basic';
@@ -190,6 +214,22 @@ describe('adhoc-logging', () => {
190214
logger = al.log(system);
191215
});
192216

217+
it('logs to console.log by default', () => {
218+
al.setBackend(al.getStructuredBackend());
219+
logger = al.log(system);
220+
const sandbox = sinon.createSandbox();
221+
let called = false;
222+
sandbox.stub(console, 'log').callsFake((message, ...params) => {
223+
assert.strictEqual(message, '%s');
224+
assert.deepStrictEqual(params, [
225+
'{"severity":"INFO","message":"test info"}',
226+
]);
227+
called = true;
228+
});
229+
logger.info('test info');
230+
assert.strictEqual(called, true);
231+
});
232+
193233
it('logs with severity', () => {
194234
logger.info('test info');
195235
logger.warn('test warn');

0 commit comments

Comments
 (0)