Times out when trying to write log entry on GCF

[jacobg]

Environment details

• OS: GCF runtime
• Node.js version: 18
• npm version: 8?
• @google-cloud/logging version: 10.4.0

Steps to reproduce

1. Deploy the following source code to GCF https://github.com/jacobg/gcf-node-logging/tree/gc-log. There is an npm run deploy script for easy deployment. This code calls console.log a couple times, and then uses the official cloud logging node client to write a request log in order to correlate all logs for this request.
2. Make http request to the function, e.g., https://REGION-PROJECT.cloudfunctions.net/gcf-node-logging.

Expected results

Request responds with 200, and Log Explorer should show all log entry correlated to the request log.

Actual results

Request times out calling log.write() function. The console.log entries show up in Logs Explorer, but not the request log.

Additional information

Here is sample source code that tries to create a correlating request log using console.log with json: https://github.com/jacobg/gcf-node-logging/tree/console-log The request log does show up in Logs Explorer, but the other log entries in that request are not correlated with it. It seems the issue is that GCF does not provide a way to set the log name to cloudfunctions.googleapis.com%2Frequest_log so that it can be correlated. That's why I tries using the official Node logging client instead, but now there's this timeout issue.

[jacobg]

Also, the nodejs-logging-winston and bunyan libraries have the following comment:

  // Unless we are running on Google App Engine or Cloud Functions, generate a
  // parent request log entry that all the request specific logs ("app logs")
  // will nest under. GAE and GCF generate the parent request logs
  // automatically.
  let emitRequestLogEntry;
  if (env !== GCPEnv.APP_ENGINE && env !== GCPEnv.CLOUD_FUNCTIONS) {
    const requestLogName = Log.formatName_(
      projectId,
      `${transport.common.logName}${REQUEST_LOG_SUFFIX}`
    );

https://github.com/googleapis/nodejs-logging-winston/blob/main/src/middleware/express.ts#L78-L87

This comment seems to be incorrect: Cloud Functions is not creating a parent request log that will correlate with child logs for that request.

[losalex]

Thanks @jacobg for opening this issue! I am not sure why exactly you have a timeout, but for serverless it is recommended to leverage LogSync.

[jacobg]

Thanks @losalex for the reply. I figured out the issue was that I was setting the httpRequest.latency as a string like this: '1.4s' instead of httpRequest.latency = { seconds: 1.4 }. I mixed it up with Python which uses that string format. You may want to test that case to ensure it fails fast instead of hanging and timing out.

Regarding LogSync, it doesn't seem to support writing a correlated request log. It seems that the Cloud Functions logging agent forces the logName to cloudfunctions.googleapis.com%2Fcloud-functions instead of the logName cloudfunctions.googleapis.com%2Frequest_log necessary for request logs. Do you agree with that?

Also, is there a tested pattern to generating a request log with response size before calling express res.end()? I tried swizzling the end function to do that, but was getting a connection error for some strange reason.

[cindy-peng]

Hi @jacobg , Glad you figured out the issue with latency, more details about the string format is documented here: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#HttpRequest

LogSync will default logging to stdout and then picked up by logging agent. By default, the logs from the agent are named projects/[PROJECT_ID]/logs/[LOG_ID]: https://cloud.google.com/logging/docs/agent/default-logs#linux-instances. I believe that's why logName was defaulted to be cloudfunctions.googleapis.com%2Fcloud-functions.

Regarding the pattern for tested pattern, res.end() will end the process without any data. You can try res.send() to respond with data : https://github.dev/GoogleCloudPlatform/nodejs-docs-samples/blob/5ae41d635ea99d0c2d101c365aa5c3f1d8fd1f5c/functions/http/httpMethods/test/index.test.js