Fix flaky 3PID inhibit error unit tests

[anoadragon453]

Fixes flakes in the following unit tests:

• tests.rest.client.test_account.PasswordResetTestCase.test_password_reset_bad_email_inhibit_error
• tests.rest.client.test_register.RegisterRestServletTestCase.test_request_token_existing_email_inhibit_error

These tests could flake as the endpoints would intentionally wait for 100-1000ms in order to prevent a timing attack allowing one to deduce whether an email was already registered.

The tests were only waiting 1000ms for the endpoint to return, so a randomly-chosen jitter any higher than ~900ms would cause the test to fail.

---

I'm unsure why this started failing recently, as the jitter has been in place for years. There was a recent change with the Duration work - we used randrandom.randint(1, 10) / 10 and now Duration(milliseconds=random.randint(100, 1000)), but the math is technically equivalent.

Dev notes

There are multiple places we add jitter in both synapse/rest/client/account.py and synapse/rest/client/register.py

synapse/synapse/rest/client/account.py

Lines 125 to 131 in 963e486

	# Make the client think the operation succeeded. See the rationale in the
	# comments for request_token_inhibit_3pid_errors.
	# Also wait for some random amount of time between 100ms and 1s to make it
	# look like we did something.
	await self.hs.get_clock().sleep(
	Duration(milliseconds=random.randint(100, 1000))
	)

synapse/synapse/rest/client/register.py

Lines 157 to 165 in 963e486

	# Make the client think the operation succeeded. See the rationale in the
	# comments for request_token_inhibit_3pid_errors.
	# Still send an email to warn the user that an account already exists.
	# Also wait for some random amount of time between 100ms and 1s to make it
	# look like we did something.
	await self.already_in_use_mailer.send_already_in_use_mail(email)
	await self.hs.get_clock().sleep(
	Duration(milliseconds=random.randint(100, 1000))
	)

Pull Request Checklist

• Pull request is based on the develop branch
• Pull request includes a changelog file. The entry should:
  • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
  • Use markdown where necessary, mostly for code blocks.
  • End with either a period (.) or an exclamation mark (!).
  • Start with a capital letter.
  • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
• Code style is correct (run the linters)

[MadLittleMods]

The tests were only waiting 1000ms for the endpoint to return, so a randomly-chosen jitter any higher than ~900ms would cause the test to fail.

I'm not understanding the logic behind 3000ms?

[MadLittleMods]

This should actually be fine with 1000ms (the default).

The only reason it's not is because await_result(...) is a bit flaky. For example, the first advance(0.1) in await_result(...) triggers any scheduled work (like database ThreadPool queries as part of the request), then the 1000ms jitter sleep starts, but await_result(...) can give up after another 0.9s (still 1s total but 0.1s short of the sleep finishing). This edge case happens when the floating point math satisfies self._reactor.seconds() > end_time one iteration early so it waits exactly 1s (10 iterations). The normal case (when everything passes) is because it gets an extra self._reactor.advance(0.1) iteration (11 iterations -> waits 1.1s).

To make it more clear, here is how we could manually drive this to completion reliably:

(test_request_token_existing_email_inhibit_error in tests/rest/client/test_register.py)

channel = self.make_request(
    "POST",
    b"register/email/requestToken",
    {"client_secret": "foobar", "email": email, "send_attempt": 1},
    # We're going to drive the reactor ourselves (just below)
    await_result=False
)
# Wait for database queries to run so we can get the jitter sleep started
self.reactor.advance(0)
# Wait for any potential jitter (up to 1 second)
self.reactor.advance(Duration(seconds=1).as_secs())

Related to #19394 (comment) and #19734 (comment)

I think a better fix would be to update await_result(...) to self._reactor.advance(0) before it starts its loop. This way, we don't burn any reactor advance time on things that are actually scheduled now (get rid of the foot-guns).

I'm working on improving FakeChannel.await_result(...) in #19879 so I'll include the fix there ⏩

Overall, I think this PR should probably be reverted. We could still benefit from the comments pointing out the jitter here though.

[anoadragon453]

Thanks for diving in deep here! That makes sense, I didn't consider that other work could be delaying the response before the jitter even started.

I noticed that the fix was included in #19879, and the PR has now merged. Nice!

I agree that we no longer need to mess with the timeout in tests if await_result acts as expected, and actually it may be a bad smell to encourage tests to do so (leading to overzealous delays in unit tests). Happy to revert this PR minus the jitter comments.

I'm not understanding the logic behind 3000ms?

It was just an arbitrarily higher value to get substantially far away from 1000ms.

[MadLittleMods]

We can use the Duration class

[MadLittleMods]

Why 1000 default if that doesn't work in these cases?

[anoadragon453]

The reasoning was that the jitter was an edge case that only applied to this endpoint, and thus these tests.

[MadLittleMods]

_request_token(...) is a custom method for the tests for this endpoint (not a general method)

[MadLittleMods]

Historically, we instead used this pattern:

channel = self.make_request(
    "GET",
    f"/_matrix/media/r0/thumbnail/{self.media_id}{params}",
    await_result=False,
)
channel.await_result(timeout_ms=1000)

The new shortcut doesn't seem bad though.