1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
|
<!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">
<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="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 "><a href="MSC1711_certificates_FAQ.html">Upgrading from pre-Synapse 1.0</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="usage/configuration/user_authentication/index.html">User Authentication</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="openid.html">OpenID Connect</a></li><li class="chapter-item expanded "><div>SAML</div></li><li class="chapter-item expanded "><div>CAS</div></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></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="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.html">Pluggable Modules</a></li><li><ol class="section"><li class="chapter-item expanded "><div>Third Party Rules</div></li><li class="chapter-item expanded "><a href="spam_checker.html">Spam Checker</a></li><li class="chapter-item expanded "><a href="presence_router_module.html">Presence Router</a></li><li class="chapter-item expanded "><div>Media Storage Providers</div></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="admin_api/delete_group.html">Delete Group</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/purge_room.html">Purge Rooms</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="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/shutdown_room.html">Shutdown Room</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></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 class="chapter-item expanded "><a href="usage/administration/request_log.html">Request log format</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="dev/git.html">Git Usage</a></li><li class="chapter-item expanded "><div>Testing</div></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 "><div>Synapse Architecture</div></li><li><ol class="section"><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="dev/saml.html">SAML</a></li><li class="chapter-item expanded "><a href="dev/cas.html">CAS</a></li></ol></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></ol>
</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>
<p>The <code>synapse.logging.context</code> module provides a facilities for managing
the current log context (as well as providing the <code>LoggingContextFilter</code>
class).</p>
<p>Deferreds make the whole thing complicated, so this document describes
how it all works, and how to write code which follows the rules.</p>
<h2 id="logcontexts-without-deferreds"><a class="header" href="#logcontexts-without-deferreds">Logcontexts without Deferreds</a></h2>
<p>In the absence of any Deferred voodoo, things are simple enough. As with
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>
<h2 id="using-logcontexts-with-deferreds"><a class="header" href="#using-logcontexts-with-deferreds">Using logcontexts with Deferreds</a></h2>
<p>Deferreds --- and in particular, <code>defer.inlineCallbacks</code> --- 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>
<p>Consider the example above, where <code>do_request_handling</code> needs to do some
blocking operation, and returns a deferred:</p>
<pre><code class="language-python">@defer.inlineCallbacks
def handle_request(request_id):
with context.LoggingContext() as request_context:
request_context.request = request_id
yield do_request_handling()
logger.debug("finished")
</code></pre>
<p>In the above flow:</p>
<ul>
<li>The logcontext is set</li>
<li><code>do_request_handling</code> is called, and returns a deferred</li>
<li><code>handle_request</code> yields the deferred</li>
<li>The <code>inlineCallbacks</code> wrapper of <code>handle_request</code> returns a deferred</li>
</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
a deferred, you will want to yield on it. To that end, whereever
functions return a deferred, we adopt the following conventions:</p>
<p><strong>Rules for functions returning deferreds:</strong></p>
<blockquote>
<ul>
<li>If the deferred is already complete, the function returns with the
same logcontext it started with.</li>
<li>If the deferred is incomplete, the function clears the logcontext
before returning; when the deferred completes, it restores the
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>
<p>If <code>do_request_handling</code> returns a completed deferred, then the
logcontext will still be in place. In this case, execution will
continue immediately after the <code>yield</code>; the "finished" line will
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>
<p>If the returned deferred is incomplete, <code>do_request_handling</code> clears
the logcontext before returning. The logcontext is therefore clear
when <code>handle_request</code> yields the deferred. At that point, the
<code>inlineCallbacks</code> wrapper adds a callback to the deferred, and
returns another (incomplete) deferred to the caller, and it is safe
to begin processing the next request.</p>
<p>Once <code>do_request_handling</code>'s deferred completes, it will reinstate
the logcontext, before running the callback added by the
<code>inlineCallbacks</code> wrapper. That callback runs 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>
</li>
</ul>
<p>As an aside, it's worth noting that <code>handle_request</code> follows our rules
-though that only matters if the caller has its own logcontext which it
cares about.</p>
<p>The following sections describe pitfalls and helpful patterns when
implementing these rules.</p>
<h2 id="always-yield-your-deferreds"><a class="header" href="#always-yield-your-deferreds">Always yield your deferreds</a></h2>
<p>Whenever you get a deferred back from a function, you should <code>yield</code> on
it as soon as possible. (Returning it directly to your caller is ok too,
if you're not doing <code>inlineCallbacks</code>.) Do not pass go; do not do any
logging; do not call any other functions.</p>
<pre><code class="language-python">@defer.inlineCallbacks
def fun():
logger.debug("starting")
yield do_some_stuff() # just like this
d = more_stuff()
result = yield d # also fine, of course
return result
def nonInlineCallbacksFun():
logger.debug("just a wrapper really")
return do_some_stuff() # this is ok too - the caller will yield on
# it anyway.
</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
so will <code>fun</code> (as wrapped by <code>inlineCallbacks</code>) and
<code>nonInlineCallbacksFun</code>.</p>
<p>It's all too easy to forget to <code>yield</code>: for instance if we forgot that
<code>do_some_stuff</code> returned a deferred, we might plough on regardless. This
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
<code>yield</code>, so this tends not to be a major problem in practice.)</p>
<p>Of course sometimes you need to do something a bit fancier with your
Deferreds - not all code follows the linear A-then-B-then-C pattern.
Notes on implementing more complex patterns are in later sections.</p>
<h2 id="where-you-create-a-new-deferred-make-it-follow-the-rules"><a class="header" href="#where-you-create-a-new-deferred-make-it-follow-the-rules">Where you create a new Deferred, make it follow the rules</a></h2>
<p>Most of the time, a Deferred comes from another synapse function.
Sometimes, though, we need to make up a new Deferred, or we get a
Deferred back from external code. We need to make it follow our rules.</p>
<p>The easy way to do it is with a combination of <code>defer.inlineCallbacks</code>,
and <code>context.PreserveLoggingContext</code>. Suppose we want to implement
<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>
<p>That doesn't follow the rules, but we can fix it by wrapping it with
<code>PreserveLoggingContext</code> and <code>yield</code> ing on it:</p>
<pre><code class="language-python">@defer.inlineCallbacks
def sleep(seconds):
with PreserveLoggingContext():
yield get_sleep_deferred(seconds)
</code></pre>
<p>This technique works equally for external functions which return
deferreds, or deferreds we have made ourselves.</p>
<p>You can also use <code>context.make_deferred_yieldable</code>, which just does the
boilerplate for you, so the above could be written:</p>
<pre><code class="language-python">def sleep(seconds):
return context.make_deferred_yieldable(get_sleep_deferred(seconds))
</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>
<pre><code class="language-python">@defer.inlineCallbacks
def do_request_handling():
yield foreground_operation()
# *don't* do this
background_operation()
logger.debug("Request handling complete")
@defer.inlineCallbacks
def background_operation():
yield first_background_step()
logger.debug("Completed first step")
yield second_background_step()
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
Deferred, it will expect its caller to <code>yield</code> immediately, so will have
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
Deferred returned by <code>background_operation</code> completes, it will restore
the original logcontext. There is nothing waiting on that Deferred, so
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>
<pre><code class="language-python">@defer.inlineCallbacks
def do_request_handling():
yield foreground_operation()
# 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
an incomplete deferred, and adds a callback to the returned deferred to
reset the logcontext. In other words, it turns a function that follows
the Synapse rules about logcontexts and Deferreds into one which behaves
more like an external function --- the opposite operation to that
described in the previous section. It can be used like this:</p>
<pre><code class="language-python">@defer.inlineCallbacks
def do_request_handling():
yield foreground_operation()
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
more deferred via <code>defer.gatherResults</code>:</p>
<pre><code class="language-python">d1 = operation1()
d2 = operation2()
d3 = defer.gatherResults([d1, d2])
</code></pre>
<p>This is really a variation of the fire-and-forget problem above, in that
we are firing off <code>d1</code> and <code>d2</code> without yielding on them. The difference
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>
<p>Of course, the new Deferred returned by <code>gatherResults</code> needs to be
wrapped in order to make it follow the logcontext rules before we can
yield it, as described in <a href="#where-you-create-a-new-deferred-make-it-follow-the-rules">Where you create a new Deferred, make it
follow the
rules</a>.</p>
<p>So, option one: reset the logcontext before starting the operations to
be gathered:</p>
<pre><code class="language-python">@defer.inlineCallbacks
def do_request_handling():
with PreserveLoggingContext():
d1 = operation1()
d2 = operation2()
result = yield defer.gatherResults([d1, d2])
</code></pre>
<p>In this case particularly, though, option two, of using
<code>context.preserve_fn</code> almost certainly makes more sense, so that
<code>operation1</code> and <code>operation2</code> are both logged against the original
logcontext. This looks like:</p>
<pre><code class="language-python">@defer.inlineCallbacks
def do_request_handling():
d1 = context.preserve_fn(operation1)()
d2 = context.preserve_fn(operation2)()
with PreserveLoggingContext():
result = yield defer.gatherResults([d1, d2])
</code></pre>
<h2 id="was-all-this-really-necessary"><a class="header" href="#was-all-this-really-necessary">Was all this really necessary?</a></h2>
<p>The conventions used work fine for a linear flow where everything
happens in series via <code>defer.inlineCallbacks</code> and <code>yield</code>, but are
certainly tricky to follow for any more exotic flows. It's hard not to
wonder if we could have done something else.</p>
<p>We're not going to rewrite Synapse now, so the following is entirely of
academic interest, but I'd like to record some thoughts on an
alternative approach.</p>
<p>I briefly prototyped some code following an alternative set of rules. I
think it would work, but I certainly didn't get as far as thinking how
it would interact with concepts as complicated as the cache descriptors.</p>
<p>My alternative rules were:</p>
<ul>
<li>functions always preserve the logcontext of their caller, whether or
not they are returning a Deferred.</li>
<li>Deferreds returned by synapse functions run their callbacks in the
same context as the function was orignally called in.</li>
</ul>
<p>The main point of this scheme is that everywhere that sets the
logcontext is responsible for clearing it before returning control to
the reactor.</p>
<p>So, for example, if you were the function which started a
<code>with LoggingContext</code> block, you wouldn't <code>yield</code> within it --- instead
you'd start off the background process, and then leave the <code>with</code> block
to wait for it:</p>
<pre><code class="language-python">def handle_request(request_id):
with context.LoggingContext() as request_context:
request_context.request = request_id
d = do_request_handling()
def cb(r):
logger.debug("finished")
d.addCallback(cb)
return d
</code></pre>
<p>(in general, mixing <code>with LoggingContext</code> blocks and
<code>defer.inlineCallbacks</code> in the same function leads to slighly
counter-intuitive code, under this scheme).</p>
<p>Because we leave the original <code>with</code> block as soon as the Deferred is
returned (as opposed to waiting for it to be resolved, as we do today),
the logcontext is cleared before control passes back to the reactor; so
if there is some code within <code>do_request_handling</code> which needs to wait
for a Deferred to complete, there is no need for it to worry about
clearing the logcontext before doing so:</p>
<pre><code class="language-python">def handle_request():
r = do_some_stuff()
r.addCallback(do_some_more_stuff)
return r
</code></pre>
<p>--- and provided <code>do_some_stuff</code> follows the rules of returning a
Deferred which runs its callbacks in the original logcontext, all is
happy.</p>
<p>The business of a Deferred which runs its callbacks in the original
logcontext isn't hard to achieve --- we have it today, in the shape of
<code>context._PreservingContextDeferred</code>:</p>
<pre><code class="language-python">def do_some_stuff():
deferred = do_some_io()
pcd = _PreservingContextDeferred(LoggingContext.current_context())
deferred.chainDeferred(pcd)
return pcd
</code></pre>
<p>It turns out that, thanks to the way that Deferreds chain together, we
automatically get the property of a context-preserving deferred with
<code>defer.inlineCallbacks</code>, provided the final Defered the function
<code>yields</code> on has that property. So we can just write:</p>
<pre><code class="language-python">@defer.inlineCallbacks
def handle_request():
yield do_some_stuff()
yield do_some_more_stuff()
</code></pre>
<p>To conclude: I think this scheme would have worked equally well, with
less danger of messing it up, and probably made some more esoteric code
easier to write. But again --- changing the conventions of the entire
Synapse codebase is not a sensible option for the marginal improvement
offered.</p>
<h2 id="a-note-on-garbage-collection-of-deferred-chains"><a class="header" href="#a-note-on-garbage-collection-of-deferred-chains">A note on garbage-collection of Deferred chains</a></h2>
<p>It turns out that our logcontext rules do not play nicely with Deferred
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")
@defer.inlineCallbacks
def await_something_interesting():
new_deferred = defer.Deferred()
listener_queue.append(new_deferred)
with PreserveLoggingContext():
yield new_deferred
</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>
<p>So, both ends of the deferred chain have now dropped their references,
and the deferred chain is now orphaned, and will be garbage-collected at
some point. Note that <code>await_something_interesting</code> is a generator
function, and when Python garbage-collects generator functions, it gives
them a chance to clean up by making the <code>yield</code> raise a <code>GeneratorExit</code>
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>
<p>To reiterate, this problem only arises when <em>both</em> ends of a deferred
chain are dropped. Dropping the the reference to a deferred you're
supposed to be calling is probably bad practice, so this doesn't
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 -->
<a rel="prev" href="development/database_schema.html" class="mobile-nav-chapters previous" title="Previous chapter" aria-label="Previous chapter" aria-keyshortcuts="Left">
<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">
<a rel="prev" href="development/database_schema.html" class="nav-chapters previous" title="Previous chapter" aria-label="Previous chapter" aria-keyshortcuts="Left">
<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>
|
