From 0304ad0c3d79e44e78f9658e71f1e1533e3aa4e2 Mon Sep 17 00:00:00 2001
From: Erik Johnston <erik@matrix.org>
Date: Fri, 7 Aug 2020 11:39:29 +0100
Subject: [PATCH] Move setting of Filter into code.

We do this to prevent foot guns. The default config uses a MemoryFilter,
but users are free to change to logging to files directly. If they do
then they have to ensure to set the `filters: [context]` on the right
handler, otherwise records get written with the wrong context.

Instead we move the logic to happen when we generate a record, which is
when we *log* rather than *handle*.

(It's possible to add filters to loggers in the config, however they
don't apply to descendant loggers and so they have to be manually set on
*every* logger used in the code base)
---
 docker/conf/log.config      |  6 ------
 docs/sample_log_config.yaml |  7 -------
 synapse/config/logger.py    | 24 ++++++++++++++++--------
 3 files changed, 16 insertions(+), 21 deletions(-)

diff --git a/docker/conf/log.config b/docker/conf/log.config
index ed418a57cd..491bbcc87a 100644
--- a/docker/conf/log.config
+++ b/docker/conf/log.config
@@ -4,16 +4,10 @@ formatters:
   precise:
    format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s'
 
-filters:
-  context:
-    (): synapse.logging.context.LoggingContextFilter
-    request: ""
-
 handlers:
   console:
     class: logging.StreamHandler
     formatter: precise
-    filters: [context]
 
 loggers:
     synapse.storage.SQL:
diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml
index 403ac005ee..55a48a9ed6 100644
--- a/docs/sample_log_config.yaml
+++ b/docs/sample_log_config.yaml
@@ -11,11 +11,6 @@ formatters:
     precise:
         format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s'
 
-filters:
-    context:
-        (): synapse.logging.context.LoggingContextFilter
-        request: ""
-
 handlers:
     file:
         class: logging.handlers.TimedRotatingFileHandler
@@ -30,7 +25,6 @@ handlers:
     # logs will still be flushed immediately.
     buffer:
         class: logging.handlers.MemoryHandler
-        filters: [context]
         target: file
         # The capacity is the number of log lines that are buffered before
         # being written to disk. Increasing this will lead to better
@@ -44,7 +38,6 @@ handlers:
     console:
         class: logging.StreamHandler
         formatter: precise
-        filters: [context]
 
 loggers:
     synapse.storage.SQL:
diff --git a/synapse/config/logger.py b/synapse/config/logger.py
index 493e98462d..c96e6ef62a 100644
--- a/synapse/config/logger.py
+++ b/synapse/config/logger.py
@@ -55,11 +55,6 @@ formatters:
         format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - \
 %(request)s - %(message)s'
 
-filters:
-    context:
-        (): synapse.logging.context.LoggingContextFilter
-        request: ""
-
 handlers:
     file:
         class: logging.handlers.TimedRotatingFileHandler
@@ -74,7 +69,6 @@ handlers:
     # logs will still be flushed immediately.
     buffer:
         class: logging.handlers.MemoryHandler
-        filters: [context]
         target: file
         # The capacity is the number of log lines that are buffered before
         # being written to disk. Increasing this will lead to better
@@ -88,7 +82,6 @@ handlers:
     console:
         class: logging.StreamHandler
         formatter: precise
-        filters: [context]
 
 loggers:
     synapse.storage.SQL:
@@ -199,11 +192,26 @@ def _setup_stdlib_logging(config, log_config, logBeginner: LogBeginner):
 
         handler = logging.StreamHandler()
         handler.setFormatter(formatter)
-        handler.addFilter(LoggingContextFilter(request=""))
         logger.addHandler(handler)
     else:
         logging.config.dictConfig(log_config)
 
+    # We add a log record factory that runs all messages through the
+    # LoggingContextFilter so that we get the context *at the time we log*
+    # rather than when we write to a handler. This can be done in config using
+    # filter options, but care must when using e.g. MemoryHandler to buffer
+    # writes.
+
+    log_filter = LoggingContextFilter(request="")
+    old_factory = logging.getLogRecordFactory()
+
+    def factory(*args, **kwargs):
+        record = old_factory(*args, **kwargs)
+        log_filter.filter(record)
+        return record
+
+    logging.setLogRecordFactory(factory)
+
     # Route Twisted's native logging through to the standard library logging
     # system.
     observer = STDLibLogObserver()