Node 10: log entries appear as string in textPayload, not structured in jsonPayload

[mickdekkers]

Environment details

• OS: N/A
• Node.js version: 10 (beta)
• npm version: N/A
• @google-cloud/logging-bunyan version: 0.10.1
• bunyan version: 1.8.12

Steps to reproduce

1. Create a new Google Cloud Function and select the Node.js 10 runtime
2. Copy the code from the example in the README into the HTTP sample code:

const bunyan = require('bunyan');

// Imports the Google Cloud client library for Bunyan (Node 6+)
const {LoggingBunyan} = require('@google-cloud/logging-bunyan');

// Creates a Bunyan Stackdriver Logging client
const loggingBunyan = new LoggingBunyan();

// Create a Bunyan logger that streams to Stackdriver Logging
// Logs will be written to: "projects/YOUR_PROJECT_ID/logs/bunyan_log"
const logger = bunyan.createLogger({
  // The JSON payload of the log as it appears in Stackdriver Logging
  // will contain "name": "my-service"
  name: 'my-service',
  // log at 'info' and above
  level: 'info',
  streams: [
    // Log to the console
    {stream: process.stdout},
    // And log to Stackdriver Logging
    loggingBunyan.stream('info'),
  ],
});

/**
 * Responds to any HTTP request.
 *
 * @param {!express:Request} req HTTP request context.
 * @param {!express:Response} res HTTP response context.
 */
exports.helloWorld = (req, res) => {
  let message = req.query.message || req.body.message || 'Hello World!';
  res.status(200).send(message);

  // Writes some log entries
  logger.error('warp nacelles offline');
  logger.info('shields at 99%');
};

3. Add dependencies to package.json:

{
  "name": "sample-http",
  "version": "0.0.1",
  "dependencies": {
    "@google-cloud/logging-bunyan": "0.10.1",
    "bunyan": "1.8.12"
  }
}

4. Trigger the cloud function through an HTTP GET request
5. View the logs

Expected result

Actual result

Additional information

The issue does not appear when I set the runtime to Node 6, nor when I set the runtime to Node 8. The expected result screenshot is the output of Node 6.

[ofrobots]

