From 1557250b13a4855183b122b1da73bc24e97f2925 Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 19 Sep 2018 00:54:15 +1000 Subject: [PATCH 01/10] log this as error --- synapse/storage/_base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index be61147b9b8d..a06eafe29fb1 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -117,7 +117,7 @@ def _do_execute(self, func, sql, *args): sql, *args ) except Exception as e: - logger.debug("[SQL FAIL] {%s} %s", self.name, e) + logger.error("[SQL FAIL] {%s} %s", self.name, e) raise finally: secs = time.time() - start From a2ebc560954d4e5584b51dd9da09d09c2f73aad4 Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 19 Sep 2018 02:17:58 +1000 Subject: [PATCH 02/10] failing test --- tests/server.py | 8 +- tests/storage/test_client_ips.py | 195 +++++++++++++++++++++++++------ tests/unittest.py | 5 +- 3 files changed, 168 insertions(+), 40 deletions(-) diff --git a/tests/server.py b/tests/server.py index 420ec4e08859..e3f9f6f3e22e 100644 --- a/tests/server.py +++ b/tests/server.py @@ -98,7 +98,7 @@ def info(self, *args, **kwargs): return FakeLogger() -def make_request(method, path, content=b"", access_token=None): +def make_request(method, path, content=b"", access_token=None, request=SynapseRequest): """ Make a web request using the given method and path, feed it the content, and return the Request and the Channel underneath. @@ -120,14 +120,16 @@ def make_request(method, path, content=b"", access_token=None): site = FakeSite() channel = FakeChannel() - req = SynapseRequest(site, channel) + req = request(site, channel) req.process = lambda: b"" req.content = BytesIO(content) if access_token: req.requestHeaders.addRawHeader(b"Authorization", b"Bearer " + access_token) - req.requestHeaders.addRawHeader(b"X-Forwarded-For", b"127.0.0.1") + if content: + req.requestHeaders.addRawHeader(b"Content-Type", b"application/json") + req.requestReceived(method, path, b"1.1") return req, channel diff --git a/tests/storage/test_client_ips.py b/tests/storage/test_client_ips.py index c9b02a062be5..d7ff6416f53b 100644 --- a/tests/storage/test_client_ips.py +++ b/tests/storage/test_client_ips.py @@ -1,5 +1,6 @@ # -*- coding: utf-8 -*- # Copyright 2016 OpenMarket Ltd +# 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. @@ -12,35 +13,46 @@ # 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 mock import Mock +import hashlib +import hmac +import json + from twisted.internet import defer -import tests.unittest -import tests.utils +from synapse.http.site import XForwardedForRequest +from synapse.rest.client.v1 import login, admin + +from tests import unittest -class ClientIpStoreTestCase(tests.unittest.TestCase): - def __init__(self, *args, **kwargs): - super(ClientIpStoreTestCase, self).__init__(*args, **kwargs) - self.store = None # type: synapse.storage.DataStore - self.clock = None # type: tests.utils.MockClock - @defer.inlineCallbacks - def setUp(self): - self.hs = yield tests.utils.setup_test_homeserver(self.addCleanup) +class ClientIpStoreTestCase(unittest.HomeserverTestCase): + def make_homeserver(self, reactor, clock): + hs = self.setup_test_homeserver() + return hs + + def prepare(self, hs, reactor, clock): self.store = self.hs.get_datastore() - self.clock = self.hs.get_clock() - @defer.inlineCallbacks def test_insert_new_client_ip(self): - self.clock.now = 12345678 + self.reactor.advance(12345678) + user_id = "@user:id" - yield self.store.insert_client_ip( - user_id, "access_token", "ip", "user_agent", "device_id" + self.get_success( + self.store.insert_client_ip( + user_id, "access_token", "ip", "user_agent", "device_id" + ) ) - result = yield self.store.get_last_client_ip_by_device(user_id, "device_id") + # Trigger the storage loop + self.reactor.advance(10) + + result = self.get_success( + self.store.get_last_client_ip_by_device(user_id, "device_id") + ) r = result[(user_id, "device_id")] self.assertDictContainsSubset( @@ -55,18 +67,18 @@ def test_insert_new_client_ip(self): r, ) - @defer.inlineCallbacks def test_disabled_monthly_active_user(self): self.hs.config.limit_usage_by_mau = False self.hs.config.max_mau_value = 50 user_id = "@user:server" - yield self.store.insert_client_ip( - user_id, "access_token", "ip", "user_agent", "device_id" + self.get_success( + self.store.insert_client_ip( + user_id, "access_token", "ip", "user_agent", "device_id" + ) ) - active = yield self.store.user_last_seen_monthly_active(user_id) + active = self.get_success(self.store.user_last_seen_monthly_active(user_id)) self.assertFalse(active) - @defer.inlineCallbacks def test_adding_monthly_active_user_when_full(self): self.hs.config.limit_usage_by_mau = True self.hs.config.max_mau_value = 50 @@ -76,38 +88,151 @@ def test_adding_monthly_active_user_when_full(self): self.store.get_monthly_active_count = Mock( return_value=defer.succeed(lots_of_users) ) - yield self.store.insert_client_ip( - user_id, "access_token", "ip", "user_agent", "device_id" + self.get_success( + self.store.insert_client_ip( + user_id, "access_token", "ip", "user_agent", "device_id" + ) ) - active = yield self.store.user_last_seen_monthly_active(user_id) + active = self.get_success(self.store.user_last_seen_monthly_active(user_id)) self.assertFalse(active) - @defer.inlineCallbacks def test_adding_monthly_active_user_when_space(self): self.hs.config.limit_usage_by_mau = True self.hs.config.max_mau_value = 50 user_id = "@user:server" - active = yield self.store.user_last_seen_monthly_active(user_id) + active = self.get_success(self.store.user_last_seen_monthly_active(user_id)) self.assertFalse(active) - yield self.store.insert_client_ip( - user_id, "access_token", "ip", "user_agent", "device_id" + # Trigger the saving loop + self.reactor.advance(10) + + self.get_success( + self.store.insert_client_ip( + user_id, "access_token", "ip", "user_agent", "device_id" + ) ) - active = yield self.store.user_last_seen_monthly_active(user_id) + active = self.get_success(self.store.user_last_seen_monthly_active(user_id)) self.assertTrue(active) - @defer.inlineCallbacks def test_updating_monthly_active_user_when_space(self): self.hs.config.limit_usage_by_mau = True self.hs.config.max_mau_value = 50 user_id = "@user:server" - yield self.store.register(user_id=user_id, token="123", password_hash=None) + self.get_success( + self.store.register(user_id=user_id, token="123", password_hash=None) + ) - active = yield self.store.user_last_seen_monthly_active(user_id) + active = self.get_success(self.store.user_last_seen_monthly_active(user_id)) self.assertFalse(active) - yield self.store.insert_client_ip( - user_id, "access_token", "ip", "user_agent", "device_id" + # Trigger the saving loop + self.reactor.advance(10) + + self.get_success( + self.store.insert_client_ip( + user_id, "access_token", "ip", "user_agent", "device_id" + ) ) - active = yield self.store.user_last_seen_monthly_active(user_id) + active = self.get_success(self.store.user_last_seen_monthly_active(user_id)) self.assertTrue(active) + + +class ClientIpAuthTestCase(unittest.HomeserverTestCase): + + servlets = [admin.register_servlets, login.register_servlets] + + def make_homeserver(self, reactor, clock): + hs = self.setup_test_homeserver() + return hs + + def prepare(self, hs, reactor, clock): + self.hs.config.registration_shared_secret = u"shared" + self.store = self.hs.get_datastore() + + # Create the user + request, channel = self.make_request("GET", "/_matrix/client/r0/admin/register") + self.render(request) + nonce = channel.json_body["nonce"] + + want_mac = hmac.new(key=b"shared", digestmod=hashlib.sha1) + want_mac.update(nonce.encode('ascii') + b"\x00bob\x00abc123\x00admin") + want_mac = want_mac.hexdigest() + + body = json.dumps( + { + "nonce": nonce, + "username": "bob", + "password": "abc123", + "admin": True, + "mac": want_mac, + } + ) + request, channel = self.make_request( + "POST", "/_matrix/client/r0/admin/register", body.encode('utf8') + ) + self.render(request) + + self.assertEqual(channel.code, 200) + self.user_id = channel.json_body["user_id"] + + def test_request_with_xforwarded(self): + """ + The IP in X-Forwarded-For is entered into the client IPs table. + """ + self._runtest({b"X-Forwarded-For": b"127.9.0.1"}, "127.9.0.1", {"request": XForwardedForRequest}) + + def test_request_from_getPeer(self): + """ + The IP returned by getPeer is entered into the client IPs table, if + there's no X-Forwarded-For header. + """ + self._runtest({}, "127.0.0.1", {}) + + def _runtest(self, headers, expected_ip, make_request_args): + device_id = "bleb" + + body = json.dumps( + { + "type": "m.login.password", + "user": "bob", + "password": "abc123", + "device_id": device_id, + } + ) + request, channel = self.make_request( + "POST", "/_matrix/client/r0/login", body.encode('utf8'), **make_request_args + ) + self.render(request) + self.assertEqual(channel.code, 200) + access_token = channel.json_body["access_token"].encode('ascii') + + # Advance to a known time + self.reactor.advance(123456 - self.reactor.seconds()) + + request, channel = self.make_request( + "GET", "/_matrix/client/r0/admin/users/" + self.user_id, body.encode('utf8'), access_token=access_token, **make_request_args + ) + request.requestHeaders.addRawHeader(b"User-Agent", b"Mozzila pizza") + + # Add the optional headers + for h, v in headers.items(): + request.requestHeaders.addRawHeader(h, v) + self.render(request) + + # Advance so the save loop occurs + self.reactor.advance(100) + + result = self.get_success( + self.store.get_last_client_ip_by_device(self.user_id, device_id) + ) + r = result[(self.user_id, device_id)] + self.assertDictContainsSubset( + { + "user_id": self.user_id, + "device_id": device_id, + "ip": expected_ip, + "user_agent": "Mozzila pizza", + "last_seen": 123456100, + }, + r, + ) diff --git a/tests/unittest.py b/tests/unittest.py index a3d39920db0a..7c4a44a10767 100644 --- a/tests/unittest.py +++ b/tests/unittest.py @@ -28,6 +28,7 @@ from synapse.http.server import JsonResource from synapse.server import HomeServer from synapse.types import UserID, create_requester +from synapse.http.site import SynapseRequest from synapse.util.logcontext import LoggingContextFilter from tests.server import get_clock, make_request, render, setup_test_homeserver @@ -236,7 +237,7 @@ def prepare(self, reactor, clock, homeserver): Function to optionally be overridden in subclasses. """ - def make_request(self, method, path, content=b""): + def make_request(self, method, path, content=b"", access_token=None, request=SynapseRequest): """ Create a SynapseRequest at the path using the method and containing the given content. @@ -254,7 +255,7 @@ def make_request(self, method, path, content=b""): if isinstance(content, dict): content = json.dumps(content).encode('utf8') - return make_request(method, path, content) + return make_request(method, path, content, access_token, request) def render(self, request): """ From 3b1f038900487b5464ea75f008854152ce37fdd0 Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 19 Sep 2018 02:18:14 +1000 Subject: [PATCH 03/10] run it on 3.6 --- .travis.yml | 5 +++++ tox.ini | 10 ++++++++++ 2 files changed, 15 insertions(+) diff --git a/.travis.yml b/.travis.yml index b3ee66da8ff1..b6faca4b9258 100644 --- a/.travis.yml +++ b/.travis.yml @@ -31,6 +31,11 @@ matrix: - python: 3.6 env: TOX_ENV=py36 + - python: 3.6 + env: TOX_ENV=py36-postgres TRIAL_FLAGS="-j 4" + services: + - postgresql + - python: 3.6 env: TOX_ENV=check_isort diff --git a/tox.ini b/tox.ini index 80ac9324df76..d92e8f6c2ae8 100644 --- a/tox.ini +++ b/tox.ini @@ -70,6 +70,16 @@ usedevelop=true [testenv:py36] usedevelop=true +[testenv:py36-postgres] +usedevelop=true +deps = + {[base]deps} + psycopg2 +setenv = + {[base]setenv} + SYNAPSE_POSTGRES = 1 + + [testenv:packaging] deps = check-manifest From 75dd1d2bf0495f1c85e3a1764f087c1d599f11de Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 19 Sep 2018 02:18:20 +1000 Subject: [PATCH 04/10] fix --- synapse/http/site.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 9579e8cd0d19..cbe88910bdb9 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -308,7 +308,7 @@ def getClientIP(self): C{b"-"}. """ return self.requestHeaders.getRawHeaders( - b"x-forwarded-for", [b"-"])[0].split(b",")[0].strip() + b"x-forwarded-for", [b"-"])[0].split(b",")[0].strip().decode('ascii') class SynapseRequestFactory(object): From 06103f0a3d2727eb77ec28463d61592cdec755ff Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 19 Sep 2018 02:24:03 +1000 Subject: [PATCH 05/10] changelog --- changelog.d/3908.bugfix | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/3908.bugfix diff --git a/changelog.d/3908.bugfix b/changelog.d/3908.bugfix new file mode 100644 index 000000000000..518aee6c4d2e --- /dev/null +++ b/changelog.d/3908.bugfix @@ -0,0 +1 @@ +Fix adding client IPs to the database failing on Python 3. \ No newline at end of file From 4caa204d4fe3bc76f67202e460b21a78daa32773 Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 19 Sep 2018 02:58:37 +1000 Subject: [PATCH 06/10] cleanups --- tests/storage/test_client_ips.py | 19 +++++++++++++------ tests/unittest.py | 6 ++++-- 2 files changed, 17 insertions(+), 8 deletions(-) diff --git a/tests/storage/test_client_ips.py b/tests/storage/test_client_ips.py index d7ff6416f53b..2ffbb9f14f0f 100644 --- a/tests/storage/test_client_ips.py +++ b/tests/storage/test_client_ips.py @@ -14,17 +14,16 @@ # See the License for the specific language governing permissions and # limitations under the License. -from mock import Mock - import hashlib import hmac import json -from twisted.internet import defer +from mock import Mock +from twisted.internet import defer from synapse.http.site import XForwardedForRequest -from synapse.rest.client.v1 import login, admin +from synapse.rest.client.v1 import admin, login from tests import unittest @@ -179,7 +178,11 @@ def test_request_with_xforwarded(self): """ The IP in X-Forwarded-For is entered into the client IPs table. """ - self._runtest({b"X-Forwarded-For": b"127.9.0.1"}, "127.9.0.1", {"request": XForwardedForRequest}) + self._runtest( + {b"X-Forwarded-For": b"127.9.0.1"}, + "127.9.0.1", + {"request": XForwardedForRequest}, + ) def test_request_from_getPeer(self): """ @@ -210,7 +213,11 @@ def _runtest(self, headers, expected_ip, make_request_args): self.reactor.advance(123456 - self.reactor.seconds()) request, channel = self.make_request( - "GET", "/_matrix/client/r0/admin/users/" + self.user_id, body.encode('utf8'), access_token=access_token, **make_request_args + "GET", + "/_matrix/client/r0/admin/users/" + self.user_id, + body.encode('utf8'), + access_token=access_token, + **make_request_args ) request.requestHeaders.addRawHeader(b"User-Agent", b"Mozzila pizza") diff --git a/tests/unittest.py b/tests/unittest.py index 7c4a44a10767..b34f3d5d9138 100644 --- a/tests/unittest.py +++ b/tests/unittest.py @@ -26,9 +26,9 @@ from twisted.trial import unittest from synapse.http.server import JsonResource +from synapse.http.site import SynapseRequest from synapse.server import HomeServer from synapse.types import UserID, create_requester -from synapse.http.site import SynapseRequest from synapse.util.logcontext import LoggingContextFilter from tests.server import get_clock, make_request, render, setup_test_homeserver @@ -237,7 +237,9 @@ def prepare(self, reactor, clock, homeserver): Function to optionally be overridden in subclasses. """ - def make_request(self, method, path, content=b"", access_token=None, request=SynapseRequest): + def make_request( + self, method, path, content=b"", access_token=None, request=SynapseRequest + ): """ Create a SynapseRequest at the path using the method and containing the given content. From 23828955212da31cc7eddfb077911e4b2bf900de Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 19 Sep 2018 03:56:11 +1000 Subject: [PATCH 07/10] fixes --- tests/utils.py | 21 +++++++++++++++++++-- 1 file changed, 19 insertions(+), 2 deletions(-) diff --git a/tests/utils.py b/tests/utils.py index 215226debfec..655d45f2a0d1 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -16,7 +16,9 @@ import atexit import hashlib import os +import time import uuid +import warnings from inspect import getcallargs from mock import Mock, patch @@ -237,20 +239,35 @@ def is_threepid_reserved(threepid): else: # We need to do cleanup on PostgreSQL def cleanup(): + import psycopg2 + # Close all the db pools hs.get_db_pool().close() + dropped = False + # Drop the test database db_conn = db_engine.module.connect( database=POSTGRES_BASE_DB, user=POSTGRES_USER ) db_conn.autocommit = True cur = db_conn.cursor() - cur.execute("DROP DATABASE IF EXISTS %s;" % (test_db,)) - db_conn.commit() + + for x in range(5): + try: + cur.execute("DROP DATABASE IF EXISTS %s;" % (test_db,)) + db_conn.commit() + dropped = True + except psycopg2.OperationalError as e: + warnings.warn("Couldn't drop old db: " + str(e), category=UserWarning) + time.sleep(0.5) + cur.close() db_conn.close() + if not dropped: + warnings.warn("Failed to drop old DB.", category=UserWarning) + if not LEAVE_DB: # Register the cleanup hook cleanup_func(cleanup) From d5676151d55c74542cc9eaef011edc6beb165450 Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 19 Sep 2018 04:05:10 +1000 Subject: [PATCH 08/10] fixes --- tests/utils.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/utils.py b/tests/utils.py index 655d45f2a0d1..1eea51d11412 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -259,7 +259,9 @@ def cleanup(): db_conn.commit() dropped = True except psycopg2.OperationalError as e: - warnings.warn("Couldn't drop old db: " + str(e), category=UserWarning) + warnings.warn( + "Couldn't drop old db: " + str(e), category=UserWarning + ) time.sleep(0.5) cur.close() From c719fc061b278e03142f33337b0a5c82d426623c Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Thu, 20 Sep 2018 19:08:48 +1000 Subject: [PATCH 09/10] fix logging and add comment --- synapse/storage/_base.py | 2 +- synapse/storage/client_ips.py | 35 ++++++++++++++++++++--------------- tests/utils.py | 4 ++++ 3 files changed, 25 insertions(+), 16 deletions(-) diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index a06eafe29fb1..be61147b9b8d 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -117,7 +117,7 @@ def _do_execute(self, func, sql, *args): sql, *args ) except Exception as e: - logger.error("[SQL FAIL] {%s} %s", self.name, e) + logger.debug("[SQL FAIL] {%s} %s", self.name, e) raise finally: secs = time.time() - start diff --git a/synapse/storage/client_ips.py b/synapse/storage/client_ips.py index 8fc678fa67be..94caacad6b93 100644 --- a/synapse/storage/client_ips.py +++ b/synapse/storage/client_ips.py @@ -119,21 +119,26 @@ def _update_client_ips_batch_txn(self, txn, to_update): for entry in iteritems(to_update): (user_id, access_token, ip), (user_agent, device_id, last_seen) = entry - self._simple_upsert_txn( - txn, - table="user_ips", - keyvalues={ - "user_id": user_id, - "access_token": access_token, - "ip": ip, - "user_agent": user_agent, - "device_id": device_id, - }, - values={ - "last_seen": last_seen, - }, - lock=False, - ) + try: + self._simple_upsert_txn( + txn, + table="user_ips", + keyvalues={ + "user_id": user_id, + "access_token": access_token, + "ip": ip, + "user_agent": user_agent, + "device_id": device_id, + }, + values={ + "last_seen": last_seen, + }, + lock=False, + ) + except Exception as e: + # Failed to upsert, log and continue + logger.error("Failed to insert client IP: %r", entry) + @defer.inlineCallbacks def get_last_client_ip_by_device(self, user_id, device_id): diff --git a/tests/utils.py b/tests/utils.py index 1eea51d11412..aaed1149c31e 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -253,6 +253,10 @@ def cleanup(): db_conn.autocommit = True cur = db_conn.cursor() + # Try a few times to drop the DB. Some things may hold on to the + # database for a few more seconds due to flakiness, preventing + # us from dropping it when the test is over. If we can't drop + # it, warn and move on. for x in range(5): try: cur.execute("DROP DATABASE IF EXISTS %s;" % (test_db,)) From d06ff4cb0dc4b8ef0dbe7819b939439a0ee33bae Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Thu, 20 Sep 2018 19:34:20 +1000 Subject: [PATCH 10/10] fix --- synapse/storage/client_ips.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/synapse/storage/client_ips.py b/synapse/storage/client_ips.py index 94caacad6b93..9ad17b7c2597 100644 --- a/synapse/storage/client_ips.py +++ b/synapse/storage/client_ips.py @@ -137,8 +137,7 @@ def _update_client_ips_batch_txn(self, txn, to_update): ) except Exception as e: # Failed to upsert, log and continue - logger.error("Failed to insert client IP: %r", entry) - + logger.error("Failed to insert client IP %r: %r", entry, e) @defer.inlineCallbacks def get_last_client_ip_by_device(self, user_id, device_id):