Fix no active span when trying to log tracing error on startup (#18959)

Fix `no active span when trying to log` tracing error on startup.

Example error:
```log
synapse.logging.opentracing - 427 - ERROR - wake_destinations_needing_catchup-0 - There was no active span when trying to log. Did you forget to start one or did a context slip?
Stack (most recent call last):
  File "/usr/lib/python3.13/threading.py", line 1014, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.13/threading.py", line 1043, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.13/threading.py", line 994, in run
    self._target(*self._args, **self._kwargs)
  File "python3.13/site-packages/twisted/_threads/_threadworker.py", line 75, in work
    task()
  File "python3.13/site-packages/twisted/_threads/_team.py", line 192, in doWork
    task()
  File "python3.13/site-packages/twisted/python/threadpool.py", line 269, in inContext
    result = inContext.theWork()  # type: ignore[attr-defined]
  File "python3.13/site-packages/twisted/python/threadpool.py", line 285, in <lambda>
    inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
  File "python3.13/site-packages/twisted/python/context.py", line 117, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "python3.13/site-packages/twisted/python/context.py", line 82, in callWithContext
    return func(*args, **kw)
  File "python3.13/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
    result = func(conn, *args, **kw)
  File "synapse/synapse/storage/database.py", line 1094, in inner_func
    return func(db_conn, *args, **kwargs)
  File "synapse/synapse/storage/database.py", line 822, in new_transaction
    opentracing.log_kv({"message": "commit"})
  File "synapse/synapse/logging/opentracing.py", line 427, in ensure_active_span_inner_2
    logger.error(
```


### Why did this happen before?

This previously occurred because we called `init_tracer(...)` after the
reactor started up in `_base.start()`. But we actually attempt some
database transactions earlier than that which try to do some tracing
because of that `oidc = hs.get_oidc_handler()` line.

Notice `oidc = hs.get_oidc_handler()` happened before `_base.start(hs)`:


5be7679dd9/synapse/app/homeserver.py (L397-L408)


With this PR, I've updated things to `init_tracer(...)` earlier on
alongside where we `setup_logging(...)`.
This commit is contained in:
Eric Eastwood
2025-09-24 10:12:08 -05:00
committed by GitHub
parent 7708801d56
commit 25fa555395
4 changed files with 11 additions and 6 deletions

1
changelog.d/18959.misc Normal file
View File

@@ -0,0 +1 @@
Fix `no active span when trying to log` tracing error on startup (when OpenTracing is enabled).

View File

@@ -73,7 +73,6 @@ 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 LoggingContext, 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
@@ -574,9 +573,6 @@ async def start(hs: "HomeServer") -> None:
# Load the certificate from disk.
refresh_certificate(hs)
# Start the tracer
init_tracer(hs) # noqa
# Instantiate the modules so they can register their web resources to the module API
# before we start the listeners.
module_api = hs.get_module_api()

View File

@@ -49,6 +49,7 @@ from synapse.config.server import ListenerConfig, TCPListenerConfig
from synapse.federation.transport.server import TransportLayerServer
from synapse.http.server import JsonResource, OptionsResource
from synapse.logging.context import LoggingContext
from synapse.logging.opentracing import init_tracer
from synapse.metrics import METRICS_PREFIX, MetricsResource, RegistryProxy
from synapse.replication.http import REPLICATION_PREFIX, ReplicationRestResource
from synapse.rest import ClientRestResource, admin
@@ -359,6 +360,9 @@ def start(config: HomeServerConfig) -> None:
setup_logging(hs, config, use_worker_options=True)
# Start the tracer
init_tracer(hs) # noqa
try:
hs.setup()

View File

@@ -29,7 +29,6 @@ from twisted.web.resource import EncodingResourceWrapper, Resource
from twisted.web.server import GzipEncoderFactory
import synapse
import synapse.config.logger
from synapse import events
from synapse.api.urls import (
CLIENT_API_PREFIX,
@@ -50,6 +49,7 @@ from synapse.app._base import (
)
from synapse.config._base import ConfigError, format_config_error
from synapse.config.homeserver import HomeServerConfig
from synapse.config.logger import setup_logging
from synapse.config.server import ListenerConfig, TCPListenerConfig
from synapse.federation.transport.server import TransportLayerServer
from synapse.http.additional_resource import AdditionalResource
@@ -60,6 +60,7 @@ from synapse.http.server import (
StaticResource,
)
from synapse.logging.context import LoggingContext
from synapse.logging.opentracing import init_tracer
from synapse.metrics import METRICS_PREFIX, MetricsResource, RegistryProxy
from synapse.replication.http import REPLICATION_PREFIX, ReplicationRestResource
from synapse.rest import ClientRestResource, admin
@@ -385,7 +386,10 @@ def setup(config: HomeServerConfig) -> SynapseHomeServer:
version_string=f"Synapse/{VERSION}",
)
synapse.config.logger.setup_logging(hs, config, use_worker_options=False)
setup_logging(hs, config, use_worker_options=False)
# Start the tracer
init_tracer(hs) # noqa
logger.info("Setting up server")