From 071037c3a3c8a9ebfe51c8f9197ff3044ab8545f Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Mon, 5 Jul 2021 15:55:31 +0100 Subject: [PATCH 1/9] Make note of suspected minor bug --- synapse/storage/databases/main/metrics.py | 1 + 1 file changed, 1 insertion(+) diff --git a/synapse/storage/databases/main/metrics.py b/synapse/storage/databases/main/metrics.py index c3f551d37756..c65dd85d9064 100644 --- a/synapse/storage/databases/main/metrics.py +++ b/synapse/storage/databases/main/metrics.py @@ -284,6 +284,7 @@ def _count_r30_users(txn): for row in txn: if row[0] == "unknown": + # XXX this is a sneaky no-op; suspect `continue` was meant. pass results[row[0]] = row[1] From e3f6af7992c2f4d713c42c6a207d5088e4e5d4a2 Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Mon, 5 Jul 2021 16:08:46 +0100 Subject: [PATCH 2/9] Characterise current R30 behaviour using tests --- tests/app/test_phone_stats_home.py | 105 +++++++++++++++++++++++++++++ 1 file changed, 105 insertions(+) create mode 100644 tests/app/test_phone_stats_home.py diff --git a/tests/app/test_phone_stats_home.py b/tests/app/test_phone_stats_home.py new file mode 100644 index 000000000000..6319ab8a7ec3 --- /dev/null +++ b/tests/app/test_phone_stats_home.py @@ -0,0 +1,105 @@ +import synapse +from synapse.rest.client.v1 import login, room + +from tests.unittest import HomeserverTestCase + +DAY = 86400 + + +class PhoneHomeTestCase(HomeserverTestCase): + servlets = [ + synapse.rest.admin.register_servlets_for_client_rest_resource, + room.register_servlets, + login.register_servlets, + ] + + def test_r30_minimum_usage(self): + """ + Tests the minimum amount of interaction necessary for the R30 metric + to consider a user 'retained'. + """ + + # Register a user, log it in, create a room and send a message + user_id = self.register_user("u1", "secret!") + access_token = self.login("u1", "secret!") + room_id = self.helper.create_room_as(room_creator=user_id, tok=access_token) + self.helper.send(room_id, "message", tok=access_token) + + # Check the R30 results do not count that user. + r30_results = self.get_success( + self.hs.get_datastore().count_r30_users() + ) + self.assertEqual(r30_results, {"all": 0}) + + # Advance 30 days (+ 1 second, because strict inequality causes issues if we are + # bang on 30 days later). + self.reactor.advance(30 * DAY + 1) + + # (Make sure the user isn't somehow counted by this point.) + r30_results = self.get_success( + self.hs.get_datastore().count_r30_users() + ) + self.assertEqual(r30_results, {"all": 0}) + + # Send a message (this counts as activity) + self.helper.send(room_id, "message2", tok=access_token) + + # TODO: Not sure why this needs 4+ seconds advancing here...? + self.reactor.advance(4) + + # *Now* the user is counted. + r30_results = self.get_success( + self.hs.get_datastore().count_r30_users() + ) + self.assertEqual(r30_results, {"all": 1, "unknown": 1}) + + # Advance 27 days. The user has now not posted for 27 days. + self.reactor.advance(27 * DAY) + + # The user is still counted. + r30_results = self.get_success( + self.hs.get_datastore().count_r30_users() + ) + self.assertEqual(r30_results, {"all": 1, "unknown": 1}) + + # Advance another day. The user has now not posted for 28 days. + self.reactor.advance(DAY) + + # The user is now no longer counted in R30. + # TODO: why is this the case after only 28 days? + r30_results = self.get_success( + self.hs.get_datastore().count_r30_users() + ) + self.assertEqual(r30_results, {"all": 0}) + + def test_r30_user_must_be_retained_for_at_least_a_month(self): + """ + Tests that a newly-registered user must be retained for a whole month + before appearing in the R30 statistic, even if they post every day + during that time! + """ + # Register a user and send a message + user_id = self.register_user("u1", "secret!") + access_token = self.login("u1", "secret!") + room_id = self.helper.create_room_as(room_creator=user_id, tok=access_token) + self.helper.send(room_id, "message", tok=access_token) + + # Check the user does not contribute to R30 yet. + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) + self.assertEqual(r30_results, {"all": 0}) + + for _ in range(30): + # This loop posts a message every day for 30 days + self.reactor.advance(DAY) + self.helper.send(room_id, "I'm still here", tok=access_token) + + # Notice that the user *still* does not contribute to R30! + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) + self.assertEqual(r30_results, {"all": 0}) + + self.reactor.advance(DAY) + self.helper.send(room_id, "Still here!", tok=access_token) + + # *Now* the user appears in R30. + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) + self.assertEqual(r30_results, {"all": 1, "unknown": 1}) From 2082de4a237f46d2594331d47aa91593b5552087 Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Mon, 5 Jul 2021 16:13:12 +0100 Subject: [PATCH 3/9] Changelog and antilint Signed-off-by: Olivier Wilkinson (reivilibre) --- changelog.d/10315.misc | 1 + tests/app/test_phone_stats_home.py | 20 +++++--------------- 2 files changed, 6 insertions(+), 15 deletions(-) create mode 100644 changelog.d/10315.misc diff --git a/changelog.d/10315.misc b/changelog.d/10315.misc new file mode 100644 index 000000000000..2c78644e2012 --- /dev/null +++ b/changelog.d/10315.misc @@ -0,0 +1 @@ +Add tests to characterise the current behaviour of R30 phone-home metrics. diff --git a/tests/app/test_phone_stats_home.py b/tests/app/test_phone_stats_home.py index 6319ab8a7ec3..0a57b6ec18f7 100644 --- a/tests/app/test_phone_stats_home.py +++ b/tests/app/test_phone_stats_home.py @@ -26,9 +26,7 @@ def test_r30_minimum_usage(self): self.helper.send(room_id, "message", tok=access_token) # Check the R30 results do not count that user. - r30_results = self.get_success( - self.hs.get_datastore().count_r30_users() - ) + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 0}) # Advance 30 days (+ 1 second, because strict inequality causes issues if we are @@ -36,9 +34,7 @@ def test_r30_minimum_usage(self): self.reactor.advance(30 * DAY + 1) # (Make sure the user isn't somehow counted by this point.) - r30_results = self.get_success( - self.hs.get_datastore().count_r30_users() - ) + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 0}) # Send a message (this counts as activity) @@ -48,18 +44,14 @@ def test_r30_minimum_usage(self): self.reactor.advance(4) # *Now* the user is counted. - r30_results = self.get_success( - self.hs.get_datastore().count_r30_users() - ) + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 1, "unknown": 1}) # Advance 27 days. The user has now not posted for 27 days. self.reactor.advance(27 * DAY) # The user is still counted. - r30_results = self.get_success( - self.hs.get_datastore().count_r30_users() - ) + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 1, "unknown": 1}) # Advance another day. The user has now not posted for 28 days. @@ -67,9 +59,7 @@ def test_r30_minimum_usage(self): # The user is now no longer counted in R30. # TODO: why is this the case after only 28 days? - r30_results = self.get_success( - self.hs.get_datastore().count_r30_users() - ) + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 0}) def test_r30_user_must_be_retained_for_at_least_a_month(self): From 9a88346cb3cfe2f03c56d0af0fc754bb4feb1e65 Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Mon, 5 Jul 2021 18:01:46 +0100 Subject: [PATCH 4/9] Discovered why we need this wait here --- tests/app/test_phone_stats_home.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/tests/app/test_phone_stats_home.py b/tests/app/test_phone_stats_home.py index 0a57b6ec18f7..a67c83fa74b6 100644 --- a/tests/app/test_phone_stats_home.py +++ b/tests/app/test_phone_stats_home.py @@ -40,8 +40,9 @@ def test_r30_minimum_usage(self): # Send a message (this counts as activity) self.helper.send(room_id, "message2", tok=access_token) - # TODO: Not sure why this needs 4+ seconds advancing here...? - self.reactor.advance(4) + # We have to wait up to 5 seconds for _update_client_ips_batch to get + # called and update the user_ips table in a batch. + self.reactor.advance(5.1) # *Now* the user is counted. r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) From b6a009371eb450851ad1337ef04ede001774c668 Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Mon, 5 Jul 2021 18:13:01 +0100 Subject: [PATCH 5/9] Figure out the questions. --- tests/app/test_phone_stats_home.py | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/tests/app/test_phone_stats_home.py b/tests/app/test_phone_stats_home.py index a67c83fa74b6..4d54c6d5c3f3 100644 --- a/tests/app/test_phone_stats_home.py +++ b/tests/app/test_phone_stats_home.py @@ -1,6 +1,7 @@ import synapse from synapse.rest.client.v1 import login, room +from tests import unittest from tests.unittest import HomeserverTestCase DAY = 86400 @@ -13,6 +14,9 @@ class PhoneHomeTestCase(HomeserverTestCase): login.register_servlets, ] + # Override the retention time for the user_ips table because otherwise it + # gets pruned too aggressively for our R30 test. + @unittest.override_config({"user_ips_max_age": "365d"}) def test_r30_minimum_usage(self): """ Tests the minimum amount of interaction necessary for the R30 metric @@ -48,18 +52,17 @@ def test_r30_minimum_usage(self): r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 1, "unknown": 1}) - # Advance 27 days. The user has now not posted for 27 days. - self.reactor.advance(27 * DAY) + # Advance 29 days. The user has now not posted for 29 days. + self.reactor.advance(29 * DAY) # The user is still counted. r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 1, "unknown": 1}) - # Advance another day. The user has now not posted for 28 days. + # Advance another day. The user has now not posted for 30 days. self.reactor.advance(DAY) # The user is now no longer counted in R30. - # TODO: why is this the case after only 28 days? r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 0}) From 9753b8bf7ad06ecc6142d267f4cd1dfe9f2a5b3f Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Tue, 6 Jul 2021 09:54:19 +0100 Subject: [PATCH 6/9] Revert "Make note of suspected minor bug" This reverts commit 071037c3a3c8a9ebfe51c8f9197ff3044ab8545f. --- synapse/storage/databases/main/metrics.py | 1 - 1 file changed, 1 deletion(-) diff --git a/synapse/storage/databases/main/metrics.py b/synapse/storage/databases/main/metrics.py index c65dd85d9064..c3f551d37756 100644 --- a/synapse/storage/databases/main/metrics.py +++ b/synapse/storage/databases/main/metrics.py @@ -284,7 +284,6 @@ def _count_r30_users(txn): for row in txn: if row[0] == "unknown": - # XXX this is a sneaky no-op; suspect `continue` was meant. pass results[row[0]] = row[1] From cc6b61ca64f9a404082a7459485ed83ee319e652 Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Thu, 8 Jul 2021 10:43:15 +0100 Subject: [PATCH 7/9] Wait a bit longer in the test for user_ips to update. Signed-off-by: Olivier Wilkinson (reivilibre) --- tests/app/test_phone_stats_home.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/app/test_phone_stats_home.py b/tests/app/test_phone_stats_home.py index 4d54c6d5c3f3..ee1ebc85ef0e 100644 --- a/tests/app/test_phone_stats_home.py +++ b/tests/app/test_phone_stats_home.py @@ -44,9 +44,9 @@ def test_r30_minimum_usage(self): # Send a message (this counts as activity) self.helper.send(room_id, "message2", tok=access_token) - # We have to wait up to 5 seconds for _update_client_ips_batch to get - # called and update the user_ips table in a batch. - self.reactor.advance(5.1) + # We have to wait some time for _update_client_ips_batch to get + # called and update the user_ips table. + self.reactor.advance(2 * 60 * 60) # *Now* the user is counted. r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) From f60b30f5019b7933473126749d79b07b2d6acd35 Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Fri, 9 Jul 2021 10:49:12 +0100 Subject: [PATCH 8/9] Rename DAY --- tests/app/test_phone_stats_home.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/tests/app/test_phone_stats_home.py b/tests/app/test_phone_stats_home.py index ee1ebc85ef0e..633654fdc0d5 100644 --- a/tests/app/test_phone_stats_home.py +++ b/tests/app/test_phone_stats_home.py @@ -4,7 +4,7 @@ from tests import unittest from tests.unittest import HomeserverTestCase -DAY = 86400 +ONE_DAY_IN_SECONDS = 86400 class PhoneHomeTestCase(HomeserverTestCase): @@ -35,7 +35,7 @@ def test_r30_minimum_usage(self): # Advance 30 days (+ 1 second, because strict inequality causes issues if we are # bang on 30 days later). - self.reactor.advance(30 * DAY + 1) + self.reactor.advance(30 * ONE_DAY_IN_SECONDS + 1) # (Make sure the user isn't somehow counted by this point.) r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) @@ -53,14 +53,14 @@ def test_r30_minimum_usage(self): self.assertEqual(r30_results, {"all": 1, "unknown": 1}) # Advance 29 days. The user has now not posted for 29 days. - self.reactor.advance(29 * DAY) + self.reactor.advance(29 * ONE_DAY_IN_SECONDS) # The user is still counted. r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 1, "unknown": 1}) # Advance another day. The user has now not posted for 30 days. - self.reactor.advance(DAY) + self.reactor.advance(ONE_DAY_IN_SECONDS) # The user is now no longer counted in R30. r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) @@ -84,14 +84,14 @@ def test_r30_user_must_be_retained_for_at_least_a_month(self): for _ in range(30): # This loop posts a message every day for 30 days - self.reactor.advance(DAY) + self.reactor.advance(ONE_DAY_IN_SECONDS) self.helper.send(room_id, "I'm still here", tok=access_token) # Notice that the user *still* does not contribute to R30! r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 0}) - self.reactor.advance(DAY) + self.reactor.advance(ONE_DAY_IN_SECONDS) self.helper.send(room_id, "Still here!", tok=access_token) # *Now* the user appears in R30. From d3f90a7bd6c8154af19cb85bbcc359b2eab8915a Mon Sep 17 00:00:00 2001 From: "Olivier Wilkinson (reivilibre)" Date: Wed, 14 Jul 2021 15:42:51 +0100 Subject: [PATCH 9/9] Add a variant of the test that uses the default config setting --- tests/app/test_phone_stats_home.py | 54 ++++++++++++++++++++++++++++++ 1 file changed, 54 insertions(+) diff --git a/tests/app/test_phone_stats_home.py b/tests/app/test_phone_stats_home.py index 633654fdc0d5..2da6ba4dde49 100644 --- a/tests/app/test_phone_stats_home.py +++ b/tests/app/test_phone_stats_home.py @@ -66,6 +66,60 @@ def test_r30_minimum_usage(self): r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) self.assertEqual(r30_results, {"all": 0}) + def test_r30_minimum_usage_using_default_config(self): + """ + Tests the minimum amount of interaction necessary for the R30 metric + to consider a user 'retained'. + + N.B. This test does not override the `user_ips_max_age` config setting, + which defaults to 28 days. + """ + + # Register a user, log it in, create a room and send a message + user_id = self.register_user("u1", "secret!") + access_token = self.login("u1", "secret!") + room_id = self.helper.create_room_as(room_creator=user_id, tok=access_token) + self.helper.send(room_id, "message", tok=access_token) + + # Check the R30 results do not count that user. + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) + self.assertEqual(r30_results, {"all": 0}) + + # Advance 30 days (+ 1 second, because strict inequality causes issues if we are + # bang on 30 days later). + self.reactor.advance(30 * ONE_DAY_IN_SECONDS + 1) + + # (Make sure the user isn't somehow counted by this point.) + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) + self.assertEqual(r30_results, {"all": 0}) + + # Send a message (this counts as activity) + self.helper.send(room_id, "message2", tok=access_token) + + # We have to wait some time for _update_client_ips_batch to get + # called and update the user_ips table. + self.reactor.advance(2 * 60 * 60) + + # *Now* the user is counted. + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) + self.assertEqual(r30_results, {"all": 1, "unknown": 1}) + + # Advance 27 days. The user has now not posted for 27 days. + self.reactor.advance(27 * ONE_DAY_IN_SECONDS) + + # The user is still counted. + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) + self.assertEqual(r30_results, {"all": 1, "unknown": 1}) + + # Advance another day. The user has now not posted for 28 days. + self.reactor.advance(ONE_DAY_IN_SECONDS) + + # The user is now no longer counted in R30. + # (This is because the user_ips table has been pruned, which by default + # only preserves the last 28 days of entries.) + r30_results = self.get_success(self.hs.get_datastore().count_r30_users()) + self.assertEqual(r30_results, {"all": 0}) + def test_r30_user_must_be_retained_for_at_least_a_month(self): """ Tests that a newly-registered user must be retained for a whole month