log_contexts.html 37 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500
  1. <!DOCTYPE HTML>
  2. <html lang="en" class="sidebar-visible no-js light">
  3. <head>
  4. <!-- Book generated using mdBook -->
  5. <meta charset="UTF-8">
  6. <title>Log Contexts - Synapse</title>
  7. <!-- Custom HTML head -->
  8. <meta content="text/html; charset=utf-8" http-equiv="Content-Type">
  9. <meta name="description" content="">
  10. <meta name="viewport" content="width=device-width, initial-scale=1">
  11. <meta name="theme-color" content="#ffffff" />
  12. <link rel="icon" href="favicon.svg">
  13. <link rel="shortcut icon" href="favicon.png">
  14. <link rel="stylesheet" href="css/variables.css">
  15. <link rel="stylesheet" href="css/general.css">
  16. <link rel="stylesheet" href="css/chrome.css">
  17. <link rel="stylesheet" href="css/print.css" media="print">
  18. <!-- Fonts -->
  19. <link rel="stylesheet" href="FontAwesome/css/font-awesome.css">
  20. <link rel="stylesheet" href="fonts/fonts.css">
  21. <!-- Highlight.js Stylesheets -->
  22. <link rel="stylesheet" href="highlight.css">
  23. <link rel="stylesheet" href="tomorrow-night.css">
  24. <link rel="stylesheet" href="ayu-highlight.css">
  25. <!-- Custom theme stylesheets -->
  26. <link rel="stylesheet" href="docs/website_files/table-of-contents.css">
  27. <link rel="stylesheet" href="docs/website_files/remove-nav-buttons.css">
  28. <link rel="stylesheet" href="docs/website_files/indent-section-headers.css">
  29. <link rel="stylesheet" href="docs/website_files/version-picker.css">
  30. </head>
  31. <body>
  32. <!-- Provide site root to javascript -->
  33. <script type="text/javascript">
  34. var path_to_root = "";
  35. var default_theme = window.matchMedia("(prefers-color-scheme: dark)").matches ? "navy" : "light";
  36. </script>
  37. <!-- Work around some values being stored in localStorage wrapped in quotes -->
  38. <script type="text/javascript">
  39. try {
  40. var theme = localStorage.getItem('mdbook-theme');
  41. var sidebar = localStorage.getItem('mdbook-sidebar');
  42. if (theme.startsWith('"') && theme.endsWith('"')) {
  43. localStorage.setItem('mdbook-theme', theme.slice(1, theme.length - 1));
  44. }
  45. if (sidebar.startsWith('"') && sidebar.endsWith('"')) {
  46. localStorage.setItem('mdbook-sidebar', sidebar.slice(1, sidebar.length - 1));
  47. }
  48. } catch (e) { }
  49. </script>
  50. <!-- Set the theme before any content is loaded, prevents flash -->
  51. <script type="text/javascript">
  52. var theme;
  53. try { theme = localStorage.getItem('mdbook-theme'); } catch(e) { }
  54. if (theme === null || theme === undefined) { theme = default_theme; }
  55. var html = document.querySelector('html');
  56. html.classList.remove('no-js')
  57. html.classList.remove('light')
  58. html.classList.add(theme);
  59. html.classList.add('js');
  60. </script>
  61. <!-- Hide / unhide sidebar before it is displayed -->
  62. <script type="text/javascript">
  63. var html = document.querySelector('html');
  64. var sidebar = 'hidden';
  65. if (document.body.clientWidth >= 1080) {
  66. try { sidebar = localStorage.getItem('mdbook-sidebar'); } catch(e) { }
  67. sidebar = sidebar || 'visible';
  68. }
  69. html.classList.remove('sidebar-visible');
  70. html.classList.add("sidebar-" + sidebar);
  71. </script>
  72. <nav id="sidebar" class="sidebar" aria-label="Table of contents">
  73. <div class="sidebar-scrollbox">
  74. <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/config_documentation.html">Configuration Manual</a></li><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="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 "><a href="modules/account_validity_callbacks.html">Account validity callbacks</a></li><li class="chapter-item expanded "><a href="modules/password_auth_provider_callbacks.html">Password auth provider callbacks</a></li><li class="chapter-item expanded "><a href="modules/background_update_controller_callbacks.html">Background update controller callbacks</a></li><li class="chapter-item expanded "><a href="modules/account_data_callbacks.html">Account data callbacks</a></li><li class="chapter-item expanded "><a href="modules/porting_legacy_module.html">Porting a legacy module to the new interface</a></li></ol></li></ol></li><li class="chapter-item expanded "><a href="workers.html">Workers</a></li><li><ol class="section"><li class="chapter-item expanded "><a href="synctl_workers.html">Using synctl with Workers</a></li><li class="chapter-item expanded "><a href="systemd-with-workers/index.html">Systemd</a></li></ol></li></ol></li><li class="chapter-item expanded "><a href="usage/administration/index.html">Administration</a></li><li><ol class="section"><li class="chapter-item expanded "><a href="usage/administration/admin_api/index.html">Admin API</a></li><li><ol class="section"><li class="chapter-item expanded "><a href="admin_api/account_validity.html">Account Validity</a></li><li class="chapter-item expanded "><a href="usage/administration/admin_api/background_updates.html">Background Updates</a></li><li class="chapter-item expanded "><a href="admin_api/event_reports.html">Event Reports</a></li><li class="chapter-item expanded "><a href="admin_api/media_admin_api.html">Media</a></li><li class="chapter-item expanded "><a href="admin_api/purge_history_api.html">Purge History</a></li><li class="chapter-item expanded "><a href="admin_api/register_api.html">Register Users</a></li><li class="chapter-item expanded "><a href="usage/administration/admin_api/registration_tokens.html">Registration Tokens</a></li><li class="chapter-item expanded "><a href="admin_api/room_membership.html">Manipulate Room Membership</a></li><li class="chapter-item expanded "><a href="admin_api/rooms.html">Rooms</a></li><li class="chapter-item expanded "><a href="admin_api/server_notices.html">Server Notices</a></li><li class="chapter-item expanded "><a href="admin_api/statistics.html">Statistics</a></li><li class="chapter-item expanded "><a href="admin_api/user_admin_api.html">Users</a></li><li class="chapter-item expanded "><a href="admin_api/version_api.html">Server Version</a></li><li class="chapter-item expanded "><a href="usage/administration/admin_api/federation.html">Federation</a></li></ol></li><li class="chapter-item expanded "><a href="manhole.html">Manhole</a></li><li class="chapter-item expanded "><a href="metrics-howto.html">Monitoring</a></li><li><ol class="section"><li class="chapter-item expanded "><a href="usage/administration/monitoring/reporting_homeserver_usage_statistics.html">Reporting Homeserver Usage Statistics</a></li></ol></li><li class="chapter-item expanded "><a href="usage/administration/monthly_active_users.html">Monthly Active Users</a></li><li class="chapter-item expanded "><a href="usage/administration/understanding_synapse_through_grafana_graphs.html">Understanding Synapse Through Grafana Graphs</a></li><li class="chapter-item expanded "><a href="usage/administration/useful_sql_for_admins.html">Useful SQL for Admins</a></li><li class="chapter-item expanded "><a href="usage/administration/database_maintenance_tools.html">Database Maintenance Tools</a></li><li class="chapter-item expanded "><a href="usage/administration/state_groups.html">State Groups</a></li><li class="chapter-item expanded "><a href="usage/administration/request_log.html">Request log format</a></li><li class="chapter-item expanded "><a href="usage/administration/admin_faq.html">Admin FAQ</a></li><li class="chapter-item expanded "><div>Scripts</div></li></ol></li><li class="chapter-item expanded "><li class="part-title">Development</li><li class="chapter-item expanded "><a href="development/contributing_guide.html">Contributing Guide</a></li><li class="chapter-item expanded "><a href="code_style.html">Code Style</a></li><li class="chapter-item expanded "><a href="development/reviews.html">Reviewing Code</a></li><li class="chapter-item expanded "><a href="development/releases.html">Release Cycle</a></li><li class="chapter-item expanded "><a href="development/git.html">Git Usage</a></li><li class="chapter-item expanded "><div>Testing</div></li><li><ol class="section"><li class="chapter-item expanded "><a href="development/demo.html">Demo scripts</a></li></ol></li><li class="chapter-item expanded "><a href="opentracing.html">OpenTracing</a></li><li class="chapter-item expanded "><a href="development/database_schema.html">Database Schemas</a></li><li class="chapter-item expanded "><a href="development/experimental_features.html">Experimental features</a></li><li class="chapter-item expanded "><a href="development/dependencies.html">Dependency management</a></li><li class="chapter-item expanded "><div>Synapse Architecture</div></li><li><ol class="section"><li class="chapter-item expanded "><a href="development/synapse_architecture/cancellation.html">Cancellation</a></li><li class="chapter-item expanded "><a href="log_contexts.html" class="active">Log Contexts</a></li><li class="chapter-item expanded "><a href="replication.html">Replication</a></li><li class="chapter-item expanded "><a href="tcp_replication.html">TCP Replication</a></li></ol></li><li class="chapter-item expanded "><a href="development/internal_documentation/index.html">Internal Documentation</a></li><li><ol class="section"><li class="chapter-item expanded "><div>Single Sign-On</div></li><li><ol class="section"><li class="chapter-item expanded "><a href="development/saml.html">SAML</a></li><li class="chapter-item expanded "><a href="development/cas.html">CAS</a></li></ol></li><li class="chapter-item expanded "><a href="development/room-dag-concepts.html">Room DAG concepts</a></li><li class="chapter-item expanded "><div>State Resolution</div></li><li><ol class="section"><li class="chapter-item expanded "><a href="auth_chain_difference_algorithm.html">The Auth Chain Difference Algorithm</a></li></ol></li><li class="chapter-item expanded "><a href="media_repository.html">Media Repository</a></li><li class="chapter-item expanded "><a href="room_and_user_statistics.html">Room and User Statistics</a></li></ol></li><li class="chapter-item expanded "><div>Scripts</div></li><li class="chapter-item expanded affix "><li class="part-title">Other</li><li class="chapter-item expanded "><a href="deprecation_policy.html">Dependency Deprecation Policy</a></li><li class="chapter-item expanded "><a href="other/running_synapse_on_single_board_computers.html">Running Synapse on a Single-Board Computer</a></li></ol>
  75. </div>
  76. <div id="sidebar-resize-handle" class="sidebar-resize-handle"></div>
  77. </nav>
  78. <div id="page-wrapper" class="page-wrapper">
  79. <div class="page">
  80. <div id="menu-bar-hover-placeholder"></div>
  81. <div id="menu-bar" class="menu-bar sticky bordered">
  82. <div class="left-buttons">
  83. <button id="sidebar-toggle" class="icon-button" type="button" title="Toggle Table of Contents" aria-label="Toggle Table of Contents" aria-controls="sidebar">
  84. <i class="fa fa-bars"></i>
  85. </button>
  86. <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">
  87. <i class="fa fa-paint-brush"></i>
  88. </button>
  89. <ul id="theme-list" class="theme-popup" aria-label="Themes" role="menu">
  90. <li role="none"><button role="menuitem" class="theme" id="light">Light (default)</button></li>
  91. <li role="none"><button role="menuitem" class="theme" id="rust">Rust</button></li>
  92. <li role="none"><button role="menuitem" class="theme" id="coal">Coal</button></li>
  93. <li role="none"><button role="menuitem" class="theme" id="navy">Navy</button></li>
  94. <li role="none"><button role="menuitem" class="theme" id="ayu">Ayu</button></li>
  95. </ul>
  96. <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">
  97. <i class="fa fa-search"></i>
  98. </button>
  99. <div class="version-picker">
  100. <div class="dropdown">
  101. <div class="select">
  102. <span></span>
  103. <i class="fa fa-chevron-down"></i>
  104. </div>
  105. <input type="hidden" name="version">
  106. <ul class="dropdown-menu">
  107. <!-- Versions will be added dynamically in version-picker.js -->
  108. </ul>
  109. </div>
  110. </div>
  111. </div>
  112. <h1 class="menu-title">Synapse</h1>
  113. <div class="right-buttons">
  114. <a href="print.html" title="Print this book" aria-label="Print this book">
  115. <i id="print-button" class="fa fa-print"></i>
  116. </a>
  117. <a href="https://github.com/matrix-org/synapse" title="Git repository" aria-label="Git repository">
  118. <i id="git-repository-button" class="fa fa-github"></i>
  119. </a>
  120. <a href="https://github.com/matrix-org/synapse/edit/develop/docs/log_contexts.md" title="Suggest an edit" aria-label="Suggest an edit">
  121. <i id="git-edit-button" class="fa fa-edit"></i>
  122. </a>
  123. </div>
  124. </div>
  125. <div id="search-wrapper" class="hidden">
  126. <form id="searchbar-outer" class="searchbar-outer">
  127. <input type="search" id="searchbar" name="searchbar" placeholder="Search this book ..." aria-controls="searchresults-outer" aria-describedby="searchresults-header">
  128. </form>
  129. <div id="searchresults-outer" class="searchresults-outer hidden">
  130. <div id="searchresults-header" class="searchresults-header"></div>
  131. <ul id="searchresults">
  132. </ul>
  133. </div>
  134. </div>
  135. <!-- Apply ARIA attributes after the sidebar and the sidebar toggle button are added to the DOM -->
  136. <script type="text/javascript">
  137. document.getElementById('sidebar-toggle').setAttribute('aria-expanded', sidebar === 'visible');
  138. document.getElementById('sidebar').setAttribute('aria-hidden', sidebar !== 'visible');
  139. Array.from(document.querySelectorAll('#sidebar a')).forEach(function(link) {
  140. link.setAttribute('tabIndex', sidebar === 'visible' ? 0 : -1);
  141. });
  142. </script>
  143. <div id="content" class="content">
  144. <main>
  145. <!-- Page table of contents -->
  146. <div class="sidetoc">
  147. <nav class="pagetoc"></nav>
  148. </div>
  149. <h1 id="log-contexts"><a class="header" href="#log-contexts">Log Contexts</a></h1>
  150. <p>To help track the processing of individual requests, synapse uses a
  151. '<code>log context</code>' to track which request it is handling at any given
  152. moment. This is done via a thread-local variable; a <code>logging.Filter</code> is
  153. then used to fish the information back out of the thread-local variable
  154. and add it to each log record.</p>
  155. <p>Logcontexts are also used for CPU and database accounting, so that we
  156. can track which requests were responsible for high CPU use or database
  157. activity.</p>
  158. <p>The <code>synapse.logging.context</code> module provides facilities for managing
  159. the current log context (as well as providing the <code>LoggingContextFilter</code>
  160. class).</p>
  161. <p>Asynchronous functions make the whole thing complicated, so this document describes
  162. how it all works, and how to write code which follows the rules.</p>
  163. <p>In this document, &quot;awaitable&quot; refers to any object which can be <code>await</code>ed. In the context of
  164. Synapse, that normally means either a coroutine or a Twisted
  165. <a href="https://twistedmatrix.com/documents/current/api/twisted.internet.defer.Deferred.html"><code>Deferred</code></a>.</p>
  166. <h2 id="logcontexts-without-asynchronous-code"><a class="header" href="#logcontexts-without-asynchronous-code">Logcontexts without asynchronous code</a></h2>
  167. <p>In the absence of any asynchronous voodoo, things are simple enough. As with
  168. any code of this nature, the rule is that our function should leave
  169. things as it found them:</p>
  170. <pre><code class="language-python">from synapse.logging import context # omitted from future snippets
  171. def handle_request(request_id):
  172. request_context = context.LoggingContext()
  173. calling_context = context.set_current_context(request_context)
  174. try:
  175. request_context.request = request_id
  176. do_request_handling()
  177. logger.debug(&quot;finished&quot;)
  178. finally:
  179. context.set_current_context(calling_context)
  180. def do_request_handling():
  181. logger.debug(&quot;phew&quot;) # this will be logged against request_id
  182. </code></pre>
  183. <p>LoggingContext implements the context management methods, so the above
  184. can be written much more succinctly as:</p>
  185. <pre><code class="language-python">def handle_request(request_id):
  186. with context.LoggingContext() as request_context:
  187. request_context.request = request_id
  188. do_request_handling()
  189. logger.debug(&quot;finished&quot;)
  190. def do_request_handling():
  191. logger.debug(&quot;phew&quot;)
  192. </code></pre>
  193. <h2 id="using-logcontexts-with-awaitables"><a class="header" href="#using-logcontexts-with-awaitables">Using logcontexts with awaitables</a></h2>
  194. <p>Awaitables break the linear flow of code so that there is no longer a single entry point
  195. where we should set the logcontext and a single exit point where we should remove it.</p>
  196. <p>Consider the example above, where <code>do_request_handling</code> needs to do some
  197. blocking operation, and returns an awaitable:</p>
  198. <pre><code class="language-python">async def handle_request(request_id):
  199. with context.LoggingContext() as request_context:
  200. request_context.request = request_id
  201. await do_request_handling()
  202. logger.debug(&quot;finished&quot;)
  203. </code></pre>
  204. <p>In the above flow:</p>
  205. <ul>
  206. <li>The logcontext is set</li>
  207. <li><code>do_request_handling</code> is called, and returns an awaitable</li>
  208. <li><code>handle_request</code> awaits the awaitable</li>
  209. <li>Execution of <code>handle_request</code> is suspended</li>
  210. </ul>
  211. <p>So we have stopped processing the request (and will probably go on to
  212. start processing the next), without clearing the logcontext.</p>
  213. <p>To circumvent this problem, synapse code assumes that, wherever you have
  214. an awaitable, you will want to <code>await</code> it. To that end, whereever
  215. functions return awaitables, we adopt the following conventions:</p>
  216. <p><strong>Rules for functions returning awaitables:</strong></p>
  217. <blockquote>
  218. <ul>
  219. <li>If the awaitable is already complete, the function returns with the
  220. same logcontext it started with.</li>
  221. <li>If the awaitable is incomplete, the function clears the logcontext
  222. before returning; when the awaitable completes, it restores the
  223. logcontext before running any callbacks.</li>
  224. </ul>
  225. </blockquote>
  226. <p>That sounds complicated, but actually it means a lot of code (including
  227. the example above) &quot;just works&quot;. There are two cases:</p>
  228. <ul>
  229. <li>
  230. <p>If <code>do_request_handling</code> returns a completed awaitable, then the
  231. logcontext will still be in place. In this case, execution will
  232. continue immediately after the <code>await</code>; the &quot;finished&quot; line will
  233. be logged against the right context, and the <code>with</code> block restores
  234. the original context before we return to the caller.</p>
  235. </li>
  236. <li>
  237. <p>If the returned awaitable is incomplete, <code>do_request_handling</code> clears
  238. the logcontext before returning. The logcontext is therefore clear
  239. when <code>handle_request</code> <code>await</code>s the awaitable.</p>
  240. <p>Once <code>do_request_handling</code>'s awaitable completes, it will reinstate
  241. the logcontext, before running the second half of <code>handle_request</code>,
  242. so again the &quot;finished&quot; line will be logged against the right context,
  243. and the <code>with</code> block restores the original context.</p>
  244. </li>
  245. </ul>
  246. <p>As an aside, it's worth noting that <code>handle_request</code> follows our rules</p>
  247. <ul>
  248. <li>though that only matters if the caller has its own logcontext which it
  249. cares about.</li>
  250. </ul>
  251. <p>The following sections describe pitfalls and helpful patterns when
  252. implementing these rules.</p>
  253. <h2 id="always-await-your-awaitables"><a class="header" href="#always-await-your-awaitables">Always await your awaitables</a></h2>
  254. <p>Whenever you get an awaitable back from a function, you should <code>await</code> on
  255. it as soon as possible. Do not pass go; do not do any logging; do not
  256. call any other functions.</p>
  257. <pre><code class="language-python">async def fun():
  258. logger.debug(&quot;starting&quot;)
  259. await do_some_stuff() # just like this
  260. coro = more_stuff()
  261. result = await coro # also fine, of course
  262. return result
  263. </code></pre>
  264. <p>Provided this pattern is followed all the way back up to the callchain
  265. to where the logcontext was set, this will make things work out ok:
  266. provided <code>do_some_stuff</code> and <code>more_stuff</code> follow the rules above, then
  267. so will <code>fun</code>.</p>
  268. <p>It's all too easy to forget to <code>await</code>: for instance if we forgot that
  269. <code>do_some_stuff</code> returned an awaitable, we might plough on regardless. This
  270. leads to a mess; it will probably work itself out eventually, but not
  271. before a load of stuff has been logged against the wrong context.
  272. (Normally, other things will break, more obviously, if you forget to
  273. <code>await</code>, so this tends not to be a major problem in practice.)</p>
  274. <p>Of course sometimes you need to do something a bit fancier with your
  275. awaitable - not all code follows the linear A-then-B-then-C pattern.
  276. Notes on implementing more complex patterns are in later sections.</p>
  277. <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>
  278. <p>Most of the time, an awaitable comes from another synapse function.
  279. Sometimes, though, we need to make up a new awaitable, or we get an awaitable
  280. back from external code. We need to make it follow our rules.</p>
  281. <p>The easy way to do it is by using <code>context.make_deferred_yieldable</code>. Suppose we want to implement
  282. <code>sleep</code>, which returns a deferred which will run its callbacks after a
  283. given number of seconds. That might look like:</p>
  284. <pre><code class="language-python"># not a logcontext-rules-compliant function
  285. def get_sleep_deferred(seconds):
  286. d = defer.Deferred()
  287. reactor.callLater(seconds, d.callback, None)
  288. return d
  289. </code></pre>
  290. <p>That doesn't follow the rules, but we can fix it by calling it through
  291. <code>context.make_deferred_yieldable</code>:</p>
  292. <pre><code class="language-python">async def sleep(seconds):
  293. return await context.make_deferred_yieldable(get_sleep_deferred(seconds))
  294. </code></pre>
  295. <h2 id="fire-and-forget"><a class="header" href="#fire-and-forget">Fire-and-forget</a></h2>
  296. <p>Sometimes you want to fire off a chain of execution, but not wait for
  297. its result. That might look a bit like this:</p>
  298. <pre><code class="language-python">async def do_request_handling():
  299. await foreground_operation()
  300. # *don't* do this
  301. background_operation()
  302. logger.debug(&quot;Request handling complete&quot;)
  303. async def background_operation():
  304. await first_background_step()
  305. logger.debug(&quot;Completed first step&quot;)
  306. await second_background_step()
  307. logger.debug(&quot;Completed second step&quot;)
  308. </code></pre>
  309. <p>The above code does a couple of steps in the background after
  310. <code>do_request_handling</code> has finished. The log lines are still logged
  311. against the <code>request_context</code> logcontext, which may or may not be
  312. desirable. There are two big problems with the above, however. The first
  313. problem is that, if <code>background_operation</code> returns an incomplete
  314. awaitable, it will expect its caller to <code>await</code> immediately, so will have
  315. cleared the logcontext. In this example, that means that 'Request
  316. handling complete' will be logged without any context.</p>
  317. <p>The second problem, which is potentially even worse, is that when the
  318. awaitable returned by <code>background_operation</code> completes, it will restore
  319. the original logcontext. There is nothing waiting on that awaitable, so
  320. the logcontext will leak into the reactor and possibly get attached to
  321. some arbitrary future operation.</p>
  322. <p>There are two potential solutions to this.</p>
  323. <p>One option is to surround the call to <code>background_operation</code> with a
  324. <code>PreserveLoggingContext</code> call. That will reset the logcontext before
  325. starting <code>background_operation</code> (so the context restored when the
  326. deferred completes will be the empty logcontext), and will restore the
  327. current logcontext before continuing the foreground process:</p>
  328. <pre><code class="language-python">async def do_request_handling():
  329. await foreground_operation()
  330. # start background_operation off in the empty logcontext, to
  331. # avoid leaking the current context into the reactor.
  332. with PreserveLoggingContext():
  333. background_operation()
  334. # this will now be logged against the request context
  335. logger.debug(&quot;Request handling complete&quot;)
  336. </code></pre>
  337. <p>Obviously that option means that the operations done in
  338. <code>background_operation</code> would be not be logged against a logcontext
  339. (though that might be fixed by setting a different logcontext via a
  340. <code>with LoggingContext(...)</code> in <code>background_operation</code>).</p>
  341. <p>The second option is to use <code>context.run_in_background</code>, which wraps a
  342. function so that it doesn't reset the logcontext even when it returns
  343. an incomplete awaitable, and adds a callback to the returned awaitable to
  344. reset the logcontext. In other words, it turns a function that follows
  345. the Synapse rules about logcontexts and awaitables into one which behaves
  346. more like an external function --- the opposite operation to that
  347. described in the previous section. It can be used like this:</p>
  348. <pre><code class="language-python">async def do_request_handling():
  349. await foreground_operation()
  350. context.run_in_background(background_operation)
  351. # this will now be logged against the request context
  352. logger.debug(&quot;Request handling complete&quot;)
  353. </code></pre>
  354. <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>
  355. <p>A typical example of this is where we want to collect together two or
  356. more awaitables via <code>defer.gatherResults</code>:</p>
  357. <pre><code class="language-python">a1 = operation1()
  358. a2 = operation2()
  359. a3 = defer.gatherResults([a1, a2])
  360. </code></pre>
  361. <p>This is really a variation of the fire-and-forget problem above, in that
  362. we are firing off <code>a1</code> and <code>a2</code> without awaiting on them. The difference
  363. is that we now have third-party code attached to their callbacks. Anyway
  364. either technique given in the <a href="#fire-and-forget">Fire-and-forget</a>
  365. section will work.</p>
  366. <p>Of course, the new awaitable returned by <code>gather</code> needs to be
  367. wrapped in order to make it follow the logcontext rules before we can
  368. 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
  369. follow the
  370. rules</a>.</p>
  371. <p>So, option one: reset the logcontext before starting the operations to
  372. be gathered:</p>
  373. <pre><code class="language-python">async def do_request_handling():
  374. with PreserveLoggingContext():
  375. a1 = operation1()
  376. a2 = operation2()
  377. result = await defer.gatherResults([a1, a2])
  378. </code></pre>
  379. <p>In this case particularly, though, option two, of using
  380. <code>context.run_in_background</code> almost certainly makes more sense, so that
  381. <code>operation1</code> and <code>operation2</code> are both logged against the original
  382. logcontext. This looks like:</p>
  383. <pre><code class="language-python">async def do_request_handling():
  384. a1 = context.run_in_background(operation1)
  385. a2 = context.run_in_background(operation2)
  386. result = await make_deferred_yieldable(defer.gatherResults([a1, a2]))
  387. </code></pre>
  388. <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>
  389. <p>It turns out that our logcontext rules do not play nicely with awaitable
  390. chains which get orphaned and garbage-collected.</p>
  391. <p>Imagine we have some code that looks like this:</p>
  392. <pre><code class="language-python">listener_queue = []
  393. def on_something_interesting():
  394. for d in listener_queue:
  395. d.callback(&quot;foo&quot;)
  396. async def await_something_interesting():
  397. new_awaitable = defer.Deferred()
  398. listener_queue.append(new_awaitable)
  399. with PreserveLoggingContext():
  400. await new_awaitable
  401. </code></pre>
  402. <p>Obviously, the idea here is that we have a bunch of things which are
  403. waiting for an event. (It's just an example of the problem here, but a
  404. relatively common one.)</p>
  405. <p>Now let's imagine two further things happen. First of all, whatever was
  406. waiting for the interesting thing goes away. (Perhaps the request times
  407. out, or something <em>even more</em> interesting happens.)</p>
  408. <p>Secondly, let's suppose that we decide that the interesting thing is
  409. never going to happen, and we reset the listener queue:</p>
  410. <pre><code class="language-python">def reset_listener_queue():
  411. listener_queue.clear()
  412. </code></pre>
  413. <p>So, both ends of the awaitable chain have now dropped their references,
  414. and the awaitable chain is now orphaned, and will be garbage-collected at
  415. some point. Note that <code>await_something_interesting</code> is a coroutine,
  416. which Python implements as a generator function. When Python
  417. garbage-collects generator functions, it gives them a chance to
  418. clean up by making the <code>await</code> (or <code>yield</code>) raise a <code>GeneratorExit</code>
  419. exception. In our case, that means that the <code>__exit__</code> handler of
  420. <code>PreserveLoggingContext</code> will carefully restore the request context, but
  421. there is now nothing waiting for its return, so the request context is
  422. never cleared.</p>
  423. <p>To reiterate, this problem only arises when <em>both</em> ends of a awaitable
  424. chain are dropped. Dropping the the reference to an awaitable you're
  425. supposed to be awaiting is bad practice, so this doesn't
  426. actually happen too much. Unfortunately, when it does happen, it will
  427. lead to leaked logcontexts which are incredibly hard to track down.</p>
  428. </main>
  429. <nav class="nav-wrapper" aria-label="Page navigation">
  430. <!-- Mobile navigation buttons -->
  431. <a rel="prev" href="development/synapse_architecture/cancellation.html" class="mobile-nav-chapters previous" title="Previous chapter" aria-label="Previous chapter" aria-keyshortcuts="Left">
  432. <i class="fa fa-angle-left"></i>
  433. </a>
  434. <a rel="next" href="replication.html" class="mobile-nav-chapters next" title="Next chapter" aria-label="Next chapter" aria-keyshortcuts="Right">
  435. <i class="fa fa-angle-right"></i>
  436. </a>
  437. <div style="clear: both"></div>
  438. </nav>
  439. </div>
  440. </div>
  441. <nav class="nav-wide-wrapper" aria-label="Page navigation">
  442. <a rel="prev" href="development/synapse_architecture/cancellation.html" class="nav-chapters previous" title="Previous chapter" aria-label="Previous chapter" aria-keyshortcuts="Left">
  443. <i class="fa fa-angle-left"></i>
  444. </a>
  445. <a rel="next" href="replication.html" class="nav-chapters next" title="Next chapter" aria-label="Next chapter" aria-keyshortcuts="Right">
  446. <i class="fa fa-angle-right"></i>
  447. </a>
  448. </nav>
  449. </div>
  450. <script type="text/javascript">
  451. window.playground_copyable = true;
  452. </script>
  453. <script src="elasticlunr.min.js" type="text/javascript" charset="utf-8"></script>
  454. <script src="mark.min.js" type="text/javascript" charset="utf-8"></script>
  455. <script src="searcher.js" type="text/javascript" charset="utf-8"></script>
  456. <script src="clipboard.min.js" type="text/javascript" charset="utf-8"></script>
  457. <script src="highlight.js" type="text/javascript" charset="utf-8"></script>
  458. <script src="book.js" type="text/javascript" charset="utf-8"></script>
  459. <!-- Custom JS scripts -->
  460. <script type="text/javascript" src="docs/website_files/table-of-contents.js"></script>
  461. <script type="text/javascript" src="docs/website_files/version-picker.js"></script>
  462. <script type="text/javascript" src="docs/website_files/version.js"></script>
  463. </body>
  464. </html>