MSC4140: update error responses#19539
Conversation
Prevent users from having more than a configured number of delayed events scheduled at once.
Also don't return a custom error (that was never in the MSC) when adding a delayed event if not enabled in the config
Set the new "max_delayed_events_per_user" config in the same module
as where the other MSC4140 config ("max_event_delay_duration") is set.
Also give it aliases for experimental & stable usage.
in an attempt to better explain what it is and why it is being examined
Don't want a stable alias for it yet, as it may change
Set its value to the remaining time until the requesting user's next delayed event will be sent. Also drop test against the error message of the thrown LimitExceededError, as now the Retry-After is there to clearly distinguish the thrown error as being related to a specific delayed event request.
If delayed events are to be disabled, it should be done by leaving the max_event_delay_duration config unspecified, not by setting the delayed event limit to 0. Also add test coverage, and tweak the error thrown for max_delay_event_ms to be consistent with the newly-added error.
| LimitExceededError: if the user has reached the limit of | ||
| how many delayed events they may have scheduled at once. | ||
| """ | ||
| assert limit > 0 # Should be enforced at config read time |
There was a problem hiding this comment.
Why do we enforce this? Seems valid
I see this commit message but none of that context made it into the code.
Enforce max delayed event config to be positive
If delayed events are to be disabled, it should be done by leaving the
max_event_delay_duration config unspecified, not by setting the delayed
event limit to 0.-- 43e14e9
And I don't think it's something for us to worry about at this level (just in the config validation)
There was a problem hiding this comment.
It looks like it was updated to "Allow delayed event limit to be set to 0". Why did this change versus leaving max_event_delay_duration unspecified as originally intended?
It was also updated to still enforce the condition in add_delayed_event. I don't think we need to care at all there (just throw the LimitExceededError per the logic).
If you want to prevent sending delayed events when it's disabled, it should be done in the handler layer instead.
There was a problem hiding this comment.
It looks like it was updated to "Allow delayed event limit to be set to 0". Why did this change versus leaving
max_event_delay_durationunspecified as originally intended?
This was done to make the config more user-friendly. A server admin who wants to disable delayed events may attempt to do so by configuring the limit to 0, rather than leaving the max duration unspecified / setting it to null. The only reason for having disallowed a limit of 0 was to slightly simplify the implementation of config-disabled delayed events, so I've walked back on that.
Also, once the MSC is stabilized, Synapse may/should change its default value of the max duration to a non-null value, in which case 0 values for both the max duration & limit should be accepted as a way to disable delayed events.
It was also updated to still enforce the condition in
add_delayed_event. I don't think we need to care at all there (just throw theLimitExceededErrorper the logic).If you want to prevent sending delayed events when it's disabled, it should be done in the handler layer instead.
The reason I did it this way is because nothing technically prevents something from calling add_delayed_event with a limit <= 0, and (to my knowledge) there isn't a way for static type checks to enforce a variable to be a strictly positive integer. (The closest thing is Pydantic's PositiveInt, but that requires runtime checks that feel like overkill.)
So instead of working with the assumption that nothing will ever call this with limit <= 0, I figured it may as well just support it. This also leaves the door open for supporting user-specific limits, where callers may pass a specified limit instead of always the globally-configured one.
There's also the matter of a LimitExceededError not making as much sense in the limit <= 0 case, in which the Retry-After time is effectively infinite, which is why IMO it's more appropriate to error with M_UNKNOWN in that case. (I've also put this consideration in the MSC.) The docstring now mentions that special case with 0b0aab1.
There was a problem hiding this comment.
I don't think we should be worrying about "Sending delayed events has been disallowed" in a storage function. Something to decide on the handler level.
Having the assert is fine but I called it out as I thought the assertion may be too tight and not necessary given the logic will reject if over the limit.
There's also the matter of a
LimitExceededErrornot making as much sense in thelimit<= 0 case, in which theRetry-Aftertime is effectively infinite
As a possibility, if there are no existing rows, retry_after_ms could just be None in that case.
There was a problem hiding this comment.
af16899 moves all of the limit-checking to the handler.
I didn't add the assert back to the storage function, as I might change it to just use the simplified approach as per your suggestion.
There was a problem hiding this comment.
I decided to keep disallowing a 0 limit, because it eliminates the need to guard against an empty list returned from the DB query. I'm also going to stick with the non-simplified query for the reasons I state here.
To better communicate the restrictions on the limit, 80b47aa enforces it with a ValueError instead of an assert, and adds a docstring to explicitly state that the limit must be positive.
| raise ConfigError( | ||
| "Expected a positive value", ("max_event_delay_duration",) | ||
| ) |
There was a problem hiding this comment.
Explain more why and what do do.
Enforce max delayed event config to be positive
If delayed events are to be disabled, it should be done by leaving the
max_event_delay_duration config unspecified, not by setting the delayed
event limit to 0.-- 43e14e9
There was a problem hiding this comment.
267a7e5 rewords the error message to be a bit more descriptive, and to follow the same format used by similar errors in this module.
There was a problem hiding this comment.
Per the original intentions, I was more looking for something like this:
| raise ConfigError( | |
| "Expected a positive value", ("max_event_delay_duration",) | |
| ) | |
| raise ConfigError( | |
| "Expected a non-zero, positive value for the delay duration. To disable delayed events, leave `max_event_delay_duration` unspecified.", ("max_event_delay_duration",) | |
| ) |
It seems like ideally, we would have had this kind of structure for delayed event config:
delayed_events:
enabled: true
max_event_delay_duration: 24h
max_delayed_events_per_user: 100If we're going with 0 as a valid value to disable delayed events, I guess the updated error message works ⏩
There was a problem hiding this comment.
That new config does look better, though I'd prefer using a dedicated PR to change it, given that max_event_delay_duration has been around for a while now & moving it would be a breaking change.
I'd also prefer to keep config suggestions in the documentation instead of error messages, to reduce churn on code changes while the MSC is still unstable.
| expected_retry_after_ms = send_after_ms - wait_ms - step_ms | ||
| self.assertEqual( | ||
| expected_retry_after_ms, | ||
| channel.json_body["retry_after_ms"], | ||
| channel.json_body, | ||
| ) | ||
| retry_header = channel.headers.getRawHeaders("Retry-After") | ||
| assert retry_header | ||
| self.assertSequenceEqual( | ||
| [str(math.ceil(expected_retry_after_ms / 1000))], | ||
| retry_header, | ||
| ) |
There was a problem hiding this comment.
We probably don't care about testing the exact value. Just that it's > 0.
There is no comments here what we expect this to be
There was a problem hiding this comment.
This is mentioned in the MSC:
If a user's request to schedule a delayed event would exceed [the configured] limit, the homeserver will respond with ... a Retry-After header whose value is set to the time of/until the scheduled send time of the next of the user's delayed events to be sent, rounded up to the nearest second.
There was a problem hiding this comment.
At a minimum, we should explain what/why we're trying to test/assert (comment)
Overall, I think there is probably a smarter way to assert this. It's a bit hard to onboard to this months apart with each review cycle.
For example, the better way to do this kind of thing might be to send delayed events until the limit, wait for whatever Retry-After specifies and sanity check that you can send delayed events again.
There was a problem hiding this comment.
The context of what and why we're waiting for Retry-After needs to be explained in the comments (what the MSC is describing).
| retry_header = channel.headers.getRawHeaders("Retry-After") | ||
| assert retry_header |
There was a problem hiding this comment.
Feels like it could be better to assert a single header and use the single value in whatever comparison we want to do.
Otherwise, it would be better renamed retry_header and explain things.
There was a problem hiding this comment.
Agreed that this would be better, but it looks like Twisted's Headers API doesn't allow looking up a single header value, but only a list of all headers with a given name, even for single-valued headers like Retry-After.
There was a problem hiding this comment.
We can still assert there is a single value and use that
There was a problem hiding this comment.
Ideally, we'd do one step better and even assert that there is one Retry-After header. I guess I'm ok with how things are given this is just test code ⏩
If we were using Rust, I'd do something like this:
Matching slices (example from element-hq/matrix-authentication-service/ -> crates/handlers/src/compat/login.rs#L1991-L2006)
// Make sure we only see one `loginToken` parameter
let login_token = match query_map
.get("loginToken")
// We're using slice syntax here so we can match easily
.map_or(&[] as &[String], |v| v.as_slice())
{
[login_token] => login_token.to_owned(),
[] => {
panic!("Expected `loginToken` query parameter in uri={parsed_location_uri}");
}
_ => {
panic!(
"Expected one but found multiple `loginToken` query parameters in uri={parsed_location_uri}"
);
}
};Before I learned about the slice thing, I did this:
let room_id = match (rooms.len(), rooms.first())) {
(1, Some(room_id)) => room_id.to_owned(),
_ => {
panic!(
"Expected *one* room"
);
}
};There was a problem hiding this comment.
It's not so hard to test for a single header, so it's now done by d805c4d.
This reverts commit f69ddc1. See element-hq#19539 (comment)
Do this as it is intuitive to want to configure a limit of 0 in order to disable delayed events. Update errors & config parsing as appropriate. Also raise the same error for whether the max allowed delay duration or the max number of delayed events is 0.
| # Confirm that ratelimit overrides do not unblock this kind of limit | ||
| self.get_success( | ||
| self.hs.get_datastores().main.set_ratelimit_for_user(self.user_id, 0, 0) | ||
| ) |
There was a problem hiding this comment.
IMO it's appropriate here because it's relevant to the goal of the test, which is to ensure that the delayed event limit is applied as intended.
Can you expand on this?
If this part were to be split, it would probably end up duplicating most of the code in this test anyways.
That's fine
| num_existing: int = self.db_pool.simple_select_one_onecol_txn( | ||
| txn, | ||
| table="delayed_events", | ||
| keyvalues={"user_localpart": user_localpart}, | ||
| retcol="COUNT(*)", | ||
| ) |
There was a problem hiding this comment.
Double-checked there is a database index for this ✅ : "delayed_events_pkey" PRIMARY KEY, btree (user_localpart, delay_id)
$ psql --username=postgres synapse
psql (18.3)
Type "help" for help.
synapse=# \d+ delayed_events
Table "public.delayed_events"
Column | Type | Collation | Nullable | Default | Storage | Compression | Stats target | Description
--------------------+---------+-----------+----------+---------+----------+-------------+--------------+-------------
delay_id | text | | not null | | extended | | |
user_localpart | text | | not null | | extended | | |
device_id | text | | | | extended | | |
delay | bigint | | not null | | plain | | |
send_ts | bigint | | not null | | plain | | |
room_id | text | | not null | | extended | | |
event_type | text | | not null | | extended | | |
state_key | text | | | | extended | | |
origin_server_ts | bigint | | | | plain | | |
content | text | | not null | | extended | | |
is_processed | boolean | | not null | false | plain | | |
sticky_duration_ms | bigint | | | | plain | | |
Indexes:
"delayed_events_pkey" PRIMARY KEY, btree (user_localpart, delay_id)
"delayed_events_idx" UNIQUE, btree (delay_id)
"delayed_events_is_processed" btree (is_processed)
"delayed_events_room_state_event_idx" btree (room_id, event_type, state_key) WHERE state_key IS NOT NULL
"delayed_events_send_ts" btree (send_ts)
Not-null constraints:
"delayed_events_delay_id_not_null" NOT NULL "delay_id"
"delayed_events_user_localpart_not_null" NOT NULL "user_localpart"
"delayed_events_delay_not_null" NOT NULL "delay"
"delayed_events_send_ts_not_null" NOT NULL "send_ts"
"delayed_events_room_id_not_null" NOT NULL "room_id"
"delayed_events_event_type_not_null" NOT NULL "event_type"
"delayed_events_content_not_null" NOT NULL "content"
"delayed_events_is_processed_not_null" NOT NULL "is_processed"There was a problem hiding this comment.
Testing the new queries with EXPLAIN shows that they indeed use indexes.
| num_existing: int = self.db_pool.simple_select_one_onecol_txn( | ||
| txn, | ||
| table="delayed_events", | ||
| keyvalues={"user_localpart": user_localpart}, | ||
| retcol="COUNT(*)", | ||
| ) |
There was a problem hiding this comment.
Should this query be looking for is_processed: False only?
In this vein, there should probably be a test to make sure that if you sent N number delayed events (more than the configured limit) which are all in the past, you can still send more delayed events.
There was a problem hiding this comment.
This query wasn't updated to take into account is_processed: False yet
I don't think that test covers this case especially given it didn't catch this.
There was a problem hiding this comment.
This query wasn't updated to take into account
is_processed: Falseyet
The change I did make is to have both queries here ignore is_processed, so that events in the midst of being sent will count towards the limit. The reason for doing so is to avoid the (hopefully very rare) case of there being a buildup of such mid-processed events.
As a reminder, is_processed means the condition for sending a delayed event has been reached (i.e. the delayed event has either reached its scheduled send time, or was requested to be sent on-demand), but the event has not yet landed in its target room. The DB tracks this to allow recovering delayed events that would otherwise be lost if the homeserver were to crash/restart between the time of a delayed event wanting to be sent & it actually getting sent.
da30132 adds a test to confirm that the limit properly counts is_processed events. It does so by simulating the server taking a long time to process delayed events, and checking that more events cannot be scheduled until the existing ones that exceed the limit have finished being processed.
test to make sure that if you sent N number delayed events (more than the configured limit) which are all in the past, you can still send more delayed events.
I believe this is already done, because the two tests that set a limit of N>0 both check that an N+1th delayed event can be scheduled after having waited for as long as Retry-After said to. But perhaps I misunderstood your request.
With that said, what I had thought you meant was to test lowering the limit after already having scheduled enough events to exceed the new limit. That's what e1a0ba4 was for.
| next_send_ts = self.db_pool.simple_select_one_onecol_txn( | ||
| txn, | ||
| table="delayed_events", | ||
| keyvalues={ | ||
| "is_processed": False, | ||
| "user_localpart": user_localpart, | ||
| }, | ||
| retcol="MIN(send_ts)", | ||
| ) |
There was a problem hiding this comment.
Seems like something we should just return as part of the first query since we have to do a scan for that anyway.
Might not be worth it as this is the error case 🤷 (consider query plan)
| ) | ||
| e = LimitExceededError( | ||
| limiter_name="add_delayed_event", | ||
| retry_after_ms=next_send_ts - creation_ts, |
There was a problem hiding this comment.
Do we actually want to be using creation_ts here?
Seems like we might want to be using clock.time_msec() and creation_ts was just convenient
There was a problem hiding this comment.
Using creation_ts should be more accurate, as the baseline time should be the time when the request was made, instead of whatever the time is when these DB queries have finished. To illustrate that, if the DB queries were take a long time, then that should count as time waited, but using clock.time_msec() here wouldn't capture that.
Don't assert the specific value of the Retry-After header, but test only that waiting for its returned duration is sufficient to bypass the limit
Co-authored-by: Eric Eastwood <madlittlemods@gmail.com>
| LimitExceededError: if the user has reached the limit of | ||
| how many delayed events they may have scheduled at once. | ||
| """ | ||
| assert limit > 0 # Should be enforced at config read time |
There was a problem hiding this comment.
I don't think we should be worrying about "Sending delayed events has been disallowed" in a storage function. Something to decide on the handler level.
Having the assert is fine but I called it out as I thought the assertion may be too tight and not necessary given the logic will reject if over the limit.
There's also the matter of a
LimitExceededErrornot making as much sense in thelimit<= 0 case, in which theRetry-Aftertime is effectively infinite
As a possibility, if there are no existing rows, retry_after_ms could just be None in that case.
| SELECT MAX(send_ts) FROM ( | ||
| SELECT * FROM delayed_events | ||
| WHERE user_localpart = ? | ||
| ORDER BY send_ts LIMIT ? | ||
| ) AS subquery |
There was a problem hiding this comment.
This deserves a proper comment about what it's trying to do.
Explanation for myself: First find N (closest to being sent) existing delayed events over the configured limit. Then take the max send_ts of those which marks when they will be sent and make room for another delayed event.
| retry_after_ms = int(retry_after_header[0]) | ||
| assert retry_after_ms > 0 | ||
|
|
||
| self.reactor.advance(retry_after_ms) |
There was a problem hiding this comment.
Since we're going through the trouble of staggering the delayed event time, perhaps we're also interested in checking whether Retry-After is using the minimum value necessary to allow us to send another delayed event.
Additionally, setting self.hs.config.server.max_delayed_events_per_user = 1 doesn't give us a representative example of this though since it will wait until all delayed events have been sent. It would be better to use self.hs.config.server.max_delayed_events_per_user = 2 at-least.
We could check that there are still scheduled delayed events that haven't been sent or check whether the actual events have been sent. Not sure on the cleanest option.
If we don't care about any of this, then we might as well not stagger anything and simplify the test. Overall, I think it could be useful to test as that SQL is non-trivial.
There was a problem hiding this comment.
Since we're going through the trouble of staggering the delayed event time, perhaps we're also interested in checking whether Retry-After is using the minimum value necessary to allow us to send another delayed event.
I believe the test already covers this, by waiting for no less than the returned Retry-After duration before making another request, which is expected to succeed.
It would be better to use
self.hs.config.server.max_delayed_events_per_user = 2at-least.
Good idea. 17d1bfe
We could check that there are still scheduled delayed events that haven't been sent or check whether the actual events have been sent. Not sure on the cleanest option.
I'd rather not have to do this, because it would involve calling endpoints other than just the /send?delay=X endpoint which this module is interested in. Besides, it is technically tested already by virtue of the pre-wait request getting a 429 and a post-wait one getting 200.
| retry_header = channel.headers.getRawHeaders("Retry-After") | ||
| assert retry_header |
There was a problem hiding this comment.
Ideally, we'd do one step better and even assert that there is one Retry-After header. I guess I'm ok with how things are given this is just test code ⏩
If we were using Rust, I'd do something like this:
Matching slices (example from element-hq/matrix-authentication-service/ -> crates/handlers/src/compat/login.rs#L1991-L2006)
// Make sure we only see one `loginToken` parameter
let login_token = match query_map
.get("loginToken")
// We're using slice syntax here so we can match easily
.map_or(&[] as &[String], |v| v.as_slice())
{
[login_token] => login_token.to_owned(),
[] => {
panic!("Expected `loginToken` query parameter in uri={parsed_location_uri}");
}
_ => {
panic!(
"Expected one but found multiple `loginToken` query parameters in uri={parsed_location_uri}"
);
}
};Before I learned about the slice thing, I did this:
let room_id = match (rooms.len(), rooms.first())) {
(1, Some(room_id)) => room_id.to_owned(),
_ => {
panic!(
"Expected *one* room"
);
}
};|
|
||
| self.assertEqual(channel.code, HTTPStatus.OK) | ||
| self.assertEqual( | ||
| capabilities["org.matrix.msc4140.delayed_events"]["max_delay"], 86400000 |
There was a problem hiding this comment.
| capabilities["org.matrix.msc4140.delayed_events"]["max_delay"], 86400000 | |
| capabilities["org.matrix.msc4140.delayed_events"]["max_delay"], Duration(days=1).as_millis() |
Something for the MSC but the max_delay name without a time suffix kinda sucks to figure out. max_delay_ms would be nice.
There was a problem hiding this comment.
TBH I'd rather it get canonicalized to a millisecond value, as that will prevent clients from having to parse a duration string from the /capabilities response.
There was a problem hiding this comment.
Not sure what you're referring to. What I suggested is just a human-readable function to produce 86400000 to better avoid typos and make it obvious.
There was a problem hiding this comment.
Oh, I thought you meant for the value of max_delay to have a time suffix. Having a suffix on the field name is a good idea. I can raise that in the MSC discussion and see where it goes.
There was a problem hiding this comment.
I've gone ahead with renaming this to max_delay_ms in the MSC, so this PR can now follow suit. a3d0def
| SELECT MAX(send_ts) FROM ( | ||
| SELECT * FROM delayed_events | ||
| WHERE user_localpart = ? | ||
| ORDER BY send_ts LIMIT ? | ||
| ) AS subquery |
There was a problem hiding this comment.
Overall, I'd also be fine with the simplification where we just grab the max send_ts and ignore the edge case of the scheduled delayed events being more than the configured limit. Just call it out in the comments.
There was a problem hiding this comment.
This should admittedly be a rare edge case, but I still feel uneasy leaving it unhandled, especially since the extra cost of the more complex query is offset by it not being on a hot path.
There was a problem hiding this comment.
I wrote "max send_ts" in my previous suggestion but I think I meant "min send_ts".
This should admittedly be a rare edge case, but I still feel uneasy leaving it unhandled
With my simplified suggestion, we're still handling the edge case. The edge case happens when the homeserver admin reduces max_delayed_events_per_user and you've already scheduled more delayed events; we'd just tell the user to wait until the next delayed event gets sent (min send_ts) to try again.
There was a problem hiding this comment.
The downside of the simplified approach is that it makes the returned Retry-After duration not long enough of a wait if there are many more delayed events scheduled than the limit allows. (Note that the case of Retry-After being long enough in that situation is what's covered by test_delayed_event_custom_user_limit_exceeded.)
Granted, that situation is possible only when a homeserver admin restarts the server with a lower limit while users have enough scheduled events to exceed the new limit. Although I'd expect that situation be rare, there is nothing stopping it from happening, so it may as well be addressed.
| num_existing: int = self.db_pool.simple_select_one_onecol_txn( | ||
| txn, | ||
| table="delayed_events", | ||
| keyvalues={"user_localpart": user_localpart}, | ||
| retcol="COUNT(*)", | ||
| ) |
There was a problem hiding this comment.
This query wasn't updated to take into account is_processed: False yet
I don't think that test covers this case especially given it didn't catch this.
Co-authored-by: Eric Eastwood <madlittlemods@gmail.com>
Co-authored-by: Eric Eastwood <madlittlemods@gmail.com>
as opposed to running part of the test before lifting ratelimits & part of it after, for the sake of simplifying the test
Retry-After returns a value in seconds, not milliseconds
Disallow calling the storage function with a non-positive `limit`. Better communicate this restriction by raising a ValueError on an invalid `limit`, and add a docstring that mentions the restriction. Also move `limit` to the end of the parameter list, to make it more noticeable (and to allow its docstring to come last & match the ordering in the parameter list). Note that a limit of 0 is still allowed for the handler function. Now only the storage function does not allow it.
Test with the limit dropped to 2 rather than 1, so that the required wait won't be for all delayed events to be sent, just for enough of them to be sent to permit scheduling a new one.
Pull Request Checklist
EventStoretoEventWorkerStore.".code blocks.