diff --git a/.flake8 b/.flake8 new file mode 100644 index 0000000..a6578a3 --- /dev/null +++ b/.flake8 @@ -0,0 +1,2 @@ +[flake8] +extend-ignore = E501 diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml new file mode 100644 index 0000000..b2dc331 --- /dev/null +++ b/.github/workflows/test.yml @@ -0,0 +1,35 @@ +name: Test + +on: + push: + branches: + - "**" + + workflow_dispatch: + +jobs: + test: + runs-on: ubuntu-latest + name: Test Python + + strategy: + matrix: + python-version: + - "3.9" + - "3.10" + - "3.11" + + steps: + - name: Checkout + uses: actions/checkout@v3 + + - name: Setup Poetry + run: pipx install hatch + + - name: Setup Python + uses: actions/setup-python@v4 + with: + python-version: ${{ matrix.python-version }} + + - name: Test + run: hatch run pytest --color=yes diff --git a/README.md b/README.md index e69de29..2bcdf4a 100644 --- a/README.md +++ b/README.md @@ -0,0 +1,72 @@ +# Google Cloud Logging formatter for structlog + +This is an opiniated package that configures [structlog](https://structlog.org/) +to output log compatible with the [Google Cloud Logging log +format](https://cloud.google.com/logging/docs/structured-logging). + +The intention of this package is to be used for applications that run in [Google +Kubernetes Engine (GKE)](https://cloud.google.com/kubernetes-engine/) or [Google +Cloud Function](https://cloud.google.com/functions/). + +As such, the package is only concerned about **formatting logs**, where logs are +expected to be written on the standard output. Sending the logs to the actual +Google Logging API is supposed to be done by an external agent. + + +In particular, this package provides the following configuration by default: + +* Logs are formatted as JSON using the [Google Cloud Logging log + format](https://cloud.google.com/logging/docs/structured-logging) +* The [Python standard library's + `logging`](https://docs.python.org/3/library/logging.html) log levels are + available and translated to their GCP equivalents. +* Exceptions and `CRITICAL` log messages will be reported into [Google Error + Reporting dashboard](https://cloud.google.com/error-reporting/) +* Additional logger bound arguments will be reported as `labels` in GCP. + + +## How to use? + +Install the package with `pip` or your favorite Python package manager: + +```sh +pip install structlog-gcp +``` + +Then, configure `structlog` as usual, using the Structlog processors the package +provides: + +```python +import structlog +import structlog_gcp + +gcp_logs = structlog_gcp.StructlogGCP() + +structlog.configure(processors=gcp_logs.build_processors()) +``` + +Then, you can use `structlog` as usual: + +```python +logger = structlog.get_logger().bind(arg1="something") + +logger.info("Hello world") + +converted = False +try: + int("foobar") + converted = True +except: + logger.exception("Something bad happens") + +if not converted: + logger.critical("This is not supposed to happen", converted=converted) +``` + + + +## Reference + +* https://cloud.google.com/logging/docs/structured-logging +* https://cloud.google.com/error-reporting/docs/formatting-error-messages +* https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry diff --git a/docs/errors.png b/docs/errors.png new file mode 100644 index 0000000..9bd7071 Binary files /dev/null and b/docs/errors.png differ diff --git a/docs/logs.png b/docs/logs.png new file mode 100644 index 0000000..2df97a3 Binary files /dev/null and b/docs/logs.png differ diff --git a/examples/cloud-function/.gcloudignore b/examples/cloud-function/.gcloudignore new file mode 100644 index 0000000..fb252d6 --- /dev/null +++ b/examples/cloud-function/.gcloudignore @@ -0,0 +1,16 @@ +# This file specifies files that are *not* uploaded to Google Cloud +# using gcloud. It follows the same syntax as .gitignore, with the addition of +# "#!include" directives (which insert the entries of the given .gitignore-style +# file at that point). +# +# For more information, run: +# $ gcloud topic gcloudignore +# +.gcloudignore +# If you would like to upload your .git directory, .gitignore file or files +# from your .gitignore file, remove the corresponding line +# below: +.git +.gitignore + +node_modules diff --git a/examples/cloud-function/Makefile b/examples/cloud-function/Makefile new file mode 100644 index 0000000..acc07b0 --- /dev/null +++ b/examples/cloud-function/Makefile @@ -0,0 +1,8 @@ +deploy: + gcloud functions deploy test-log \ + --gen2 \ + --region europe-west1 \ + --runtime python310 \ + --source . \ + --entry-point test_func1 \ + --trigger-http diff --git a/examples/cloud-function/main.py b/examples/cloud-function/main.py new file mode 100644 index 0000000..d1db36d --- /dev/null +++ b/examples/cloud-function/main.py @@ -0,0 +1,71 @@ +import logging + +import functions_framework +import google.cloud.error_reporting +import google.cloud.logging +import structlog + +import structlog_gcp + +gcp_logs = structlog_gcp.StructlogGCP() +structlog.configure(processors=gcp_logs.build_processors()) + + +@functions_framework.http +def test_func1(request): + """Test the logging framework. + + * `GET` the deployed URL to trigger the `structlog-gcp` behavior + * `POST` the deployed URL to trigger the official Google logging + error + reporting libraries behavior + * `DELETE` the deployed URL to crash the function and force a cold-restart + """ + + if request.method == "GET": + logger = structlog.get_logger("test") + + logger.debug("a debug message", foo="bar") + logger.info("an info message", foo="bar") + logger.warning("a warning message", arg="something else") + + logger.error("an error message") + logger.critical("a critical message with reported error") + + try: + 1 / 0 + except ZeroDivisionError: + logger.exception("division by zero") + + try: + raise TypeError("crash") + except TypeError: + logger.exception("type error") + + elif request.method == "POST": + error = google.cloud.error_reporting.Client() + google.cloud.logging.Client().setup_logging() + + logging.debug("a debug message") + logging.info("an info message") + logging.warning("a warning message") + + logging.error("an error message") + logging.critical("a critical message with reported error") + + error.report("a reported error") + + try: + 1 / 0 + except ZeroDivisionError: + error.report_exception() + + try: + raise TypeError("crash") + except TypeError: + logging.exception("type error") + + elif request.method == "DELETE": + # crash the function to force a cold restart + raise RuntimeError("restart") + + return "OK" diff --git a/examples/cloud-function/requirements.txt b/examples/cloud-function/requirements.txt new file mode 100644 index 0000000..29ad772 --- /dev/null +++ b/examples/cloud-function/requirements.txt @@ -0,0 +1,3 @@ +functions-framework==3.* +google-cloud-error-reporting==1.* +structlog-gcp diff --git a/pyproject.toml b/pyproject.toml index 9f2d346..0d70ffe 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -3,7 +3,7 @@ requires = ["hatchling"] build-backend = "hatchling.build" [project] -name = "structlog-google-cloud-logging" +name = "structlog-gcp" description = 'A structlog set of processors to output as Google Cloud Logging format' readme = "README.md" requires-python = ">=3.7" @@ -15,42 +15,58 @@ authors = [ classifiers = [ "Development Status :: 4 - Beta", "Programming Language :: Python", - "Programming Language :: Python :: 3.7", - "Programming Language :: Python :: 3.8", "Programming Language :: Python :: 3.9", "Programming Language :: Python :: 3.10", "Programming Language :: Python :: 3.11", "Programming Language :: Python :: Implementation :: CPython", "Programming Language :: Python :: Implementation :: PyPy", ] -dependencies = [] +dependencies = [ + "structlog", +] dynamic = ["version"] [project.urls] -Documentation = "https://github.com/multani/structlog-google-cloud-logging#readme" -Issues = "https://github.com/multani/structlog-google-cloud-logging/issues" -Source = "https://github.com/multani/structlog-google-cloud-logging" +Documentation = "https://github.com/multani/structlog-gcp#readme" +Issues = "https://github.com/multani/structlog-gcp/issues" +Source = "https://github.com/multani/structlog-gcp" [tool.hatch.version] -path = "src/structlog_google_cloud_logging/__about__.py" +path = "structlog_gcp/__about__.py" [tool.hatch.envs.default] dependencies = [ + "black", + "isort", "pytest", "pytest-cov", + "flake8", ] + [tool.hatch.envs.default.scripts] -cov = "pytest --cov-report=term-missing --cov-config=pyproject.toml --cov=structlog_google_cloud_logging --cov=tests {args}" -no-cov = "cov --no-cov {args}" +test = "pytest" -[[tool.hatch.envs.test.matrix]] -python = ["37", "38", "39", "310", "311"] +[[tool.hatch.envs.default.matrix]] +python = ["39", "310", "311"] + +[tool.pytest.ini_options] +addopts = [ + "--doctest-modules", + "--cov", "structlog_gcp", + "--cov-branch", + "--cov-report", "html", + "--cov-report", "term", + "--tb", "short", + "--verbose", + "--verbose", +] +testpaths = "tests" [tool.coverage.run] branch = true parallel = true omit = [ - "structlog_google_cloud_logging/__about__.py", + "structlog_gcp/__about__.py", ] [tool.coverage.report] @@ -59,3 +75,6 @@ exclude_lines = [ "if __name__ == .__main__.:", "if TYPE_CHECKING:", ] + +[tool.isort] +profile = "black" diff --git a/src/structlog_google_cloud_logging/__about__.py b/src/structlog_google_cloud_logging/__about__.py deleted file mode 100644 index e69de29..0000000 diff --git a/structlog_gcp/__about__.py b/structlog_gcp/__about__.py new file mode 100644 index 0000000..f102a9c --- /dev/null +++ b/structlog_gcp/__about__.py @@ -0,0 +1 @@ +__version__ = "0.0.1" diff --git a/structlog_gcp/__init__.py b/structlog_gcp/__init__.py new file mode 100644 index 0000000..d9d758e --- /dev/null +++ b/structlog_gcp/__init__.py @@ -0,0 +1 @@ +from .base import StructlogGCP # noqa: F401 diff --git a/structlog_gcp/base.py b/structlog_gcp/base.py new file mode 100644 index 0000000..7744ded --- /dev/null +++ b/structlog_gcp/base.py @@ -0,0 +1,19 @@ +from . import errors, processors + + +class StructlogGCP: + def __init__(self): + pass + + def build_processors(self): + procs = [] + + procs.extend(processors.CoreCloudLogging().setup()) + procs.extend(processors.LogSeverity().setup()) + procs.extend(processors.CodeLocation().setup()) + procs.extend(errors.ReportException().setup()) + procs.extend(errors.ReportError(["CRITICAL"]).setup()) + procs.append(errors.add_service_context) + procs.extend(processors.FormatAsCloudLogging().setup()) + + return procs diff --git a/structlog_gcp/errors.py b/structlog_gcp/errors.py new file mode 100644 index 0000000..5ac3594 --- /dev/null +++ b/structlog_gcp/errors.py @@ -0,0 +1,108 @@ +import os + +import structlog + +from .types import CLOUD_LOGGING_KEY, ERROR_EVENT_TYPE, SOURCE_LOCATION_KEY + + +def add_service_context(logger, method_name, event_dict): + """Add a service context in which an error has occurred. + + This is part of the Error Reporting API, so it's only added when an error happens. + """ + + event_type = event_dict[CLOUD_LOGGING_KEY].get("@type") + if event_type != ERROR_EVENT_TYPE: + return event_dict + + service_context = { + # https://cloud.google.com/functions/docs/configuring/env-var#runtime_environment_variables_set_automatically + "service": os.environ.get("K_SERVICE", "unknown service"), + "version": os.environ.get("K_REVISION", "unknown version"), + } + + # https://cloud.google.com/error-reporting/reference/rest/v1beta1/ServiceContext + event_dict[CLOUD_LOGGING_KEY]["serviceContext"] = service_context + + return event_dict + + +class ReportException: + """Transform exception into a Google Cloud Error Reporting event.""" + + # https://cloud.google.com/error-reporting/reference/rest/v1beta1/projects.events/report + # https://cloud.google.com/error-reporting/docs/formatting-error-messages#log-entry-examples + + def __init__(self, log_level="CRITICAL"): + self.log_level = log_level + + def setup(self): + return [ + # structlog.processors.ExceptionRenderer(self.format_exception), + structlog.processors.format_exc_info, + self.__call__, + ] + + def __call__(self, logger, method_name, event_dict): + exception = event_dict.pop("exception", None) + if exception is None: + return event_dict + + event_dict[CLOUD_LOGGING_KEY]["@type"] = ERROR_EVENT_TYPE + event_dict[CLOUD_LOGGING_KEY]["severity"] = self.log_level + + # https://cloud.google.com/error-reporting/docs/formatting-error-messages + message = event_dict[CLOUD_LOGGING_KEY]["message"] + error_message = f"{message}\n{exception}" + event_dict[CLOUD_LOGGING_KEY]["stack_trace"] = error_message + + return event_dict + + +class ReportError: + """Report to Google Cloud Error Reporting specific log severities""" + + # https://cloud.google.com/error-reporting/reference/rest/v1beta1/projects.events/report + # https://cloud.google.com/error-reporting/docs/formatting-error-messages#log-entry-examples + + def __init__(self, severities=None): + if severities is None: + severities = [] + + self.severities = severities + + def setup(self): + return [self.__call__] + + def _build_service_context(self): + import os + + # https://cloud.google.com/error-reporting/reference/rest/v1beta1/ServiceContext + service_context = { + # https://cloud.google.com/functions/docs/configuring/env-var#runtime_environment_variables_set_automatically + "service": os.environ.get("K_SERVICE", "unknown service"), + "version": os.environ.get("K_REVISION", "unknown version"), + } + + return service_context + + def __call__(self, logger, method_name, event_dict): + severity = event_dict[CLOUD_LOGGING_KEY]["severity"] + + if severity not in self.severities: + return event_dict + + event_dict[CLOUD_LOGGING_KEY]["@type"] = ERROR_EVENT_TYPE + + if SOURCE_LOCATION_KEY in event_dict[CLOUD_LOGGING_KEY]: + # https://cloud.google.com/error-reporting/reference/rest/v1beta1/ErrorContext + error_context = { + "reportLocation": event_dict[CLOUD_LOGGING_KEY][SOURCE_LOCATION_KEY], + } + event_dict[CLOUD_LOGGING_KEY]["context"] = error_context + else: + event_dict[CLOUD_LOGGING_KEY]["context"] = "no location :(" + + event_dict[CLOUD_LOGGING_KEY]["serviceContext"] = self._build_service_context() + + return event_dict diff --git a/structlog_gcp/processors.py b/structlog_gcp/processors.py new file mode 100644 index 0000000..d9f9f7e --- /dev/null +++ b/structlog_gcp/processors.py @@ -0,0 +1,114 @@ +# https://cloud.google.com/functions/docs/monitoring/logging#writing_structured_logs +# https://cloud.google.com/logging/docs/agent/logging/configuration#process-payload +# https://cloud.google.com/logging/docs/structured-logging#special-payload-fields + +import structlog.processors + +from .types import CLOUD_LOGGING_KEY, SOURCE_LOCATION_KEY + + +class CoreCloudLogging: + """Initialize the Google Cloud Logging event message""" + + def setup(self): + return [ + # If some value is in bytes, decode it to a unicode str. + structlog.processors.UnicodeDecoder(), + # Add a timestamp in ISO 8601 format. + structlog.processors.TimeStamper(fmt="iso"), + self.__call__, + ] + + def __call__(self, logger, method_name, event_dict): + value = { + "message": event_dict.pop("event"), + "time": event_dict.pop("timestamp"), + } + + event_dict[CLOUD_LOGGING_KEY] = value + return event_dict + + +class FormatAsCloudLogging: + """Finalize the Google Cloud Logging event message and replace the logging event""" + + def setup(self): + return [ + self.__call__, + structlog.processors.JSONRenderer(), + ] + + def __call__(self, logger, method_name, event_dict): + event = event_dict.pop(CLOUD_LOGGING_KEY) + + if event_dict: + event["logging.googleapis.com/labels"] = event_dict + + return event + + +class LogSeverity: + """Set the severity using the Google Cloud Logging severities""" + + def __init__(self): + self.default = "notset" + + # From Python's logging level to Google level + self.mapping = { + "notset": "DEFAULT", # The log entry has no assigned severity level. + "debug": "DEBUG", # Debug or trace information. + "info": "INFO", # Routine information, such as ongoing status or performance. + # "notice": "NOTICE", # Normal but significant events, such as start up, shut down, or a configuration change. + "warn": "WARNING", # Warning events might cause problems. + "warning": "WARNING", # Warning events might cause problems. + "error": "ERROR", # Error events are likely to cause problems. + "critical": "CRITICAL", # Critical events cause more severe problems or outages. + # "alert": "ALERT", # A person must take an action immediately. + # "emergency": "EMERGENCY", # One or more systems are unusable. + } + + def setup(self): + return [ + # Add log level to event dict. + structlog.processors.add_log_level, + self.__call__, + ] + + def __call__(self, logger, method_name, event_dict): + """Format a Python log level value as a GCP log severity. + + See: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity + """ + + log_level = event_dict.pop("level") + severity = self.mapping.get(log_level, self.default) + + event_dict[CLOUD_LOGGING_KEY]["severity"] = severity + return event_dict + + +class CodeLocation: + """Inject the location of the logging message into the logs""" + + def setup(self): + # Add callsite parameters. + call_site_proc = structlog.processors.CallsiteParameterAdder( + parameters=[ + structlog.processors.CallsiteParameter.PATHNAME, + structlog.processors.CallsiteParameter.MODULE, + structlog.processors.CallsiteParameter.FUNC_NAME, + structlog.processors.CallsiteParameter.LINENO, + ] + ) + return [call_site_proc, self.__call__] + + def __call__(self, logger, method_name, event_dict): + location = { + "file": event_dict.pop("pathname"), + "line": str(event_dict.pop("lineno")), + "function": f"{event_dict.pop('module')}:{event_dict.pop('func_name')}", + } + + event_dict[CLOUD_LOGGING_KEY][SOURCE_LOCATION_KEY] = location + + return event_dict diff --git a/structlog_gcp/types.py b/structlog_gcp/types.py new file mode 100644 index 0000000..d16f154 --- /dev/null +++ b/structlog_gcp/types.py @@ -0,0 +1,7 @@ +ERROR_EVENT_TYPE = ( + "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent" +) + +SOURCE_LOCATION_KEY = "logging.googleapis.com/sourceLocation" + +CLOUD_LOGGING_KEY = "cloud-logging" diff --git a/tests/conftest.py b/tests/conftest.py new file mode 100644 index 0000000..fb115ae --- /dev/null +++ b/tests/conftest.py @@ -0,0 +1,30 @@ +from unittest.mock import patch + +import pytest +import structlog + +import structlog_gcp + +from . import fakes + + +@pytest.fixture +def logger(): + """Setup a logger for testing and return it""" + + with ( + patch( + "structlog.processors.CallsiteParameterAdder", + side_effect=fakes.CallsiteParameterAdder, + ), + patch("structlog.processors.TimeStamper", side_effect=fakes.TimeStamper), + patch( + "structlog.processors.format_exc_info", side_effect=fakes.format_exc_info + ), + ): + gcp_logs = structlog_gcp.StructlogGCP() + structlog.configure(processors=gcp_logs.build_processors()) + logger = structlog.get_logger() + yield logger + + structlog.reset_defaults() diff --git a/tests/fakes.py b/tests/fakes.py new file mode 100644 index 0000000..71d2389 --- /dev/null +++ b/tests/fakes.py @@ -0,0 +1,29 @@ +"""Fake implementations of structlog processors with side-effects""" + + +class CallsiteParameterAdder: + def __init__(self, *args, **kwargs): + pass + + def __call__(self, logger, method_name, event_dict): + event_dict["pathname"] = "/app/test.py" + event_dict["lineno"] = 42 + event_dict["module"] = "test" + event_dict["func_name"] = "test123" + return event_dict + + +class TimeStamper: + def __init__(self, *args, **kwargs): + pass + + def __call__(self, logger, method_name, event_dict): + event_dict["timestamp"] = "2023-04-01T08:00:00.000000Z" + return event_dict + + +def format_exc_info(logger, method_name, event_dict): + exc_info = event_dict.pop("exc_info", None) + if exc_info: + event_dict["exception"] = "Traceback blabla" + return event_dict diff --git a/tests/test_log.py b/tests/test_log.py new file mode 100644 index 0000000..f81c2fb --- /dev/null +++ b/tests/test_log.py @@ -0,0 +1,62 @@ +import json + + +def test_normal(capsys, logger): + logger.info("test") + + output = capsys.readouterr() + + assert "" == output.err + + msg = json.loads(output.out) + + expected = { + "logging.googleapis.com/sourceLocation": { + "file": "/app/test.py", + "function": "test:test123", + "line": "42", + }, + "message": "test", + "severity": "INFO", + "time": "2023-04-01T08:00:00.000000Z", + } + assert expected == msg + + +def test_error(capsys, logger): + try: + 1 / 0 + except ZeroDivisionError: + logger.exception("oh noes", foo="bar") + + output = capsys.readouterr() + + assert "" == output.err + + msg = json.loads(output.out) + + expected = { + "@type": "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent", + "context": { + "reportLocation": { + "file": "/app/test.py", + "function": "test:test123", + "line": "42", + }, + }, + "logging.googleapis.com/sourceLocation": { + "file": "/app/test.py", + "function": "test:test123", + "line": "42", + }, + "serviceContext": { + "service": "unknown service", + "version": "unknown version", + }, + "logging.googleapis.com/labels": {"foo": "bar"}, + "severity": "CRITICAL", + "message": "oh noes", + "stack_trace": "oh noes\nTraceback blabla", + "time": "2023-04-01T08:00:00.000000Z", + } + assert expected == msg