From 1af663d604a551f849e32e01462bf31f46baac47 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 6 Aug 2020 16:51:19 +0100 Subject: [PATCH 01/11] Change default log config to buffer by default. This batches up writes to the filesystem, which is more efficient for disk I/O. This means that it can take some time for logs to get written to disk. Note that ERROR logs (and above) immediately flush the buffer. This only effects new installs, as we only write the log config if started with `--generate-config` (in the same way we do for generating signing keys). --- docs/sample_log_config.yaml | 13 ++++++++++++- synapse/config/logger.py | 13 ++++++++++++- 2 files changed, 24 insertions(+), 2 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index 1a2739455ef2..d1ca5e7445ca 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -25,6 +25,17 @@ handlers: backupCount: 10 filters: [context] encoding: utf8 + + # Default to buffering writes to log file for efficiency. This means that + # will be a delay for WARNING/INFO/DEBUG logs to get written, but ERROR + # logs will still be flushed immediately. + buffer: + class: logging.handlers.MemoryHandler + formatter: precise + level: DEBUG + target: file + capacity: 100 + console: class: logging.StreamHandler formatter: precise @@ -38,6 +49,6 @@ loggers: root: level: INFO - handlers: [file, console] + handlers: [buffer, console] disable_existing_loggers: false diff --git a/synapse/config/logger.py b/synapse/config/logger.py index dd775a97e884..50d4760a8f5c 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -69,6 +69,17 @@ backupCount: 10 filters: [context] encoding: utf8 + + # Default to buffering writes to log file for efficiency. This means that + # will be a delay for WARNING/INFO/DEBUG logs to get written, but ERROR + # logs will still be flushed immediately. + buffer: + class: logging.handlers.MemoryHandler + formatter: precise + level: DEBUG + target: file + capacity: 100 + console: class: logging.StreamHandler formatter: precise @@ -82,7 +93,7 @@ root: level: INFO - handlers: [file, console] + handlers: [buffer, console] disable_existing_loggers: false """ From 29b921e2326a46908971049049716d8518756d70 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 6 Aug 2020 17:00:49 +0100 Subject: [PATCH 02/11] Default to keeping last 4 days of logs. This hopefully reduces the amount of logs kept for new servers. Keeping the last 1GB of logs is likely overkill for new servers, but equally may not be enough for busy ones. Instead, we keep the last four days worth of logs, enough so that admins can investigate any problems that happened over e.g. a long weekend. --- docs/sample_log_config.yaml | 6 +++--- synapse/config/logger.py | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index d1ca5e7445ca..18fe624e9176 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -18,11 +18,11 @@ filters: handlers: file: - class: logging.handlers.RotatingFileHandler + class: logging.handlers.TimedRotatingFileHandler formatter: precise filename: /var/log/matrix-synapse/homeserver.log - maxBytes: 104857600 - backupCount: 10 + when: midnight + backupCount: 3 # Does not include the current log file. filters: [context] encoding: utf8 diff --git a/synapse/config/logger.py b/synapse/config/logger.py index 50d4760a8f5c..1894b081ba49 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -62,11 +62,11 @@ handlers: file: - class: logging.handlers.RotatingFileHandler + class: logging.handlers.TimedRotatingFileHandler formatter: precise filename: ${log_file} - maxBytes: 104857600 - backupCount: 10 + when: midnight + backupCount: 3 # Does not include the current log file. filters: [context] encoding: utf8 From ed8a1839a0f6e5bf90d856bfef22cecc60cc69c5 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 6 Aug 2020 17:05:26 +0100 Subject: [PATCH 03/11] Newsfile --- changelog.d/8040.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/8040.misc diff --git a/changelog.d/8040.misc b/changelog.d/8040.misc new file mode 100644 index 000000000000..a12615139237 --- /dev/null +++ b/changelog.d/8040.misc @@ -0,0 +1 @@ +Change the default log config to reduce disk I/O and storage for new servers. From 07465f040f746c3e12770fd1b086478a53939171 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Thu, 6 Aug 2020 17:17:22 +0100 Subject: [PATCH 04/11] Remove spurious level: DEBUG --- docs/sample_log_config.yaml | 1 - synapse/config/logger.py | 1 - 2 files changed, 2 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index 18fe624e9176..0feec68cc548 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -32,7 +32,6 @@ handlers: buffer: class: logging.handlers.MemoryHandler formatter: precise - level: DEBUG target: file capacity: 100 diff --git a/synapse/config/logger.py b/synapse/config/logger.py index 1894b081ba49..d86d64f1486b 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -76,7 +76,6 @@ buffer: class: logging.handlers.MemoryHandler formatter: precise - level: DEBUG target: file capacity: 100 From 5936b1a389f702868c6519e72a50605f533e81e1 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 7 Aug 2020 11:30:16 +0100 Subject: [PATCH 05/11] Review comments --- docs/sample_log_config.yaml | 11 ++++++++--- synapse/config/logger.py | 11 ++++++++--- 2 files changed, 16 insertions(+), 6 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index 0feec68cc548..6d84a91de52c 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -23,7 +23,6 @@ handlers: filename: /var/log/matrix-synapse/homeserver.log when: midnight backupCount: 3 # Does not include the current log file. - filters: [context] encoding: utf8 # Default to buffering writes to log file for efficiency. This means that @@ -31,7 +30,7 @@ handlers: # logs will still be flushed immediately. buffer: class: logging.handlers.MemoryHandler - formatter: precise + filters: [context] target: file capacity: 100 @@ -46,8 +45,14 @@ loggers: # information such as access tokens. level: INFO + twisted: + # We send the twisted logging directly to the file handler, + # to work around https://github.com/matrix-org/synapse/issues/3471 + handlers: [file] + propagate: false + root: level: INFO - handlers: [buffer, console] + handlers: [buffer] disable_existing_loggers: false diff --git a/synapse/config/logger.py b/synapse/config/logger.py index d86d64f1486b..00e1bdc0bfed 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -67,7 +67,6 @@ filename: ${log_file} when: midnight backupCount: 3 # Does not include the current log file. - filters: [context] encoding: utf8 # Default to buffering writes to log file for efficiency. This means that @@ -75,7 +74,7 @@ # logs will still be flushed immediately. buffer: class: logging.handlers.MemoryHandler - formatter: precise + filters: [context] target: file capacity: 100 @@ -90,9 +89,15 @@ # information such as access tokens. level: INFO + twisted: + # We send the twisted logging directly to the file handler, + # to work around https://github.com/matrix-org/synapse/issues/3471 + handlers: [file] + propagate: false + root: level: INFO - handlers: [buffer, console] + handlers: [buffer] disable_existing_loggers: false """ From c2fc81e417cc4632eefd22c52dd41ecc659917f6 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 7 Aug 2020 11:39:29 +0100 Subject: [PATCH 06/11] 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) --- docs/sample_log_config.yaml | 7 ------- synapse/config/logger.py | 24 ++++++++++++++++-------- 2 files changed, 16 insertions(+), 15 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index 6d84a91de52c..53164ec125f5 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,14 +25,12 @@ handlers: # logs will still be flushed immediately. buffer: class: logging.handlers.MemoryHandler - filters: [context] target: file capacity: 100 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 00e1bdc0bfed..48da3be9b437 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -55,11 +55,6 @@ 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,14 +69,12 @@ # logs will still be flushed immediately. buffer: class: logging.handlers.MemoryHandler - filters: [context] target: file capacity: 100 console: class: logging.StreamHandler formatter: precise - filters: [context] loggers: synapse.storage.SQL: @@ -183,11 +176,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 5590a7391bb31c64f2a2537029ff9830eea61132 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 7 Aug 2020 11:50:48 +0100 Subject: [PATCH 07/11] Flush at WARNING logs as well We don't WARN too frequently, so this is fine and ensures that we log things like "STARTING" immediately. --- docs/sample_log_config.yaml | 3 ++- synapse/config/logger.py | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index 53164ec125f5..48a6287e5b7e 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -21,12 +21,13 @@ handlers: encoding: utf8 # Default to buffering writes to log file for efficiency. This means that - # will be a delay for WARNING/INFO/DEBUG logs to get written, but ERROR + # will be a delay for INFO/DEBUG logs to get written, but WARNING/ERROR # logs will still be flushed immediately. buffer: class: logging.handlers.MemoryHandler target: file capacity: 100 + flushLevel: 30 # Flush for WARNING logs as well console: class: logging.StreamHandler diff --git a/synapse/config/logger.py b/synapse/config/logger.py index 48da3be9b437..c67902113ecc 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -65,12 +65,13 @@ encoding: utf8 # Default to buffering writes to log file for efficiency. This means that - # will be a delay for WARNING/INFO/DEBUG logs to get written, but ERROR + # will be a delay for INFO/DEBUG logs to get written, but WARNING/ERROR # logs will still be flushed immediately. buffer: class: logging.handlers.MemoryHandler target: file capacity: 100 + flushLevel: 30 # Flush for WARNING logs as well console: class: logging.StreamHandler From dd0b6f20cb38add43dff6a5e1ad81d3c0fafe116 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 7 Aug 2020 15:01:10 +0100 Subject: [PATCH 08/11] Revert "Move setting of Filter into code." This reverts commit c2fc81e417cc4632eefd22c52dd41ecc659917f6. --- docs/sample_log_config.yaml | 7 +++++++ synapse/config/logger.py | 24 ++++++++---------------- 2 files changed, 15 insertions(+), 16 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index 48a6287e5b7e..4da4c071896c 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -11,6 +11,11 @@ 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 @@ -25,6 +30,7 @@ handlers: # logs will still be flushed immediately. buffer: class: logging.handlers.MemoryHandler + filters: [context] target: file capacity: 100 flushLevel: 30 # Flush for WARNING logs as well @@ -32,6 +38,7 @@ 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 c67902113ecc..baa17a6a21f5 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -55,6 +55,11 @@ 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 @@ -69,6 +74,7 @@ # logs will still be flushed immediately. buffer: class: logging.handlers.MemoryHandler + filters: [context] target: file capacity: 100 flushLevel: 30 # Flush for WARNING logs as well @@ -76,6 +82,7 @@ console: class: logging.StreamHandler formatter: precise + filters: [context] loggers: synapse.storage.SQL: @@ -177,26 +184,11 @@ 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 e7d2a9ef455d7602904c1fa16b89331e75f0aae3 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 7 Aug 2020 15:04:39 +0100 Subject: [PATCH 09/11] Reduce default buffer capacity and doc the option --- docs/sample_log_config.yaml | 6 +++++- synapse/config/logger.py | 6 +++++- 2 files changed, 10 insertions(+), 2 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index 4da4c071896c..8b78e58397ba 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -32,7 +32,11 @@ handlers: class: logging.handlers.MemoryHandler filters: [context] target: file - capacity: 100 + # The capacity is the number of log lines that are buffered before + # being written to disk. Increasing this will lead to better + # performance, at the expensive of it taking longer for log lines to + # be written to disk. + capacity: 10 flushLevel: 30 # Flush for WARNING logs as well console: diff --git a/synapse/config/logger.py b/synapse/config/logger.py index baa17a6a21f5..49efe9b3c595 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -76,7 +76,11 @@ class: logging.handlers.MemoryHandler filters: [context] target: file - capacity: 100 + # The capacity is the number of log lines that are buffered before + # being written to disk. Increasing this will lead to better + # performance, at the expensive of it taking longer for log lines to + # be written to disk. + capacity: 10 flushLevel: 30 # Flush for WARNING logs as well console: From 62289fa1cbdb712952df4f19c7ea4ac978f9b860 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Mon, 10 Aug 2020 13:51:43 +0100 Subject: [PATCH 10/11] Document console handler --- docs/sample_log_config.yaml | 6 ++++++ synapse/config/logger.py | 6 ++++++ 2 files changed, 12 insertions(+) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index 8b78e58397ba..f4819ddc17d6 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -39,6 +39,8 @@ handlers: capacity: 10 flushLevel: 30 # Flush for WARNING logs as well + # A handler that writes logs to stderr. Unused by default, but can be used + # instead of "buffer" and "file" in the logger handlers. console: class: logging.StreamHandler formatter: precise @@ -53,11 +55,15 @@ loggers: twisted: # We send the twisted logging directly to the file handler, # to work around https://github.com/matrix-org/synapse/issues/3471 + # when using "buffer" logger. Use "console" to log to stderr instead. handlers: [file] propagate: false root: level: INFO + + # By default buffer logs in memory before logging to file. Replace "buffer" + # with "console" to log to stderr instead. handlers: [buffer] disable_existing_loggers: false diff --git a/synapse/config/logger.py b/synapse/config/logger.py index 49efe9b3c595..06f97797ea32 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -83,6 +83,8 @@ capacity: 10 flushLevel: 30 # Flush for WARNING logs as well + # A handler that writes logs to stderr. Unused by default, but can be used + # instead of "buffer" and "file" in the logger handlers. console: class: logging.StreamHandler formatter: precise @@ -97,11 +99,15 @@ twisted: # We send the twisted logging directly to the file handler, # to work around https://github.com/matrix-org/synapse/issues/3471 + # when using "buffer" logger. Use "console" to log to stderr instead. handlers: [file] propagate: false root: level: INFO + + # By default buffer logs in memory before logging to file. Replace "buffer" + # with "console" to log to stderr instead. handlers: [buffer] disable_existing_loggers: false From 538efd014997fb46f6e62296abe2e83baebb63f0 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 11 Aug 2020 15:11:49 +0100 Subject: [PATCH 11/11] Update wording as per review --- docs/sample_log_config.yaml | 9 +++++++-- synapse/config/logger.py | 9 +++++++-- 2 files changed, 14 insertions(+), 4 deletions(-) diff --git a/docs/sample_log_config.yaml b/docs/sample_log_config.yaml index f4819ddc17d6..403ac005ee48 100644 --- a/docs/sample_log_config.yaml +++ b/docs/sample_log_config.yaml @@ -62,8 +62,13 @@ loggers: root: level: INFO - # By default buffer logs in memory before logging to file. Replace "buffer" - # with "console" to log to stderr instead. + # Write logs to the `buffer` handler, which will buffer them together in memory, + # then write them to a file. + # + # Replace "buffer" with "console" to log to stderr instead. (Note that you'll + # also need to update the configuation for the `twisted` logger above, in + # this case.) + # handlers: [buffer] disable_existing_loggers: false diff --git a/synapse/config/logger.py b/synapse/config/logger.py index 06f97797ea32..493e98462d68 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -106,8 +106,13 @@ root: level: INFO - # By default buffer logs in memory before logging to file. Replace "buffer" - # with "console" to log to stderr instead. + # Write logs to the `buffer` handler, which will buffer them together in memory, + # then write them to a file. + # + # Replace "buffer" with "console" to log to stderr instead. (Note that you'll + # also need to update the configuation for the `twisted` logger above, in + # this case.) + # handlers: [buffer] disable_existing_loggers: false