Adds structured logging API. #665

mbleigh · 2020-04-21T23:59:58Z

Node 10 runtime will soon support structured logging by emitting single-line JSON-encoded data to STDOUT / STDERR. This adds a new firebase-functions/logger export that provides structured logging in easy-to-use methods as well as firebase-functions/logger/compat that patches system console methods to output structured logs, solving the "multi-line log" problem for Node 10.

TODO

Write reference docs
Write tests
Get API finalized / approved internally

mbleigh · 2020-04-22T23:25:19Z

@laurenzlong for code review
@egilmorez for reference doc review

laurenzlong · 2020-04-24T18:25:00Z

src/logger.ts

@@ -0,0 +1,135 @@
+// Determine if structured logs are supported (node >= 10). If something goes wrong,
+import { format } from 'util';


I think this import got in the middle of two lines of comments?

Oops, fixed.

laurenzlong · 2020-04-24T18:27:23Z

src/logger.ts

+
+// Map LogSeverity types to their equivalent `console.*` method.
+const CONSOLE_SEVERITY: {
+  [severity: string]: 'debug' | 'info' | 'warn' | 'error';


(I'm not sure if TS would let you do this, but if it does). This would be clearer as:
[severity: LogSeverity]: 'debug' | 'info' | 'warn' | 'error';

TS doesn't let you do this 😢

laurenzlong · 2020-04-24T18:39:30Z

CHANGELOG.md

@@ -0,0 +1,16 @@
+- Adds `functions.logger` SDK to enabled structured logging in the Node.js 10 runtime. Example:


Should add that in Node.js versions < 10, the method still is supported but the data is displayed in a single line.

laurenzlong · 2020-04-24T18:57:14Z

src/logger.ts

+import { format } from 'util';
+
+// safely preserve unpatched console.* methods in case of compat require
+const unpatchedConsole = {


I think this still won't work if somebody did this:

require('firebase-functions/logger/compat'); // Already overwrote console.* methods before requiring "firebase-functions" const functions = require('firebase-functions'); // unpatchedConsole is actually the patched console functions.logger.info('something') // will probably do weird things

I think there's many opportunities for there to be weird bugs and edge cases with 'compat', and I'm not sure it's worth the incremental convenience of providing this functionality.

It does work, because the first thing compat does is require logger which preserves the unpatched console methods. Added a comment to clarify.

This wasn't in my original proposal but Kato asked if it was possible and it turned out to be easier than expected. I do worry about the chance for bugs here but this is just one way to use the SDK and provides a convenience. Anyone who encounters bugs we can just tell to use the other ways of using the SDK.

Ah yes, compat does import logger first, this is really subtle behavior, it's good you added a comment to clarify.

I'm still not a fan of compat and I think it's just making this SDK harder to maintain (it's already way too complicated and has too many subtle behaviors) But if you feel like the risk is worth the user experience benefit, we can keep it in.

spec/logger.spec.ts

laurenzlong · 2020-04-27T21:55:03Z

src/logger.ts

+import { format } from 'util';
+
+// safely preserve unpatched console.* methods in case of compat require
+const unpatchedConsole = {


Ah yes, compat does import logger first, this is really subtle behavior, it's good you added a comment to clarify.

I'm still not a fan of compat and I think it's just making this SDK harder to maintain (it's already way too complicated and has too many subtle behaviors) But if you feel like the risk is worth the user experience benefit, we can keep it in.

laurenzlong · 2020-04-27T21:55:16Z

src/logger.ts

+
+// Map LogSeverity types to their equivalent `console.*` method.
+const CONSOLE_SEVERITY: {
+  [severity: string]: 'debug' | 'info' | 'warn' | 'error';


…mb-logger

egilmorez

Thanks Michael! Some style things for you to look at.

egilmorez · 2020-04-28T21:02:51Z

CHANGELOG.md

@@ -0,0 +1,18 @@
+- Adds `functions.logger` SDK to enabled structured logging in the Node.js 10 runtime. Example:


Typo, should be "to enable"

egilmorez · 2020-04-28T21:03:29Z

CHANGELOG.md

@@ -0,0 +1,18 @@
+- Adds `functions.logger` SDK to enabled structured logging in the Node.js 10 runtime. Example:
+


A nit, but in a text flow we prefer "For example:"

egilmorez · 2020-04-28T21:04:12Z

CHANGELOG.md

@@ -0,0 +1,18 @@
+- Adds `functions.logger` SDK to enabled structured logging in the Node.js 10 runtime. Example:
+
+  ```js


Wow, does this work? In the d.ts files we use ```javascript, but a shorter form would be nice.

egilmorez · 2020-04-28T21:05:49Z

CHANGELOG.md

+  require('firebase-functions/logger/compat');
+  ```
+
+  In older runtimes, the logger will print to console, no structured data is saved.


Suggest "logger prints to the console, and no..."

egilmorez · 2020-04-28T21:08:09Z

src/logger.ts

@@ -0,0 +1,135 @@
+import { format } from 'util';
+
+// safely preserve unpatched console.* methods in case of compat require


Will these be parsed into the reference by our TypeDoc script? If so, suggest "//Safely . . . require." with init cap and period.

egilmorez · 2020-04-28T21:08:50Z

src/logger.ts

+const SUPPORTS_STRUCTURED_LOGS =
+  parseInt(process.versions?.node?.split('.')?.[0] || '8', 10) >= 10;
+
+// Map LogSeverity types to their equivalent `console.*` method.


If this goes to public docs, let's backtick LogSeverity or just say "log severity" in the text flow.

Won't be in public docs.

egilmorez · 2020-04-28T21:09:18Z

src/logger.ts

+};
+
+/**
+ * LogSeverity indicates the detailed severity of the log entry. See [Cloud Logging docs](https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#logseverity) for more.


Suggest backticks for LogSeverity

egilmorez · 2020-04-28T21:10:58Z

src/logger.ts

+};
+
+/**
+ * LogSeverity indicates the detailed severity of the log entry. See [Cloud Logging docs](https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#logseverity) for more.


Suggest the actual doc section title, LogSeverity

egilmorez · 2020-04-28T21:11:41Z

src/logger.ts

+  | 'EMERGENCY';
+
+/**
+ * LogEntry represents a structured Cloud Logging entry. All keys aside from `severity` and `message` are


Suggest backticks for LogEntry

egilmorez · 2020-04-28T21:12:08Z

src/logger.ts

+}
+
+/**
+ * Writes a LogEntry to `stdout`/`stderr` (depending on severity).


Suggest backticks for LogEntry (and every other literal that appears in the HTML output for the reference docs).

rhodgkins · 2020-05-22T08:07:33Z

Any ideas when this is due to be merged/released?

sk- · 2020-05-26T14:17:44Z

@mbleigh Will this PR correctly display the log severity when using firebase-functions/logger/compat? See https://issuetracker.google.com/issues/124403972 for context.

…mb-logger

…to mb-logger

mbleigh · 2020-05-26T18:02:15Z

@sk- yes, although I'm waiting for some corresponding changes to land in the Firebase console before merging and releasing this as we need to adjust for some changes to the way logs are structured in Node 10.

sk- · 2020-06-03T15:42:09Z

@mbleigh I can confirm that the severity is respected, at least on Cloud Logging (I don't see it on Firebase yet).

However there are some issues:

The log entry in Cloud Logging is double quoted.

2) The `message` field does not populate the `textPayload` log field, so one needs to change the queries to use `jsonPayload.message` instead. Is there any way to keep using `textPayload` for the queries? As it is now, using the compat module would be a breaking change, as it would break any metrics one may have.

mbleigh · 2020-06-03T16:00:48Z

Hmm...interesting. Will try to dig into this a bit more before release. The way this works is using the container logs contract from Cloud Run (newer Cloud Functions runtimes are built on the same infra).

It seems like it should be populating textPayload so long as there is no structured data attached to the log.

sk- · 2020-06-03T17:11:27Z

@mbleigh You are right, if there is no structured data (meaning no extra fields other than message and severity) the logs do populate textPayload and are displayed without the double quotes.

By reading the logs contract docs, it only says about the message field that it is used as the display text, but mentions nothing of the special case when only these two fields are populated.

It'd be great if textPayload was always populated, and no double quotes were added to the displayed message.

mbleigh · 2020-06-03T17:52:21Z

Let's continue this conversation on #697 since this PR is closed and merged.

Adds structured logger API.

a6f77a0

googlebot added cla: yes labels Apr 22, 2020

mbleigh added 3 commits April 22, 2020 14:00

Adds tests.

3c614e1

Restore stdout/stderr in test method.

2735dfc

JSDoc

a0be017

mbleigh requested a review from laurenzlong April 22, 2020 21:27

mbleigh marked this pull request as ready for review April 22, 2020 21:27

if/else structure

b837799

mbleigh assigned laurenzlong Apr 22, 2020

mbleigh requested a review from egilmorez April 22, 2020 23:25

mbleigh assigned egilmorez Apr 22, 2020

Adds changelog

484a4af

laurenzlong suggested changes Apr 24, 2020

View reviewed changes

Address review feedback.

9228bb4

mbleigh requested a review from laurenzlong April 24, 2020 20:53

Merge branch 'master' into mb-logger

b728e01

laurenzlong approved these changes Apr 27, 2020

View reviewed changes

Merge branch 'master' of github.com:firebase/firebase-functions into …

1b9356f

…mb-logger

egilmorez reviewed Apr 28, 2020

View reviewed changes

mbleigh added 2 commits April 28, 2020 14:36

Docs fixes.

58ab50f

Merge branch 'master' into mb-logger

1ae83f9

mbleigh added 2 commits May 26, 2020 09:35

Merge branch 'master' of github.com:firebase/firebase-functions into …

f1acceb

…mb-logger

Merge branch 'mb-logger' of github.com:firebase/firebase-functions in…

a8001d1

…to mb-logger

Merge branch 'master' into mb-logger

f95aa28

mbleigh merged commit bb92d38 into master Jun 2, 2020

mbleigh deleted the mb-logger branch June 2, 2020 16:31

mbleigh mentioned this pull request Jun 3, 2020

Investigate textPayload population and double-quoting in logger #697

Closed

mbleigh mentioned this pull request Jun 4, 2020

Console.log calls result in multiple log entries where a single entry is expected #612

Closed

rhodgkins mentioned this pull request Jun 8, 2020

Add execution_id to the labels of a manual stackdriver log entry #560

Closed

		@@ -0,0 +1,135 @@
		// Determine if structured logs are supported (node >= 10). If something goes wrong,
		import { format } from 'util';

		@@ -0,0 +1,16 @@
		- Adds `functions.logger` SDK to enabled structured logging in the Node.js 10 runtime. Example:

		@@ -0,0 +1,18 @@
		- Adds `functions.logger` SDK to enabled structured logging in the Node.js 10 runtime. Example:

		@@ -0,0 +1,18 @@
		- Adds `functions.logger` SDK to enabled structured logging in the Node.js 10 runtime. Example:

		```js

		@@ -0,0 +1,135 @@
		import { format } from 'util';

		// safely preserve unpatched console.* methods in case of compat require

Adds structured logging API. #665

Adds structured logging API. #665

Uh oh!

Conversation

mbleigh commented Apr 21, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

TODO

Uh oh!

mbleigh commented Apr 22, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

laurenzlong Apr 27, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

laurenzlong Apr 27, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

egilmorez left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mbleigh commented Apr 21, 2020 •

edited

Loading

laurenzlong Apr 27, 2020 •

edited

Loading

laurenzlong Apr 27, 2020 •

edited

Loading