2021-07-07 03:44:14 -06:00
<!DOCTYPE HTML>
< html lang = "en" class = "sidebar-visible no-js light" >
< head >
<!-- Book generated using mdBook -->
< meta charset = "UTF-8" >
< title > Log Contexts - Synapse< / title >
<!-- Custom HTML head -->
< meta content = "text/html; charset=utf-8" http-equiv = "Content-Type" >
< meta name = "description" content = "" >
< meta name = "viewport" content = "width=device-width, initial-scale=1" >
< meta name = "theme-color" content = "#ffffff" / >
< link rel = "icon" href = "favicon.svg" >
< link rel = "shortcut icon" href = "favicon.png" >
< link rel = "stylesheet" href = "css/variables.css" >
< link rel = "stylesheet" href = "css/general.css" >
< link rel = "stylesheet" href = "css/chrome.css" >
< link rel = "stylesheet" href = "css/print.css" media = "print" >
<!-- Fonts -->
< link rel = "stylesheet" href = "FontAwesome/css/font-awesome.css" >
< link rel = "stylesheet" href = "fonts/fonts.css" >
<!-- Highlight.js Stylesheets -->
< link rel = "stylesheet" href = "highlight.css" >
< link rel = "stylesheet" href = "tomorrow-night.css" >
< link rel = "stylesheet" href = "ayu-highlight.css" >
<!-- Custom theme stylesheets -->
< link rel = "stylesheet" href = "docs/website_files/table-of-contents.css" >
< link rel = "stylesheet" href = "docs/website_files/remove-nav-buttons.css" >
< link rel = "stylesheet" href = "docs/website_files/indent-section-headers.css" >
< / head >
< body >
<!-- Provide site root to javascript -->
< script type = "text/javascript" >
var path_to_root = "";
var default_theme = window.matchMedia("(prefers-color-scheme: dark)").matches ? "navy" : "light";
< / script >
<!-- Work around some values being stored in localStorage wrapped in quotes -->
< script type = "text/javascript" >
try {
var theme = localStorage.getItem('mdbook-theme');
var sidebar = localStorage.getItem('mdbook-sidebar');
if (theme.startsWith('"') & & theme.endsWith('"')) {
localStorage.setItem('mdbook-theme', theme.slice(1, theme.length - 1));
}
if (sidebar.startsWith('"') & & sidebar.endsWith('"')) {
localStorage.setItem('mdbook-sidebar', sidebar.slice(1, sidebar.length - 1));
}
} catch (e) { }
< / script >
<!-- Set the theme before any content is loaded, prevents flash -->
< script type = "text/javascript" >
var theme;
try { theme = localStorage.getItem('mdbook-theme'); } catch(e) { }
if (theme === null || theme === undefined) { theme = default_theme; }
var html = document.querySelector('html');
html.classList.remove('no-js')
html.classList.remove('light')
html.classList.add(theme);
html.classList.add('js');
< / script >
<!-- Hide / unhide sidebar before it is displayed -->
< script type = "text/javascript" >
var html = document.querySelector('html');
var sidebar = 'hidden';
if (document.body.clientWidth >= 1080) {
try { sidebar = localStorage.getItem('mdbook-sidebar'); } catch(e) { }
sidebar = sidebar || 'visible';
}
html.classList.remove('sidebar-visible');
html.classList.add("sidebar-" + sidebar);
< / script >
< nav id = "sidebar" class = "sidebar" aria-label = "Table of contents" >
< div class = "sidebar-scrollbox" >
2022-03-22 10:30:53 -06:00
< ol class = "chapter" > < li class = "chapter-item expanded affix " > < li class = "part-title" > Introduction< / li > < li class = "chapter-item expanded " > < a href = "welcome_and_overview.html" > Welcome and Overview< / a > < / li > < li class = "chapter-item expanded affix " > < li class = "part-title" > Setup< / li > < li class = "chapter-item expanded " > < a href = "setup/installation.html" > Installation< / a > < / li > < li class = "chapter-item expanded " > < a href = "postgres.html" > Using Postgres< / a > < / li > < li class = "chapter-item expanded " > < a href = "reverse_proxy.html" > Configuring a Reverse Proxy< / a > < / li > < li class = "chapter-item expanded " > < a href = "setup/forward_proxy.html" > Configuring a Forward/Outbound Proxy< / a > < / li > < li class = "chapter-item expanded " > < a href = "turn-howto.html" > Configuring a Turn Server< / a > < / li > < li class = "chapter-item expanded " > < a href = "delegate.html" > Delegation< / a > < / li > < li class = "chapter-item expanded affix " > < li class = "part-title" > Upgrading< / li > < li class = "chapter-item expanded " > < a href = "upgrade.html" > Upgrading between Synapse Versions< / a > < / li > < li class = "chapter-item expanded affix " > < li class = "part-title" > Usage< / li > < li class = "chapter-item expanded " > < a href = "federate.html" > Federation< / a > < / li > < li class = "chapter-item expanded " > < a href = "usage/configuration/index.html" > Configuration< / a > < / li > < li > < ol class = "section" > < li class = "chapter-item expanded " > < a href = "usage/configuration/homeserver_sample_config.html" > Homeserver Sample Config File< / a > < / li > < li class = "chapter-item expanded " > < a href = "usage/configuration/logging_sample_config.html" > Logging Sample Config File< / a > < / li > < li class = "chapter-item expanded " > < a href = "structured_logging.html" > Structured Logging< / a > < / li > < li class = "chapter-item expanded " > < a href = "templates.html" > Templates< / a > < / li > < li class = "chapter-item expanded " > < a href = "usage/configuration/user_authentication/index.html" > User Authentication< / a > < / li > < li > < ol class = "section" > < li class = "chapter-item expanded " > < a href = "usage/configuration/user_authentication/single_sign_on/index.html" > Single-Sign On< / a > < / li > < li > < ol class = "section" > < li class = "chapter-item expanded " > < a href = "openid.html" > OpenID Connect< / a > < / li > < li class = "chapter-item expanded " > < a href = "usage/configuration/user_authentication/single_sign_on/saml.html" > SAML< / a > < / li > < li class = "chapter-item expanded " > < a href = "usage/configuration/user_authentication/single_sign_on/cas.html" > CAS< / a > < / li > < li class = "chapter-item expanded " > < a href = "sso_mapping_providers.html" > SSO Mapping Providers< / a > < / li > < / ol > < / li > < li class = "chapter-item expanded " > < a href = "password_auth_providers.html" > Password Auth Providers< / a > < / li > < li class = "chapter-item expanded " > < a href = "jwt.html" > JSON Web Tokens< / a > < / li > < li class = "chapter-item expanded " > < a href = "usage/configuration/user_authentication/refresh_tokens.html" > Refresh Tokens< / a > < / li > < / ol > < / li > < li class = "chapter-item expanded " > < a href = "CAPTCHA_SETUP.html" > Registration Captcha< / a > < / li > < li class = "chapter-item expanded " > < a href = "application_services.html" > Application Services< / a > < / li > < li class = "chapter-item expanded " > < a href = "server_notices.html" > Server Notices< / a > < / li > < li class = "chapter-item expanded " > < a href = "consent_tracking.html" > Consent Tracking< / a > < / li > < li class = "chapter-item expanded " > < a href = "development/url_previews.html" > URL Previews< / a > < / li > < li class = "chapter-item expanded " > < a href = "user_directory.html" > User Directory< / a > < / li > < li class = "chapter-item expanded " > < a href = "message_retention_policies.html" > Message Retention Policies< / a > < / li > < li class = "chapter-item expanded " > < a href = "modules/index.html" > Pluggable Modules< / a > < / li > < li > < ol class = "section" > < li class = "chapter-item expanded " > < a href = "modules/writing_a_module.html" > Writing a module< / a > < / li > < li > < ol class = "section" > < li class = "chapter-item expanded " > < a href = "modules/spam_checker_callbacks.html" > Spam checker callbacks< / a > < / li > < li class = "chapter-item expanded " > < a href = "modules/third_party_rules_callbacks.html" > Third-party rules callbacks< / a > < / li > < li class = "chapter-item expanded " > < a href = "modules/presence_router_callbacks.html" > Presence router callbacks< / a > < / li > < li class = "chapter-item expanded "
2021-07-07 03:44:14 -06:00
< / div >
< div id = "sidebar-resize-handle" class = "sidebar-resize-handle" > < / div >
< / nav >
< div id = "page-wrapper" class = "page-wrapper" >
< div class = "page" >
< div id = "menu-bar-hover-placeholder" > < / div >
< div id = "menu-bar" class = "menu-bar sticky bordered" >
< div class = "left-buttons" >
< button id = "sidebar-toggle" class = "icon-button" type = "button" title = "Toggle Table of Contents" aria-label = "Toggle Table of Contents" aria-controls = "sidebar" >
< i class = "fa fa-bars" > < / i >
< / button >
< button id = "theme-toggle" class = "icon-button" type = "button" title = "Change theme" aria-label = "Change theme" aria-haspopup = "true" aria-expanded = "false" aria-controls = "theme-list" >
< i class = "fa fa-paint-brush" > < / i >
< / button >
< ul id = "theme-list" class = "theme-popup" aria-label = "Themes" role = "menu" >
< li role = "none" > < button role = "menuitem" class = "theme" id = "light" > Light (default)< / button > < / li >
< li role = "none" > < button role = "menuitem" class = "theme" id = "rust" > Rust< / button > < / li >
< li role = "none" > < button role = "menuitem" class = "theme" id = "coal" > Coal< / button > < / li >
< li role = "none" > < button role = "menuitem" class = "theme" id = "navy" > Navy< / button > < / li >
< li role = "none" > < button role = "menuitem" class = "theme" id = "ayu" > Ayu< / button > < / li >
< / ul >
< button id = "search-toggle" class = "icon-button" type = "button" title = "Search. (Shortkey: s)" aria-label = "Toggle Searchbar" aria-expanded = "false" aria-keyshortcuts = "S" aria-controls = "searchbar" >
< i class = "fa fa-search" > < / i >
< / button >
< / div >
< h1 class = "menu-title" > Synapse< / h1 >
< div class = "right-buttons" >
< a href = "print.html" title = "Print this book" aria-label = "Print this book" >
< i id = "print-button" class = "fa fa-print" > < / i >
< / a >
< a href = "https://github.com/matrix-org/synapse" title = "Git repository" aria-label = "Git repository" >
< i id = "git-repository-button" class = "fa fa-github" > < / i >
< / a >
< a href = "https://github.com/matrix-org/synapse/edit/develop/docs/log_contexts.md" title = "Suggest an edit" aria-label = "Suggest an edit" >
< i id = "git-edit-button" class = "fa fa-edit" > < / i >
< / a >
< / div >
< / div >
< div id = "search-wrapper" class = "hidden" >
< form id = "searchbar-outer" class = "searchbar-outer" >
< input type = "search" id = "searchbar" name = "searchbar" placeholder = "Search this book ..." aria-controls = "searchresults-outer" aria-describedby = "searchresults-header" >
< / form >
< div id = "searchresults-outer" class = "searchresults-outer hidden" >
< div id = "searchresults-header" class = "searchresults-header" > < / div >
< ul id = "searchresults" >
< / ul >
< / div >
< / div >
<!-- Apply ARIA attributes after the sidebar and the sidebar toggle button are added to the DOM -->
< script type = "text/javascript" >
document.getElementById('sidebar-toggle').setAttribute('aria-expanded', sidebar === 'visible');
document.getElementById('sidebar').setAttribute('aria-hidden', sidebar !== 'visible');
Array.from(document.querySelectorAll('#sidebar a')).forEach(function(link) {
link.setAttribute('tabIndex', sidebar === 'visible' ? 0 : -1);
});
< / script >
< div id = "content" class = "content" >
< main >
<!-- Page table of contents -->
< div class = "sidetoc" >
< nav class = "pagetoc" > < / nav >
< / div >
< h1 id = "log-contexts" > < a class = "header" href = "#log-contexts" > Log Contexts< / a > < / h1 >
< p > To help track the processing of individual requests, synapse uses a
'< code > log context< / code > ' to track which request it is handling at any given
moment. This is done via a thread-local variable; a < code > logging.Filter< / code > is
then used to fish the information back out of the thread-local variable
and add it to each log record.< / p >
< p > Logcontexts are also used for CPU and database accounting, so that we
can track which requests were responsible for high CPU use or database
activity.< / p >
2021-09-21 07:05:07 -06:00
< p > The < code > synapse.logging.context< / code > module provides facilities for managing
2021-07-07 03:44:14 -06:00
the current log context (as well as providing the < code > LoggingContextFilter< / code >
class).< / p >
2021-07-29 04:09:19 -06:00
< p > Asynchronous functions make the whole thing complicated, so this document describes
2021-07-07 03:44:14 -06:00
how it all works, and how to write code which follows the rules.< / p >
2021-07-29 04:09:19 -06:00
< p > In this document, " awaitable" refers to any object which can be < code > await< / code > ed. In the context of
Synapse, that normally means either a coroutine or a Twisted
< a href = "https://twistedmatrix.com/documents/current/api/twisted.internet.defer.Deferred.html" > < code > Deferred< / code > < / a > .< / p >
< h2 id = "logcontexts-without-asynchronous-code" > < a class = "header" href = "#logcontexts-without-asynchronous-code" > Logcontexts without asynchronous code< / a > < / h2 >
< p > In the absence of any asynchronous voodoo, things are simple enough. As with
2021-07-07 03:44:14 -06:00
any code of this nature, the rule is that our function should leave
things as it found them:< / p >
< pre > < code class = "language-python" > from synapse.logging import context # omitted from future snippets
def handle_request(request_id):
request_context = context.LoggingContext()
calling_context = context.set_current_context(request_context)
try:
request_context.request = request_id
do_request_handling()
logger.debug(" finished" )
finally:
context.set_current_context(calling_context)
def do_request_handling():
logger.debug(" phew" ) # this will be logged against request_id
< / code > < / pre >
< p > LoggingContext implements the context management methods, so the above
can be written much more succinctly as:< / p >
< pre > < code class = "language-python" > def handle_request(request_id):
with context.LoggingContext() as request_context:
request_context.request = request_id
do_request_handling()
logger.debug(" finished" )
def do_request_handling():
logger.debug(" phew" )
< / code > < / pre >
2021-07-29 04:09:19 -06:00
< h2 id = "using-logcontexts-with-awaitables" > < a class = "header" href = "#using-logcontexts-with-awaitables" > Using logcontexts with awaitables< / a > < / h2 >
< p > Awaitables break the linear flow of code so that there is no longer a single entry point
where we should set the logcontext and a single exit point where we should remove it.< / p >
2021-07-07 03:44:14 -06:00
< p > Consider the example above, where < code > do_request_handling< / code > needs to do some
2021-07-29 04:09:19 -06:00
blocking operation, and returns an awaitable:< / p >
< pre > < code class = "language-python" > async def handle_request(request_id):
2021-07-07 03:44:14 -06:00
with context.LoggingContext() as request_context:
request_context.request = request_id
2021-07-29 04:09:19 -06:00
await do_request_handling()
2021-07-07 03:44:14 -06:00
logger.debug(" finished" )
< / code > < / pre >
< p > In the above flow:< / p >
< ul >
< li > The logcontext is set< / li >
2021-07-29 04:09:19 -06:00
< li > < code > do_request_handling< / code > is called, and returns an awaitable< / li >
< li > < code > handle_request< / code > awaits the awaitable< / li >
< li > Execution of < code > handle_request< / code > is suspended< / li >
2021-07-07 03:44:14 -06:00
< / ul >
< p > So we have stopped processing the request (and will probably go on to
start processing the next), without clearing the logcontext.< / p >
< p > To circumvent this problem, synapse code assumes that, wherever you have
2021-07-29 04:09:19 -06:00
an awaitable, you will want to < code > await< / code > it. To that end, whereever
functions return awaitables, we adopt the following conventions:< / p >
< p > < strong > Rules for functions returning awaitables:< / strong > < / p >
2021-07-07 03:44:14 -06:00
< blockquote >
< ul >
2021-07-29 04:09:19 -06:00
< li > If the awaitable is already complete, the function returns with the
2021-07-07 03:44:14 -06:00
same logcontext it started with.< / li >
2021-07-29 04:09:19 -06:00
< li > If the awaitable is incomplete, the function clears the logcontext
before returning; when the awaitable completes, it restores the
2021-07-07 03:44:14 -06:00
logcontext before running any callbacks.< / li >
< / ul >
< / blockquote >
< p > That sounds complicated, but actually it means a lot of code (including
the example above) " just works" . There are two cases:< / p >
< ul >
< li >
2021-07-29 04:09:19 -06:00
< p > If < code > do_request_handling< / code > returns a completed awaitable, then the
2021-07-07 03:44:14 -06:00
logcontext will still be in place. In this case, execution will
2021-07-29 04:09:19 -06:00
continue immediately after the < code > await< / code > ; the " finished" line will
2021-07-07 03:44:14 -06:00
be logged against the right context, and the < code > with< / code > block restores
the original context before we return to the caller.< / p >
< / li >
< li >
2021-07-29 04:09:19 -06:00
< p > If the returned awaitable is incomplete, < code > do_request_handling< / code > clears
2021-07-07 03:44:14 -06:00
the logcontext before returning. The logcontext is therefore clear
2021-07-29 04:09:19 -06:00
when < code > handle_request< / code > < code > await< / code > s the awaitable.< / p >
< p > Once < code > do_request_handling< / code > 's awaitable completes, it will reinstate
the logcontext, before running the second half of < code > handle_request< / code > ,
so again the " finished" line will be logged against the right context,
and the < code > with< / code > block restores the original context.< / p >
2021-07-07 03:44:14 -06:00
< / li >
< / ul >
2021-07-29 04:09:19 -06:00
< p > As an aside, it's worth noting that < code > handle_request< / code > follows our rules< / p >
< ul >
< li > though that only matters if the caller has its own logcontext which it
cares about.< / li >
< / ul >
2021-07-07 03:44:14 -06:00
< p > The following sections describe pitfalls and helpful patterns when
implementing these rules.< / p >
2021-07-29 04:09:19 -06:00
< h2 id = "always-await-your-awaitables" > < a class = "header" href = "#always-await-your-awaitables" > Always await your awaitables< / a > < / h2 >
< p > Whenever you get an awaitable back from a function, you should < code > await< / code > on
it as soon as possible. Do not pass go; do not do any logging; do not
call any other functions.< / p >
< pre > < code class = "language-python" > async def fun():
2021-07-07 03:44:14 -06:00
logger.debug(" starting" )
2021-07-29 04:09:19 -06:00
await do_some_stuff() # just like this
2021-07-07 03:44:14 -06:00
2021-07-29 04:09:19 -06:00
coro = more_stuff()
result = await coro # also fine, of course
2021-07-07 03:44:14 -06:00
return result
< / code > < / pre >
< p > Provided this pattern is followed all the way back up to the callchain
to where the logcontext was set, this will make things work out ok:
provided < code > do_some_stuff< / code > and < code > more_stuff< / code > follow the rules above, then
2021-07-29 04:09:19 -06:00
so will < code > fun< / code > .< / p >
< p > It's all too easy to forget to < code > await< / code > : for instance if we forgot that
< code > do_some_stuff< / code > returned an awaitable, we might plough on regardless. This
2021-07-07 03:44:14 -06:00
leads to a mess; it will probably work itself out eventually, but not
before a load of stuff has been logged against the wrong context.
(Normally, other things will break, more obviously, if you forget to
2021-07-29 04:09:19 -06:00
< code > await< / code > , so this tends not to be a major problem in practice.)< / p >
2021-07-07 03:44:14 -06:00
< p > Of course sometimes you need to do something a bit fancier with your
2021-07-29 04:09:19 -06:00
awaitable - not all code follows the linear A-then-B-then-C pattern.
2021-07-07 03:44:14 -06:00
Notes on implementing more complex patterns are in later sections.< / p >
2021-07-29 04:09:19 -06:00
< h2 id = "where-you-create-a-new-awaitable-make-it-follow-the-rules" > < a class = "header" href = "#where-you-create-a-new-awaitable-make-it-follow-the-rules" > Where you create a new awaitable, make it follow the rules< / a > < / h2 >
< p > Most of the time, an awaitable comes from another synapse function.
Sometimes, though, we need to make up a new awaitable, or we get an awaitable
back from external code. We need to make it follow our rules.< / p >
< p > The easy way to do it is by using < code > context.make_deferred_yieldable< / code > . Suppose we want to implement
2021-07-07 03:44:14 -06:00
< code > sleep< / code > , which returns a deferred which will run its callbacks after a
given number of seconds. That might look like:< / p >
< pre > < code class = "language-python" > # not a logcontext-rules-compliant function
def get_sleep_deferred(seconds):
d = defer.Deferred()
reactor.callLater(seconds, d.callback, None)
return d
< / code > < / pre >
2021-07-29 04:09:19 -06:00
< p > That doesn't follow the rules, but we can fix it by calling it through
< code > context.make_deferred_yieldable< / code > :< / p >
< pre > < code class = "language-python" > async def sleep(seconds):
return await context.make_deferred_yieldable(get_sleep_deferred(seconds))
2021-07-07 03:44:14 -06:00
< / code > < / pre >
< h2 id = "fire-and-forget" > < a class = "header" href = "#fire-and-forget" > Fire-and-forget< / a > < / h2 >
< p > Sometimes you want to fire off a chain of execution, but not wait for
its result. That might look a bit like this:< / p >
2021-07-29 04:09:19 -06:00
< pre > < code class = "language-python" > async def do_request_handling():
await foreground_operation()
2021-07-07 03:44:14 -06:00
# *don't* do this
background_operation()
logger.debug(" Request handling complete" )
2021-07-29 04:09:19 -06:00
async def background_operation():
await first_background_step()
2021-07-07 03:44:14 -06:00
logger.debug(" Completed first step" )
2021-07-29 04:09:19 -06:00
await second_background_step()
2021-07-07 03:44:14 -06:00
logger.debug(" Completed second step" )
< / code > < / pre >
< p > The above code does a couple of steps in the background after
< code > do_request_handling< / code > has finished. The log lines are still logged
against the < code > request_context< / code > logcontext, which may or may not be
desirable. There are two big problems with the above, however. The first
problem is that, if < code > background_operation< / code > returns an incomplete
2021-07-29 04:09:19 -06:00
awaitable, it will expect its caller to < code > await< / code > immediately, so will have
2021-07-07 03:44:14 -06:00
cleared the logcontext. In this example, that means that 'Request
handling complete' will be logged without any context.< / p >
< p > The second problem, which is potentially even worse, is that when the
2021-07-29 04:09:19 -06:00
awaitable returned by < code > background_operation< / code > completes, it will restore
the original logcontext. There is nothing waiting on that awaitable, so
2021-07-07 03:44:14 -06:00
the logcontext will leak into the reactor and possibly get attached to
some arbitrary future operation.< / p >
< p > There are two potential solutions to this.< / p >
< p > One option is to surround the call to < code > background_operation< / code > with a
< code > PreserveLoggingContext< / code > call. That will reset the logcontext before
starting < code > background_operation< / code > (so the context restored when the
deferred completes will be the empty logcontext), and will restore the
current logcontext before continuing the foreground process:< / p >
2021-07-29 04:09:19 -06:00
< pre > < code class = "language-python" > async def do_request_handling():
await foreground_operation()
2021-07-07 03:44:14 -06:00
# start background_operation off in the empty logcontext, to
# avoid leaking the current context into the reactor.
with PreserveLoggingContext():
background_operation()
# this will now be logged against the request context
logger.debug(" Request handling complete" )
< / code > < / pre >
< p > Obviously that option means that the operations done in
< code > background_operation< / code > would be not be logged against a logcontext
(though that might be fixed by setting a different logcontext via a
< code > with LoggingContext(...)< / code > in < code > background_operation< / code > ).< / p >
< p > The second option is to use < code > context.run_in_background< / code > , which wraps a
function so that it doesn't reset the logcontext even when it returns
2021-07-29 04:09:19 -06:00
an incomplete awaitable, and adds a callback to the returned awaitable to
2021-07-07 03:44:14 -06:00
reset the logcontext. In other words, it turns a function that follows
2021-07-29 04:09:19 -06:00
the Synapse rules about logcontexts and awaitables into one which behaves
2021-07-07 03:44:14 -06:00
more like an external function --- the opposite operation to that
described in the previous section. It can be used like this:< / p >
2021-07-29 04:09:19 -06:00
< pre > < code class = "language-python" > async def do_request_handling():
await foreground_operation()
2021-07-07 03:44:14 -06:00
context.run_in_background(background_operation)
# this will now be logged against the request context
logger.debug(" Request handling complete" )
< / code > < / pre >
< h2 id = "passing-synapse-deferreds-into-third-party-functions" > < a class = "header" href = "#passing-synapse-deferreds-into-third-party-functions" > Passing synapse deferreds into third-party functions< / a > < / h2 >
< p > A typical example of this is where we want to collect together two or
2021-07-29 04:09:19 -06:00
more awaitables via < code > defer.gatherResults< / code > :< / p >
< pre > < code class = "language-python" > a1 = operation1()
a2 = operation2()
a3 = defer.gatherResults([a1, a2])
2021-07-07 03:44:14 -06:00
< / code > < / pre >
< p > This is really a variation of the fire-and-forget problem above, in that
2021-07-29 04:09:19 -06:00
we are firing off < code > a1< / code > and < code > a2< / code > without awaiting on them. The difference
2021-07-07 03:44:14 -06:00
is that we now have third-party code attached to their callbacks. Anyway
either technique given in the < a href = "#fire-and-forget" > Fire-and-forget< / a >
section will work.< / p >
2021-07-29 04:09:19 -06:00
< p > Of course, the new awaitable returned by < code > gather< / code > needs to be
2021-07-07 03:44:14 -06:00
wrapped in order to make it follow the logcontext rules before we can
2021-07-29 04:09:19 -06:00
yield it, as described in < a href = "#where-you-create-a-new-awaitable-make-it-follow-the-rules" > Where you create a new awaitable, make it
2021-07-07 03:44:14 -06:00
follow the
rules< / a > .< / p >
< p > So, option one: reset the logcontext before starting the operations to
be gathered:< / p >
2021-07-29 04:09:19 -06:00
< pre > < code class = "language-python" > async def do_request_handling():
2021-07-07 03:44:14 -06:00
with PreserveLoggingContext():
2021-07-29 04:09:19 -06:00
a1 = operation1()
a2 = operation2()
result = await defer.gatherResults([a1, a2])
2021-07-07 03:44:14 -06:00
< / code > < / pre >
< p > In this case particularly, though, option two, of using
2021-07-29 04:09:19 -06:00
< code > context.run_in_background< / code > almost certainly makes more sense, so that
2021-07-07 03:44:14 -06:00
< code > operation1< / code > and < code > operation2< / code > are both logged against the original
logcontext. This looks like:< / p >
2021-07-29 04:09:19 -06:00
< pre > < code class = "language-python" > async def do_request_handling():
a1 = context.run_in_background(operation1)
a2 = context.run_in_background(operation2)
2021-07-07 03:44:14 -06:00
2021-07-29 04:09:19 -06:00
result = await make_deferred_yieldable(defer.gatherResults([a1, a2]))
2021-07-07 03:44:14 -06:00
< / code > < / pre >
2021-07-29 04:09:19 -06:00
< h2 id = "a-note-on-garbage-collection-of-awaitable-chains" > < a class = "header" href = "#a-note-on-garbage-collection-of-awaitable-chains" > A note on garbage-collection of awaitable chains< / a > < / h2 >
< p > It turns out that our logcontext rules do not play nicely with awaitable
2021-07-07 03:44:14 -06:00
chains which get orphaned and garbage-collected.< / p >
< p > Imagine we have some code that looks like this:< / p >
< pre > < code class = "language-python" > listener_queue = []
def on_something_interesting():
for d in listener_queue:
d.callback(" foo" )
2021-07-29 04:09:19 -06:00
async def await_something_interesting():
new_awaitable = defer.Deferred()
listener_queue.append(new_awaitable)
2021-07-07 03:44:14 -06:00
with PreserveLoggingContext():
2021-07-29 04:09:19 -06:00
await new_awaitable
2021-07-07 03:44:14 -06:00
< / code > < / pre >
< p > Obviously, the idea here is that we have a bunch of things which are
waiting for an event. (It's just an example of the problem here, but a
relatively common one.)< / p >
< p > Now let's imagine two further things happen. First of all, whatever was
waiting for the interesting thing goes away. (Perhaps the request times
out, or something < em > even more< / em > interesting happens.)< / p >
< p > Secondly, let's suppose that we decide that the interesting thing is
never going to happen, and we reset the listener queue:< / p >
< pre > < code class = "language-python" > def reset_listener_queue():
listener_queue.clear()
< / code > < / pre >
2021-07-29 04:09:19 -06:00
< p > So, both ends of the awaitable chain have now dropped their references,
and the awaitable chain is now orphaned, and will be garbage-collected at
some point. Note that < code > await_something_interesting< / code > is a coroutine,
which Python implements as a generator function. When Python
garbage-collects generator functions, it gives them a chance to
2021-09-21 07:05:07 -06:00
clean up by making the < code > await< / code > (or < code > yield< / code > ) raise a < code > GeneratorExit< / code >
2021-07-07 03:44:14 -06:00
exception. In our case, that means that the < code > __exit__< / code > handler of
< code > PreserveLoggingContext< / code > will carefully restore the request context, but
there is now nothing waiting for its return, so the request context is
never cleared.< / p >
2021-07-29 04:09:19 -06:00
< p > To reiterate, this problem only arises when < em > both< / em > ends of a awaitable
chain are dropped. Dropping the the reference to an awaitable you're
supposed to be awaiting is bad practice, so this doesn't
2021-07-07 03:44:14 -06:00
actually happen too much. Unfortunately, when it does happen, it will
lead to leaked logcontexts which are incredibly hard to track down.< / p >
< / main >
< nav class = "nav-wrapper" aria-label = "Page navigation" >
<!-- Mobile navigation buttons -->
2021-10-05 07:13:48 -06:00
< a rel = "prev" href = "development/experimental_features.html" class = "mobile-nav-chapters previous" title = "Previous chapter" aria-label = "Previous chapter" aria-keyshortcuts = "Left" >
2021-07-07 03:44:14 -06:00
< i class = "fa fa-angle-left" > < / i >
< / a >
< a rel = "next" href = "replication.html" class = "mobile-nav-chapters next" title = "Next chapter" aria-label = "Next chapter" aria-keyshortcuts = "Right" >
< i class = "fa fa-angle-right" > < / i >
< / a >
< div style = "clear: both" > < / div >
< / nav >
< / div >
< / div >
< nav class = "nav-wide-wrapper" aria-label = "Page navigation" >
2021-10-05 07:13:48 -06:00
< a rel = "prev" href = "development/experimental_features.html" class = "nav-chapters previous" title = "Previous chapter" aria-label = "Previous chapter" aria-keyshortcuts = "Left" >
2021-07-07 03:44:14 -06:00
< i class = "fa fa-angle-left" > < / i >
< / a >
< a rel = "next" href = "replication.html" class = "nav-chapters next" title = "Next chapter" aria-label = "Next chapter" aria-keyshortcuts = "Right" >
< i class = "fa fa-angle-right" > < / i >
< / a >
< / nav >
< / div >
< script type = "text/javascript" >
window.playground_copyable = true;
< / script >
< script src = "elasticlunr.min.js" type = "text/javascript" charset = "utf-8" > < / script >
< script src = "mark.min.js" type = "text/javascript" charset = "utf-8" > < / script >
< script src = "searcher.js" type = "text/javascript" charset = "utf-8" > < / script >
< script src = "clipboard.min.js" type = "text/javascript" charset = "utf-8" > < / script >
< script src = "highlight.js" type = "text/javascript" charset = "utf-8" > < / script >
< script src = "book.js" type = "text/javascript" charset = "utf-8" > < / script >
<!-- Custom JS scripts -->
< script type = "text/javascript" src = "docs/website_files/table-of-contents.js" > < / script >
< / body >
< / html >
