From db131b6b22350ea73128ac69ea82a48a6cf78a20 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Tue, 11 Aug 2020 18:09:46 +0100 Subject: Change the default log config to reduce disk I/O and storage (#8040) * 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). * 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. --- synapse/config/logger.py | 41 ++++++++++++++++++++++++++++++++++++----- 1 file changed, 36 insertions(+), 5 deletions(-) (limited to 'synapse/config/logger.py') diff --git a/synapse/config/logger.py b/synapse/config/logger.py index dd775a97e8..493e98462d 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -62,13 +62,29 @@ filters: handlers: file: - class: logging.handlers.RotatingFileHandler + class: logging.handlers.TimedRotatingFileHandler formatter: precise filename: ${log_file} - maxBytes: 104857600 - backupCount: 10 - filters: [context] + when: midnight + backupCount: 3 # Does not include the current log file. encoding: utf8 + + # Default to buffering writes to log file for efficiency. This means that + # 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 + 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 + # 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 + + # 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 @@ -80,9 +96,24 @@ 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 + # when using "buffer" logger. Use "console" to log to stderr instead. + handlers: [file] + propagate: false + root: level: INFO - handlers: [file, console] + + # 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 """ -- cgit 1.5.1 From 0304ad0c3d79e44e78f9658e71f1e1533e3aa4e2 Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Fri, 7 Aug 2020 11:39:29 +0100 Subject: 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(-) (limited to 'synapse/config/logger.py') 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() -- cgit 1.5.1 From 77794ebc776564291c5c8135b33f76d3fd79f550 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Mon, 7 Sep 2020 16:54:30 +0100 Subject: Fix stack overflow when logging system encounters an error (#8268) --- changelog.d/8268.bugfix | 1 + synapse/config/logger.py | 25 +++++++++++++++++++++++-- 2 files changed, 24 insertions(+), 2 deletions(-) create mode 100644 changelog.d/8268.bugfix (limited to 'synapse/config/logger.py') diff --git a/changelog.d/8268.bugfix b/changelog.d/8268.bugfix new file mode 100644 index 0000000000..4b15a60253 --- /dev/null +++ b/changelog.d/8268.bugfix @@ -0,0 +1 @@ +Fix stack overflow when stderr is redirected to the logging system, and the logging system encounters an error. diff --git a/synapse/config/logger.py b/synapse/config/logger.py index c96e6ef62a..13d6f6a3ea 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -17,6 +17,7 @@ import logging import logging.config import os import sys +import threading from string import Template import yaml @@ -25,6 +26,7 @@ from twisted.logger import ( ILogObserver, LogBeginner, STDLibLogObserver, + eventAsText, globalLogBeginner, ) @@ -216,8 +218,9 @@ def _setup_stdlib_logging(config, log_config, logBeginner: LogBeginner): # system. observer = STDLibLogObserver() - def _log(event): + threadlocal = threading.local() + def _log(event): if "log_text" in event: if event["log_text"].startswith("DNSDatagramProtocol starting on "): return @@ -228,7 +231,25 @@ def _setup_stdlib_logging(config, log_config, logBeginner: LogBeginner): if event["log_text"].startswith("Timing out client"): return - return observer(event) + # this is a workaround to make sure we don't get stack overflows when the + # logging system raises an error which is written to stderr which is redirected + # to the logging system, etc. + if getattr(threadlocal, "active", False): + # write the text of the event, if any, to the *real* stderr (which may + # be redirected to /dev/null, but there's not much we can do) + try: + event_text = eventAsText(event) + print("logging during logging: %s" % event_text, file=sys.__stderr__) + except Exception: + # gah. + pass + return + + try: + threadlocal.active = True + return observer(event) + finally: + threadlocal.active = False logBeginner.beginLoggingTo([_log], redirectStandardIO=not config.no_redirect_stdio) if not config.no_redirect_stdio: -- cgit 1.5.1