Merge tag 'v0.31.0'

Changes in synapse v0.31.0 (2018-06-06)
======================================

Most notable change from v0.30.0 is to switch to python prometheus library to improve system
stats reporting. WARNING this changes a number of prometheus metrics in a
backwards-incompatible manner. For more details, see
`docs/metrics-howto.rst <docs/metrics-howto.rst#removal-of-deprecated-metrics--time-based-counters-becoming-histograms-in-0310>`_.

Bug Fixes:

* Fix metric documentation tables (PR #3341)
* Fix LaterGuage error handling (694968f)
* Fix replication metrics (b7e7fd2)

Changes in synapse v0.31.0-rc1 (2018-06-04)
==========================================

Features:

* Switch to the Python Prometheus library (PR #3256, #3274)
* Let users leave the server notice room after joining (PR #3287)

Changes:

* daily user type phone home stats (PR #3264)
* Use iter* methods for _filter_events_for_server (PR #3267)
* Docs on consent bits (PR #3268)
* Remove users from user directory on deactivate (PR #3277)
* Avoid sending consent notice to guest users (PR #3288)
* disable CPUMetrics if no /proc/self/stat (PR #3299)
* Add local and loopback IPv6 addresses to url_preview_ip_range_blacklist (PR #3312) Thanks to @thegcat!
* Consistently use six's iteritems and wrap lazy keys/values in list() if they're not meant to be lazy (PR #3307)
* Add private IPv6 addresses to example config for url preview blacklist (PR #3317) Thanks to @thegcat!
* Reduce stuck read-receipts: ignore depth when updating (PR #3318)
* Put python's logs into Trial when running unit tests (PR #3319)

Changes, python 3 migration:

* Replace some more comparisons with six (PR #3243) Thanks to @NotAFile!
* replace some iteritems with six (PR #3244) Thanks to @NotAFile!
* Add batch_iter to utils (PR #3245) Thanks to @NotAFile!
* use repr, not str (PR #3246) Thanks to @NotAFile!
* Misc Python3 fixes (PR #3247) Thanks to @NotAFile!
* Py3 storage/_base.py (PR #3278) Thanks to @NotAFile!
* more six iteritems (PR #3279) Thanks to @NotAFile!
* More Misc. py3 fixes (PR #3280) Thanks to @NotAFile!
* remaining isintance fixes (PR #3281) Thanks to @NotAFile!
* py3-ize state.py (PR #3283) Thanks to @NotAFile!
* extend tox testing for py3 to avoid regressions (PR #3302) Thanks to @krombel!
* use memoryview in py3 (PR #3303) Thanks to @NotAFile!

Bugs:

* Fix federation backfill bugs (PR #3261)
* federation: fix LaterGauge usage (PR #3328) Thanks to @intelfx!

7 files changed, 37 insertions, 211 deletions

diff --git a/tests/__init__.py b/tests/__init__.py
index bfebb0f644..aab20e8e02 100644
--- a/tests/__init__.py
+++ b/tests/__init__.py
@@ -12,3 +12,6 @@
 # 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 twisted.trial import util
+util.DEFAULT_TIMEOUT_DURATION = 10
diff --git a/tests/metrics/__init__.py b/tests/metrics/__init__.py
deleted file mode 100644
index e69de29bb2..0000000000
--- a/tests/metrics/__init__.py
+++ /dev/null
diff --git a/tests/metrics/test_metric.py b/tests/metrics/test_metric.py
deleted file mode 100644
index 069c0be762..0000000000
--- a/tests/metrics/test_metric.py
+++ /dev/null
@@ -1,192 +0,0 @@
-# -*- coding: utf-8 -*-
-# Copyright 2015, 2016 OpenMarket 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 tests import unittest
-
-from synapse.metrics.metric import (
-    CounterMetric, CallbackMetric, DistributionMetric, CacheMetric,
-    _escape_label_value,
-)
-
-
-class CounterMetricTestCase(unittest.TestCase):
-
-    def test_scalar(self):
-        counter = CounterMetric("scalar")
-
-        self.assertEquals(counter.render(), [
-            'scalar 0',
-        ])
-
-        counter.inc()
-
-        self.assertEquals(counter.render(), [
-            'scalar 1',
-        ])
-
-        counter.inc_by(2)
-
-        self.assertEquals(counter.render(), [
-            'scalar 3'
-        ])
-
-    def test_vector(self):
-        counter = CounterMetric("vector", labels=["method"])
-
-        # Empty counter doesn't yet know what values it has
-        self.assertEquals(counter.render(), [])
-
-        counter.inc("GET")
-
-        self.assertEquals(counter.render(), [
-            'vector{method="GET"} 1',
-        ])
-
-        counter.inc("GET")
-        counter.inc("PUT")
-
-        self.assertEquals(counter.render(), [
-            'vector{method="GET"} 2',
-            'vector{method="PUT"} 1',
-        ])
-
-
-class CallbackMetricTestCase(unittest.TestCase):
-
-    def test_scalar(self):
-        d = dict()
-
-        metric = CallbackMetric("size", lambda: len(d))
-
-        self.assertEquals(metric.render(), [
-            'size 0',
-        ])
-
-        d["key"] = "value"
-
-        self.assertEquals(metric.render(), [
-            'size 1',
-        ])
-
-    def test_vector(self):
-        vals = dict()
-
-        metric = CallbackMetric("values", lambda: vals, labels=["type"])
-
-        self.assertEquals(metric.render(), [])
-
-        # Keys have to be tuples, even if they're 1-element
-        vals[("foo",)] = 1
-        vals[("bar",)] = 2
-
-        self.assertEquals(metric.render(), [
-            'values{type="bar"} 2',
-            'values{type="foo"} 1',
-        ])
-
-
-class DistributionMetricTestCase(unittest.TestCase):
-
-    def test_scalar(self):
-        metric = DistributionMetric("thing")
-
-        self.assertEquals(metric.render(), [
-            'thing:count 0',
-            'thing:total 0',
-        ])
-
-        metric.inc_by(500)
-
-        self.assertEquals(metric.render(), [
-            'thing:count 1',
-            'thing:total 500',
-        ])
-
-    def test_vector(self):
-        metric = DistributionMetric("queries", labels=["verb"])
-
-        self.assertEquals(metric.render(), [])
-
-        metric.inc_by(300, "SELECT")
-        metric.inc_by(200, "SELECT")
-        metric.inc_by(800, "INSERT")
-
-        self.assertEquals(metric.render(), [
-            'queries:count{verb="INSERT"} 1',
-            'queries:count{verb="SELECT"} 2',
-            'queries:total{verb="INSERT"} 800',
-            'queries:total{verb="SELECT"} 500',
-        ])
-
-
-class CacheMetricTestCase(unittest.TestCase):
-
-    def test_cache(self):
-        d = dict()
-
-        metric = CacheMetric("cache", lambda: len(d), "cache_name")
-
-        self.assertEquals(metric.render(), [
-            'cache:hits{name="cache_name"} 0',
-            'cache:total{name="cache_name"} 0',
-            'cache:size{name="cache_name"} 0',
-            'cache:evicted_size{name="cache_name"} 0',
-        ])
-
-        metric.inc_misses()
-        d["key"] = "value"
-
-        self.assertEquals(metric.render(), [
-            'cache:hits{name="cache_name"} 0',
-            'cache:total{name="cache_name"} 1',
-            'cache:size{name="cache_name"} 1',
-            'cache:evicted_size{name="cache_name"} 0',
-        ])
-
-        metric.inc_hits()
-
-        self.assertEquals(metric.render(), [
-            'cache:hits{name="cache_name"} 1',
-            'cache:total{name="cache_name"} 2',
-            'cache:size{name="cache_name"} 1',
-            'cache:evicted_size{name="cache_name"} 0',
-        ])
-
-        metric.inc_evictions(2)
-
-        self.assertEquals(metric.render(), [
-            'cache:hits{name="cache_name"} 1',
-            'cache:total{name="cache_name"} 2',
-            'cache:size{name="cache_name"} 1',
-            'cache:evicted_size{name="cache_name"} 2',
-        ])
-
-
-class LabelValueEscapeTestCase(unittest.TestCase):
-    def test_simple(self):
-        string = "safjhsdlifhyskljfksdfh"
-        self.assertEqual(string, _escape_label_value(string))
-
-    def test_escape(self):
-        self.assertEqual(
-            "abc\\\"def\\nghi\\\\",
-            _escape_label_value("abc\"def\nghi\\"),
-        )
-
-    def test_sequence_of_escapes(self):
-        self.assertEqual(
-            "abc\\\"def\\nghi\\\\\\n",
-            _escape_label_value("abc\"def\nghi\\\n"),
-        )
diff --git a/tests/storage/test_registration.py b/tests/storage/test_registration.py
index cc637dda1c..f863b75846 100644
--- a/tests/storage/test_registration.py
+++ b/tests/storage/test_registration.py
@@ -49,6 +49,7 @@ class RegistrationStoreTestCase(unittest.TestCase):
                 "is_guest": 0,
                 "consent_version": None,
                 "consent_server_notice_sent": None,
+                "appservice_id": None,
             },
             (yield self.store.get_user_by_id(self.user_id))
         )
diff --git a/tests/test_dns.py b/tests/test_dns.py
index af607d626f..3b360a0fc7 100644
--- a/tests/test_dns.py
+++ b/tests/test_dns.py
@@ -62,7 +62,7 @@ class DnsTestCase(unittest.TestCase):
         dns_client_mock = Mock()
         dns_client_mock.lookupService.return_value = defer.fail(error.DNSServerError())
 
-        service_name = "test_service.examle.com"
+        service_name = "test_service.example.com"
 
         entry = Mock(spec_set=["expires"])
         entry.expires = 0
@@ -87,7 +87,7 @@ class DnsTestCase(unittest.TestCase):
         dns_client_mock = Mock(spec_set=['lookupService'])
         dns_client_mock.lookupService = Mock(spec_set=[])
 
-        service_name = "test_service.examle.com"
+        service_name = "test_service.example.com"
 
         entry = Mock(spec_set=["expires"])
         entry.expires = 999999999
@@ -111,7 +111,7 @@ class DnsTestCase(unittest.TestCase):
 
         dns_client_mock.lookupService.return_value = defer.fail(error.DNSServerError())
 
-        service_name = "test_service.examle.com"
+        service_name = "test_service.example.com"
 
         cache = {}
 
@@ -126,7 +126,7 @@ class DnsTestCase(unittest.TestCase):
 
         dns_client_mock.lookupService.return_value = defer.fail(error.DNSNameError())
 
-        service_name = "test_service.examle.com"
+        service_name = "test_service.example.com"
 
         cache = {}
 
diff --git a/tests/unittest.py b/tests/unittest.py
index 7b478c4294..184fe880f3 100644
--- a/tests/unittest.py
+++ b/tests/unittest.py
@@ -12,23 +12,37 @@
 # 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.
+
+import logging
+
 import twisted
+import twisted.logger
 from twisted.trial import unittest
 
-import logging
+from synapse.util.logcontext import LoggingContextFilter
+
+# Set up putting Synapse's logs into Trial's.
+rootLogger = logging.getLogger()
+
+log_format = (
+    "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s"
+)
+
+
+class ToTwistedHandler(logging.Handler):
+    tx_log = twisted.logger.Logger()
+
+    def emit(self, record):
+        log_entry = self.format(record)
+        log_level = record.levelname.lower().replace('warning', 'warn')
+        self.tx_log.emit(twisted.logger.LogLevel.levelWithName(log_level), log_entry)
 
-# logging doesn't have a "don't log anything at all EVARRRR setting,
-# but since the highest value is 50, 1000000 should do ;)
-NEVER = 1000000
 
-handler = logging.StreamHandler()
-handler.setFormatter(logging.Formatter(
-    "%(levelname)s:%(name)s:%(message)s  [%(pathname)s:%(lineno)d]"
-))
-logging.getLogger().addHandler(handler)
-logging.getLogger().setLevel(NEVER)
-logging.getLogger("synapse.storage.SQL").setLevel(NEVER)
-logging.getLogger("synapse.storage.txn").setLevel(NEVER)
+handler = ToTwistedHandler()
+formatter = logging.Formatter(log_format)
+handler.setFormatter(formatter)
+handler.addFilter(LoggingContextFilter(request=""))
+rootLogger.addHandler(handler)
 
 
 def around(target):
@@ -61,7 +75,7 @@ class TestCase(unittest.TestCase):
 
         method = getattr(self, methodName)
 
-        level = getattr(method, "loglevel", getattr(self, "loglevel", NEVER))
+        level = getattr(method, "loglevel", getattr(self, "loglevel", logging.ERROR))
 
         @around(self)
         def setUp(orig):
diff --git a/tests/util/test_wheel_timer.py b/tests/util/test_wheel_timer.py
index c44567e52e..fdb24a48b0 100644
--- a/tests/util/test_wheel_timer.py
+++ b/tests/util/test_wheel_timer.py
@@ -33,7 +33,7 @@ class WheelTimerTestCase(unittest.TestCase):
         self.assertListEqual(wheel.fetch(156), [obj])
         self.assertListEqual(wheel.fetch(170), [])
 
-    def test_mutli_insert(self):
+    def test_multi_insert(self):
         wheel = WheelTimer(bucket_size=5)
 
         obj1 = object()
@@ -58,7 +58,7 @@ class WheelTimerTestCase(unittest.TestCase):
         wheel.insert(100, obj, 50)
         self.assertListEqual(wheel.fetch(120), [obj])
 
-    def test_insert_past_mutli(self):
+    def test_insert_past_multi(self):
         wheel = WheelTimer(bucket_size=5)
 
         obj1 = object()