Remove sentinel logcontext where we log in setup, start and exit

synapse/app/_base.py

@@ -18,75 +18,75 @@
 # [This file includes modifications made by New Vector Limited]
 #
 #
 import atexit
 import gc
 import logging
 import os
 import signal
 import socket
 import sys
 import traceback
 import warnings
 from textwrap import indent
 from typing import (
     TYPE_CHECKING,
     Any,
     Awaitable,
     Callable,
     Dict,
     List,
     NoReturn,
     Optional,
     Tuple,
     cast,
 )
 
 from cryptography.utils import CryptographyDeprecationWarning
 from typing_extensions import ParamSpec
 
 import twisted
 from twisted.internet import defer, error, reactor as _reactor
 from twisted.internet.interfaces import (
     IOpenSSLContextFactory,
     IReactorSSL,
     IReactorTCP,
     IReactorUNIX,
 )
 from twisted.internet.protocol import ServerFactory
 from twisted.internet.tcp import Port
 from twisted.logger import LoggingFile, LogLevel
 from twisted.protocols.tls import TLSMemoryBIOFactory
 from twisted.python.threadpool import ThreadPool
 from twisted.web.resource import Resource
 
 import synapse.util.caches
 from synapse.api.constants import MAX_PDU_SIZE
 from synapse.app import check_bind_error
 from synapse.app.phone_stats_home import start_phone_stats_home
 from synapse.config import ConfigError
 from synapse.config._base import format_config_error
 from synapse.config.homeserver import HomeServerConfig
 from synapse.config.server import ListenerConfig, ManholeConfig, TCPListenerConfig
 from synapse.crypto import context_factory
 from synapse.events.auto_accept_invites import InviteAutoAccepter
 from synapse.events.presence_router import load_legacy_presence_router
 from synapse.handlers.auth import load_legacy_password_auth_providers
 from synapse.http.site import SynapseSite
-from synapse.logging.context import PreserveLoggingContext
 from synapse.logging.opentracing import init_tracer
 from synapse.metrics import install_gc_manager, register_threadpool
 from synapse.metrics.background_process_metrics import run_as_background_process
 from synapse.metrics.jemalloc import setup_jemalloc_stats
 from synapse.module_api.callbacks.spamchecker_callbacks import load_legacy_spam_checkers
 from synapse.module_api.callbacks.third_party_event_rules_callbacks import (
     load_legacy_third_party_event_rules,
 )
+from synapse.logging.context import PreserveLoggingContext
 from synapse.types import ISynapseReactor, StrCollection
 from synapse.util import SYNAPSE_VERSION
 from synapse.util.caches.lrucache import setup_expire_lru_cache_entries
 from synapse.util.daemonize import daemonize_process
 from synapse.util.gai_resolver import GAIResolver
 from synapse.util.rlimit import change_resource_limit
 
 if TYPE_CHECKING:
     from synapse.server import HomeServer
@@ -183,25 +183,23 @@
         if gc_thresholds:
             gc.set_threshold(*gc_thresholds)
         install_gc_manager()
-        run_command()
 
-    # make sure that we run the reactor with the sentinel log context,
-    # otherwise other PreserveLoggingContext instances will get confused
-    # and complain when they see the logcontext arbitrarily swapping
-    # between the sentinel and `run` logcontexts.
-    #
-    # We also need to drop the logcontext before forking if we're daemonizing,
-    # otherwise the cputime metrics get confused about the per-thread resource usage
-    # appearing to go backwards.
-    with PreserveLoggingContext():
-        if daemonize:
-            assert pid_file is not None
+        # Reset the logging context when we start the reactor (whenever we yield control
+        # to the reactor, the `sentinel` logging context needs to be set so we don't
+        # leak the current logging context and erroneously apply it to the next task the
+        # reactor event loop picks up)
+        with PreserveLoggingContext():
+            run_command()
+
+    if daemonize:
+        assert pid_file is not None
+
+        if print_pidfile:
+            print(pid_file)
 
-            if print_pidfile:
-                print(pid_file)
+        daemonize_process(pid_file, logger)
 
-            daemonize_process(pid_file, logger)
-        run()
+    run()
 
 
 def quit_with_error(error_string: str) -> NoReturn:
@@ -242,6 +240,7 @@
     print("Redirected stdout/stderr to logs")
 
 
+# TODO: Re-establish log context at this point
 def register_start(
     cb: Callable[P, Awaitable], *args: P.args, **kwargs: P.kwargs
 ) -> None:

synapse/app/homeserver.py

@@ -415,6 +415,7 @@ def main() -> None:
             redirect_stdio_to_logs()
 
         run(hs)
+    logger.info("asdf outside main")
 
 
 if __name__ == "__main__":

synapse/handlers/federation.py

@@ -22,65 +22,66 @@
 
 """Contains handlers for federation events."""
 
 import enum
 import itertools
 import logging
 from enum import Enum
 from http import HTTPStatus
 from typing import (
     TYPE_CHECKING,
     AbstractSet,
     Dict,
     Iterable,
     List,
     Optional,
     Set,
     Tuple,
     Union,
 )
 
