Closing scope `Scope<xxx matrix.org synchrotron.write_bytes_to_request>` which is not the currently-active one

[anoadragon453]

We're seeing millions of instances of:

Closing scope Scope<3383a8e8423cb969:6132fe74719247d5:0:0 matrix.org synchrotron.write_bytes_to_request> which is not the currently-active one None

on matrix.org, which appears to be raised by any log line that logs at the ERROR level. The sheer volume of exceptions being sent to sentry was causing 25% CPU usage alone.

This appears to be related to #18804 (cc @MadLittleMods), which instrumented write_bytes_to_request and went out in 1.138.0. To stop the immediate spam, @erikjohnston added the following patch:

diff --git a/synapse/logging/scopecontextmanager.py b/synapse/logging/scopecontextmanager.py
index feaadc4d87..f896de3c50 100644
--- a/synapse/logging/scopecontextmanager.py
+++ b/synapse/logging/scopecontextmanager.py
@@ -146,7 +146,7 @@ class _LogContextScope(Scope):
     def close(self) -> None:
         active_scope = self.manager.active
         if active_scope is not self:
-            logger.error(
+            logger.warning(
                 "Closing scope %s which is not the currently-active one %s",
                 self,
                 active_scope,

but this still needs a proper fix.

[MadLittleMods]

Probably a combination of #18804 (shipped in 1.138.0rc1) and #19007 (shipped in 1.140.0rc1). ContextVarsScopeManager kept the tracing scope open long enough for things to complete more properly in more cases but we've switched back to our own LogContextScopeManager again (see PR's for more context).