Custom logs from a GCP Function do not contain execution-id

[amertkara]

I am not sure if this is a bug or a misconfiguration issue but we are unable to get the execution-id in our logs. GCP's own function logs like startup/teardown/timeout contain it however our own logs don't. This makes it impossible to correlate all logs from an instance.

Example (GCP function startup log)

{
  insertId: "000000-a51b0cd9-1f4d-4396-b812-4b35c8878b69"
  labels: {
    execution_id: "j57c7yk340qq"
  }
  logName: "projects/PROJECT-ID/logs/cloudfunctions.googleapis.com%2Fcloud-functions"
  receiveTimestamp: "2021-06-30T17:37:16.202805413Z"
  resource: {
    labels: {
      function_name: "FUNCTION-NAME",
      project_id: "PROJECT-ID",
      region: "REGION"
    }
    type: "cloud_function"
  }
  severity: "DEBUG"
  textPayload: "Function execution started"
  timestamp: "2021-06-30T17:37:05.341077546Z"
}

We also tried setting a custom label in CloudLoggingHandler with a trace-id however GCP's own logs don't reflect the custom trace-id. This makes me think that GCP is using a separate logger which attaches the execution-id and our logs are isolated from that logger.

Environment details

• OS type and version: N/A
• Python version: 3.7.9
• pip version: 21.1.2
• google-cloud-logging version: 2.3.1

Steps to reproduce

1. Create and attach CloudLoggingHandler to a logger in a GCP function
2. Log an INFO message
3. Verify the log does not contain execution-id inside labels

Code example

A simplified version of our logging setup and a basic event-trigger function.

import logging

import google.cloud.logging
from google.cloud.logging_v2.handlers.handlers import CloudLoggingHandler


class FunctionLogger(logging.Logger):

    def __init__(self, level=logging.NOTSET):
        super().__init__("logger_name", level)

        client = google.cloud.logging.Client()

        self._handler = CloudLoggingHandler(client)

        self.propagate = False  # prevent logging from root logger
        self.addHandler(self._handler)


def handler(event, context=None):
    """function entry point"""
    logger = FunctionLogger()

    logger.info("Test message")

Thanks!!

[daniel-sanche]

The CloudLoggingHandler you are using sends batched logs over the network. This works well in most environments, but it has issues in Cloud Functions, since the code is ephemeral. We recently added StructuredLogHandler as the new default handler for GCF, which prints all logs as structured JSON to stdout for the agent to parse. Using this method should solve your issue.

You can either manually specify StructuredLogHandler in place of CloudLoggingHandler in your existing code, or you can just use client.setup_logging() and let the library do the recommended set-up based on the environment for you (see docs here)

[amertkara]

Thanks for the quick response! StructuredLogHandler made the execution-id appear for all logs, however my log message is now printed inside textPayload. Before, I would pass my message along with a context dictionary and CloudLoggingHandler would allow me to log it under jsonPayload. How can I achieve this with StructuredLogHandler?

[daniel-sanche]

Hmm I didn't think the CloudLoggingHandler supported sending arbitrary jsonPayloads yet. The transport classes are hard-coded to only send a message and a python_logger field (so it is technically a jsonPayload, but you can only control the message field). I'd be interested in seeing the code you used.

Full support for jsonPayloads is a new feature we are adding in v3.0.0. If you want to try it early, you should be able to install the library from the v3.0.0 branch, or just copy the updated StructuredLogHandler code directly from the codebase.