From a6ac0fd515463c1ce38d72709ad50fabf9ba7bfa Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 16 Jun 2021 20:11:17 +0100 Subject: [PATCH 1/3] Defer stdio redirection until we are about to start the reactor --- synapse/app/_base.py | 17 +++++++++++++++++ synapse/app/generic_worker.py | 10 +++++++++- synapse/app/homeserver.py | 6 ++++++ synapse/config/logger.py | 4 +--- 4 files changed, 33 insertions(+), 4 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index 1329af2e2be7..3667ead27087 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -26,7 +26,9 @@ from cryptography.utils import CryptographyDeprecationWarning from typing_extensions import NoReturn +import twisted from twisted.internet import defer, error, reactor +from twisted.logger import LoggingFile, LogLevel from twisted.protocols.tls import TLSMemoryBIOFactory import synapse @@ -149,6 +151,21 @@ def quit_with_error(error_string: str) -> NoReturn: sys.exit(1) +def redirect_stdio_to_logs() -> None: + streams = [("stdout", LogLevel.info), ("stderr", LogLevel.error)] + + for (stream, level) in streams: + oldStream = getattr(sys, stream) + loggingFile = LoggingFile( + logger=twisted.logger.Logger(namespace=stream), + level=level, + encoding=getattr(oldStream, "encoding", None), + ) + setattr(sys, stream, loggingFile) + + print("Redirected stdout/stderr to logs") + + def register_start(cb: Callable[..., Awaitable], *args, **kwargs) -> None: """Register a callback with the reactor, to be called once it is running diff --git a/synapse/app/generic_worker.py b/synapse/app/generic_worker.py index 57c2fc2e88b2..8689be7b985a 100644 --- a/synapse/app/generic_worker.py +++ b/synapse/app/generic_worker.py @@ -32,7 +32,11 @@ SERVER_KEY_V2_PREFIX, ) from synapse.app import _base -from synapse.app._base import max_request_body_size, register_start +from synapse.app._base import ( + max_request_body_size, + redirect_stdio_to_logs, + register_start, +) from synapse.config._base import ConfigError from synapse.config.homeserver import HomeServerConfig from synapse.config.logger import setup_logging @@ -473,6 +477,10 @@ def start(config_options): register_start(_base.start, hs) + # redirect stdio to the logs, if configured. + if not hs.config.no_redirect_stdio: + redirect_stdio_to_logs() + _base.start_worker_reactor("synapse-generic-worker", config) diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index b2501ee4d7f0..a7ebe5031121 100644 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -41,6 +41,7 @@ listen_tcp, max_request_body_size, quit_with_error, + redirect_stdio_to_logs, register_start, ) from synapse.config._base import ConfigError @@ -500,6 +501,11 @@ def main(): # check base requirements check_requirements() hs = setup(sys.argv[1:]) + + # redirect stdio to the logs, if configured. + if not hs.config.no_redirect_stdio: + redirect_stdio_to_logs() + run(hs) diff --git a/synapse/config/logger.py b/synapse/config/logger.py index 813076dfe2c9..91d9bcf32ee3 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -259,9 +259,7 @@ def _log(event: dict) -> None: finally: threadlocal.active = False - logBeginner.beginLoggingTo([_log], redirectStandardIO=not config.no_redirect_stdio) - if not config.no_redirect_stdio: - print("Redirected stdout/stderr to logs") + logBeginner.beginLoggingTo([_log], redirectStandardIO=False) def _load_logging_config(log_config_path: str) -> None: From aac8c9c6e5976ef3508ee39588df12cc971c5711 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 16 Jun 2021 20:31:17 +0100 Subject: [PATCH 2/3] Catch and handle exceptions during startup --- synapse/app/_base.py | 11 ++++++++++- synapse/app/generic_worker.py | 12 ++++++++---- synapse/app/homeserver.py | 10 +++------- 3 files changed, 21 insertions(+), 12 deletions(-) diff --git a/synapse/app/_base.py b/synapse/app/_base.py index 3667ead27087..3cd39e931e38 100644 --- a/synapse/app/_base.py +++ b/synapse/app/_base.py @@ -143,7 +143,7 @@ def run(): def quit_with_error(error_string: str) -> NoReturn: message_lines = error_string.split("\n") - line_length = max(len(line) for line in message_lines if len(line) < 80) + 2 + line_length = min(max(len(line) for line in message_lines), 80) + 2 sys.stderr.write("*" * line_length + "\n") for line in message_lines: sys.stderr.write(" %s\n" % (line.rstrip(),)) @@ -151,6 +151,15 @@ def quit_with_error(error_string: str) -> NoReturn: sys.exit(1) +def handle_startup_exception(e: Exception) -> NoReturn: + # Exceptions that occur between setting up the logging and forking or starting + # the reactor are written to the logs, followed by a summary to stderr. + logger.exception("Exception during startup") + quit_with_error( + f"Error during initialisation:\n {e}\nThere may be more information in the logs." + ) + + def redirect_stdio_to_logs() -> None: streams = [("stdout", LogLevel.info), ("stderr", LogLevel.error)] diff --git a/synapse/app/generic_worker.py b/synapse/app/generic_worker.py index 8689be7b985a..907581cd2e70 100644 --- a/synapse/app/generic_worker.py +++ b/synapse/app/generic_worker.py @@ -33,6 +33,7 @@ ) from synapse.app import _base from synapse.app._base import ( + handle_startup_exception, max_request_body_size, redirect_stdio_to_logs, register_start, @@ -469,11 +470,14 @@ def start(config_options): setup_logging(hs, config, use_worker_options=True) - hs.setup() + try: + hs.setup() - # Ensure the replication streamer is always started in case we write to any - # streams. Will no-op if no streams can be written to by this worker. - hs.get_replication_streamer() + # Ensure the replication streamer is always started in case we write to any + # streams. Will no-op if no streams can be written to by this worker. + hs.get_replication_streamer() + except Exception as e: + handle_startup_exception(e) register_start(_base.start, hs) diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py index a7ebe5031121..dd534afe5e43 100644 --- a/synapse/app/homeserver.py +++ b/synapse/app/homeserver.py @@ -37,10 +37,10 @@ ) from synapse.app import _base from synapse.app._base import ( + handle_startup_exception, listen_ssl, listen_tcp, max_request_body_size, - quit_with_error, redirect_stdio_to_logs, register_start, ) @@ -70,8 +70,6 @@ from synapse.rest.well_known import WellKnownResource from synapse.server import HomeServer from synapse.storage import DataStore -from synapse.storage.engines import IncorrectDatabaseSetup -from synapse.storage.prepare_database import UpgradeDatabaseException from synapse.util.httpresourcetree import create_resource_tree from synapse.util.module_loader import load_module from synapse.util.versionstring import get_version_string @@ -359,10 +357,8 @@ def setup(config_options): try: hs.setup() - except IncorrectDatabaseSetup as e: - quit_with_error(str(e)) - except UpgradeDatabaseException as e: - quit_with_error("Failed to upgrade database: %s" % (e,)) + except Exception as e: + handle_startup_exception(e) async def do_acme() -> bool: """ From 3b2e8195801b1af3d1766ef59a9125bac5dc2531 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 16 Jun 2021 20:42:21 +0100 Subject: [PATCH 3/3] changelog --- changelog.d/10191.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/10191.feature diff --git a/changelog.d/10191.feature b/changelog.d/10191.feature new file mode 100644 index 000000000000..40f306c4219a --- /dev/null +++ b/changelog.d/10191.feature @@ -0,0 +1 @@ +Ensure that errors during startup are written to the logs and the console.