diff --git a/google/cloud/logging/handlers/__init__.py b/google/cloud/logging/handlers/__init__.py index 29ed8f0d..e27f8e67 100644 --- 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 index 17d85340..0b5fd1dd 100644 --- 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 index 29ed8f0d..a1ed08b5 100644 --- 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 index ffcc03ae..175cd010 100644 --- 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 new file mode 100644 index 00000000..56d032d0 --- /dev/null +++ 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 index 1962721d..f0e27265 160000 --- 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 index 80a1368b..9772d7b0 100644 --- 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 new file mode 100644 index 00000000..64c63c02 --- /dev/null +++ b/tests/unit/handlers/test_structured_log.py @@ -0,0 +1,151 @@ +# 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. + +import unittest + + +class TestStructuredLogHandler(unittest.TestCase): + PROJECT = "PROJECT" + + def _get_target_class(self): + from google.cloud.logging.handlers import StructuredLogHandler + + return StructuredLogHandler + + 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_ctor_defaults(self): + handler = self._make_one() + self.assertIsNone(handler.name) + + def test_ctor_w_name(self): + handler = self._make_one(name="foo") + self.assertEqual(handler.name, "foo") + + def test_format(self): + import logging + import json + + handler = 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 + ) + expected_payload = { + "message": message, + "severity": record.levelname, + "logging.googleapis.com/trace": "", + "logging.googleapis.com/sourceLocation": { + "file": pathname, + "line": str(lineno), + "function": func, + }, + "httpRequest": { + "requestMethod": "", + "requestUrl": "", + "userAgent": "", + "protocol": "", + }, + } + handler.filter(record) + result = json.loads(handler.format(record)) + for (key, value) in expected_payload.items(): + self.assertEqual(value, result[key]) + self.assertEqual( + len(expected_payload.keys()), + len(result.keys()), + f"result dictionary has unexpected keys: {result.keys()}", + ) + + def test_format_minimal(self): + import logging + import json + + handler = self._make_one() + record = logging.LogRecord(None, logging.INFO, None, None, None, None, None,) + record.created = None + expected_payload = { + "message": "", + "logging.googleapis.com/trace": "", + "logging.googleapis.com/sourceLocation": { + "file": "", + "line": "0", + "function": "", + }, + "httpRequest": { + "requestMethod": "", + "requestUrl": "", + "userAgent": "", + "protocol": "", + }, + } + handler.filter(record) + result = json.loads(handler.format(record)) + for (key, value) in expected_payload.items(): + self.assertEqual( + value, result[key], f"expected_payload[{key}] != result[{key}]" + ) + + def test_format_with_request(self): + import logging + import json + + handler = self._make_one() + logname = "loggername" + message = "hello world，嗨 世界" + record = logging.LogRecord(logname, logging.INFO, "", 0, message, None, None) + expected_path = "http://testserver/123" + expected_agent = "Mozilla/5.0" + expected_trace = "123" + expected_payload = { + "logging.googleapis.com/trace": expected_trace, + "httpRequest": { + "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, + }, + ) + handler.filter(record) + result = json.loads(handler.format(record)) + for (key, value) in expected_payload.items(): + self.assertEqual(value, result[key])