+from twisted.internet import defer
 import attr
 from prometheus_client import Histogram
 from signedjson.key import decode_verify_key_bytes
 from signedjson.sign import verify_signed_json
 from unpaddedbase64 import decode_base64
 
 from synapse import event_auth
 from synapse.api.constants import MAX_DEPTH, EventContentFields, EventTypes, Membership
 from synapse.api.errors import (
     AuthError,
     CodeMessageException,
     Codes,
     FederationDeniedError,
     FederationError,
     FederationPullAttemptBackoffError,
     HttpResponseException,
     NotFoundError,
     PartialStateConflictError,
     RequestSendFailed,
     SynapseError,
 )
 from synapse.api.room_versions import KNOWN_ROOM_VERSIONS, RoomVersion
 from synapse.crypto.event_signing import compute_event_signature
 from synapse.event_auth import validate_event_for_room_version
 from synapse.events import EventBase
 from synapse.events.snapshot import EventContext, UnpersistedEventContextBase
 from synapse.events.validator import EventValidator
 from synapse.federation.federation_client import InvalidResponseError
 from synapse.handlers.pagination import PURGE_PAGINATION_LOCK_NAME
 from synapse.http.servlet import assert_params_in_dict
-from synapse.logging.context import nested_logging_context
+from synapse.logging.context import nested_logging_context, make_deferred_yieldable
 from synapse.logging.opentracing import SynapseTags, set_tag, tag_args, trace
 from synapse.metrics import SERVER_NAME_LABEL
 from synapse.metrics.background_process_metrics import run_as_background_process
 from synapse.module_api import NOT_SPAM
 from synapse.storage.databases.main.events_worker import EventRedactBehaviour
 from synapse.storage.invite_rule import InviteRule
 from synapse.types import JsonDict, StrCollection, get_domain_from_id
 from synapse.types.state import StateFilter
 from synapse.util.async_helpers import Linearizer
 from synapse.util.retryutils import NotRetryingDestination
 from synapse.visibility import filter_events_for_server
 
 if TYPE_CHECKING:
     from synapse.server import HomeServer
@@ -188,7 +189,8 @@
         # were shut down.
         if not hs.config.worker.worker_app:
             run_as_background_process(
-                "resume_sync_partial_state_room",
+                # "resume_sync_partial_state_room",
+                "rspsr",
                 self.server_name,
                 self._resume_partial_state_room_sync,
             )
@@ -1788,15 +1790,26 @@
 
     async def _resume_partial_state_room_sync(self) -> None:
         """Resumes resyncing of all partial-state rooms after a restart."""
+        logger.info("asdf->_resume_partial_state_room_sync")
         assert not self.config.worker.worker_app
 
-        partial_state_rooms = await self.store.get_partial_state_room_resync_info()
-        for room_id, resync_info in partial_state_rooms.items():
-            self._start_partial_state_room_sync(
-                initial_destination=resync_info.joined_via,
-                other_destinations=resync_info.servers_in_room,
-                room_id=room_id,
-            )
+        # a function which returns an incomplete deferred, but doesn't follow
+        # the synapse rules.
+        def blocking_function() -> defer.Deferred:
+            d: defer.Deferred = defer.Deferred()
+            self.hs.get_reactor().callLater(0, d.callback, None)
+            return d
+
+        await make_deferred_yieldable(blocking_function())
+
+        # partial_state_rooms = await self.store.get_partial_state_room_resync_info()
+        # for room_id, resync_info in partial_state_rooms.items():
+        #     self._start_partial_state_room_sync(
+        #         initial_destination=resync_info.joined_via,
+        #         other_destinations=resync_info.servers_in_room,
+        #         room_id=room_id,
+        #     )
+        logger.info("asdf->_resume_partial_state_room_sync done")
 
     def _start_partial_state_room_sync(
         self,

synapse/http/site.py

@@ -299,6 +299,7 @@ def get_authenticated_entity(self) -> Tuple[Optional[str], Optional[str]]:
         return None, None
 
     def render(self, resrc: Resource) -> None:
+        logger.info("asdf->SynapseRequest.render")
         # this is called once a Resource has been found to serve the request; in our
         # case the Resource in question will normally be a JsonResource.
 
@@ -319,6 +320,11 @@ def render(self, resrc: Resource) -> None:
                 user_agent=get_request_user_agent(self),
             ),
         )
+        logger.info(
+            "asdf request logcontext=%s logcontext.previous_context=%s",
+            self.logcontext,
+            self.logcontext.previous_context,
+        )
 
         # override the Server header which is set by twisted
         self.setHeader("Server", self.synapse_site.server_version_string)
@@ -342,6 +348,7 @@ def render(self, resrc: Resource) -> None:
                 servlet=self.request_metrics.name,
                 **{SERVER_NAME_LABEL: self.our_server_name},
             ).inc()
+        logger.info("asdf->SynapseRequest.render done")
 
     @contextlib.contextmanager
     def processing(self) -> Generator[None, None, None]: