From 0304ad0c3d79e44e78f9658e71f1e1533e3aa4e2 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 7 Aug 2020 11:39:29 +0100 Subject: [PATCH 1/3] 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 ed418a57c..491bbcc87 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 403ac005e..55a48a9ed 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 493e98462..c96e6ef62 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() From e1af09dccbb9d3a87728b8acb3b7425bba35a1fa Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 7 Aug 2020 15:18:51 +0100 Subject: [PATCH 2/3] Newsfile --- changelog.d/8051.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/8051.misc diff --git a/changelog.d/8051.misc b/changelog.d/8051.misc new file mode 100644 index 000000000..7657b503c --- /dev/null +++ b/changelog.d/8051.misc @@ -0,0 +1 @@ +Remove the need to set `filters` in the logging config. This change is backwards compatible, as setting the filters explicitly still works. From 3c796e4159601d93df53000806f95bb42f9275a7 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 11 Aug 2020 21:08:43 +0100 Subject: [PATCH 3/3] Update changelog.d/8051.misc Co-authored-by: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> --- changelog.d/8051.misc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog.d/8051.misc b/changelog.d/8051.misc index 7657b503c..9e472cd48 100644 --- a/changelog.d/8051.misc +++ b/changelog.d/8051.misc @@ -1 +1 @@ -Remove the need to set `filters` in the logging config. This change is backwards compatible, as setting the filters explicitly still works. +It is no longer necessary to explicitly define `filters` in the logging configuration. (Continuing to do so is redundant but harmless.)