initial commitv0.0.1

9 files changed, 661 insertions, 0 deletions

diff --git a/.gitignore b/.gitignore
new file mode 100644
index 0000000..64a852a
--- /dev/null
+++ b/.gitignore
@@ -0,0 +1,11 @@
+*.pyc
+*.egg-info/
+
+# created by `pip install . --config-settings editable_mode=compat`
+build/
+
+# created by `python3 -m build`
+dist/
+
+# created by `nix-build`
+result
diff --git a/LICENSE b/LICENSE
new file mode 100644
index 0000000..b37cec7
--- /dev/null
+++ b/LICENSE
@@ -0,0 +1,19 @@
+Copyright (c) 2025 Martin Fischer
+
+Permission is hereby granted, free of charge, to any person obtaining a copy
+of this software and associated documentation files (the "Software"), to deal
+in the Software without restriction, including without limitation the rights
+to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+copies of the Software, and to permit persons to whom the Software is
+furnished to do so, subject to the following conditions:
+
+The above copyright notice and this permission notice shall be included in all
+copies or substantial portions of the Software.
+
+THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
+SOFTWARE.
diff --git a/README.md b/README.md
new file mode 100644
index 0000000..78bbda9
--- /dev/null
+++ b/README.md
@@ -0,0 +1,57 @@
+# logformat - logfmt logging for Python
+
+* implements the same value escaping as the [logfmt library] used by Grafana Loki
+* implements a `logging.Formatter` so it works with any library using the standard library logging
+* implements a convenience wrapper around `logging.Logging` for specifying structured fields via `kwargs`
+
+```python
+import logging
+
+import logformat
+
+logfmt_handler = logging.StreamHandler()
+logfmt_handler.setFormatter(logformat.LogfmtFormatter())
+logging.basicConfig(handlers=[logfmt_handler], level=logging.INFO)
+
+logger = logformat.get_logger()
+
+logger.warning("this seems off", some_id=33)
+```
+
+Will output a line like:
+
+```
+time=2025-03-23T06:21:36Z level=warning msg="this seems off" some_id=33
+```
+
+`exc_info` and `stack_info` are supported via `backtrace=True` and `stack=True`
+(which will add same-named fields).
+
+In the main method of a script you should always catch any exception and log
+them as errors, so that unexpected errors show up properly in your log file.
+This library makes this easy by providing a `log_uncaught` decorator:
+
+```python
+logger = logformat.get_logger()
+
+@logger.log_uncaught
+def run():
+    # your script
+    ...
+```
+
+This library intentionally doesn't provide any pretty terminal output but the
+produced logs can be viewed with the [logfmt CLI] (since that tool again uses
+the [logfmt library] that this library is compatible with).
+
+## Alternatives
+
+* structlog's `get_logger` returns `Any`.
+  While there's a typed alternative that's a bit of a footgun.
+
+* logfmter doesn't include the time by default, names the time field `when` by default
+  and the level field `at` by default, doesn't use ISO dates by default
+  and isn't compatible with the Go [logfmt library] as of March 2025
+
+[logfmt library]: https://github.com/go-logfmt/logfmt
+[logfmt CLI]: https://github.com/TheEdgeOfRage/logfmt
diff --git a/default.nix b/default.nix
new file mode 100644
index 0000000..07331d7
--- /dev/null
+++ b/default.nix
@@ -0,0 +1,19 @@
+{ pkgs ? import <nixpkgs> {} }:
+with pkgs.python313Packages;
+
+buildPythonPackage rec {
+  pname = "logformat";
+  version = "git";
+  src = ./.;
+  pyproject = true;
+
+  build-system = [
+    setuptools
+  ];
+
+  disabled = pythonOlder "3.13";
+
+  installCheckPhase = ''
+    python ${./test_logformat.py}
+  '';
+}
diff --git a/example.py b/example.py
new file mode 100755
index 0000000..0892117
--- /dev/null
+++ b/example.py
@@ -0,0 +1,26 @@
+#!/usr/bin/env python3
+import json
+import logging
+
+import logformat
+import requests
+
+
+logfmt_handler = logging.StreamHandler()
+logfmt_handler.setFormatter(logformat.LogfmtFormatter())
+logging.basicConfig(handlers=[logfmt_handler], level=logging.DEBUG)
+
+
+logger = logformat.get_logger()
+
+requests.get('http://example.com')
+
+logger.debug("what's happening")
+logger.info("something's happening")
+logger.warning("this seems off", some_id=33)
+logger.error("oh no")
+
+try:
+    json.loads("maybe")
+except:
+    logger.error("failed to decode", traceback=True)
diff --git a/logformat/__init__.py b/logformat/__init__.py
new file mode 100644
index 0000000..4af5c46
--- /dev/null
+++ b/logformat/__init__.py
@@ -0,0 +1,282 @@
+import asyncio
+import base64
+import datetime
+import functools
+import json
+import logging
+import time
+from typing import Callable, Never, cast
+
+
+class LogfmtFormatter(logging.Formatter):
+    converter = time.gmtime
+
+    def __init__(self, process_id=False, process_name=False, thread_id=False, thread_name=False):
+        """Initializes a logfmt formatter."""
+        self._process_id = process_id
+        self._process_name = process_name
+        self._thread_id = thread_id
+        self._thread_name = thread_name
+
+    def format(self, record):
+        fields: dict = {
+            "time": self.formatTime(record, "%Y-%m-%dT%H:%M:%SZ"),
+            "level": record.levelname.lower(),
+        }
+
+        if record.name != "root":
+            # omitting logger=root for readability
+            fields['logger'] = record.name
+
+        fields['msg'] = record.getMessage()
+
+        for k, v in record.__dict__.items():
+            # using getattr because of https://github.com/python/typeshed/issues/12136
+            if k in getattr(logging.LogRecord, "__static_attributes__"):
+                continue
+            if k in ('time', 'msg'):
+                continue
+
+            # This mirrors the logic of https://github.com/go-logfmt/logfmt/blob/main/encode.go.
+            k = ''.join(c for c in k if c > ' ' and c not in '="')
+            if k == '':
+                continue
+
+            fields[k] = v
+
+        if self._process_id:
+            fields['process_id'] = record.process
+        if self._process_name:
+            fields['process_name'] = record.processName
+        if self._thread_id:
+            fields['thread_id'] = record.thread
+        if self._thread_name:
+            fields['thread_name'] = record.threadName
+        if record.taskName:
+            fields['task'] = record.taskName
+        if record.exc_info:
+            fields['traceback'] = self.formatException(record.exc_info)
+        if record.stack_info:
+            fields['stack'] = self.formatStack(record.stack_info)
+
+        return ' '.join(f'{k}={_fmt_value(v)}' for k, v in fields.items())
+
+
+def get_logger(name: str | None = None):
+    return _Logger(logging.getLogger(name))
+
+
+def _fmt_value(obj):
+    if obj is None:
+        value = "null"
+    elif isinstance(obj, bool):
+        value = str(obj).lower()
+    elif isinstance(obj, bytes):
+        value = base64.b64encode(obj).decode()
+    elif isinstance(obj, datetime.datetime):
+        value = obj.isoformat().replace('+00:00', 'Z')
+    else:
+        value = str(obj)
+
+    # This mirrors the logic of https://github.com/go-logfmt/logfmt/blob/main/encode.go.
+    if any(c <= ' ' or c in '="' for c in value):
+        return json.dumps(value, ensure_ascii=False)
+    else:
+        return value
+
+
+_never: Never = cast(Never, None)
+
+
+class _Logger:
+    def __init__(self, logger: logging.Logger):
+        self._logger = logger
+
+    def debug(
+        self,
+        msg: str,
+        traceback=False,
+        stack=False,
+        time=_never,
+        level=_never,
+        process_id=_never,
+        process_name=_never,
+        thread_id=_never,
+        thread_name=_never,
+        task=_never,
+        # Logger.makeRecord raises if any of logging.LogRecord.__static_attributes__ are in extra.
+        args=_never,
+        created=_never,
+        exc_info=_never,
+        exc_text=_never,
+        filename=_never,
+        funcName=_never,
+        levelname=_never,
+        levelno=_never,
+        module=_never,
+        msecs=_never,
+        name=_never,
+        pathname=_never,
+        process=_never,
+        processName=_never,
+        relativeCreated=_never,
+        stack_info=_never,
+        taskName=_never,
+        thread=_never,
+        threadName=_never,
+        **kwargs,
+    ):
+        self._logger.debug(msg, exc_info=traceback, stack_info=stack, extra=kwargs)
+
+    def info(
+        self,
+        msg: str,
+        traceback=False,
+        stack=False,
+        time=_never,
+        level=_never,
+        process_id=_never,
+        process_name=_never,
+        thread_id=_never,
+        thread_name=_never,
+        task=_never,
+        # Logger.makeRecord raises if any of logging.LogRecord.__static_attributes__ are in extra.
+        args=_never,
+        created=_never,
+        exc_info=_never,
+        exc_text=_never,
+        filename=_never,
+        funcName=_never,
+        levelname=_never,
+        levelno=_never,
+        module=_never,
+        msecs=_never,
+        name=_never,
+        pathname=_never,
+        process=_never,
+        processName=_never,
+        relativeCreated=_never,
+        stack_info=_never,
+        taskName=_never,
+        thread=_never,
+        threadName=_never,
+        **kwargs,
+    ):
+        self._logger.info(msg, exc_info=traceback, stack_info=stack, extra=kwargs)
+
+    def warning(
+        self,
+        msg: str,
+        traceback=False,
+        stack=False,
+        time=_never,
+        level=_never,
+        process_id=_never,
+        process_name=_never,
+        thread_id=_never,
+        thread_name=_never,
+        task=_never,
+        # Logger.makeRecord raises if any of logging.LogRecord.__static_attributes__ are in extra.
+        args=_never,
+        created=_never,
+        exc_info=_never,
+        exc_text=_never,
+        filename=_never,
+        funcName=_never,
+        levelname=_never,
+        levelno=_never,
+        module=_never,
+        msecs=_never,
+        name=_never,
+        pathname=_never,
+        process=_never,
+        processName=_never,
+        relativeCreated=_never,
+        stack_info=_never,
+        taskName=_never,
+        thread=_never,
+        threadName=_never,
+        **kwargs,
+    ):
+        self._logger.warning(msg, exc_info=traceback, stack_info=stack, extra=kwargs)
+
+    def error(
+        self,
+        msg: str,
+        traceback=False,
+        stack=False,
+        time=_never,
+        level=_never,
+        process_id=_never,
+        process_name=_never,
+        thread_id=_never,
+        thread_name=_never,
+        task=_never,
+        # Logger.makeRecord raises if any of logging.LogRecord.__static_attributes__ are in extra.
+        args=_never,
+        created=_never,
+        exc_info=_never,
+        exc_text=_never,
+        filename=_never,
+        funcName=_never,
+        levelname=_never,
+        levelno=_never,
+        module=_never,
+        msecs=_never,
+        name=_never,
+        pathname=_never,
+        process=_never,
+        processName=_never,
+        relativeCreated=_never,
+        stack_info=_never,
+        taskName=_never,
+        thread=_never,
+        threadName=_never,
+        **kwargs,
+    ):
+        self._logger.error(msg, exc_info=traceback, stack_info=stack, extra=kwargs)
+
+    # intentionally omitting critical ... just use errors
+
+    def log_uncaught(self, f: Callable):
+        """
+        Wraps the given function to log an uncaught exception as an error with a traceback and raise SystemExit(1).
+
+        Meant to be used as a decorator on the main function.
+        """
+
+        @functools.wraps(f)
+        def sync_wrapper(*args, **kwargs):
+            try:
+                return f(*args, **kwargs)
+            except Exception as exc:
+                exc_str = self._stringify_exception(exc)
+                self.error(f"unexpected exception: {exc_str}", traceback=True)
+                raise SystemExit(1)
+
+        @functools.wraps(f)
+        async def async_wrapper(*args, **kwargs):
+            try:
+                return await f(*args, **kwargs)
+            except Exception as exc:
+                exc_str = self._stringify_exception(exc)
+                self.error(f"unexpected exception: {exc_str}", traceback=True)
+                raise SystemExit(1)
+
+        if asyncio.iscoroutinefunction(f):
+            return async_wrapper
+        else:
+            return sync_wrapper
+
+    def _stringify_exception(self, exc: Exception):
+        try:
+            return str(exc)
+        except Exception:
+            self.warning("while logging unexpected exception str(exc) raised", traceback=True)
+
+        try:
+            return repr(exc)
+        except Exception:
+            self.warning("while logging unexpected exception repr(exc) raised", traceback=True)
+
+        return '??? (str and repr failed)'
diff --git a/logformat/py.typed b/logformat/py.typed
new file mode 100644
index 0000000..e69de29
--- /dev/null
+++ b/logformat/py.typed
diff --git a/pyproject.toml b/pyproject.toml
new file mode 100644
index 0000000..7640b73
--- /dev/null
+++ b/pyproject.toml
@@ -0,0 +1,25 @@
+[project]
+name = "logformat"
+version = "0.0.1"
+authors = [
+  { name="Martin Fischer", email="martin@push-f.com" },
+]
+description = "logfmt logging for Python"
+requires-python = ">=3.13" # because of __static_attributes__
+
+readme = "README.md"
+classifiers = [
+  "Programming Language :: Python :: 3",
+  "Operating System :: OS Independent",
+]
+license = "MIT"
+license-files = ["LICENSE"]
+
+[project.urls]
+repository = "https://git.push-f.com/logformat"
+
+[tool.setuptools]
+packages = ["logformat"]
+
+[tool.black]
+line-length = 100
diff --git a/test_logformat.py b/test_logformat.py
new file mode 100755
index 0000000..cbcc14d
--- /dev/null
+++ b/test_logformat.py
@@ -0,0 +1,222 @@
+#!/usr/bin/env python3
+import asyncio
+import contextlib
+import datetime
+import functools
+import io
+import logging
+import textwrap
+import unittest
+import unittest.mock
+
+import logformat
+
+
+def set_up(level=logging.DEBUG):
+    stream = io.StringIO()
+    logfmt_handler = logging.StreamHandler(stream)
+    logfmt_handler.setFormatter(logformat.LogfmtFormatter())
+    logging.basicConfig(handlers=[logfmt_handler], level=level, force=True)
+    return stream
+
+
+# We're not using pytest here because pytest messes with the logging config,
+# setting it's own handlers, apparently even when disabling the pytest logging
+# plugin with `-p no:logging`.
+test_suite = unittest.TestSuite()
+
+
+def test(test):
+    @functools.wraps(test)
+    def wrapped_test():
+        t = unittest.TestCase()
+        with unittest.mock.patch("time.time_ns", return_value=1742634901036965331):
+            test(t)
+
+    test_suite.addTest(unittest.FunctionTestCase(wrapped_test))
+
+
+@test
+def test_logformat(t: unittest.TestCase):
+    stream = set_up()
+    logger = logformat.get_logger()
+    logger.debug("what's happening")
+    logger.info("something's happening")
+    logger.warning("this seems off")
+    logger.error("oh no")
+    t.assertEqual(
+        stream.getvalue(),
+        textwrap.dedent(
+            '''
+            time=2025-03-22T09:15:01Z level=debug msg="what's happening"
+            time=2025-03-22T09:15:01Z level=info msg="something's happening"
+            time=2025-03-22T09:15:01Z level=warning msg="this seems off"
+            time=2025-03-22T09:15:01Z level=error msg="oh no"
+            '''
+        ).lstrip(),
+    )
+
+
+@test
+def test_escaping(t: unittest.TestCase):
+    stream = set_up()
+    logger = logformat.get_logger()
+    logger.warning(" \t\n\x00='\"‽")
+    t.assertEqual(
+        stream.getvalue(),
+        'time=2025-03-22T09:15:01Z level=warning msg=" \\t\\n\\u0000=\'\\"‽"\n',
+    )
+
+
+@test
+def test_fmtlogger_extra_uses_str(t: unittest.TestCase):
+    class Foo:
+        def __str__(self):
+            return "hello!"
+
+    stream = set_up()
+    logger = logformat.get_logger()
+    logger.warning("test", value=Foo())
+    t.assertEqual(
+        stream.getvalue(),
+        'time=2025-03-22T09:15:01Z level=warning msg=test value=hello!\n',
+    )
+
+
+@test
+def test_fmtlogger_extra_none(t: unittest.TestCase):
+    stream = set_up()
+    logger = logformat.get_logger()
+    logger.warning("test", helpful_info=None)
+    t.assertEqual(
+        stream.getvalue(),
+        'time=2025-03-22T09:15:01Z level=warning msg=test helpful_info=null\n',
+    )
+
+
+@test
+def test_fmtlogger_extra_bool(t: unittest.TestCase):
+    stream = set_up()
+    logger = logformat.get_logger()
+    logger.warning("test", off_by_one=True)
+    t.assertEqual(
+        stream.getvalue(),
+        'time=2025-03-22T09:15:01Z level=warning msg=test off_by_one=true\n',
+    )
+
+
+@test
+def test_fmtlogger_extra_datetime(t: unittest.TestCase):
+    stream = set_up()
+    logger = logformat.get_logger()
+    logger.warning(
+        "test",
+        expiry=datetime.datetime(2025, 3, 22, 15, 30, 00, 00, tzinfo=datetime.UTC),
+    )
+    t.assertEqual(
+        stream.getvalue(),
+        'time=2025-03-22T09:15:01Z level=warning msg=test expiry=2025-03-22T15:30:00Z\n',
+    )
+
+
+@test
+def test_stdlib_logger(t: unittest.TestCase):
+    stream = set_up()
+    logger = logging.getLogger()
+    logger.debug("what's happening %s", 1234)
+    logger.info("something's happening")
+    logger.warning("this seems off")
+    logger.error("oh no")
+    logger.critical("aaaaaaaaah!")
+    t.assertEqual(
+        stream.getvalue(),
+        textwrap.dedent(
+            '''
+            time=2025-03-22T09:15:01Z level=debug msg="what's happening 1234"
+            time=2025-03-22T09:15:01Z level=info msg="something's happening"
+            time=2025-03-22T09:15:01Z level=warning msg="this seems off"
+            time=2025-03-22T09:15:01Z level=error msg="oh no"
+            time=2025-03-22T09:15:01Z level=critical msg=aaaaaaaaah!
+            '''
+        ).lstrip(),
+    )
+
+
+@test
+def test_log_uncaught_sync_returns(t: unittest.TestCase):
+    stream = set_up()
+
+    logger = logformat.get_logger()
+
+    @logger.log_uncaught
+    def run():
+        return 42
+
+    t.assertEqual(run(), 42)
+    t.assertEqual(stream.getvalue(), "")
+
+
+@test
+def test_log_uncaught_sync_raises(t: unittest.TestCase):
+    stream = set_up()
+
+    logger = logformat.get_logger()
+
+    @logger.log_uncaught
+    def run():
+        5 / 0
+
+    with t.assertRaises(SystemExit), stub_traceback():
+        run()
+
+    t.assertEqual(
+        stream.getvalue(),
+        'time=2025-03-22T09:15:01Z level=error msg="unexpected exception: division by zero" traceback="stub traceback"\n',
+    )
+
+
+@test
+def test_log_uncaught_async_returns(t: unittest.TestCase):
+    stream = set_up(level=logging.INFO)
+
+    logger = logformat.get_logger()
+
+    @logger.log_uncaught
+    async def run():
+        return 42
+
+    t.assertEqual(asyncio.run(run()), 42)
+    t.assertEqual(stream.getvalue(), "")
+
+
+@test
+def test_log_uncaught_async_raises(t: unittest.TestCase):
+    stream = set_up(level=logging.INFO)
+
+    logger = logformat.get_logger()
+
+    @logger.log_uncaught
+    async def run():
+        5 / 0
+
+    with t.assertRaises(SystemExit), stub_traceback():
+        asyncio.run(run())
+
+    t.assertEqual(
+        stream.getvalue(),
+        'time=2025-03-22T09:15:01Z level=error msg="unexpected exception: division by zero" task=Task-4 traceback="stub traceback"\n',
+    )
+
+
+@contextlib.contextmanager
+def stub_traceback():
+    def stub_print_exception(*args, **kwargs):
+        kwargs['file'].write('stub traceback')
+
+    with unittest.mock.patch("traceback.print_exception", stub_print_exception):
+        yield
+
+
+if __name__ == "__main__":
+    runner = unittest.TextTestRunner()
+    runner.run(test_suite)