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

[kitfit-dave]

Console.log calls that end up with newlines in them cause multiple log entries rather than single (collapsed) log entries. Logging a string with newlines causes this, as does logging a "large enough" object (which seems to get stringified differently to a "small enough" object to get newlines in its output).

I also note that the log type field is ? rather than I as is was under node 8.

The log outputs below were produced by just changing between "engines": { "node": "8" } and "engines": { "node": "10" }, and deploying, with no other changes.

Related issues

none

Version info

node:

v10.15.3

firebase-functions:

3.3.0

firebase-tools:

7.12.1

firebase-admin:

8.9.0

Test case

exports.test = functions.https.onRequest((req, res) => {
	console.log('multiple lines', 'line one\nline two\nline three')
	console.log('small object', { one: 'one', two: 'two', three: 'three' })
	console.log('object', { one: 'one', two: 'two', three: 'three', four: 'four', five: 'five', six: 'six' })
	res.send({})
})

Steps to reproduce

deploy test function
call test function
view log

Expected behaviour

single log entries (as per node8 version)

2020-01-20T00:31:29.897645002Z D test: Function execution started
2020-01-20T00:31:29.907Z I test: multiple lines line one
line two
line three
2020-01-20T00:31:30.004Z I test: small object { one: 'one', two: 'two', three: 'three' }
2020-01-20T00:31:30.005Z I test: object { one: 'one',
  two: 'two',
  three: 'three',
  four: 'four',
  five: 'five',
  six: 'six' }
2020-01-20T00:31:30.006307295Z D test: Function execution took 109 ms, finished with status code: 200

Actual behavior

multiple log entries for "large enough" objects, or any string with newlines

2020-01-20T00:29:01.446537764Z D test: Function execution started
2020-01-20T00:29:01.791Z ? test: multiple lines line one
2020-01-20T00:29:01.792Z ? test: line two
2020-01-20T00:29:01.792Z ? test: line three
2020-01-20T00:29:01.795Z ? test: small object { one: 'one', two: 'two', three: 'three' }
2020-01-20T00:29:01.795Z ? test: object { one: 'one',
2020-01-20T00:29:01.795Z ? test:   two: 'two',
2020-01-20T00:29:01.795Z ? test:   three: 'three',
2020-01-20T00:29:01.795Z ? test:   four: 'four',
2020-01-20T00:29:01.795Z ? test:   five: 'five',
2020-01-20T00:29:01.795Z ? test:   six: 'six' }
2020-01-20T00:29:01.802375869Z D test: Function execution took 356 ms, finished with status code: 200

Were you able to successfully deploy your functions?

yes, no errors

[lirantal]

The same thing reproduces for me too unfortunately.

[kitfit-dave]

Thanks.

Yeah, this is stopping me from switching over to node 10. I wonder if there is anyone we can mention, or somewhere else to post that might get some attention.

[0x6368656174]

We have some issue too. It is really not comfortable read such logs.

[mbleigh]

We are tracking this issue internally. Since it's a backend issue (we can't fix it through code changes in the SDK) I'm going to close this issue, but will try to circle back around and ping this thread when there's news. Thanks all!

Internal bug ID: 153748705

[lirantal]

Thanks Michael 🙏

[kitfit-dave]

Thanks @mbleigh - really wanting to upgrade our functions to node 10. Good to know it is a known issue.

[kitfit-dave]

Hello, apologies for commenting on a closed issue, but with the email today stating "Developers will no longer be able to create new functions or update existing functions that use Node.js 8." from February 15, 2021 - I thought I would check back and see what had happened.

@mbleigh Do you have any update for us? Is there anywhere else I can go to track this issue and get info on what is being done? We REALLY want to go to node 10 but all of our logging has newlines in it (an object through console.log (i.e. via utils.inspect) can cause that for example). Indeed, we are already running into issues where libs that we are using have (quite rightly) removed support for node 8.

[mbleigh]

We are working on a new logging SDK for Cloud Functions for Firebase that will support richer logging and proper multiline logs. Stay tuned!

…