Hi @mickdekkers. Looking at the screenshot, the 'actual' screenshot seems to showing the console log stream rather the bunyan log stream. Observe the logName property. It would be bunyan_log in the case of the bunyan log stream (as you've configured in your app). The console stream is expected to be unstructured text.

Can you recheck the Cloud Logging UI again to make sure you're looking at the bunyan_log log stream?

[mickdekkers]

Hi @ofrobots, thanks for your reply. It looks like you're right: I wasn't looking at the bunyan_log log stream. I checked and the log entries do show up there for Node 10.

I looked into this some more and found something interesting: the bunyan_log log stream seems to appear in different places in the log viewer depending on whether the function is deployed with a Node 8 or Node 10 runtime.

For Node 8, the bunyan_log log stream can be found on the cloud function resource (the one you're directed to when you click View Logs on a cloud function). It does not appear on the Global resource in the log viewer.

For Node 10, the bunyan_log log stream can only be found on the Global resource in the log viewer, but not the cloud function resource. This means that clicking on the View Logs button is not enough to take you there, unlike for Node 8.

To illustrate this, I took a screenshot of the cloud function resource in the log viewer after:

• deploying the function with a Node 10 runtime
• triggering the function through an HTTP request
• deploying the function with a Node 8 runtime
• triggering the function through an HTTP request

As you can see, the Node 10 logs appear as unstructured text in this view, while the Node 8 logs appear structured. The Node 10 structured logs are available under the Global resource, but it seems strange that they would not appear in this view.

I'm not sure if this is an issue with the bunyan integration or the Stackdriver log viewer UI itself, but I thought I'd report it either way.

[DominicKramer]

It looks like the next steps that we need to investigate is whether or not the global resources is being used only in Node 10 for logs.

[ofrobots]

@mickdekkers I can reproduce the behavior you describe. I'm investigating.

[ofrobots]

The root cause is that nodejs10 runtime no longer exposes the FUNCTION_NAME environment variable. This breaks the environment-detection code we use (from google-auth-library).

[ofrobots]

Just an update - we are continuing to look into this and trying to figure out the best way to resolve the issue. The nodejs10 runtime on GCF now follows the container runtime contract. We need to update code in google-auth-library and @google-cloud/logging to properly deal with this change. The complicating factor is that functions running on Google Cloud Run also follow the container runtime contract, and a proper solution here needs to properly distinguish that.

[ChemaMX]

Any updates on this?. It is really annoying trying to read the logs from the log console looking like this.

[soldair]

reproed. still broken with the latest version

so. this example contains both a stdout stream and a logging stream.
the one you see in the default function log is the version that was output to stdout as a string.

if you search for the log by the logs "name" you get the correct result.

this seems unexpected where we thought the structured log output should go to the same log in the google cloud dashboard as the stdout stream. (projects/ryan-gcr-test/logs/cloudfunctions.googleapis.com%2Fcloud-function)

the log name we passed into the bunyan constructor also looks nothing like the logName it ended up with in the logging ui.

[soldair]

looks like we can configure this.
https://github.com/googleapis/nodejs-logging-bunyan/blob/master/src/index.ts#L146

so if we pass the logName set to where you expected to see the logs
"cloudfunctions.googleapis.com%2Fcloud-function"

and remove the stdout log to prevent duplicates things should be back to NEARLY making the result you expect.

there is still a problem where GOOGLE_CLOUD_REGION and FUNCTION_REGION aren't defined in node 10 cloud functions. this results in a resource with an undefined region.

https://github.com/googleapis/nodejs-logging/blob/master/src/metadata.ts#L41

this means that from the function dashboard if you click view logs you'll be taken to a filter that excludes the logs from logging bunyan.

default filter:

resource=cloud_function%2Ffunction_name%2Frepro_LoggingBunyan_291%2Fregion%2Fus-central1

There doesnt seem to be a way to query the region from the metadata service in the node 10 and cloud run environment. the mtadata service does respond to "zone" with something like
"projects/537335811501/zones/us6" but that doesn't help you click from the function tab to the logs you want to see.

the only work around i can think of at the moment is to specify the GOOGLE_CLOUD_REGION env var in your function deployment so the resource is constructed correctly.

the work to fix this is out of scope for this repo and could be managed at quite a few levels.

1. making the default filter for your cloud function logs not include region
2. adding region to cloud function deployment infrastructure for node >10 (unlikely)
3. finding the region another way i haven't thought of.
4. changing how well formed objects written to stdout of a function are interpreted.

4 is probably the best because sending logs in cloud function was always a bit of a race condition so a blocking write to a collector is needed to ensure logs aren't lost when functions are shutdown.

companion issue on logging-winston googleapis/nodejs-logging-winston#333

[ErikSquiresOX]

Hello,

Just FYI, I am having the same issue using Go in a cloud function.

[soldair]

If you need consistent log names and attributes across runtimes you'll need to manually provide the resource metadata rather than depending on the environment of the runtime to auto populate the attributes you need.

see this comment above for details.
#291 (comment)

this is not the most satisfactory resolution but there are too many run times and your log data is much more valuable when collated along consistent attributes.

[techieshark]

changing how well formed objects written to stdout of a function are interpreted.

4 is probably the best because sending logs in cloud function was always a bit of a race condition so a blocking write to a collector is needed to ensure logs aren't lost when functions are shutdown.

Was #4 actually completed? I'm wondering if there's a way to simply write to stdout (or use console.log/info/warn) and still see structured output (so we don't need to wait for network traffic to Stackdriver to complete before exiting a cloud function).

[clementohNZ]

This is what worked for me to make sure logs show up in their desired location and not just the global view:

const serviceName = `service-authentication`
const loggingBunyan = new LoggingBunyan({
    resource: {
        type: `cloud_run_revision`,
        labels: {
            service_name: serviceName,
            location: `australia-southeast1`,
        },
    },
})

const bunyanLogger = createLogger({
    name: `authentication-service`,
    streams: [
        // Log to the console at 'info' and above
        { stream: process.stdout, level: `debug` },
        // And log to Cloud Logging, logging at 'info' and above
        loggingBunyan.stream(`debug`),
    ],
})

The key part here is adding the custom resource labels so it shows up in your desired logging location. For me I was running my application using cloud run and I found out by clicking the "open in stackdriver/log viewer" button that the query it was making was:

resource.type = "cloud_run_revision"
resource.labels.service_name = "service-authentication"
resource.labels.location = "australia-southeast1"
 severity>=DEFAULT

So after adding these resource properties to my bunyan configuration, they appeared in the cloud run logging view when previously they only appeared in the global view.