Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
evil-shrike opened this issue Apr 17, 2023 · 2 comments
Assignees
Labels
api: logging Issues related to the googleapis/nodejs-logging-winston API. priority: p3 Desirable enhancement or fix. May not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.

Comments

@evil-shrike
Copy link

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:
image

Here's a log entry with redirectToStdout: true:
image

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.

@evil-shrike evil-shrike added priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. labels Apr 17, 2023
@product-auto-label product-auto-label bot added the api: logging Issues related to the googleapis/nodejs-logging-winston API. label Apr 17, 2023
@losalex losalex removed their assignment Jul 3, 2023
@triplequark triplequark self-assigned this Oct 4, 2023
@cindy-peng cindy-peng added priority: p3 Desirable enhancement or fix. May not be included in next release. and removed priority: p2 Moderately-important priority. Fix may not be included in next release. labels Jan 9, 2024
@cindy-peng
Copy link
Contributor

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

@evil-shrike
Copy link
Author

evil-shrike commented Aug 14, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api: logging Issues related to the googleapis/nodejs-logging-winston API. priority: p3 Desirable enhancement or fix. May not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.
Projects
None yet
Development

No branches or pull requests

4 participants