On Thu, May 21, 2020, 5:47 PM David Clark ***@***.***> wrote: Hello, apologies for commenting on a closed issue, but with the email today stating "Developers will no longer be able to create new functions or update existing functions that use Node.js 8." from February 15, 2021 - I thought I would check back and see what had happened. @mbleigh <https://github.com/mbleigh> Do you have any update for us? Is there anywhere else I can go to track this issue and get info on what is being done? We REALLY want to go to node 10 but all of our logging has newlines in it (an object through JSON.stringify can cause that for example). Indeed, we are already running into issues where libs that we are using have (quite rightly) removed support for node 8. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#612 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAAH7RWFSDTOI3R5UVEFPLRSXDRBANCNFSM4KI4WPVQ> .

[kitfit-dave]

just by the way, thinking about this today again has made me realise a workaround:

multiline console.log message do not work (poroduce multiple messages)
if you can avoid them by never having literal newlines in your strings, the only thing I was finding was passing objects to console.log was adding newlienes (util.inspect gets called by console.log to output objects)
we can call util.inspect ourselves on any object parameters, with an option that makes it not insert newlines, before calling console.log OR (better) we can monkey patch console.log to do that for us (this way you won't have to change any other existing code, see proviso below)

the proviso is that (at least in this implementation) console.log will probably not be able to accept format parameters in the first arg (%d etc), but as long as you are not using those (we never do), then this seems to work.

Here, FWIW, is my implementation of that:

const util = require('util')

// prevent console log creating multiline messages (via util.inspect) by calling inspect for it with no line length
const inspect = args => args.map(arg => (typeof arg === 'string' ? arg : util.inspect(arg, { breakLength: Infinity })))

// patch console functions to avoid outputting newlines
// Note: format arguments will not work with console.* functions now
const consoleLog = console.log
const consoleWarn = console.warn
const consoleError = console.error

console.log = (...args) => consoleLog(...inspect(args))
console.warn = (...args) => consoleWarn(...inspect(args))
console.error = (...args) => consoleError(...inspect(args))

So:
patch console.log
do not call console.log with format parameters
avoid passing strings with newlines in them to console.log
upgrade to node 10!

[nicoqh]

It also seems impossible to log errors with the Node 10 runtime. Every entry gets the same unknown log level, and nothing is reported to Stackdriver. Definitely can't use Node 10 yet.

[mbleigh]

@nicoqh we are adding a new logging API (see #665) to the Cloud Functions SDK very soon that will address this. There are some last minute questions to answer before we push it out the door, but it will allow you to have multi-line logs as well as appropriate severity levels. Stay tuned!

[kitfit-dave]

Hi @mbleigh - good the hear that we are nearly there with the logging sdk. It's a bit of a shame the node 10 stuff could not have been implemented without breaking existing logging functionality (multiline logs and severity levels used to just work - indeed the "error" severity still works for the internal console.error call when say a quota fails, it's just the function itself calling console.error that does not work - i assume that that is a console.* func which has already been patched somewhere by that point), but I do understand that it gets complicated when we start to monkey patch console.* etc, and if we get a nice structured logging solution out of it then all the better. Looks like it's close by the look of those PRs.

Thanks!

[lirantal]

The thing with the SDK is that maybe I want to use a logging utility and that behind the scenes probably uses things like process.write() or console.log() and not the SDK itself, right? so the SDK doesn't help me if I want to use something like https://www.npmjs.com/package/pino, does it?

[mbleigh]

That's correct, if you're using a separate logging utility it won't structure the output properly. However, if your logger has customizable output serialization you can likely tweak it to work by making it emit a single-line JSON string.

You can read these docs to understand the format that's expected by Cloud Functions logging.

[ashemah]

So we now need to spend additional time and money upgrading all of our apps just so logging is back to where it was before? What kind of weird logic is this?

[mbleigh]

If you put require('firebase-functions/lib/logger/compat'); at the top of your functions code with the latest version of the sdk logging should work as it did before in node 10. You can also use the new logging SDK to take advantage of structured logging support

…

On Fri, Jun 19, 2020, 6:53 AM Ashemah Harrison ***@***.***> wrote: So we now need to spend additional time and money upgrading all of our apps just so logging is back to where it was before? What kind of weird logic is this? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#612 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAAH7TGWZITNAH4KWUB5FDRXNUXBANCNFSM4KI4WPVQ> .

[p-young]

Will this be added to the documentation somewhere? (Only place I can find is the release notes
right now)

Also, without requiring compat, will console.log() be broken?

Thanks!

[mbleigh]

Yes, we will add to the docs (but wanted to get the release out ASAP to help folks). If you don't require the compat library, in Node 10 multi-line console.log() statements will each be broken into individual log entries and log severity won't necessarily be correctly reflected. You should still see all of the logs, though.

[skalashnyk]

@mbleigh, and what about Google cloud function deployment without using firebase-functions wrapper & deployment tools (firebase-tools)?..
As we don't have firebase-functions dependency

[mbleigh]

For that you'll need to either manually follow the structured logging guidance (tl;dr emit JSON objects for logs) or you can add firebase-functions as a dependency and require the logger directly:

// import the new logger
import { debug, info, error, warn } from "firebase-functions/lib/logger";
// alternatively, compat mode
import "firebase-functions/lib/logger/compat";

[kylecordes]

This issue is really vexing, would really appreciate an official update on the plan.

In the current state, adding the compatibility layer fixes some console log output, but other output (from libraries, where I have no desire to go edit their source code) still gets chopped up into many separate log messages.

There are indications that the new logging API will get better and better - great, for my code, will use.

But we can’t expect to eliminate all console.log and console.error from the Node ecosystem, nor persuade every library author to stop emitting strings and always emit JSON the matches Firebase needs.

Will this be fixed?

[mbleigh]

The new logging API is the canonical solution to this problem. If you rely on libraries that do their own console.* calls, the compatibility layer will transform those calls into the appropriate shape:

require("firebase-functions/lib/logger/compat");

If libraries write directly to STDOUT or STDERR, there is no way for us to make them match the old behavior and additional solutions are not coming.

Note that you can use the logger API and the compatibility layer together.

[fastfedora]

Curious why the compatibility layer wasn't enabled by default with the new logger API being opt-in? That would have made the upgrade path much easier.

It would also have been useful to include this information in the email asking developers to upgrade to Node 10. Breaking changes like these should be included in those emails. I read through that email completely before upgrading and the only reason I found out why the logs were all messed up was the Firebase News newsletter on Substack.

Please add this information to the Firebase FAQ and the specific instructions for upgrading from Node 8 to Node 10 described, both of which were linked to from the email about the upgrade.

[mbleigh]

Thanks for the feedback. Because the compat layer monkeypatches console.*, we didn't think it was appropriate to "turn on by default." I definitely think we should be clear in our documentation about the need when upgrading, I'll file an issue internally to take a look at that.

[ftzi]

For that you'll need to either manually follow the structured logging guidance (tl;dr emit JSON objects for logs) or you can add firebase-functions as a dependency and require the logger directly:

// import the new logger
import { debug, info, error, warn } from "firebase-functions/lib/logger";
// alternatively, compat mode
import "firebase-functions/lib/logger/compat";

Can someone tests if it also throws an error for you if using it on the firebase emulator? ("Unhandled error TypeError: Cannot read property 'error' of undefined", while using import Logger from 'firebase-functions/lib/logger' and then Logger.error(...))

Edit: Fixed it by importing with import * as Logger from 'firebase-functions/lib/logger'

[FiringBlanks]

I tried adding require("firebase-functions/lib/logger/compat"); but I keep getting the following error:

Error: Error parsing triggers: Cannot find module 'firebase-functions/lib/logger/compat'
Require stack:
- C:\Program Files\Git\projects\quizmenot\functions\index.js
- C:\Users\FiringBlanks\AppData\Roaming\npm\node_modules\firebase-tools\

Try running "npm install" in your functions directory before deploying.

So I went into the functions folder and tried npm install but no luck.

[mbleigh]

Check that you are on the most recent version of the SDK

…

On Sun, Oct 25, 2020, 2:21 AM Fahad Shah ***@***.***> wrote: I tried adding require("firebase-functions/lib/logger/compat"); but I keep getting the following error: Error: Error parsing triggers: Cannot find module 'firebase-functions/lib/logger/compat' Require stack: - C:\Program Files\Git\projects\quizmenot\functions\index.js - C:\Users\FiringBlanks\AppData\Roaming\npm\node_modules\firebase-tools\ Try running "npm install" in your functions directory before deploying. So I went into the functions folder and tried npm install but no luck. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#612 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAAH7U7GLBC2FZJXKYTW2LSMPUYXANCNFSM4KI4WPVQ> .

[michaelalhilly]

@mbleigh I've tried a few different approaches to this including:

Writing Structured Logs:
https://cloud.google.com/run/docs/logging#writing_structured_logs

functions.logger.log
https://medium.com/firebase-developers/migrate-your-firebase-cloud-functions-to-node-js-10-d9c677933ee

Adding: require("firebase-functions/lib/logger/compat")

Still nothing outputs except the logs that are autogenerated and showing the function finished with status ok.

Can you please provide a short and full working example?

The docs on this are still incorrect.

[vdias38]

Hi @michaelalhilly,

It works if you access logs from Logging > Logs Explorer (Take car to switch from Legacy Logs Viewer to Logs Explorer)
I've tested on Node.js v10 with [email protected], using functions.logger.log()

export const helloWorld = functions.https.onRequest((request, response) => {
  functions.logger.debug('Provider data: ', {a: 'foo', b: 'tt'});
  functions.logger.error('Log error', {a: 'foo', b: 'tt'});
  functions.logger.info('Log info', {a: 'foo', b: 'tt'});
  functions.logger.log('Log log', {a: 'foo', b: 'tt'});
  functions.logger.warn('Log warn', {a: 'foo', b: 'tt'});
  const entry = Object.assign(
    {
      severity: 'ALERT',
      message: 'This is the default display field.',
      // Log viewer accesses 'component' as 'jsonPayload.component'.
      component: 'arbitrary-property',
    },
  );

  functions.logger.write(entry);

  response.send("Hello from Firebase!");
});

On logs tab of cloud function page, payload is not displayed

[michaelalhilly]

@vdias38 Thanks for responding. I'll give it a try.

[sogern]

@vdias38 It works beautifully! 🎉 Just tried it with Node v12.

[ajgomezrivera]

What worked for me is using console.log(JSON.stringify(object))

[ftzi]

Is it fixed, without using @vdias38 solution?

[ingen0s]

Using import 'firebase-functions/lib/logger/compat' at the top of the each function file with an update to firebase-functions in package does the trick. Also, recommend using https://cloud.google.com/logging/docs/view/logs-viewer-interface as mentioned above for a better dev experience.

Will be moving over to the new Logger soon enough, loving the interface.

[ftzi]

Sorry for commenting again after those months, but is this already fixed without workaround / importing the compat?

I want to know if I can remove the workaround I still have in the code I did back then.

[yairopro]

Hi everyone

logger/compat is very useful but still, logs are not regrouped by request call like it is with app-engine logs:

logs.mp4

Is there a way to regroup logs by firebase-function call ? A library maybe ?
Or do I need to setup the whole thing using @google-cloud/logging ?

[taeold]

@yairopro I'm not very familiar with who App Engine log grouping works. Do you mind sharing a little more detail? Does App Engine automatically group request log and application log in a single line or do you mean that there is a property like request_id that you want to filter logs for a single request?

[yairopro]

Hi @taeold

It seems that App engine automatically collects all Logger calls across the codebase (the corresponding JS' console.log for Java) into 1 single log entry which has the following format below (I downloaded one sample from the cloud console).

The magic field that makes it openable on the console is the protoPayload.line: LogEntry[] field.
I tried to reproduce this kind of log using @google-cloud/logging SDK, I didn't manage to do so. It always end-up producing a log entry with jsonPayload.

{
    "protoPayload": {
      "@type": "type.googleapis.com/google.appengine.logging.v1.RequestLog",
      "appId": "...",
      "versionId": "v8",
      "requestId": "62458c6900ff0adb39710c02950001657e72636d35352d62616773686f70000173686f702d74656d706c6174653a7638000100",
      "ip": "2a01:e0a:4ec:3ae0:a414:3130:69aa:dc21",
      "startTime": "2022-03-31T11:11:37.715272Z",
      "endTime": "2022-03-31T11:11:38.052255Z",
      "latency": "0.336983s",
      "megaCycles": "166",
      "method": "GET",
      "resource": "/?_keywords=boucherie-marseille-13008",
      "httpVersion": "HTTP/1.1",
      "status": 200,
      "responseSize": "2456",
      "userAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.74 Safari/537.36 Edg/99.0.1150.55",
      "urlMapEntry": "unused",
      "host": "example.com",
      "cost": 2.74479e-7,
      "instanceIndex": -1,
      "finished": true,
      "instanceId": "00c61b117cd9ac4b232a78b9a4c9dbd1b78445ba2aa6e9971405de90f4ee17aff43a83f71849bdcabe3919b1b8efc258b7d3b096ca1fc432824b94c85051eef0c5e836906a3670",
      "line": [ // <-
        {
          "time": "2022-03-31T11:11:37.751Z",
          "severity": "INFO",
          "logMessage": "[e~appId/shop-template:v8.440096094102736335].<stdout>: User Agent : Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.74 Safari/537.36 Edg/99.0.1150.55\n\n"
        },
        {
          "time": "2022-03-31T11:11:37.751Z",
          "severity": "INFO",
          "logMessage": "com.example.controler.PolymerServlet doGet: Shop prefix URL: example.com\n",
          "sourceLocation": {
            "file": "PolymerServlet.java",
            "line": "114",
            "functionName": "com.example.controler.PolymerServlet.doGet"
          }
        },
        {
          "time": "2022-03-31T11:11:37.751Z",
          "severity": "INFO",
          "logMessage": "com.examplelib.model.dao.generic.DBStatementSender firstPostgreSQL: SELECT  *  FROM \"sites\"  WHERE  \"domain\" = 'baba.com'  LIMIT 1 \n",
          "sourceLocation": {
            "file": "DBStatementSender.java",
            "line": "116",
            "functionName": "com.examplelib.model.dao.generic.DBStatementSender.firstPostgreSQL"
          }
        }
      ],
      "moduleId": "shop-template",
      "appEngineRelease": "1.9.71",
      "traceId": "74b003ed618202ad1be972ad9c5d476a",
      "first": true,
      "traceSampled": true
    },
    "insertId": "62458c6a0000cf9970d1b781",
    "httpRequest": {
      "status": 200
    },
    "resource": {
      "type": "gae_app",
      "labels": {
        "version_id": "v8",
        "module_id": "shop-template",
        "zone": "eu6",
        "project_id": "appId"
      }
    },
    "timestamp": "2022-03-31T11:11:37.715272Z",
    "severity": "INFO",
    "labels": {
      "clone_id": "00c61b117cd9ac4b224a78b9a4c9dbd1b78445ba2aa6e9971405de90f4ee17aff43a83f71849bdcabe3919b1b8efc258b7d3b096ca1fc432824b94c85051eef0c5e836906a3670"
    },
    "logName": "projects/appId/logs/appengine.googleapis.com%2Frequest_log",
    "operation": {
      "id": "62458c6900ff0adb39710c02950001657e72636d35352d62616773686f70000173686f702d74656d706c6174653a7638000100",
      "producer": "appengine.googleapis.com/request_id",
      "first": true,
      "last": true
    },
    "trace": "projects/appId/traces/74b003ed618202ad1be972ad9c5d476a",
    "receiveTimestamp": "2022-03-31T11:11:38.056860325Z",
    "traceSampled": true
  },

[taeold]

@yairopro Thanks for sharing the info - I wasn't familiar with App Engine logs and can see how that would be useful! I think this can become a feature request, though I'm not 100% clear on whether we can do this without Google Cloud Function's platform support 🤔

[yairopro]

@taeold I understand. Thank for the consideration of the demand.
Should I post it somewhere else as feature request? A new issue?