diff --git a/README.md b/README.md index 43c0697..d90af35 100644 --- a/README.md +++ b/README.md @@ -9,17 +9,31 @@ ## Why? -LINZ has a standard logging format based loosely on the [pinojs](https://github.com/pinojs/pino) logging format: +[OpenTelemetry Log Data Model](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md) ```json { - "level": 30, - "time": 1571696532994, - "pid": 10671, - "hostname": "Ubuntu1", - "id": "01DQR6KQG0K60TP4T1C4VC5P74", - "msg": "SomeMessage", - "v": 1 + "timestamp": 1586960586000, + "attributes": { + "http.status_code": 500, + "http.url": "http://example.com", + "my.custom.application.tag": "hello" + }, + "resource": { + "service.name": "donut_shop", + "service.version": "semver:2.0.0", + "k8s.pod.name": "1138528c-c36e-11e9-a1a7-42010a800198" + }, + "trace_id": "f4dbb3edd765f620", + "span_id": "43222c2d51a7abe3", + "severity": "INFO", + "body": { + "i": "am", + "an": "event", + "of": { + "some": "complexity" + } + } } ``` diff --git a/linz_logger/__init__.py b/linz_logger/__init__.py index 0e89edb..94c97fa 100644 --- a/linz_logger/__init__.py +++ b/linz_logger/__init__.py @@ -1 +1,3 @@ -from .logger import LogLevel, get_log, remove_contextvars, set_contextvars, set_level +from .logger import Severity, get_log, set_severity +from .ot_attributes import OpenTelemetryAttributes +from .ot_resources import OpenTelemetryResource diff --git a/linz_logger/logger.py b/linz_logger/logger.py index 92063d2..0633084 100644 --- a/linz_logger/logger.py +++ b/linz_logger/logger.py @@ -1,113 +1,124 @@ import os import time +from dataclasses import asdict, replace from enum import Enum from functools import partial from platform import node import structlog -from structlog.contextvars import bind_contextvars, clear_contextvars, merge_contextvars, unbind_contextvars from structlog.exceptions import DropEvent from ulid import ULID +from linz_logger.ot_attributes import OpenTelemetryAttributes +from linz_logger.ot_resources import OpenTelemetryResource -class LogLevel(Enum): + +class Severity(Enum): """ - Convert to pinojs standard level numbers + https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md#field-severitynumber """ - critical = 60 - exception = 50 - error = 50 - warn = 40 - warning = 40 - info = 30 - debug = 20 - notset = 10 - trace = 10 + TRACE = 1 + DEBUG = 5 + INFO = 9 + WARN = 13 + ERROR = 17 + FATAL = 21 -current_level = LogLevel.debug structlog.PrintLogger.trace = structlog.PrintLogger.msg pid = os.getpid() hostname = node() ulid = str(ULID()) -clear_contextvars() +current_severity: Severity = Severity.DEBUG +resources: OpenTelemetryResource = OpenTelemetryResource(host_name=hostname) +attributes: OpenTelemetryAttributes = OpenTelemetryAttributes() + +def remove_none_empty_values(_dict: dict): + new_dict = _dict.copy() + for key, value in list(new_dict.items()): + if value is None or value == "": + del new_dict[key] + elif isinstance(value, dict): + remove_none_empty_values(value) + return new_dict -def set_level(level: LogLevel): + +def set_severity(severity: Severity): """ Set the loggging level. All logs less than the given value will not be displayed. """ - global current_level - current_level = level + global current_severity + current_severity = severity -def set_contextvars(key_value: dict): - """Set the context variables. +def set_resources(ctx: OpenTelemetryResource) -> None: + global resources + resources = replace(resources, **asdict(ctx)) - Args: - key_value (dict): A dictionnary of key-value pairs. - """ - bind_contextvars(**key_value) +def set_attributes(ctx: OpenTelemetryAttributes) -> None: + global attributes + attributes = replace(attributes, **asdict(ctx)) -def remove_contextvars(keys): - """Remove the context variables. - Args: - keys (list): A list of keys. +def severity_filter(_, __, event_dict: dict): """ - unbind_contextvars(*keys) - - -def level_filter(_, __, event_dict: dict): - """ - Silently drop logs lower than the set level. + Silently drop logs lower than the set severity. """ - if event_dict.get("level", 0) < current_level.value: + if event_dict.get("SeverityNumber", 0) < current_severity.value: raise DropEvent return event_dict # This is a standard format for the function so it needs all three arguments -# Even thought we do not use them +# Even though we do not use them # pylint: disable=unused-argument def add_default_keys(current_logger, method_name: str, event_dict: dict): """ - Configure structlog to output the same format as pinojs + Configure structlog to output aligning with the openTelemety Log Data Model format { - "level": 30, - "time": 1571696532994, - "pid": 10671, - "hostname": "Ubuntu1", - "id": "01DQR6KQG0K60TP4T1C4VC5P74", - "msg": "SomeMessage", - "v": 1 + "Timestamp": 1586960586000, + "Attributes": { + "http.status_code": 500, + "http.url": "http://example.com", + "my.custom.application.tag": "hello", + }, + "Resource": { + "service.name": "donut_shop", + "service.version": "semver:2.0.0", + "k8s.pod.uid": "1138528c-c36e-11e9-a1a7-42010a800198", + }, + "TraceId": "f4dbb3edd765f620", // this is a byte sequence + // (hex-encoded in JSON) + "SpanId": "43222c2d51a7abe3", + "SeverityText": "INFO", + "SeverityNumber": 9, + "Body": "20200415T072306-0700 INFO I like donuts" } """ - event_dict["level"] = LogLevel[method_name].value if LogLevel[method_name] else 10 - # Time needs to be in ms - event_dict["time"] = int(time.time() * 1000) - # Standard keys that need to be added - event_dict["v"] = 1 - event_dict["pid"] = pid - event_dict["hostname"] = hostname - event_dict["id"] = ulid - # Remap event -> msg - event_dict["msg"] = event_dict["event"] + severity_name = method_name.upper() + severity_name = severity_name.replace("WARNING", "WARN") + event_dict["SeverityText"] = Severity[severity_name].name if Severity[severity_name] else Severity.TRACE.name + event_dict["SeverityNumber"] = Severity[severity_name].value if Severity[severity_name] else Severity.TRACE.value + event_dict["Timestamp"] = time.time_ns() + # TODO: do we want to delete empty values - I've done that to manage default values in both OpenTelemetryAttributes and OpenTelemetryResource + event_dict["Attributes"] = remove_none_empty_values(attributes.to_dict()) + event_dict["Resources"] = remove_none_empty_values(resources.to_dict()) + event_dict["Attributes"]["msg"] = event_dict["event"] del event_dict["event"] return event_dict structlog.configure( processors=[ - merge_contextvars, add_default_keys, - level_filter, + severity_filter, structlog.processors.StackInfoRenderer(), structlog.processors.format_exc_info, - structlog.processors.JSONRenderer(), + structlog.processors.JSONRenderer(allow_nan=False, sort_keys=True), ] ) @@ -121,8 +132,14 @@ def get_log(): return log -def trace(self, event, **kw): - """ - add trace level +def trace(self, event, name, **kw): + """_summary_ + + Args: + event (_type_): _description_ + name (_type_): Short event identifier that does not contain varying parts. + + Returns: + _type_: _description_ """ - return self._proxy_to_logger("trace", event, **kw) + return self._proxy_to_logger("trace", event, Name=name, **kw) diff --git a/linz_logger/ot_attributes.py b/linz_logger/ot_attributes.py new file mode 100644 index 0000000..b748faf --- /dev/null +++ b/linz_logger/ot_attributes.py @@ -0,0 +1,15 @@ +from dataclasses import dataclass, field +from typing import Optional + +from dataclasses_json import config, dataclass_json + + +@dataclass_json +@dataclass +class OpenTelemetryAttributes: + """https://github.com/open-telemetry/oteps/blob/main/text/logs/0097-log-data-model.md#field-attributes""" + + error_id: Optional[str] = field(metadata=config(field_name="error.id"), default=None) + error_code: Optional[str] = field(metadata=config(field_name="error.code"), default=None) + error_message: Optional[str] = field(metadata=config(field_name="error.message"), default=None) + error_stack_trace: Optional[str] = field(metadata=config(field_name="error.stack_trace"), default=None) diff --git a/linz_logger/ot_resources.py b/linz_logger/ot_resources.py new file mode 100644 index 0000000..9498a3c --- /dev/null +++ b/linz_logger/ot_resources.py @@ -0,0 +1,19 @@ +from dataclasses import dataclass, field + +from dataclasses_json import config, dataclass_json + + +@dataclass_json +@dataclass +class OpenTelemetryResource: + """https://github.com/open-telemetry/oteps/blob/main/text/logs/0097-log-data-model.md#field-resource""" + + host_name: str = field(metadata=config(field_name="host.name"), default="") + host_id: str = field(metadata=config(field_name="host.id"), default="") + host_ip: str = field(metadata=config(field_name="host.ip"), default="") + host_mac: str = field(metadata=config(field_name="host.mac"), default="") + + container_id: str = field(metadata=config(field_name="container.id"), default="") + container_image_name: str = field(metadata=config(field_name="container.image.name"), default="") + container_image_hash: str = field(metadata=config(field_name="container.image.hash"), default="") + container_name: str = field(metadata=config(field_name="container.name"), default="") diff --git a/linz_logger/test_logger.py b/linz_logger/test_logger.py index d640e41..bcfda97 100644 --- a/linz_logger/test_logger.py +++ b/linz_logger/test_logger.py @@ -1,7 +1,10 @@ import json import os -from .logger import LogLevel, get_log, remove_contextvars, set_contextvars, set_level +from linz_logger.ot_attributes import OpenTelemetryAttributes +from linz_logger.ot_resources import OpenTelemetryResource + +from .logger import Severity, get_log, set_attributes, set_resources, set_severity def test_hello_without_name(): @@ -11,48 +14,69 @@ def test_hello_without_name(): def test_trace(capsys): """Test trace level""" - set_level(LogLevel.trace) - get_log().trace("abc") + set_severity(Severity.TRACE) + get_log().trace("abc", "logStarted") + stdout, _ = capsys.readouterr() + log = json.loads(stdout) + assert log["SeverityText"] == Severity.TRACE.name + assert log["Attributes"]["msg"] == "abc" + + +def test_debug(capsys): + """Test debug level""" + set_severity(Severity.DEBUG) + get_log().debug("abc") stdout, _ = capsys.readouterr() log = json.loads(stdout) - assert log["level"] == 10 - assert log["msg"] == "abc" + assert log["SeverityText"] == Severity.DEBUG.name + assert log["Attributes"]["msg"] == "abc" + + +def test_warn(capsys): + """Test warn level""" + set_severity(Severity.WARN) + get_log().warn("abc") + stdout, _ = capsys.readouterr() + log = json.loads(stdout) + assert log["SeverityText"] == Severity.WARN.name + assert log["Attributes"]["msg"] == "abc" def test_trace_at_debug_level(capsys): """Test trace level outputs nothing when log set to debug""" - set_level(LogLevel.debug) - get_log().trace("abc") + set_severity(Severity.DEBUG) + get_log().trace("abc", "logStarted") stdout, _ = capsys.readouterr() assert stdout == "" def test_timestamp(capsys): """Test timestamp is actually a timestamp""" - set_level(LogLevel.trace) + set_severity(Severity.TRACE) - systime = int(os.popen("date +%s").read()) * 1000 - get_log().trace("abc") + systime = int(os.popen("date +%s").read()) * 10000000000 + get_log().trace("abc", "logStarted") stdout, _ = capsys.readouterr() log = json.loads(stdout) - assert log["time"] - systime < 1000 - + assert log["Timestamp"] - systime < 1000 -def test_contextvars(capsys): - set_contextvars({"ip": "192.168.0.2", "country": "NZ"}) - get_log().trace("abc") +def test_set_resources(capsys): + """Test setting resources""" + set_resources(OpenTelemetryResource(host_ip="192.168.0.2")) + get_log().trace("abc", "logStarted") stdout, _ = capsys.readouterr() log = json.loads(stdout) - assert log["ip"] == "192.168.0.2" - assert log["country"] == "NZ" + assert log["Resources"]["host.ip"] == "192.168.0.2" - remove_contextvars(["country"]) - get_log().trace("def") +def test_set_attributes(capsys): + """Test setting resources""" + set_attributes(OpenTelemetryAttributes(error_message="test error")) + get_log().debug("abc") stdout, _ = capsys.readouterr() log = json.loads(stdout) - assert not "country" in log + assert log["Attributes"]["error.message"] == "test error" diff --git a/poetry.lock b/poetry.lock index 5386c28..0c77e8d 100644 --- a/poetry.lock +++ b/poetry.lock @@ -77,6 +77,22 @@ category = "dev" optional = false python-versions = ">=2.7, !=3.0.*, !=3.1.*, !=3.2.*, !=3.3.*, !=3.4.*" +[[package]] +name = "dataclasses-json" +version = "0.5.7" +description = "Easily serialize dataclasses to and from JSON" +category = "dev" +optional = false +python-versions = ">=3.6" + +[package.dependencies] +marshmallow = ">=3.3.0,<4.0.0" +marshmallow-enum = ">=1.5.1,<2.0.0" +typing-inspect = ">=0.4.0" + +[package.extras] +dev = ["flake8", "hypothesis", "ipython", "mypy (>=0.710)", "portray", "pytest (>=6.2.3)", "simplejson", "types-dataclasses"] + [[package]] name = "dill" version = "0.3.5.1" @@ -118,6 +134,34 @@ category = "dev" optional = false python-versions = ">=3.6" +[[package]] +name = "marshmallow" +version = "3.18.0" +description = "A lightweight library for converting complex datatypes to and from native Python datatypes." +category = "dev" +optional = false +python-versions = ">=3.7" + +[package.dependencies] +packaging = ">=17.0" + +[package.extras] +dev = ["flake8 (==5.0.4)", "flake8-bugbear (==22.9.11)", "mypy (==0.971)", "pre-commit (>=2.4,<3.0)", "pytest", "pytz", "simplejson", "tox"] +docs = ["alabaster (==0.7.12)", "autodocsumm (==0.2.9)", "sphinx (==5.1.1)", "sphinx-issues (==3.0.1)", "sphinx-version-warning (==1.1.2)"] +lint = ["flake8 (==5.0.4)", "flake8-bugbear (==22.9.11)", "mypy (==0.971)", "pre-commit (>=2.4,<3.0)"] +tests = ["pytest", "pytz", "simplejson"] + +[[package]] +name = "marshmallow-enum" +version = "1.5.1" +description = "Enum field for Marshmallow" +category = "dev" +optional = false +python-versions = "*" + +[package.dependencies] +marshmallow = ">=2.0.0" + [[package]] name = "mccabe" version = "0.7.0" @@ -268,9 +312,9 @@ optional = false python-versions = ">=3.7" [package.extras] -dev = ["cogapp", "coverage", "freezegun (>=0.2.8)", "furo", "myst-parser", "pre-commit", "pretend", "pytest (>=6.0)", "pytest-asyncio (>=0.17)", "rich", "simplejson", "sphinx", "sphinx-notfound-page", "sphinxcontrib-mermaid", "tomli", "twisted"] +dev = ["cogapp", "coverage[toml]", "freezegun (>=0.2.8)", "furo", "myst-parser", "pre-commit", "pretend", "pytest (>=6.0)", "pytest-asyncio (>=0.17)", "rich", "simplejson", "sphinx", "sphinx-notfound-page", "sphinxcontrib-mermaid", "tomli", "twisted"] docs = ["furo", "myst-parser", "sphinx", "sphinx-notfound-page", "sphinxcontrib-mermaid", "twisted"] -tests = ["coverage", "freezegun (>=0.2.8)", "pretend", "pytest (>=6.0)", "pytest-asyncio (>=0.17)", "simplejson"] +tests = ["coverage[toml]", "freezegun (>=0.2.8)", "pretend", "pytest (>=6.0)", "pytest-asyncio (>=0.17)", "simplejson"] [[package]] name = "tomli" @@ -296,6 +340,18 @@ category = "dev" optional = false python-versions = ">=3.6" +[[package]] +name = "typing-inspect" +version = "0.8.0" +description = "Runtime inspection utilities for typing module." +category = "dev" +optional = false +python-versions = "*" + +[package.dependencies] +mypy-extensions = ">=0.3.0" +typing-extensions = ">=3.7.4" + [[package]] name = "wrapt" version = "1.14.1" @@ -307,7 +363,7 @@ python-versions = "!=3.0.*,!=3.1.*,!=3.2.*,!=3.3.*,!=3.4.*,>=2.7" [metadata] lock-version = "1.1" python-versions = "^3.8" -content-hash = "4719e5dd2a8c63cb01d59d28ec91ad967d336b08b5495650102304493e8f1bda" +content-hash = "30544366f3c82bebdca8f37359ef4f66ea804887086fb8eebf396734614c0b59" [metadata.files] astroid = [ @@ -354,6 +410,10 @@ colorama = [ {file = "colorama-0.4.5-py2.py3-none-any.whl", hash = "sha256:854bf444933e37f5824ae7bfc1e98d5bce2ebe4160d46b5edf346a89358e99da"}, {file = "colorama-0.4.5.tar.gz", hash = "sha256:e6c6b4334fc50988a639d9b98aa429a0b57da6e17b9a44f0451f930b6967b7a4"}, ] +dataclasses-json = [ + {file = "dataclasses-json-0.5.7.tar.gz", hash = "sha256:c2c11bc8214fbf709ffc369d11446ff6945254a7f09128154a7620613d8fda90"}, + {file = "dataclasses_json-0.5.7-py3-none-any.whl", hash = "sha256:bc285b5f892094c3a53d558858a88553dd6a61a11ab1a8128a0e554385dcc5dd"}, +] dill = [ {file = "dill-0.3.5.1-py2.py3-none-any.whl", hash = "sha256:33501d03270bbe410c72639b350e941882a8b0fd55357580fbc873fba0c59302"}, {file = "dill-0.3.5.1.tar.gz", hash = "sha256:d75e41f3eff1eee599d738e76ba8f4ad98ea229db8b085318aa2b3333a208c86"}, @@ -405,6 +465,14 @@ lazy-object-proxy = [ {file = "lazy_object_proxy-1.7.1-cp39-cp39-win_amd64.whl", hash = "sha256:677ea950bef409b47e51e733283544ac3d660b709cfce7b187f5ace137960d61"}, {file = "lazy_object_proxy-1.7.1-pp37.pp38-none-any.whl", hash = "sha256:d66906d5785da8e0be7360912e99c9188b70f52c422f9fc18223347235691a84"}, ] +marshmallow = [ + {file = "marshmallow-3.18.0-py3-none-any.whl", hash = "sha256:35e02a3a06899c9119b785c12a22f4cda361745d66a71ab691fd7610202ae104"}, + {file = "marshmallow-3.18.0.tar.gz", hash = "sha256:6804c16114f7fce1f5b4dadc31f4674af23317fcc7f075da21e35c1a35d781f7"}, +] +marshmallow-enum = [ + {file = "marshmallow-enum-1.5.1.tar.gz", hash = "sha256:38e697e11f45a8e64b4a1e664000897c659b60aa57bfa18d44e226a9920b6e58"}, + {file = "marshmallow_enum-1.5.1-py2.py3-none-any.whl", hash = "sha256:57161ab3dbfde4f57adeb12090f39592e992b9c86d206d02f6bd03ebec60f072"}, +] mccabe = [ {file = "mccabe-0.7.0-py2.py3-none-any.whl", hash = "sha256:6c2d30ab6be0e4a46919781807b4f0d834ebdd6c6e3dca0bda5a15f863427b6e"}, {file = "mccabe-0.7.0.tar.gz", hash = "sha256:348e0240c33b60bbdf4e523192ef919f28cb2c3d7d5c7794f74009290f236325"}, @@ -468,6 +536,10 @@ typing-extensions = [ {file = "typing_extensions-4.0.1-py3-none-any.whl", hash = "sha256:7f001e5ac290a0c0401508864c7ec868be4e701886d5b573a9528ed3973d9d3b"}, {file = "typing_extensions-4.0.1.tar.gz", hash = "sha256:4ca091dea149f945ec56afb48dae714f21e8692ef22a395223bcd328961b6a0e"}, ] +typing-inspect = [ + {file = "typing_inspect-0.8.0-py3-none-any.whl", hash = "sha256:5fbf9c1e65d4fa01e701fe12a5bca6c6e08a4ffd5bc60bfac028253a447c5188"}, + {file = "typing_inspect-0.8.0.tar.gz", hash = "sha256:8b1ff0c400943b6145df8119c41c244ca8207f1f10c9c057aeed1560e4806e3d"}, +] wrapt = [ {file = "wrapt-1.14.1-cp27-cp27m-macosx_10_9_x86_64.whl", hash = "sha256:1b376b3f4896e7930f1f772ac4b064ac12598d1c38d04907e696cc4d794b43d3"}, {file = "wrapt-1.14.1-cp27-cp27m-manylinux1_i686.whl", hash = "sha256:903500616422a40a98a5a3c4ff4ed9d0066f3b4c951fa286018ecdf0750194ef"}, diff --git a/pyproject.toml b/pyproject.toml index fa6df9e..4ade795 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -15,6 +15,7 @@ keywords = ["LINZ", "logging"] python = "^3.8" structlog = "^22.1.0" python-ulid = "^1.1.0" +dataclasses-json = "^0.5.7" [tool.poetry.dev-dependencies] black = "^22.6.0" @@ -23,6 +24,8 @@ pylint = "^2.15.0" pytest = "^7.1.2" pytest-dependency = "^0.5.1" + + [build-system] requires = ["poetry-core>=1.0.0"] build-backend = "poetry.core.masonry.api"