def test_verify_json_for_server(self):
        kr = keyring.Keyring(self.hs)

        key1 = signedjson.key.generate_signing_key(1)
        yield self.hs.datastore.store_server_verify_key(
            "server9", "", time.time() * 1000, signedjson.key.get_verify_key(key1)
        )
        json1 = {}
        signedjson.sign.sign_json(json1, "server9", key1)

        sentinel_context = LoggingContext.current_context()

        with LoggingContext("one") as context_one:
            context_one.request = "one"

            defer = kr.verify_json_for_server("server9", {})
            try:
                yield defer
                self.fail("should fail on unsigned json")
            except SynapseError:
                pass
            self.assertIs(LoggingContext.current_context(), context_one)

            defer = kr.verify_json_for_server("server9", json1)
            self.assertFalse(defer.called)
            self.assertIs(LoggingContext.current_context(), sentinel_context)
            yield defer

            self.assertIs(LoggingContext.current_context(), context_one)

 def assert_sentinel_context(self):
     if LoggingContext.current_context() != LoggingContext.sentinel:
         self.fail(
             "Expected sentinel context but got %s" % (
                 LoggingContext.current_context(),
             )
         )

        def setUp(orig):
            # enable debugging of delayed calls - this means that we get a
            # traceback when a unit test exits leaving things on the reactor.
            twisted.internet.base.DelayedCall.debug = True

            # if we're not starting in the sentinel logcontext, then to be honest
            # all future bets are off.
            if LoggingContext.current_context() is not LoggingContext.sentinel:
                self.fail(
                    "Test starting with non-sentinel logging context %s"
                    % (LoggingContext.current_context(),)
                )

            old_level = logging.getLogger().level
            if level is not None and old_level != level:

                @around(self)
                def tearDown(orig):
                    ret = orig()
                    logging.getLogger().setLevel(old_level)
                    return ret

                logging.getLogger().setLevel(level)

            return orig()

class Measure(object):
    __slots__ = [
        "clock", "name", "start_context", "start", "new_context", "ru_utime",
        "ru_stime", "db_txn_count", "db_txn_duration", "created_context"
    ]

    def __init__(self, clock, name):
        self.clock = clock
        self.name = name
        self.start_context = None
        self.start = None
        self.created_context = False

    def __enter__(self):
        self.start = self.clock.time_msec()
        self.start_context = LoggingContext.current_context()
        if not self.start_context:
            logger.warn("Entered Measure without log context: %s", self.name)
            self.start_context = LoggingContext("Measure")
            self.start_context.__enter__()
            self.created_context = True

        self.ru_utime, self.ru_stime = self.start_context.get_resource_usage()
        self.db_txn_count = self.start_context.db_txn_count
        self.db_txn_duration = self.start_context.db_txn_duration

    def __exit__(self, exc_type, exc_val, exc_tb):
        if exc_type is not None or not self.start_context:
            return

        duration = self.clock.time_msec() - self.start
        block_timer.inc_by(duration, self.name)

        context = LoggingContext.current_context()

        if context != self.start_context:
            logger.warn(
                "Context have unexpectedly changed from '%s' to '%s'. (%r)",
                context, self.start_context, self.name
            )
            return

        if not context:
            logger.warn("Expected context. (%r)", self.name)
            return

        ru_utime, ru_stime = context.get_resource_usage()

        block_ru_utime.inc_by(ru_utime - self.ru_utime, self.name)
        block_ru_stime.inc_by(ru_stime - self.ru_stime, self.name)
        block_db_txn_count.inc_by(
            context.db_txn_count - self.db_txn_count, self.name
        )
        block_db_txn_duration.inc_by(
            context.db_txn_duration - self.db_txn_duration, self.name
        )

        if self.created_context:
            self.start_context.__exit__(exc_type, exc_val, exc_tb)

        def tearDown(orig):
            ret = orig()
            # force a GC to workaround problems with deferreds leaking logcontexts when
            # they are GCed (see the logcontext docs)
            gc.collect()
            LoggingContext.set_current_context(LoggingContext.sentinel)

            return ret

 def errback(res, deferred_name):
     self.assertIs(
         LoggingContext.current_context(),
         context_one,
         "errback %s run in unexpected logcontext %s"
         % (deferred_name, LoggingContext.current_context()),
     )
     return res

 def check_ctx(r):
     if LoggingContext.current_context() != start_context:
         err = "%s completion of %s changed context from %s to %s" % (
             "Failure" if isinstance(r, Failure) else "Success",
             f, start_context, LoggingContext.current_context(),
         )
         print(err, file=sys.stderr)
         raise Exception(err)
     return r

    def __enter__(self):
        self.start = self.clock.time()
        self.start_context = LoggingContext.current_context()
        if not self.start_context:
            self.start_context = LoggingContext("Measure")
            self.start_context.__enter__()
            self.created_context = True

        self.start_usage = self.start_context.get_resource_usage()

        in_flight.register((self.name,), self._update_in_flight)

    def __enter__(self):
        self.start = self.clock.time_msec()
        self.start_context = LoggingContext.current_context()
        if not self.start_context:
            self.start_context = LoggingContext("Measure")
            self.start_context.__enter__()
            self.created_context = True

        self.ru_utime, self.ru_stime = self.start_context.get_resource_usage()
        self.db_txn_count = self.start_context.db_txn_count
        self.db_txn_duration = self.start_context.db_txn_duration

    def test_make_deferred_yieldable_with_chained_deferreds(self):
        sentinel_context = LoggingContext.current_context()

        with LoggingContext() as context_one:
            context_one.request = "one"

            d1 = logcontext.make_deferred_yieldable(_chained_deferred_function())
            # make sure that the context was reset by make_deferred_yieldable
            self.assertIs(LoggingContext.current_context(), sentinel_context)

            yield d1

            # now it should be restored
            self._check_test_key("one")

 def get_perspectives(**kwargs):
     self.assertEquals(
         LoggingContext.current_context().request, "11",
     )
     with logcontext.PreserveLoggingContext():
         yield persp_deferred
     defer.returnValue(persp_resp)

    def runInteraction(self, desc, func, *args, **kwargs):
        """Wraps the .runInteraction() method on the underlying db_pool."""
        current_context = LoggingContext.current_context()

        start_time = time.time() * 1000

        after_callbacks = []

        def inner_func(conn, *args, **kwargs):
            with LoggingContext("runInteraction") as context:
                sql_scheduling_timer.inc_by(time.time() * 1000 - start_time)

                if self.database_engine.is_connection_closed(conn):
                    logger.debug("Reconnecting closed database connection")
                    conn.reconnect()

                current_context.copy_to(context)
                return self._new_transaction(
                    conn, desc, after_callbacks, func, *args, **kwargs
                )

        result = yield preserve_context_over_fn(
            self._db_pool.runWithConnection,
            inner_func, *args, **kwargs
        )

        for after_callback, after_args in after_callbacks:
            after_callback(*after_args)
        defer.returnValue(result)

    def __exit__(self, exc_type, exc_val, exc_tb):
        if exc_type is not None or not self.start_context:
            return

        duration = self.clock.time_msec() - self.start
        block_timer.inc_by(duration, self.name)

        context = LoggingContext.current_context()

        if context != self.start_context:
            logger.warn(
                "Context have unexpectedly changed from '%s' to '%s'. (%r)",
                context, self.start_context, self.name
            )
            return

        if not context:
            logger.warn("Expected context. (%r)", self.name)
            return

        ru_utime, ru_stime = context.get_resource_usage()

        block_ru_utime.inc_by(ru_utime - self.ru_utime, self.name)
        block_ru_stime.inc_by(ru_stime - self.ru_stime, self.name)
        block_db_txn_count.inc_by(
            context.db_txn_count - self.db_txn_count, self.name
        )
        block_db_txn_duration.inc_by(
            context.db_txn_duration - self.db_txn_duration, self.name
        )

        if self.created_context:
            self.start_context.__exit__(exc_type, exc_val, exc_tb)

    def _wait_for_sync_for_user(self, sync_config, since_token, timeout,
                                full_state):
        context = LoggingContext.current_context()
        if context:
            if since_token is None:
                context.tag = "initial_sync"
            elif full_state:
                context.tag = "full_state_sync"
            else:
                context.tag = "incremental_sync"

        if timeout == 0 or since_token is None or full_state:
            # we are going to return immediately, so don't bother calling
            # notifier.wait_for_events.
            result = yield self.current_sync_for_user(
                sync_config, since_token, full_state=full_state,
            )
            defer.returnValue(result)
        else:
            def current_sync_callback(before_token, after_token):
                return self.current_sync_for_user(sync_config, since_token)

            result = yield self.notifier.wait_for_events(
                sync_config.user.to_string(), timeout, current_sync_callback,
                from_token=since_token,
            )
            defer.returnValue(result)

    def wait_for_sync_for_user(self, sync_config, since_token=None, timeout=0,
                               full_state=False):
        """Get the sync for a client if we have new data for it now. Otherwise
        wait for new data to arrive on the server. If the timeout expires, then
        return an empty sync result.
        Returns:
            A Deferred SyncResult.
        """

        context = LoggingContext.current_context()
        if context:
            if since_token is None:
                context.tag = "initial_sync"
            elif full_state:
                context.tag = "full_state_sync"
            else:
                context.tag = "incremental_sync"

        if timeout == 0 or since_token is None or full_state:
            # we are going to return immediately, so don't bother calling
            # notifier.wait_for_events.
            result = yield self.current_sync_for_user(
                sync_config, since_token, full_state=full_state,
            )
            defer.returnValue(result)
        else:
            def current_sync_callback(before_token, after_token):
                return self.current_sync_for_user(sync_config, since_token)

            result = yield self.notifier.wait_for_events(
                sync_config.user.to_string(), timeout, current_sync_callback,
                from_token=since_token,
            )
            defer.returnValue(result)

    def runInteraction(self, desc, func, *args, **kwargs):
        """Wraps the .runInteraction() method on the underlying db_pool."""
        current_context = LoggingContext.current_context()

        def inner_func(txn, *args, **kwargs):
            with LoggingContext("runInteraction") as context:
                current_context.copy_to(context)
                start = time.clock() * 1000
                txn_id = SQLBaseStore._TXN_ID

                # We don't really need these to be unique, so lets stop it from
                # growing really large.
                self._TXN_ID = (self._TXN_ID + 1) % (sys.maxint - 1)

                name = "%s-%x" % (desc, txn_id, )

                transaction_logger.debug("[TXN START] {%s}", name)
                try:
                    return func(LoggingTransaction(txn, name), *args, **kwargs)
                except:
                    logger.exception("[TXN FAIL] {%s}", name)
                    raise
                finally:
                    end = time.clock() * 1000
                    transaction_logger.debug(
                        "[TXN END] {%s} %f",
                        name, end - start
                    )
        with PreserveLoggingContext():
            result = yield self._db_pool.runInteraction(
                inner_func, *args, **kwargs
            )
        defer.returnValue(result)

        def do_lookup():

            with LoggingContext("one") as ctx:
                resolve_d = resolver.resolve_service(service_name)

                self.assertNoResult(resolve_d)

                # should have reset to the sentinel context
                self.assertIs(LoggingContext.current_context(), LoggingContext.sentinel)

                result = yield resolve_d

                # should have restored our context
                self.assertIs(LoggingContext.current_context(), ctx)

                defer.returnValue(result)

    def finished_processing(self):

        try:
            context = LoggingContext.current_context()
            ru_utime, ru_stime = context.get_resource_usage()
            db_txn_count = context.db_txn_count
            db_txn_duration = context.db_txn_duration
        except:
            ru_utime, ru_stime = (0, 0)
            db_txn_count, db_txn_duration = (0, 0)

        self.site.access_logger.info(
            "%s - %s - {%s}"
            " Processed request: %dms (%dms, %dms) (%dms/%d)"
            " %sB %s \"%s %s %s\" \"%s\"",
            self.getClientIP(),
            self.site.site_tag,
            self.authenticated_entity,
            int(time.time() * 1000) - self.start_time,
            int(ru_utime * 1000),
            int(ru_stime * 1000),
            int(db_txn_duration * 1000),
            int(db_txn_count),
            self.sentLength,
            self.code,
            self.method,
            self.get_redacted_uri(),
            self.clientproto,
            self.get_user_agent(),
        )

    def call_later(self, delay, callback):
        current_context = LoggingContext.current_context()

        def wrapped_callback():
            LoggingContext.thread_local.current_context = current_context
            callback()
        return reactor.callLater(delay, wrapped_callback)

    def stop(self, clock, request):
        context = LoggingContext.current_context()

        tag = ""
        if context:
            tag = context.tag

            if context != self.start_context:
                logger.warn(
                    "Context have unexpectedly changed %r, %r",
                    context, self.start_context
                )
                return

        incoming_requests_counter.inc(request.method, self.name, tag)

        response_timer.inc_by(
            clock.time_msec() - self.start, request.method,
            self.name, tag
        )

        ru_utime, ru_stime = context.get_resource_usage()

        response_ru_utime.inc_by(
            ru_utime, request.method, self.name, tag
        )
        response_ru_stime.inc_by(
            ru_stime, request.method, self.name, tag
        )
        response_db_txn_count.inc_by(
            context.db_txn_count, request.method, self.name, tag
        )
        response_db_txn_duration.inc_by(
            context.db_txn_duration, request.method, self.name, tag
        )