Adds option for outputting a JSON log (#42)

* adding option for json logger

* adding packge dep

* updating readme

* linting

* updating docstring

* more cleanup

* linting

README.md

@@ -53,9 +53,12 @@ log = get_logger(NAME)
 
 You can get a logger using the `rich` `RichHandler` by passing `use_rich_handler=True`.
 
-The file logger is disabled by default and can be started by calling `log.start_file_logger(path)`. By default a `TimedRotatingFileHandler` is created. If you want a normal `FileHandler` use `rotate=False`. The file mode defaults to `mode='a'` (append).
+The file logger is disabled by default and can be started by calling `log.start_file_logger(path)`. By default a `TimedRotatingFileHandler` is created. If you want a normal `FileHandler` use `rotating=False`. The file mode defaults to `mode='a'` (append).  The `TimedRotatingFileHandler` options `when`, `utc`, and `at_time` are available to
+`log.start_file_logger` for controlling aspects of the rollover time.
 
-The `SDSSLoger` instance also include an `asyncio_exception_handler` method that can be added to the asyncio event loop to handle exceptions; for example `loop.set_exception_handler(log.asyncio_exception_handler)`.
+By default, the file logger is formatted to output a human-readble `log` file.  To output a JSON log instead, set `as_json=True`, when calling `log.start_file_logger`.  This will create a `.json` log file which can machine-read and more easily parsed for content.  To output both a human-readable (`.log`) and JSON log (`.json`), set `with_json=True`.
+
+The `SDSSLogger` instance also include an `asyncio_exception_handler` method that can be added to the asyncio event loop to handle exceptions; for example `loop.set_exception_handler(log.asyncio_exception_handler)`.
 
 Console logging uses the standard `StreamHandler`. It's possible to use the `rich` library [RichHandler](https://rich.readthedocs.io/en/stable/logging.html) instead by
 passing `use_rich_handler=True` to `get_logger()`. Additional keyword arguments to `RichHandler` can be passed as a `rich_handler_kwargs` dictionary. In the future the `rich` handler may become the default console logger.

pyproject.toml

@@ -26,6 +26,7 @@ packaging = ">=20.4"
 daemonocle = "^1.0.2"
 typing-extensions = "^4.6.3"
 rich = "^13.4.2"
+python-json-logger = "^2.0.7"
 
 [tool.poetry.group.dev.dependencies]
 ipython = [{version = ">=8.14.0", python = ">=3.9"},

src/sdsstools/logger.py

@@ -10,6 +10,7 @@
 import datetime
 import logging
 import os
+import pathlib
 import re
 import shutil
 import sys
@@ -22,6 +23,7 @@
 from pygments import highlight
 from pygments.formatters import TerminalFormatter
 from pygments.lexers import get_lexer_by_name
+from pythonjsonlogger import jsonlogger
 from rich.console import Console
 from rich.logging import RichHandler
 from rich.text import Text
@@ -143,6 +145,27 @@ def format(self, record):
         return logging.Formatter.format(self, record_cp)
 
 
+class CustomJsonFormatter(jsonlogger.JsonFormatter):
+    """Custom `jsonlogger.JsonFormatter` for the JSON file handler"""
+
+    def add_fields(self, log_record, record, message_dict):
+        """Add custom fields to the JSON body"""
+        super().add_fields(log_record, record, message_dict)
+        if not log_record.get("timestamp"):
+            now = datetime.datetime.fromtimestamp(record.created).strftime(
+                "%Y-%m-%dT%H:%M:%S.%fZ"
+            )  # noqa: E501
+            log_record["timestamp"] = now
+        log_record["type"] = "log"
+        log_record["level"] = record.levelname
+        log_record.update(record.__dict__)
+        if record.exc_info:
+            log_record["error"] = {
+                "type": record.exc_info[0].__name__,
+                "trace": message_dict["exc_info"],
+            }
+
+
 class CustomRichHandler(RichHandler):
     """A slightly custom ``RichHandler`` logging handler."""
 
@@ -257,10 +280,13 @@ def init(
         self.addHandler(self.sh)
         self.sh.setLevel(log_level)
 
-        # Placeholders for the file handler.
+        # Placeholders for the file handlers.
         self.fh: Union[logging.FileHandler, None] = None
         self.log_filename: Union[str, None] = None
 
+        self.jh: Union[logging.FileHandler, None] = None
+        self.json_log_filename: Union[str, None] = None
+
         # A header that precedes every message.
         self.header = ""
 
@@ -311,6 +337,28 @@ def asyncio_exception_handler(self, loop, context):
     def save_log(self, path: str):
         assert self.log_filename, "File logger not running."
         shutil.copyfile(self.log_filename, os.path.expanduser(path))
+        if self.json_log_filename:
+            assert self.json_log_filename, "JSON file logger not running."
+            shutil.copyfile(self.json_log_filename, os.path.expanduser(path))
+
+    def _set_file_handler(
+        self,
+        filepath: str,
+        suffix: str,
+        rotating: bool = True,
+        mode: str = "a",
+        when: str = "midnight",
+        utc: bool = True,
+        at_time: Union[str, datetime.time] = None,
+    ):
+        if rotating:
+            fh = TimedRotatingFileHandler(
+                str(filepath), when=when, utc=utc, atTime=at_time
+            )
+            fh.suffix = suffix  # type: ignore
+        else:
+            fh = logging.FileHandler(str(filepath), mode=mode)
+        return fh
 
     def start_file_logger(
         self,
@@ -322,6 +370,8 @@ def start_file_logger(
         when: str = "midnight",
         utc: bool = True,
         at_time: Union[str, datetime.time] = None,
+        as_json: bool = False,
+        with_json: bool = False,
     ):
         """Start file logging.
 
@@ -347,13 +397,24 @@ def start_file_logger(
         at_time
             The time of day when rollover occurs, when rollover is set to occur
             at “midnight” or “on a particular weekday”.
+        as_json
+            If `True`, outputs a JSON log instead of a human log
+        with_json
+            If `True`, outputs both a JSON log and a human log
         """
 
         log_file_path = os.path.realpath(os.path.expanduser(path))
         logdir = os.path.dirname(log_file_path)
 
         SUFFIX = "%Y-%m-%d_%H:%M:%S"
 
+        # set the JSON file path name
+        suffix = pathlib.Path(log_file_path).suffix
+        if as_json and suffix != ".json":
+            log_file_path = log_file_path.replace(suffix, ".json")
+        elif with_json:
+            json_log_file_path = log_file_path.replace(suffix, ".json")
+
         try:
             if not os.path.exists(logdir):
                 os.makedirs(logdir)
@@ -367,13 +428,27 @@ def start_file_logger(
             if at_time and isinstance(at_time, str):
                 at_time = datetime.time.fromisoformat(at_time)
 
-            if rotating:
-                self.fh = TimedRotatingFileHandler(
-                    str(log_file_path), when=when, utc=utc, atTime=at_time
+            # get the file handler
+            self.fh = self._set_file_handler(
+                log_file_path,
+                SUFFIX,
+                mode=mode,
+                rotating=rotating,
+                when=when,
+                utc=utc,
+                at_time=at_time,
+            )
+
+            if with_json:
+                self.jh = self._set_file_handler(
+                    json_log_file_path,
+                    SUFFIX,
+                    mode=mode,
+                    rotating=rotating,
+                    when=when,
+                    utc=utc,
+                    at_time=at_time,
                 )
-                self.fh.suffix = SUFFIX  # type: ignore
-            else:
-                self.fh = logging.FileHandler(str(log_file_path), mode=mode)
 
         except (IOError, OSError, ValueError) as ee:
             warnings.warn(
@@ -383,7 +458,9 @@ def start_file_logger(
             )
 
         else:
-            self.fh.setFormatter(FileFormatter())
+            # set the correct file or json formatter
+            formatter = CustomJsonFormatter() if as_json else FileFormatter()
+            self.fh.setFormatter(formatter)
             self.addHandler(self.fh)
             self.fh.setLevel(log_level)
 
@@ -392,6 +469,15 @@ def start_file_logger(
 
             self.log_filename = log_file_path
 
+            # set json file handler and formatter
+            if with_json and self.jh:
+                self.jh.setFormatter(CustomJsonFormatter())
+                self.addHandler(self.jh)
+                self.jh.setLevel(log_level)
+                self.json_log_filename = json_log_file_path
+                if self.warnings_logger:
+                    self.warnings_logger.addHandler(self.jh)
+
     def handle(self, record):
         """Handles a record but first stores it."""
 

test/test_logger.py

@@ -7,6 +7,7 @@
 # @License: BSD 3-clause (http://www.opensource.org/licenses/BSD-3-Clause)
 
 import asyncio
+import json
 import logging
 import logging.handlers
 import os
@@ -217,3 +218,34 @@ def test_catch_exception_rich_logger(tmp_path, mocker):
 
     logger.handle_exceptions(excinfo.type, excinfo.value, excinfo.tb)
     emit_mock.assert_called()
+
+
+def test_as_json_logger(tmp_path):
+    log_file = tmp_path / "logs" / "test_log.log"
+
+    logger1 = get_logger(str(uuid.uuid4()))
+    logger1.start_file_logger(log_file, as_json=True)
+    logger1.info("test message")
+
+    files = list((tmp_path / "logs").glob("*"))
+    assert len(files) == 1
+    assert files[0].name.endswith(".json")
+    assert not files[0].name.endswith(".log")
+
+    with open(str(log_file).replace(".log", ".json")) as f:
+        data = [json.loads(i) for i in f.readlines()]
+        assert len(data) == 1
+        assert data[0]["message"] == "test message"
+
+
+def test_with_json_logger(tmp_path):
+    log_file = tmp_path / "logs" / "test_log.log"
+
+    logger1 = get_logger(str(uuid.uuid4()))
+    logger1.start_file_logger(log_file, with_json=True)
+    logger1.info("test message")
+
+    files = list(sorted((tmp_path / "logs").glob("*")))
+    assert len(files) == 2
+    assert files[0].name.endswith(".json")
+    assert files[1].name.endswith(".log")