Ensure that errors during startup are written to the logs and the console. (#10191)

* Defer stdio redirection until we are about to start the reactor

* Catch and handle exceptions during startup

Author: richvdh

changelog.d/10191.feature

@@ -0,0 +1 @@
+Ensure that errors during startup are written to the logs and the console.

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
@@ -139,14 +141,38 @@ 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(),))
     sys.stderr.write("*" * line_length + "\n")
     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)]
+
+    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
 

synapse/app/generic_worker.py

@@ -32,7 +32,12 @@
     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 (
+    handle_startup_exception,
+    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
@@ -469,14 +474,21 @@ 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)
 
+    # 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)
 
 

synapse/app/homeserver.py

@@ -37,10 +37,11 @@
 )
 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,
 )
 from synapse.config._base import ConfigError
@@ -69,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
@@ -362,10 +361,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 start():
         # Load the OIDC provider metadatas, if OIDC is enabled.
@@ -456,6 +453,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)
 
 

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: