synapse-old/synapse/util/patch_inline_callbacks.py

220 lines
8.3 KiB
Python
Raw Normal View History

# -*- coding: utf-8 -*-
# Copyright 2018 New Vector Ltd
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
from __future__ import print_function
import functools
import sys
2019-10-10 05:20:29 -06:00
from typing import Any, Callable, List
2019-10-10 05:15:17 -06:00
from twisted.internet import defer
from twisted.internet.defer import Deferred
from twisted.python.failure import Failure
2019-10-10 05:15:17 -06:00
# Tracks if we've already patched inlineCallbacks
_already_patched = False
def do_patch():
"""
Patch defer.inlineCallbacks so that it checks the state of the logcontext on exit
"""
from synapse.logging.context import LoggingContext
2019-10-10 05:15:17 -06:00
global _already_patched
orig_inline_callbacks = defer.inlineCallbacks
2019-10-10 05:15:17 -06:00
if _already_patched:
2019-09-27 08:58:14 -06:00
return
def new_inline_callbacks(f):
@functools.wraps(f)
def wrapped(*args, **kwargs):
start_context = LoggingContext.current_context()
2019-10-10 05:29:38 -06:00
changes = [] # type: List[str]
2019-10-10 05:15:17 -06:00
orig = orig_inline_callbacks(_check_yield_points(f, changes))
try:
res = orig(*args, **kwargs)
except Exception:
if LoggingContext.current_context() != start_context:
2019-09-27 08:11:14 -06:00
for err in changes:
print(err, file=sys.stderr)
err = "%s changed context from %s to %s on exception" % (
2019-05-09 23:12:11 -06:00
f,
start_context,
LoggingContext.current_context(),
)
print(err, file=sys.stderr)
raise Exception(err)
raise
if not isinstance(res, Deferred) or res.called:
if LoggingContext.current_context() != start_context:
2019-09-27 08:11:14 -06:00
for err in changes:
print(err, file=sys.stderr)
err = "Completed %s changed context from %s to %s" % (
2019-05-09 23:12:11 -06:00
f,
start_context,
LoggingContext.current_context(),
)
# print the error to stderr because otherwise all we
# see in travis-ci is the 500 error
print(err, file=sys.stderr)
raise Exception(err)
return res
if LoggingContext.current_context() != LoggingContext.sentinel:
err = (
"%s returned incomplete deferred in non-sentinel context "
"%s (start was %s)"
2019-05-09 23:12:11 -06:00
) % (f, LoggingContext.current_context(), start_context)
print(err, file=sys.stderr)
raise Exception(err)
def check_ctx(r):
if LoggingContext.current_context() != start_context:
2019-09-27 08:11:14 -06:00
for err in changes:
print(err, file=sys.stderr)
err = "%s completion of %s changed context from %s to %s" % (
"Failure" if isinstance(r, Failure) else "Success",
2019-05-09 23:12:11 -06:00
f,
start_context,
LoggingContext.current_context(),
)
print(err, file=sys.stderr)
raise Exception(err)
return r
res.addBoth(check_ctx)
return res
return wrapped
defer.inlineCallbacks = new_inline_callbacks
2019-10-10 05:15:17 -06:00
_already_patched = True
2019-09-27 08:11:14 -06:00
2019-10-10 05:15:17 -06:00
def _check_yield_points(f: Callable, changes: List[str]):
"""Wraps a generator that is about to be passed to defer.inlineCallbacks
2019-09-27 08:58:14 -06:00
checking that after every yield the log contexts are correct.
2019-10-10 04:53:57 -06:00
It's perfectly valid for log contexts to change within a function, e.g. due
2019-10-10 04:53:57 -06:00
to new Measure blocks, so such changes are added to the given `changes`
list instead of triggering an exception.
Args:
f: generator function to wrap
2019-10-10 05:15:17 -06:00
changes: A list of strings detailing how the contexts
2019-10-10 04:53:57 -06:00
changed within a function.
Returns:
function
2019-09-27 08:58:14 -06:00
"""
2019-09-27 08:11:14 -06:00
from synapse.logging.context import LoggingContext
@functools.wraps(f)
def check_yield_points_inner(*args, **kwargs):
gen = f(*args, **kwargs)
2019-10-10 03:59:07 -06:00
last_yield_line_no = gen.gi_frame.f_lineno
2019-10-10 05:47:07 -06:00
result = None # type: Any
2019-09-27 08:11:14 -06:00
while True:
2019-10-10 05:15:17 -06:00
expected_context = LoggingContext.current_context()
2019-09-27 08:11:14 -06:00
try:
isFailure = isinstance(result, Failure)
if isFailure:
d = result.throwExceptionIntoGenerator(gen)
else:
d = gen.send(result)
except (StopIteration, defer._DefGen_Return) as e:
2019-09-27 08:58:14 -06:00
if LoggingContext.current_context() != expected_context:
2019-09-27 08:11:14 -06:00
# This happens when the context is lost sometime *after* the
# final yield and returning. E.g. we forgot to yield on a
# function that returns a deferred.
2019-10-10 04:53:57 -06:00
#
# We don't raise here as it's perfectly valid for contexts to
2019-10-10 04:53:57 -06:00
# change in a function, as long as it sets the correct context
# on resolving (which is checked separately).
2019-09-27 08:11:14 -06:00
err = (
2019-09-27 08:58:14 -06:00
"Function %r returned and changed context from %s to %s,"
" in %s between %d and end of func"
2019-09-27 08:11:14 -06:00
% (
f.__qualname__,
2019-10-10 03:59:07 -06:00
expected_context,
2019-09-27 08:11:14 -06:00
LoggingContext.current_context(),
f.__code__.co_filename,
last_yield_line_no,
)
)
changes.append(err)
return getattr(e, "value", None)
2019-10-10 03:58:32 -06:00
frame = gen.gi_frame
2019-10-10 03:59:07 -06:00
if isinstance(d, defer.Deferred) and not d.called:
2019-10-10 03:58:32 -06:00
# This happens if we yield on a deferred that doesn't follow
# the log context rules without wrapping in a `make_deferred_yieldable`.
2019-10-10 04:53:57 -06:00
# We raise here as this should never happen.
2019-10-10 03:59:07 -06:00
if LoggingContext.current_context() is not LoggingContext.sentinel:
2019-10-10 03:58:32 -06:00
err = (
2019-10-10 03:59:07 -06:00
"%s yielded with context %s rather than sentinel,"
2019-10-10 03:58:32 -06:00
" yielded on line %d in %s"
% (
frame.f_code.co_name,
LoggingContext.current_context(),
frame.f_lineno,
frame.f_code.co_filename,
)
)
2019-10-10 04:53:57 -06:00
raise Exception(err)
2019-10-10 03:58:32 -06:00
2019-09-27 08:11:14 -06:00
try:
result = yield d
except Exception as e:
result = Failure(e)
2019-09-27 08:58:14 -06:00
if LoggingContext.current_context() != expected_context:
2019-10-10 04:53:57 -06:00
2019-09-27 08:11:14 -06:00
# This happens because the context is lost sometime *after* the
# previous yield and *after* the current yield. E.g. the
# deferred we waited on didn't follow the rules, or we forgot to
# yield on a function between the two yield points.
2019-10-10 04:53:57 -06:00
#
# We don't raise here as its perfectly valid for contexts to
# change in a function, as long as it sets the correct context
# on resolving (which is checked separately).
2019-09-27 08:11:14 -06:00
err = (
"%s changed context from %s to %s, happened between lines %d and %d in %s"
% (
frame.f_code.co_name,
2019-10-10 05:15:17 -06:00
expected_context,
2019-09-27 08:11:14 -06:00
LoggingContext.current_context(),
last_yield_line_no,
frame.f_lineno,
frame.f_code.co_filename,
)
)
changes.append(err)
last_yield_line_no = frame.f_lineno
return check_yield_points_inner