Support outputting structured logs in addition to standard logs

synapse/config/logger.py

@@ -32,6 +32,7 @@
 import synapse
 from synapse.app import _base as appbase
 from synapse.logging.context import LoggingContextFilter
+from synapse.logging.filter import MetadataFilter
 from synapse.util.versionstring import get_version_string
 
 from ._base import Config, ConfigError
@@ -199,12 +200,14 @@ def _setup_stdlib_logging(config, log_config, logBeginner: LogBeginner) -> None:
     # filter options, but care must when using e.g. MemoryHandler to buffer
     # writes.
 
-    log_filter = LoggingContextFilter(request="")
+    log_context_filter = LoggingContextFilter(request="")
+    log_metadata_filter = MetadataFilter({"server_name": config.server_name})
     old_factory = logging.getLogRecordFactory()
 
     def factory(*args, **kwargs):
         record = old_factory(*args, **kwargs)
-        log_filter.filter(record)
+        log_context_filter.filter(record)
+        log_metadata_filter.filter(record)
         return record
 
     logging.setLogRecordFactory(factory)

synapse/logging/_terse_json.py

@@ -18,32 +18,49 @@
 """
 import json
 import logging
-from typing import Optional
 
 _encoder = json.JSONEncoder(ensure_ascii=False, separators=(",", ":"))
 
+# The properties of a standard LogRecord.
+_LOG_RECORD_ATTRIBUTES = {
+    "args",
+    "asctime",
+    "created",
+    "exc_info",
+    # exc_text isn't a public attribute, but is used to cache the result of formatException.
+    "exc_text",
+    "filename",
+    "funcName",
+    "levelname",
+    "levelno",
+    "lineno",
+    "message",
+    "module",
+    "msecs",
+    "msg",
+    "name",
+    "pathname",
+    "process",
+    "processName",
+    "relativeCreated",
+    "stack_info",
+    "thread",
+    "threadName",
+}
 
-class TerseJsonFormatter:
-    def __init__(
-        self, *args, include_time: bool = True, metadata: Optional[dict] = None
-    ):
-        self.include_time = include_time
-        self.metadata = metadata or {}
 
+class TerseJsonFormatter(logging.Formatter):
     def format(self, record: logging.LogRecord) -> str:
         event = {
             "log": record.getMessage(),
             "namespace": record.name,
             "level": record.levelname,
+            "time": round(record.created, 2),
         }
 
-        # We want to include the timestamp when forwarding over the network, but
-        # exclude it when we are writing to stdout. This is because the log ingester
-        # (e.g. logstash, fluentd) can add its own timestamp.
-        if self.include_time:
-            event["time"] = round(record.created, 2)
-
-        # Add the metadata information to the event (e.g. the server_name).
-        event.update(self.metadata)
+        # Add any extra attributes to the event.
+        extra_attributes = set(record.__dict__.keys()) - _LOG_RECORD_ATTRIBUTES
+        for key in extra_attributes:
+            event[key] = getattr(record, key)
 
         return _encoder.encode(event)

synapse/logging/filter.py

@@ -0,0 +1,33 @@
+# -*- coding: utf-8 -*-
+# Copyright 2020 The Matrix.org Foundation C.I.C.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+import logging
+
+from typing_extensions import Literal
+
+
+class MetadataFilter(logging.Filter):
+    """Logging filter that adds constant values to each record.
+
+    Args:
+        metadata: Key-value pairs to add to each record.
+    """
+
+    def __init__(self, metadata: dict):
+        self._metadata = metadata
+
+    def filter(self, record: logging.LogRecord) -> Literal[True]:
+        for key, value in self._metadata.items():
+            setattr(record, key, value)
+        return True

tests/logging/test_terse_json.py

@@ -31,7 +31,7 @@ def test_log_output(self):
         output = StringIO()
 
         handler = logging.StreamHandler(output)
-        handler.setFormatter(TerseJsonFormatter(metadata={"server_name": "foo"}))
+        handler.setFormatter(TerseJsonFormatter())
 
         logger = logging.getLogger()
         logger.addHandler(handler)
@@ -51,7 +51,8 @@ def test_log_output(self):
             "time",
             "level",
             "namespace",
-            "server_name",
+            # Added via LoggingContextFilter, configured in tests.test_utils.logging_setup.setup_logging.
+            "request",
         ]
         self.assertCountEqual(log.keys(), expected_log_keys)
         self.assertEqual(log["log"], "Hello there, wally!")