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

daniel-sanche · web-flow · commit a78f577bda17 · 2021-04-09T13:41:58.000-07:00
diff --git a/google/cloud/logging/handlers/__init__.py b/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",
 ]
diff --git a/google/cloud/logging_v2/client.py b/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
diff --git a/google/cloud/logging_v2/handlers/__init__.py b/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",
 ]
diff --git a/google/cloud/logging_v2/handlers/handlers.py b/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.
 
diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/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
diff --git a/tests/environment b/tests/environment
@@ -1 +1 @@
-Subproject commit 1962721db8aa382bb1f658921979a1c183bf2d1a
+Subproject commit f0e2726579ef96f8e6b3ceaed8145d2bfbfa32bc
diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py
@@ -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"
diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py
