feat: use standard output logs on serverless environments (#228)

Author: daniel-sanche

google/cloud/logging/handlers/__init__.py

@@ -16,12 +16,16 @@
 
 from google.cloud.logging_v2.handlers.app_engine import AppEngineHandler
 from google.cloud.logging_v2.handlers.container_engine import ContainerEngineHandler
+from google.cloud.logging_v2.handlers.structured_log import StructuredLogHandler
+from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter
 from google.cloud.logging_v2.handlers.handlers import CloudLoggingHandler
 from google.cloud.logging_v2.handlers.handlers import setup_logging
 
 __all__ = [
  "AppEngineHandler",
+ "CloudLoggingFilter",
  "CloudLoggingHandler",
  "ContainerEngineHandler",
+ "StructuredLogHandler",
  "setup_logging",
 ]

google/cloud/logging_v2/client.py

@@ -16,6 +16,7 @@
 
 import logging
 import os
+import sys
 
 try:
  from google.cloud.logging_v2 import _gapic
@@ -36,6 +37,7 @@
 from google.cloud.logging_v2.handlers import CloudLoggingHandler
 from google.cloud.logging_v2.handlers import AppEngineHandler
 from google.cloud.logging_v2.handlers import ContainerEngineHandler
+from google.cloud.logging_v2.handlers import StructuredLogHandler
 from google.cloud.logging_v2.handlers import setup_logging
 from google.cloud.logging_v2.handlers.handlers import EXCLUDED_LOGGER_DEFAULTS
 from google.cloud.logging_v2.resource import Resource
@@ -53,6 +55,7 @@
 _GAE_RESOURCE_TYPE = "gae_app"
 _GKE_RESOURCE_TYPE = "k8s_container"
 _GCF_RESOURCE_TYPE = "cloud_function"
+_RUN_RESOURCE_TYPE = "cloud_run_revision"
 
 
 class Client(ClientWithProject):
@@ -347,18 +350,22 @@ def get_default_handler(self, **kw):
  """
  monitored_resource = kw.pop("resource", detect_resource(self.project))
 
- if (
- isinstance(monitored_resource, Resource)
- and monitored_resource.type == _GAE_RESOURCE_TYPE
- ):
- return AppEngineHandler(self, **kw)
- elif (
- isinstance(monitored_resource, Resource)
- and monitored_resource.type == _GKE_RESOURCE_TYPE
- ):
- return ContainerEngineHandler(**kw)
- else:
- return CloudLoggingHandler(self, resource=monitored_resource, **kw)
+ if isinstance(monitored_resource, Resource):
+ if monitored_resource.type == _GAE_RESOURCE_TYPE:
+ return AppEngineHandler(self, **kw)
+ elif monitored_resource.type == _GKE_RESOURCE_TYPE:
+ return ContainerEngineHandler(**kw)
+ elif (
+ monitored_resource.type == _GCF_RESOURCE_TYPE
+ and sys.version_info[0] == 3
+ and sys.version_info[1] >= 8
+ ):
+ # Cloud Functions with runtimes > 3.8 supports structured logs on standard out
+ # 3.7 should use the standard CloudLoggingHandler, which sends logs over the network.
+ return StructuredLogHandler(**kw, project=self.project)
+ elif monitored_resource.type == _RUN_RESOURCE_TYPE:
+ return StructuredLogHandler(**kw, project=self.project)
+ return CloudLoggingHandler(self, resource=monitored_resource, **kw)
 
  def setup_logging(
  self, *, log_level=logging.INFO, excluded_loggers=EXCLUDED_LOGGER_DEFAULTS, **kw

google/cloud/logging_v2/handlers/__init__.py

@@ -16,12 +16,16 @@
 
 from google.cloud.logging_v2.handlers.app_engine import AppEngineHandler
 from google.cloud.logging_v2.handlers.container_engine import ContainerEngineHandler
+from google.cloud.logging_v2.handlers.structured_log import StructuredLogHandler
 from google.cloud.logging_v2.handlers.handlers import CloudLoggingHandler
+from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter
 from google.cloud.logging_v2.handlers.handlers import setup_logging
 
 __all__ = [
  "AppEngineHandler",
+ "CloudLoggingFilter",
  "CloudLoggingHandler",
  "ContainerEngineHandler",
+ "StructuredLogHandler",
  "setup_logging",
 ]

google/cloud/logging_v2/handlers/handlers.py

@@ -16,10 +16,10 @@
 
 import logging
 
-
 from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
 from google.cloud.logging_v2.handlers.transports import BackgroundThreadTransport
 from google.cloud.logging_v2.handlers._monitored_resources import detect_resource
+from google.cloud.logging_v2.handlers._helpers import get_request_data
 
 DEFAULT_LOGGER_NAME = "python"
 
@@ -28,6 +28,38 @@
 _CLEAR_HANDLER_RESOURCE_TYPES = ("gae_app", "cloud_function")
 
 
+class CloudLoggingFilter(logging.Filter):
+ """Python standard ``logging`` Filter class to add Cloud Logging
+ information to each LogRecord.
+
+ When attached to a LogHandler, each incoming log will receive trace and
+ http_request related to the request. This data can be overwritten using
+ the `extras` argument when writing logs.
+ """
+
+ def __init__(self, project=None):
+ self.project = project
+
+ def filter(self, record):
+ # ensure record has all required fields set
+ record.lineno = 0 if record.lineno is None else record.lineno
+ record.msg = "" if record.msg is None else record.msg
+ record.funcName = "" if record.funcName is None else record.funcName
+ record.pathname = "" if record.pathname is None else record.pathname
+ # find http request data
+ inferred_http, inferred_trace = get_request_data()
+ if inferred_trace is not None and self.project is not None:
+ inferred_trace = f"projects/{self.project}/traces/{inferred_trace}"
+
+ record.trace = getattr(record, "trace", inferred_trace) or ""
+ record.http_request = getattr(record, "http_request", inferred_http) or {}
+ record.request_method = record.http_request.get("requestMethod", "")
+ record.request_url = record.http_request.get("requestUrl", "")
+ record.user_agent = record.http_request.get("userAgent", "")
+ record.protocol = record.http_request.get("protocol", "")
+ return True
+
+
 class CloudLoggingHandler(logging.StreamHandler):
  """Handler that directly makes Cloud Logging API calls.
 

google/cloud/logging_v2/handlers/structured_log.py

@@ -0,0 +1,55 @@
+# Copyright 2021 Google LLC All Rights Reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+"""Logging handler for printing formatted structured logs to standard output.
+"""
+
+import logging.handlers
+
+from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter
+
+GCP_FORMAT = '{"message": "%(message)s", "severity": "%(levelname)s", "logging.googleapis.com/trace": "%(trace)s", "logging.googleapis.com/sourceLocation": { "file": "%(pathname)s", "line": "%(lineno)d", "function": "%(funcName)s"}, "httpRequest": {"requestMethod": "%(request_method)s", "requestUrl": "%(request_url)s", "userAgent": "%(user_agent)s", "protocol": "%(protocol)s"} }'
+
+
+class StructuredLogHandler(logging.StreamHandler):
+ """Handler to format logs into the Cloud Logging structured log format,
+ and write them to standard output
+ """
+
+ def __init__(self, *, name=None, stream=None, project=None):
+ """
+ Args:
+ name (Optional[str]): The name of the custom log in Cloud Logging.
+ stream (Optional[IO]): Stream to be used by the handler.
+ """
+ super(StructuredLogHandler, self).__init__(stream=stream)
+ self.name = name
+ self.project_id = project
+
+ # add extra keys to log record
+ self.addFilter(CloudLoggingFilter(project))
+
+ # make logs appear in GCP structured logging format
+ self.formatter = logging.Formatter(GCP_FORMAT)
+
+ def format(self, record):
+ """Format the message into structured log JSON.
+ Args:
+ record (logging.LogRecord): The log record.
+ Returns:
+ str: A JSON string formatted for GKE fluentd.
+ """
+
+ payload = self.formatter.format(record)
+ return payload

tests/environment

@@ -23,6 +23,170 @@
 )
 
 
+class TestCloudLoggingFilter(unittest.TestCase):
+
+ PROJECT = "PROJECT"
+
+ @staticmethod
+ def _get_target_class():
+ from google.cloud.logging.handlers import CloudLoggingFilter
+
+ return CloudLoggingFilter
+
+ def _make_one(self, *args, **kw):
+ return self._get_target_class()(*args, **kw)
+
+ @staticmethod
+ def create_app():
+ import flask
+
+ app = flask.Flask(__name__)
+
+ @app.route("/")
+ def index():
+ return "test flask trace" # pragma: NO COVER
+
+ return app
+
+ def test_filter_record(self):
+ """
+ test adding fields to a standard record
+ """
+ import logging
+
+ filter_obj = self._make_one()
+ logname = "loggername"
+ message = "hello world，嗨 世界"
+ pathname = "testpath"
+ lineno = 1
+ func = "test-function"
+ record = logging.LogRecord(
+ logname, logging.INFO, pathname, lineno, message, None, None, func=func
+ )
+
+ success = filter_obj.filter(record)
+ self.assertTrue(success)
+
+ self.assertEqual(record.lineno, lineno)
+ self.assertEqual(record.msg, message)
+ self.assertEqual(record.funcName, func)
+ self.assertEqual(record.pathname, pathname)
+ self.assertEqual(record.trace, "")
+ self.assertEqual(record.http_request, {})
+ self.assertEqual(record.request_method, "")
+ self.assertEqual(record.request_url, "")
+ self.assertEqual(record.user_agent, "")
+ self.assertEqual(record.protocol, "")
+
+ def test_minimal_record(self):
+ """
+ test filter adds empty strings on missing attributes
+ """
+ import logging
+
+ filter_obj = self._make_one()
+ record = logging.LogRecord(None, logging.INFO, None, None, None, None, None,)
+ record.created = None
+
+ success = filter_obj.filter(record)
+ self.assertTrue(success)
+
+ self.assertEqual(record.lineno, 0)
+ self.assertEqual(record.msg, "")
+ self.assertEqual(record.funcName, "")
+ self.assertEqual(record.pathname, "")
+ self.assertEqual(record.trace, "")
+ self.assertEqual(record.http_request, {})
+ self.assertEqual(record.request_method, "")
+ self.assertEqual(record.request_url, "")
+ self.assertEqual(record.user_agent, "")
+ self.assertEqual(record.protocol, "")
+
+ def test_record_with_request(self):
+ """
+ test filter adds http request data when available
+ """
+ import logging
+
+ filter_obj = self._make_one()
+ record = logging.LogRecord(None, logging.INFO, None, None, None, None, None,)
+ record.created = None
+
+ expected_path = "http://testserver/123"
+ expected_agent = "Mozilla/5.0"
+ expected_trace = "123"
+ expected_request = {
+ "requestMethod": "PUT",
+ "requestUrl": expected_path,
+ "userAgent": expected_agent,
+ "protocol": "HTTP/1.1",
+ }
+
+ app = self.create_app()
+ with app.test_client() as c:
+ c.put(
+ path=expected_path,
+ data="body",
+ headers={
+ "User-Agent": expected_agent,
+ "X_CLOUD_TRACE_CONTEXT": expected_trace,
+ },
+ )
+ success = filter_obj.filter(record)
+ self.assertTrue(success)
+
+ self.assertEqual(record.trace, expected_trace)
+ for key, val in expected_request.items():
+ self.assertEqual(record.http_request[key], val)
+ self.assertEqual(record.request_method, "PUT")
+ self.assertEqual(record.request_url, expected_path)
+ self.assertEqual(record.user_agent, expected_agent)
+ self.assertEqual(record.protocol, "HTTP/1.1")
+
+ def test_user_overrides(self):
+ """
+ ensure user can override fields
+ """
+ import logging
+
+ filter_obj = self._make_one()
+ record = logging.LogRecord(
+ "name", logging.INFO, "default", 99, "message", None, None, func="default"
+ )
+ record.created = 5.03
+
+ app = self.create_app()
+ with app.test_client() as c:
+ c.put(
+ path="http://testserver/123",
+ data="body",
+ headers={"User-Agent": "default", "X_CLOUD_TRACE_CONTEXT": "default"},
+ )
+ # override values
+ overwritten_trace = "456"
+ record.trace = overwritten_trace
+ overwritten_method = "GET"
+ overwritten_url = "www.google.com"
+ overwritten_agent = "custom"
+ overwritten_protocol = "test"
+ overwritten_request_object = {
+ "requestMethod": overwritten_method,
+ "requestUrl": overwritten_url,
+ "userAgent": overwritten_agent,
+ "protocol": overwritten_protocol,
+ }
+ record.http_request = overwritten_request_object
+ success = filter_obj.filter(record)
+ self.assertTrue(success)
+
+ self.assertEqual(record.trace, overwritten_trace)
+ self.assertEqual(record.http_request, overwritten_request_object)
+ self.assertEqual(record.request_method, overwritten_method)
+ self.assertEqual(record.request_url, overwritten_url)
+ self.assertEqual(record.user_agent, overwritten_agent)
+ self.assertEqual(record.protocol, overwritten_protocol)
+
+
 class TestCloudLoggingHandler(unittest.TestCase):
 
  PROJECT = "PROJECT"