Fix server_name in logging context for multiple Synapse instances in one process

[MadLittleMods]

Background

As part of Element's plan to support a light form of vhosting (virtual host) (multiple instances of Synapse in the same Python process), we're currently diving into the details and implications of running multiple instances of Synapse in the same Python process.

"Per-tenant logging" tracked internally by https://github.com/element-hq/synapse-small-hosts/issues/48

Prior art

Previously, we exposed server_name by providing a static logging MetadataFilter that injected the values:

synapse/synapse/config/logger.py

Line 216 in 205d9e4

log_metadata_filter = MetadataFilter({"server_name": config.server.server_name})

While this can work fine for the normal case of one Synapse instance per Python process, this configures things globally and isn't compatible when we try to start multiple Synapse instances because each subsequent tenant will overwrite the previous tenant.

What does this PR do?

We remove the MetadataFilter and replace it by tracking the server_name in the LoggingContext and expose it with our existing LoggingContextFilter that we already use to expose information about the request.

This means that the server_name value follows wherever we log as expected even when we have multiple Synapse instances running in the same process.

A note on logcontext

Anywhere, Synapse mistakenly uses the sentinel logcontext to log something, we won't know which server sent the log. We've been fixing up sentinel logcontext usage as tracked by #18905

Any further sentinel logcontext usage we find in the future can be fixed piecemeal as normal.

synapse/docs/log_contexts.md

Lines 71 to 81 in d2a966f

	Ideally, nothing from the Synapse homeserver would be logged against the `sentinel`
	logcontext as we want to know which server the logs came from. In practice, this is not
	always the case yet especially outside of request handling.
	Global things outside of Synapse (e.g. Twisted reactor code) should run in the
	`sentinel` logcontext. It's only when it calls into application code that a logcontext
	gets activated. This means the reactor should be started in the `sentinel` logcontext,
	and any time an awaitable yields control back to the reactor, it should reset the
	logcontext to be the `sentinel` logcontext. This is important to avoid leaking the
	current logcontext to the reactor (which would then get picked up and associated with
	the next thing the reactor does).

Testing strategy

1. Adjust your logging config to include %(server_name)s in the format

   formatters:
       precise:
           format: '%(asctime)s - %(server_name)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s'

