feat: align log format to Open Telemetry Log Data Model

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"
+    }
+  }
 }
 ```
 

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

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)

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)

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="")

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"