Diffrences in log entry structure with different modes of redirectToStdout (missing resource.labels.function_name when redirectToStdout:true)

[evil-shrike]

I have a lib, that uses winston for logging, which I want to use inside my cloud function and integrate its logging with Cloud Logging. So inside the lib I check whether it's running in Cloud and if so I create a winston logger with LoggingWinston transport:

export function createLogger() {
  if (process.env.K_SERVICE) {
    // we're in Google Cloud (Run/Functions)
    return createCloudLogger();
  } else {
    return createConsoleLogger();
  }
}

where createCloudLogger is:

export function createCloudLogger() {
  const cloudLogger = winston.createLogger({
    level: LOG_LEVEL,
    format: format.combine(
      format((info) => {
        info.trace = process.env.TRACE_ID;
        info[LOGGING_TRACE_KEY] = process.env.TRACE_ID;
        return info;
      })(),
    ),
    defaultMeta: getDefaultMetadataForTracing(),
    transports: [
      new LoggingWinston({
        projectId: process.env.GCP_PROJECT,
        labels: {
          component: <string>process.env.LOG_COMPONENT,
        },
        logName: "mylog",
        resource: {
          labels: {
            function_name: <string>process.env.K_SERVICE,
          },
          type: "cloud_function",
        },
        useMessageField: false,
        redirectToStdout: false,
      }),
    ],
  });
  return cloudLogger;
}

Please note I specify redirectToStdout: false.
It worked fine in general but recently I've noticed that in logs there're a lot of entries like this:
DEFAULT 2023-04-17T11:03:56.398817Z Exception from a finished function: Error: Total timeout of API google.logging.v2.LoggingServiceV2 exceeded 60000 milliseconds before any response was received.

and sometime they are even turned into error:

Error: Total timeout of API google.logging.v2.LoggingServiceV2 exceeded 60000 milliseconds before any response was received.
    at repeat (/workspace/node_modules/google-gax/build/src/normalCalls/retries.js:66:31)
    at Timeout._onTimeout (/workspace/node_modules/google-gax/build/src/normalCalls/retries.js:101:25)
    at listOnTimeout (node:internal/timers:559:17)
    at processTimers (node:internal/timers:502:7)

in the related bug googleapis/nodejs-logging#1185 it's suggested to turn on stdout writing.
So I changed redirectToStdout to true.
Unfortunately the result isn't the same.

Here's a log entry with redirectToStdout: false:

Here's a log entry with redirectToStdout: true:

there are very similar but redirectToStdout: true resource.labels.function_name goes to jsonPayload instead of to the root object as with redirectToStdout: false. Which results in missing label (chip) with function name on the log entry.

[cindy-peng]

Hi @evil-shrike， I am wondering are you still running into this issue? If so, do you mind providing a latest repro?

[evil-shrike]

Hi @cindy-peng . Yes, the issue is still actual.
But actually I'm not sure it's a LoggingWinston's issue. With redirectToStdout:true we can see all output in terminal when running locally and they are correct. The problem is that a handler in Cloud Run environment captures that output and puts it inside jsonPayload field in a log entry. So we get the result I provided in the first comment, i.e. resource.labels.function_name is put into jsonPayload (instead of putting at the root level).
Basically with redirectToStdout: true all meta attributes for Cloud Logging that we inserted in a entry are placed wrongly in inside jsonPayload field which makes them useless (no chips, no filtering, etc).

import winston from "winston";
import {
  LoggingWinston,
  getDefaultMetadataForTracing,
} from "@google-cloud/logging-winston";

function createCloudLogger() {
  const cloudLogger = winston.createLogger({
    level: "debug",
    defaultMeta: getDefaultMetadataForTracing(),
    transports: [
      new LoggingWinston({
        labels: {
          component: process.env.LOG_COMPONENT || "mycomponent",
        },
        logName: "mylog",
        resource: {
          labels: {
            function_name: process.env.K_SERVICE || "myfunction",
          },
          type: "cloud_function",
        },
        useMessageField: false,
        redirectToStdout: true,
      }),
    ],
  });
  return cloudLogger;
}

function main() {
  const logger = createCloudLogger();
  logger.info("log message", {meta: "value1"});
}
main()

it's the output:

/Users/segy/work/samples/google-cloud/logging$ node ./index.mjs                                                                    ↑
{"timestamp":{"seconds":1723672001,"nanos":809000015},"resource":{"labels":{"function_name":"gaarf"},"type":"cloud_function"},"sever
ity":"INFO","logging.googleapis.com/labels":{"component":"gaarf"},"logging.googleapis.com/insertId":"..........8dMnfugFC1b9G9ejVarRn
b","message":{"message":"log message","metadata":{"meta":"value1"}},"logName":"projects/{{projectId}}/logs/mylog"}
{"timestamp":{"seconds":1723672001,"nanos":809000015},"resource":{"labels":{"function_name":"gaarf"},"type":"cloud_function"},"sever
ity":"INFO","logging.googleapis.com/insertId":"..........4dMnfugFC1b9G9ejVarRnb","message":{"logging.googleapis.com/diagnostic":{"in
strumentation_source":[{"name":"nodejs-winston","version":"6.0.0"},{"name":"nodejs","version":"11.2.0"}]}},"logName":"projects/{{pro
jectId}}/logs/mylog"}

it's more or less looks good.
But the article describing the structured logging Json format lists JSON log fields understandable by the logger Agent quite differently.
For example, for labels it's supposed to use 'logging.googleapis.com/labels' field, not resource.labels. But I can't set that field in LoggingWinston's options.

[cindy-peng]

Hi @evil-shrike, like you have probably already figured out here, this logic is not controlled by logging client libraries but controlled by the integrated logging agent on cloud functions environment: https://cloud.google.com/logging/docs/agent/logging/configuration#process-payload
The agent automatically picks up logs from stdout and send to cloud logging. For structured logs, it process the special fields in json payloads before sending to cloud logging: https://cloud.google.com/functions/docs/monitoring/logging#processing_special_json_fields_in_messages

In the underlying nodejs-logging library, we process and set logging.googleapis.com/labels field from logging options, which will be picked up by logging agent: https://github.com/googleapis/nodejs-logging/blob/9d1d480406c4d1526c8a7fafd9b18379c0c7fcea/src/entry.ts#L274. That's why you will not be able to set the field logging.googleapis.com/labels with client libraries directly.

In this case, I would recommend reaching out to the logging agent's team and see if this is intended:
https://github.com/GoogleCloudPlatform/google-fluentd.

I am closing this issue for now. Please let me know if there is any other question. Thank you!