2. Start Synapse: poetry run synapse_homeserver --config-path homeserver.yaml
3. Make some requests (curl http://localhost:8008/_matrix/client/versions, etc)
4. Open the homeserver logs and notice the server_name in the logs as expected. unknown_server_from_sentinel_context is expected for the sentinel logcontext (things outside of Synapse).

Dev notes

• Lift pausing on ratelimited requests to http layer #18595
• Fix backwards compat for DirectServeJsonResource #18600

---

• Linearizer uses a different reactor than the homeserver during tests matrix-org/synapse#12841

---

• (LoggingContextFilter) Auto set logging filter matrix-org/synapse#8051

Todo

• Remove sentinel logcontext usage (unknown_server_from_sentinel_context), Remove sentinel logcontext where we log in Synapse #18905

Pull Request Checklist

• Pull request is based on the develop branch
• Pull request includes a changelog file. The entry should:
  • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
  • Use markdown where necessary, mostly for code blocks.
  • End with either a period (.) or an exclamation mark (!).
  • Start with a capital letter.
  • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
• Code style is correct (run the linters)

[MadLittleMods]

We previously recommended adding this to your logging config and became no longer necessary after matrix-org/synapse#8051 although was just redundant and harmless if you still did.

filters:
  context:
    (): synapse.logging.context.LoggingContextFilter
    request: ""

If we remove this __init__ constructor, we then start to see exceptions like #18868 (comment) so we should consider just reverting and putting it back in place for now.

Since it's been 5 years since we started adding LoggingContextFilter automatically for people, we could consider making a breaking change but it would be best to do this in a separate PR to track the decision easier.

I only tried to remove it because it seemed useless.

[MadLittleMods]

Restored LoggingContextFilter.__init__ constructor for now ⏩

I've also added all of the history context in a comment

[MadLittleMods]

Progressed outside of this PR: We have removed enough sentinel logcontext usage in Synapse for this to be useful (tracked by #18905).

With this PR, we will be able to distinguish which server sent the logs wherever we're not using sentinel logcontext. And if we find any more sentinel logcontext usage, we can be fix it up piecemeal like normal.

[reivilibre]

This looked like a scary PR numbers-wise but was actually pretty approachable since it was almost entirely just straightforward plumbing; a real gold star for structuring your PR sequence to make this possible, so thanks!

[reivilibre]

nice comment, thanks :)

[anoadragon453]

Is it possible to track which server this is running on? Such information would be useful if a particular module is misbehaving.

[MadLittleMods]

While we could do a pattern like the following today because we expose ModuleApi.server_name(), I'd prefer not to make a further mess.

Modified DirectServeJsonResource

class DirectServeJsonResource(_AsyncResource):
    """A resource that will call `self._async_on_<METHOD>` on new requests,
    formatting responses and errors as JSON.
    """

    def __init__(
        self,
        canonical_json: bool = False,
        extract_context: bool = False,
        # Clock is optional as this class is exposed to the module API.
        clock: Optional[Clock] = None,
        # This is only necessary for Module API users who don't pass in a `clock`.
        server_name: Optional[str] = None,
    ):
        """
        Args:
            canonical_json: TODO
            extract_context: TODO
            clock: This is expected to be passed in by any Synapse code.
                Only optional for the Module API.
            server_name: The homeserver name (this should be `ModuleApi.server_name()`).
                Only used for the Module API if `clock` is not passed in.
        """

        if clock is None:
            clock = Clock(
                cast(ISynapseThreadlessReactor, reactor),
                server_name=server_name
                if server_name is not None
                else "synapse_module_running_from_unknown_server",
            )
        else:
            assert server_name is None, (
                "No need to pass in `server_name` if clock is set"
            )

        super().__init__(clock, extract_context)
        self.canonical_json = canonical_json

Usage:

class SomeResource(DirectServeJsonResource):
    def __init__(
        self,
        module_api: ModuleApi,
    ):
        super().__init__(server_name=module_api.server_name())


class SomeSynapseModule:
    """
    Synapse module that TODO
    """

    def __init__(
        self, config: MyModuleConfig, module_api: ModuleApi
    ):
        # Keep a reference to the config and Module API
        self._module_api = module_api

        # "Modules **must** register their web resources in their `__init__` method."
        # (https://github.com/element-hq/synapse/blob/081f6ad50fa0ea87c348778e8be40517da25c698/docs/modules/writing_a_module.md#L69)
        self._module_api.register_web_resource(
            SomeResource(
                self._module_api
            ),
        )

The ideal solution would be using the hs.get_clock() and passing in the Clock directly. See #18868 (comment) for why the homeserver clock is ideal. We currently don't expose Clock to module API consumers and maybe we shouldn't as it's best for them to continue using the dedicated ModuleApi equivalents.

Overall, this requires much more thought. And perhaps handing out less raw interfaces like DirectServeJsonResource in the module API as it makes doing the right thing like this practically impossible without making breaking changes.

[anoadragon453]

Thanks for the detailed explanations. Agreed that this should be a lesson for future module API expansion.

This PR LGTM!

[jason-famedly]

Based on the resolved conversation in the Linearizer section, wouldn't that apply here as well?

[MadLittleMods]

I assume you're talking about #18868 (comment)

Yes, ideally we'd use the homeserver Clock 👍

We already had access to server_name here and clock wasn't being passed in at all like the Linearizer had.

[jason-famedly]

Makes sense. Thanks 🙏

[MadLittleMods]

Thanks for the review @reivilibre, @anoadragon453, and @jason-famedly 🐉